2012-10-18T03:54:07.592Z,1350532447.592 [Supervisor](DEBUG): Initializing supervisor.
2012-10-18T03:54:07.598Z,1350532447.598 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-10-18T03:54:07.599Z,1350532447.599 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-10-18T03:54:07.602Z,1350532447.602 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-10-18T03:54:07.606Z,1350532447.606 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-10-18T03:54:07.617Z,1350532447.617 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-10-18T03:54:07.618Z,1350532447.618 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-10-18T03:54:07.619Z,1350532447.619 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-10-18T03:54:07.620Z,1350532447.620 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-10-18T03:54:07.623Z,1350532447.623 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-10-18T03:54:07.937Z,1350532447.937 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-10-18T03:54:07.939Z,1350532447.939 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-10-18T03:54:08.139Z,1350532448.139 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-10-18T03:54:08.140Z,1350532448.140 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-10-18T03:54:08.238Z,1350532448.238 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-10-18T03:54:08.240Z,1350532448.240 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-10-18T03:54:08.471Z,1350532448.471 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-10-18T03:54:08.472Z,1350532448.472 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-10-18T03:54:08.623Z,1350532448.623 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-10-18T03:54:08.625Z,1350532448.625 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-10-18T03:54:08.887Z,1350532448.887 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-10-18T03:54:08.888Z,1350532448.888 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-10-18T03:54:09.078Z,1350532449.078 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-10-18T03:54:09.080Z,1350532449.080 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-10-18T03:54:09.360Z,1350532449.360 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-10-18T03:54:09.362Z,1350532449.362 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-10-18T03:54:09.475Z,1350532449.475 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-10-18T03:54:09.475Z,1350532449.476 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-10-18T03:54:09.922Z,1350532449.922 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-10-18T03:54:09.923Z,1350532449.922 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-10-18T03:54:10.051Z,1350532450.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-10-18T03:54:10.052Z,1350532450.052 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-10-18T03:54:10.147Z,1350532450.147 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-10-18T03:54:10.151Z,1350532450.151 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-10-18T03:54:10.266Z,1350532450.266 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-10-18T03:54:10.413Z,1350532450.413 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-10-18T03:54:10.510Z,1350532450.510 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-10-18T03:54:10.622Z,1350532450.622 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-10-18T03:54:10.732Z,1350532450.731 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-10-18T03:54:10.863Z,1350532450.864 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-10-18T03:54:10.970Z,1350532450.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-10-18T03:54:11.140Z,1350532451.140 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2012-10-18T03:54:11.187Z,1350532451.187 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-10-18T03:54:11.371Z,1350532451.371 [InternalSim] Loaded
2012-10-18T03:54:11.371Z,1350532451.371 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-10-18T03:54:11.372Z,1350532451.372 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-10-18T03:54:11.372Z,1350532451.372 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-10-18T03:54:11.455Z,1350532451.455 [SBIT](DEBUG): Construct Startup Built In Test.
2012-10-18T03:54:11.472Z,1350532451.472 [SBIT] Loaded
2012-10-18T03:54:11.473Z,1350532451.473 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-10-18T03:54:11.474Z,1350532451.474 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-10-18T03:54:11.502Z,1350532451.502 [IBIT] Loaded
2012-10-18T03:54:11.502Z,1350532451.502 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-10-18T03:54:11.506Z,1350532451.506 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-10-18T03:54:11.635Z,1350532451.635 [CBIT] Loaded
2012-10-18T03:54:11.636Z,1350532451.636 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-10-18T03:54:11.636Z,1350532451.636 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-10-18T03:54:11.637Z,1350532451.637 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-10-18T03:54:11.809Z,1350532451.809 [BuoyancyServo] Loaded
2012-10-18T03:54:11.809Z,1350532451.809 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-10-18T03:54:11.819Z,1350532451.819 [ElevatorServo] Loaded
2012-10-18T03:54:11.819Z,1350532451.819 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-10-18T03:54:11.831Z,1350532451.831 [MassServo] Loaded
2012-10-18T03:54:11.831Z,1350532451.831 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-10-18T03:54:11.847Z,1350532451.847 [RudderServo] Loaded
2012-10-18T03:54:11.847Z,1350532451.847 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-10-18T03:54:11.859Z,1350532451.859 [ThrusterServo] Loaded
2012-10-18T03:54:11.859Z,1350532451.859 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-10-18T03:54:11.859Z,1350532451.859 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-10-18T03:54:11.860Z,1350532451.860 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-10-18T03:54:11.893Z,1350532451.893 [DepthRateCalculator] Loaded
2012-10-18T03:54:11.893Z,1350532451.893 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-10-18T03:54:15.988Z,1350532455.988 [HFRadarModelCalc] Loaded
2012-10-18T03:54:15.988Z,1350532455.989 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-10-18T03:54:16.004Z,1350532456.004 [NavChart] Loaded
2012-10-18T03:54:16.005Z,1350532456.005 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-10-18T03:54:16.014Z,1350532456.014 [PitchRateCalculator] Loaded
2012-10-18T03:54:16.015Z,1350532456.015 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-10-18T03:54:16.021Z,1350532456.021 [SpeedCalculator] Loaded
2012-10-18T03:54:16.021Z,1350532456.021 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-10-18T03:54:16.036Z,1350532456.036 [TempGradientCalculator] Loaded
2012-10-18T03:54:16.036Z,1350532456.036 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-10-18T03:54:16.041Z,1350532456.042 [YawRateCalculator] Loaded
2012-10-18T03:54:16.042Z,1350532456.042 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-10-18T03:54:16.065Z,1350532456.066 [Navigation] Loaded
2012-10-18T03:54:16.066Z,1350532456.066 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-10-18T03:54:16.066Z,1350532456.066 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-10-18T03:54:16.067Z,1350532456.067 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-10-18T03:54:16.342Z,1350532456.342 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-10-18T03:54:16.343Z,1350532456.342 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-10-18T03:54:16.384Z,1350532456.384 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-10-18T03:54:16.385Z,1350532456.385 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-10-18T03:54:16.445Z,1350532456.445 [VerticalControl](DEBUG): Construct VerticalControl.
2012-10-18T03:54:16.495Z,1350532456.495 [VerticalControl] Loaded
2012-10-18T03:54:16.496Z,1350532456.496 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-10-18T03:54:16.496Z,1350532456.497 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-10-18T03:54:16.522Z,1350532456.522 [HorizontalControl] Loaded
2012-10-18T03:54:16.522Z,1350532456.522 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-10-18T03:54:16.523Z,1350532456.523 [SpeedControl](DEBUG): Construct SpeedControl.
2012-10-18T03:54:16.525Z,1350532456.525 [SpeedControl] Loaded
2012-10-18T03:54:16.525Z,1350532456.525 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-10-18T03:54:16.526Z,1350532456.526 [LoopControl](DEBUG): Construct LoopControl.
2012-10-18T03:54:16.526Z,1350532456.526 [LoopControl] Loaded
2012-10-18T03:54:16.527Z,1350532456.527 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-10-18T03:54:16.527Z,1350532456.527 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-10-18T03:54:16.528Z,1350532456.528 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-10-18T03:54:16.536Z,1350532456.536 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-10-18T03:54:16.541Z,1350532456.541 [AsyncPiEstimator] Loaded
2012-10-18T03:54:16.541Z,1350532456.541 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-10-18T03:54:16.542Z,1350532456.542 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406714E0
2012-10-18T03:54:16.543Z,1350532456.543 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-10-18T03:54:16.544Z,1350532456.544 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-10-18T03:54:16.721Z,1350532456.721 [AHRS_sp3003D] Loaded
2012-10-18T03:54:16.721Z,1350532456.721 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-10-18T03:54:17.004Z,1350532457.004 [Batt_Ocean_Server] Loaded
2012-10-18T03:54:17.004Z,1350532457.004 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-10-18T03:54:17.016Z,1350532457.016 [Depth_Keller] Loaded
2012-10-18T03:54:17.017Z,1350532457.017 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-10-18T03:54:17.022Z,1350532457.022 [DropWeight] Loaded
2012-10-18T03:54:17.023Z,1350532457.023 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-10-18T03:54:17.153Z,1350532457.153 [DVL_micro] Loaded
2012-10-18T03:54:17.153Z,1350532457.153 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-10-18T03:54:17.154Z,1350532457.154 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406F24E0
2012-10-18T03:54:17.244Z,1350532457.244 [NAL9602] Loaded
2012-10-18T03:54:17.245Z,1350532457.245 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-10-18T03:54:17.299Z,1350532457.299 [Onboard] Loaded
2012-10-18T03:54:17.299Z,1350532457.299 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-10-18T03:54:17.309Z,1350532457.309 [Radio_Freewave] Loaded
2012-10-18T03:54:17.310Z,1350532457.310 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-10-18T03:54:17.310Z,1350532457.310 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-10-18T03:54:17.311Z,1350532457.311 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-10-18T03:54:17.407Z,1350532457.407 [CTD_NeilBrown] Loaded
2012-10-18T03:54:17.407Z,1350532457.408 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-10-18T03:54:17.410Z,1350532457.410 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4074A4E0
2012-10-18T03:54:17.421Z,1350532457.421 [PAR_Licor] Loaded
2012-10-18T03:54:17.421Z,1350532457.421 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-10-18T03:54:17.442Z,1350532457.442 [Turbulence_NPS] Loaded
2012-10-18T03:54:17.442Z,1350532457.442 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-10-18T03:54:17.446Z,1350532457.446 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 4077A4E0
2012-10-18T03:54:17.480Z,1350532457.480 [WetLabsBB2FL] Loaded
2012-10-18T03:54:17.480Z,1350532457.480 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-10-18T03:54:17.482Z,1350532457.482 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407AA4E0
2012-10-18T03:54:17.483Z,1350532457.483 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-10-18T03:54:17.485Z,1350532457.485 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-10-18T03:54:17.486Z,1350532457.486 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-10-18T03:54:17.496Z,1350532457.496 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-10-18T03:54:17.498Z,1350532457.499 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407DA4E0
2012-10-18T03:54:17.503Z,1350532457.503 [Supervisor](DEBUG): Running supervisor.
2012-10-18T03:54:17.504Z,1350532457.504 [CommandLine](INFO): Thread ID is 749
2012-10-18T03:54:17.507Z,1350532457.507 [controlThread](INFO): Thread ID is 748
2012-10-18T03:54:17.507Z,1350532457.507 [controlThread](DEBUG): Initializing ControlThread
2012-10-18T03:54:17.508Z,1350532457.508 [CycleStarter](INFO): Thread ID is 747
2012-10-18T03:54:17.508Z,1350532457.508 [InternalSim](DEBUG):  InternalSim initializing...
2012-10-18T03:54:17.618Z,1350532457.618 [AsyncPiEstimator](INFO): Thread ID is 810
2012-10-18T03:54:17.618Z,1350532457.618 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-10-18T03:54:17.689Z,1350532457.689 [DVL_micro](INFO): Thread ID is 811
2012-10-18T03:54:17.773Z,1350532457.773 [CTD_NeilBrown](INFO): Thread ID is 812
2012-10-18T03:54:17.773Z,1350532457.773 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-10-18T03:54:17.779Z,1350532457.779 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-18T03:54:17.788Z,1350532457.788 [Turbulence_NPS](INFO): Thread ID is 813
2012-10-18T03:54:17.788Z,1350532457.788 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-10-18T03:54:17.789Z,1350532457.789 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-10-18T03:54:17.805Z,1350532457.805 [DVL_micro](INFO): Initializing
2012-10-18T03:54:17.805Z,1350532457.805 [DVL_micro](INFO): start:Powering up
2012-10-18T03:54:17.806Z,1350532457.806 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-18T03:54:17.815Z,1350532457.815 [DVL_micro](INFO): Cycling power to configure device.
2012-10-18T03:54:17.847Z,1350532457.847 [WetLabsBB2FL](INFO): Thread ID is 814
2012-10-18T03:54:17.848Z,1350532457.848 [WetLabsBB2FL](INFO): Powering down
2012-10-18T03:54:17.868Z,1350532457.868 [NavChartDb](INFO): Thread ID is 815
2012-10-18T03:54:17.869Z,1350532457.869 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-10-18T03:54:17.874Z,1350532457.874 [SBIT](INFO): Initialize SBIT Component.
2012-10-18T03:54:17.878Z,1350532457.878 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9999
2012-10-18T03:54:17.879Z,1350532457.879 [IBIT](INFO): Initialize IBIT Component.
2012-10-18T03:54:17.880Z,1350532457.880 [CBIT](DEBUG): Initialize CBIT Component.
2012-10-18T03:54:17.880Z,1350532457.880 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-10-18T03:54:17.927Z,1350532457.927 [Turbulence_NPS](INFO): Pause powering down
2012-10-18T03:54:17.939Z,1350532457.939 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-10-18T03:54:17.940Z,1350532457.940 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-10-18T03:54:17.940Z,1350532457.940 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-10-18T03:54:17.940Z,1350532457.940 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-10-18T03:54:17.941Z,1350532457.941 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-10-18T03:54:17.942Z,1350532457.942 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-10-18T03:54:17.942Z,1350532457.943 [Navigation](DEBUG): Initializing Navigation.
2012-10-18T03:54:17.943Z,1350532457.943 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-10-18T03:54:17.944Z,1350532457.944 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-10-18T03:54:17.945Z,1350532457.945 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-10-18T03:54:17.946Z,1350532457.945 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-10-18T03:54:17.979Z,1350532457.979 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA50M.000
2012-10-18T03:54:17.981Z,1350532457.981 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US2WC11M.000
2012-10-18T03:54:18.110Z,1350532458.110 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US1WC07M.000
2012-10-18T03:54:18.112Z,1350532458.112 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US3CA52M.000
2012-10-18T03:54:18.157Z,1350532458.157 [NavChartDb](INFO): Setup scan of Resources/US5CA50M.000
2012-10-18T03:54:19.298Z,1350532459.298 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2012-10-18T03:54:19.298Z,1350532459.298 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2012-10-18T03:54:19.298Z,1350532459.298 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2012-10-18T03:54:19.299Z,1350532459.299 [Batt_Ocean_Server](ERROR): Communications Fault
2012-10-18T03:54:19.323Z,1350532459.323 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-10-18T03:54:19.387Z,1350532459.387 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-18T03:54:19.397Z,1350532459.397 [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 RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-10-18T03:54:19.398Z,1350532459.398 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-10-18T03:54:19.431Z,1350532459.431 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-10-18T03:54:19.434Z,1350532459.434 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-10-18T03:54:19.441Z,1350532459.441 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-18T03:54:19.449Z,1350532459.449 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-10-18T03:54:19.452Z,1350532459.452 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-18T03:54:19.463Z,1350532459.463 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-10-18T03:54:19.472Z,1350532459.472 [Default:D.SetSpeed](DEBUG): Construct.
2012-10-18T03:54:19.475Z,1350532459.475 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-10-18T03:54:19.480Z,1350532459.480 [Default:F.Wait](DEBUG): Construct Wait.
2012-10-18T03:54:19.484Z,1350532459.484 [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 RunIn="Parallel">
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute RunIn="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><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

<!-- Wait forever at the surface-->

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

    <Guidance:Wait RunIn="Sequence"></Guidance:Wait>

</Mission>


2012-10-18T03:54:19.488Z,1350532459.488 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-10-18T03:54:19.512Z,1350532459.512 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-10-18T03:54:19.663Z,1350532459.662 [Depth_Keller](INFO): A/D timeout, 2 tries over 138 ms

2012-10-18T03:54:19.663Z,1350532459.663 [Depth_Keller] Data Fault, FailCount= 1
2012-10-18T03:54:19.663Z,1350532459.663 [Depth_Keller](ERROR): Data Fault
2012-10-18T03:54:19.691Z,1350532459.691 [Radio_Freewave](INFO): Powering up
2012-10-18T03:54:19.851Z,1350532459.851 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-10-18T03:54:19.854Z,1350532459.854 [PAR_Licor](INFO): A/D timeout, 2 tries over 154 ms

2012-10-18T03:54:19.855Z,1350532459.855 [PAR_Licor] Data Fault, FailCount= 1
2012-10-18T03:54:19.855Z,1350532459.855 [PAR_Licor](ERROR): Data Fault
2012-10-18T03:54:19.871Z,1350532459.871 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-10-18T03:54:19.871Z,1350532459.871 [DVL_micro](INFO): Querying output modes
2012-10-18T03:54:19.872Z,1350532459.872 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-10-18T03:54:19.879Z,1350532459.879 [DVL_micro](DEBUG): cmdResponse: 01 03 16
2012-10-18T03:54:19.879Z,1350532459.879 [DVL_micro](INFO): NQ1 output enabled
2012-10-18T03:54:19.879Z,1350532459.879 [DVL_micro](INFO): RSSI output enabled
2012-10-18T03:54:19.879Z,1350532459.879 [DVL_micro](INFO): ADCP output enabled
2012-10-18T03:54:19.879Z,1350532459.879 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-10-18T03:54:19.887Z,1350532459.887 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-10-18T03:54:19.892Z,1350532459.892 [DVL_micro](INFO): pause:Powering down
2012-10-18T03:54:19.957Z,1350532459.957 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-10-18T03:54:19.959Z,1350532459.959 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-10-18T03:54:19.965Z,1350532459.965 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-10-18T03:54:19.967Z,1350532459.967 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-10-18T03:54:19.973Z,1350532459.973 [MassServo](DEBUG): Initializing EZServoServo.
2012-10-18T03:54:19.975Z,1350532459.975 [MassServo](DEBUG): Initializing MassServo.
2012-10-18T03:54:19.980Z,1350532459.980 [RudderServo](DEBUG): Initializing EZServoServo.
2012-10-18T03:54:19.982Z,1350532459.982 [RudderServo](DEBUG): Initializing RudderServo.
2012-10-18T03:54:19.988Z,1350532459.988 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-10-18T03:54:19.991Z,1350532459.991 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-10-18T03:54:20.009Z,1350532460.009 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2012-10-18T03:54:20.009Z,1350532460.009 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2012-10-18T03:54:20.009Z,1350532460.009 [Batt_Ocean_Server] No Fault, FailCount= 1
2012-10-18T03:54:20.010Z,1350532460.010 [CBIT](ERROR): Data Fault in component: Depth_Keller
2012-10-18T03:54:20.010Z,1350532460.010 [CBIT](INFO): Clearing failed state for component Depth_Keller
2012-10-18T03:54:20.010Z,1350532460.010 [Depth_Keller] No Fault, FailCount= 1
2012-10-18T03:54:20.011Z,1350532460.011 [CBIT](ERROR): Data Fault in component: PAR_Licor
2012-10-18T03:54:20.011Z,1350532460.011 [CBIT](INFO): Clearing failed state for component PAR_Licor
2012-10-18T03:54:20.011Z,1350532460.011 [PAR_Licor] No Fault, FailCount= 1
2012-10-18T03:54:24.138Z,1350532464.138 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2012-10-18T03:54:24.139Z,1350532464.138 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2012-10-18T03:54:24.139Z,1350532464.139 [Batt_Ocean_Server] Communications Fault, FailCount= 2
2012-10-18T03:54:24.139Z,1350532464.139 [Batt_Ocean_Server](ERROR): Communications Fault
2012-10-18T03:54:24.164Z,1350532464.164 [NAL9602](INFO): Powering up NAL9602
2012-10-18T03:54:24.544Z,1350532464.544 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2012-10-18T03:54:25.547Z,1350532465.547 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2012-10-18T03:54:25.547Z,1350532465.547 [Batt_Ocean_Server] No Fault, FailCount= 2
2012-10-18T03:54:27.414Z,1350532467.414 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-10-18T03:54:33.959Z,1350532473.959 [SBIT](IMPORTANT): Beginning Startup BIT
2012-10-18T03:54:33.962Z,1350532473.962 [CBIT](IMPORTANT): Beginning GF scan
2012-10-18T03:54:34.631Z,1350532474.631 [NAL9602](INFO): NAL9602 initialized
2012-10-18T03:54:44.859Z,1350532484.859 [NavChartDb](INFO): Done scanning features of Resources/US5CA50M.000
2012-10-18T03:54:47.959Z,1350532487.959 [SBIT](FAULT): Mass: EXPECTED:0.004000 ACTUAL:0.001000
2012-10-18T03:55:01.881Z,1350532501.881 [CBIT](IMPORTANT): No ground fault detected
2012-10-18T03:55:31.488Z,1350532531.488 [SBIT](CRITICAL): SBIT FAILED
2012-10-18T03:55:31.611Z,1350532531.611 [NavChartDb](INFO): # of records loaded: 5000
2012-10-18T03:55:31.793Z,1350532531.793 [MissionManager](IMPORTANT): Started mission Startup
2012-10-18T03:55:31.793Z,1350532531.793 [Startup] Running Loop=1
2012-10-18T03:55:31.793Z,1350532531.793 [Startup](INFO): Aggregate::initialize Startup
2012-10-18T03:55:31.793Z,1350532531.793 [Startup:A.GoToSurface] Running Loop=1
2012-10-18T03:55:31.793Z,1350532531.793 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T03:55:31.799Z,1350532531.799 [Startup:StartupSatComms] Running Loop=1
2012-10-18T03:55:31.799Z,1350532531.799 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-10-18T03:55:31.799Z,1350532531.799 [Startup:StartupSatComms:A] Running Loop=1
2012-10-18T03:55:32.953Z,1350532532.953 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-10-18T03:55:57.538Z,1350532557.538 [NavChartDb](INFO): # of records loaded: 10000
2012-10-18T03:56:22.028Z,1350532582.028 [NavChartDb](INFO): # of records loaded: 15000
2012-10-18T03:56:32.884Z,1350532592.884 [Startup:StartupSatComms:A](INFO): Timed out from 2012-10-18T03:55:31.8Z
2012-10-18T03:56:32.885Z,1350532592.885 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2012-10-18T03:56:32.885Z,1350532592.885 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2012-10-18T03:56:32.885Z,1350532592.885 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2012-10-18T03:56:32.885Z,1350532592.885 [Startup:StartupSatComms:A] Stopped
2012-10-18T03:56:32.885Z,1350532592.885 [Startup:StartupSatComms:B] Running Loop=1
2012-10-18T03:56:33.881Z,1350532593.881 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-10-18T03:56:45.334Z,1350532605.334 [NavChartDb](INFO): # of records loaded: 20000
2012-10-18T03:57:09.001Z,1350532629.001 [NavChartDb](INFO): # of records loaded: 25000
2012-10-18T03:57:30.965Z,1350532650.965 [NavChartDb](INFO): # of records loaded: 30000
2012-10-18T03:57:33.269Z,1350532653.269 [Startup:StartupSatComms:B](INFO): Timed out from 2012-10-18T03:56:32.9Z
2012-10-18T03:57:33.269Z,1350532653.269 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2012-10-18T03:57:33.269Z,1350532653.269 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2012-10-18T03:57:33.269Z,1350532653.270 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2012-10-18T03:57:33.270Z,1350532653.270 [Startup:StartupSatComms:B] Stopped
2012-10-18T03:57:33.270Z,1350532653.270 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-10-18T03:57:33.270Z,1350532653.270 [Startup:StartupSatComms] Stopped
2012-10-18T03:57:33.270Z,1350532653.270 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-10-18T03:57:33.275Z,1350532653.275 [Startup](INFO): Completed Startup
2012-10-18T03:57:33.275Z,1350532653.275 [Startup] Stopped
2012-10-18T03:57:33.275Z,1350532653.275 [Startup](INFO): Aggregate::uninitialize Startup
2012-10-18T03:57:33.275Z,1350532653.275 [Startup:A.GoToSurface] Stopped
2012-10-18T03:57:33.275Z,1350532653.275 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T03:57:33.932Z,1350532653.932 [MissionManager](IMPORTANT): Started mission Default
2012-10-18T03:57:33.932Z,1350532653.932 [Default] Running Loop=1
2012-10-18T03:57:33.932Z,1350532653.932 [Default](INFO): Aggregate::initialize Default
2012-10-18T03:57:33.932Z,1350532653.932 [Default:D.SetSpeed] Running Loop=1
2012-10-18T03:57:33.932Z,1350532653.932 [Default:D.SetSpeed](DEBUG): Initialize.
2012-10-18T03:57:33.933Z,1350532653.932 [Default:E.GoToSurface] Running Loop=1
2012-10-18T03:57:33.933Z,1350532653.933 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium] Running Loop=1
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T03:57:33.933Z,1350532653.933 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T03:57:33.934Z,1350532653.934 [Default:E.GoToSurface] Running Loop=1
2012-10-18T03:57:33.944Z,1350532653.944 [Default:D.SetSpeed] Running Loop=1
2012-10-18T03:57:33.948Z,1350532653.948 [Default:CallIridium] Running Loop=1
2012-10-18T03:57:33.949Z,1350532653.949 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T03:57:33.949Z,1350532653.949 [Default:CallIridium:A] Running Loop=1
2012-10-18T03:57:33.951Z,1350532653.951 [Default:CallIridium:A] Stopped
2012-10-18T03:57:33.951Z,1350532653.951 [Default:CallIridium:B] Running Loop=1
2012-10-18T03:57:33.951Z,1350532653.951 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T03:57:33.956Z,1350532653.956 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T03:57:33.956Z,1350532653.956 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T03:57:33.956Z,1350532653.956 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T03:57:33.956Z,1350532653.956 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS] Running Loop=1
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS:A.SetSpeed] Running Loop=1
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS:B.GoToSurface] Running Loop=1
2012-10-18T03:57:33.961Z,1350532653.961 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T03:57:33.966Z,1350532653.966 [Default:GPS:B.GoToSurface] Stopped
2012-10-18T03:57:33.966Z,1350532653.966 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T03:57:33.967Z,1350532653.967 [Default:GPS:Read_GPS] Running Loop=1
2012-10-18T03:57:33.967Z,1350532653.967 [Default:GPS:A.SetSpeed] Running Loop=1
2012-10-18T03:57:34.649Z,1350532654.649 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-10-18T03:57:34.652Z,1350532654.652 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-10-18T03:57:55.927Z,1350532675.927 [NavChartDb](INFO): # of records loaded: 35000
2012-10-18T03:58:23.592Z,1350532703.592 [NavChartDb](INFO): # of records loaded: 40000
2012-10-18T03:58:47.540Z,1350532727.540 [NavChartDb](INFO): # of records loaded: 45000
2012-10-18T03:59:12.671Z,1350532752.671 [NavChartDb](INFO): # of records loaded: 50000
2012-10-18T03:59:42.122Z,1350532782.122 [NavChartDb](INFO): # of records loaded: 55000
2012-10-18T03:59:44.734Z,1350532784.734 [NavChartDb](INFO): Calculating coverage of Resources/US5CA50M.000
2012-10-18T04:00:01.039Z,1350532801.039 [NavChartDb](INFO): Done scanning edges of Resources/US5CA50M.000
2012-10-18T04:00:16.111Z,1350532816.111 [NavChartDb](INFO): # of records loaded: 60000
2012-10-18T04:00:41.123Z,1350532841.123 [NavChartDb](INFO): Done scanning nodes of Resources/US5CA50M.000
2012-10-18T04:00:41.159Z,1350532841.159 [NavChartDb](INFO): # of records loaded: 62026
2012-10-18T04:00:41.165Z,1350532841.165 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US5CA50M.000
2012-10-18T04:00:41.167Z,1350532841.167 [NavChartDb](INFO): Setup scan of Resources/US3CA52M.000
2012-10-18T04:00:59.509Z,1350532859.509 [NavChartDb](INFO): Done scanning features of Resources/US3CA52M.000
2012-10-18T04:01:27.764Z,1350532887.764 [NavChartDb](INFO): # of records loaded: 5000
2012-10-18T04:01:51.460Z,1350532911.460 [NavChartDb](INFO): # of records loaded: 10000
2012-10-18T04:02:02.279Z,1350532922.279 [NavChartDb](INFO): # of records loaded: 15000
2012-10-18T04:02:12.135Z,1350532932.135 [NavChartDb](INFO): # of records loaded: 20000
2012-10-18T04:02:28.943Z,1350532948.943 [NavChartDb](INFO): # of records loaded: 25000
2012-10-18T04:02:44.049Z,1350532964.049 [NavChartDb](INFO): # of records loaded: 30000
2012-10-18T04:02:52.780Z,1350532972.780 [NavChartDb](INFO): # of records loaded: 35000
2012-10-18T04:03:05.607Z,1350532985.607 [NavChartDb](INFO): # of records loaded: 40000
2012-10-18T04:03:24.386Z,1350533004.386 [NavChartDb](INFO): # of records loaded: 45000
2012-10-18T04:03:51.088Z,1350533031.088 [NavChartDb](INFO): # of records loaded: 50000
2012-10-18T04:04:10.502Z,1350533050.502 [NavChartDb](INFO): # of records loaded: 55000
2012-10-18T04:04:25.810Z,1350533065.810 [NavChartDb](INFO): # of records loaded: 60000
2012-10-18T04:04:37.436Z,1350533077.436 [NavChartDb](INFO): # of records loaded: 65000
2012-10-18T04:04:41.160Z,1350533081.160 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T04:04:41.160Z,1350533081.160 [NAL9602] Data Fault, FailCount= 1
2012-10-18T04:04:41.160Z,1350533081.160 [NAL9602](ERROR): Data Fault
2012-10-18T04:04:41.887Z,1350533081.887 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T04:04:42.104Z,1350533082.104 [NAL9602](INFO): Powering down
2012-10-18T04:04:42.513Z,1350533082.513 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T04:04:42.513Z,1350533082.513 [NAL9602] No Fault, FailCount= 1
2012-10-18T04:04:47.625Z,1350533087.625 [NAL9602](INFO): Powering up NAL9602
2012-10-18T04:04:52.938Z,1350533092.938 [NavChartDb](INFO): # of records loaded: 70000
2012-10-18T04:04:58.659Z,1350533098.659 [NAL9602](INFO): NAL9602 initialized
2012-10-18T04:05:12.759Z,1350533112.759 [NavChartDb](INFO): # of records loaded: 75000
2012-10-18T04:05:33.073Z,1350533133.073 [NavChartDb](INFO): # of records loaded: 80000
2012-10-18T04:05:49.267Z,1350533149.267 [NavChartDb](INFO): # of records loaded: 85000
2012-10-18T04:06:14.849Z,1350533174.849 [NavChartDb](INFO): # of records loaded: 90000
2012-10-18T04:06:30.780Z,1350533190.780 [NavChartDb](INFO): # of records loaded: 95000
2012-10-18T04:06:54.850Z,1350533214.850 [NavChartDb](INFO): # of records loaded: 100000
2012-10-18T04:07:18.394Z,1350533238.394 [NavChartDb](INFO): # of records loaded: 105000
2012-10-18T04:07:39.035Z,1350533259.035 [NavChartDb](INFO): # of records loaded: 110000
2012-10-18T04:07:50.578Z,1350533270.578 [NavChartDb](INFO): Calculating coverage of Resources/US3CA52M.000
2012-10-18T04:07:55.820Z,1350533275.820 [NavChartDb](INFO): Done scanning edges of Resources/US3CA52M.000
2012-10-18T04:08:03.997Z,1350533283.997 [NavChartDb](INFO): # of records loaded: 115000
2012-10-18T04:08:20.664Z,1350533300.664 [NavChartDb](INFO): Done scanning nodes of Resources/US3CA52M.000
2012-10-18T04:08:20.793Z,1350533300.793 [NavChartDb](INFO): # of records loaded: 117290
2012-10-18T04:08:20.798Z,1350533300.798 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US3CA52M.000
2012-10-18T04:08:20.799Z,1350533300.799 [NavChartDb](INFO): Setup scan of Resources/US2WC11M.000
2012-10-18T04:08:30.960Z,1350533310.960 [NavChartDb](INFO): Done scanning features of Resources/US2WC11M.000
2012-10-18T04:09:01.257Z,1350533341.257 [NavChartDb](INFO): # of records loaded: 5000
2012-10-18T04:09:23.425Z,1350533363.425 [NavChartDb](INFO): # of records loaded: 10000
2012-10-18T04:09:45.199Z,1350533385.199 [NavChartDb](INFO): # of records loaded: 15000
2012-10-18T04:10:08.282Z,1350533408.282 [NavChartDb](INFO): # of records loaded: 20000
2012-10-18T04:10:30.793Z,1350533430.793 [NavChartDb](INFO): # of records loaded: 25000
2012-10-18T04:10:58.972Z,1350533458.972 [NavChartDb](INFO): # of records loaded: 30000
2012-10-18T04:11:22.361Z,1350533482.361 [NavChartDb](INFO): # of records loaded: 35000
2012-10-18T04:11:46.463Z,1350533506.464 [NavChartDb](INFO): # of records loaded: 40000
2012-10-18T04:11:53.068Z,1350533513.068 [NavChartDb](INFO): Calculating coverage of Resources/US2WC11M.000
2012-10-18T04:11:57.593Z,1350533517.593 [NavChartDb](INFO): Done scanning edges of Resources/US2WC11M.000
2012-10-18T04:12:21.733Z,1350533541.733 [NavChartDb](INFO): Done scanning nodes of Resources/US2WC11M.000
2012-10-18T04:12:21.776Z,1350533541.776 [NavChartDb](INFO): # of records loaded: 44880
2012-10-18T04:12:21.781Z,1350533541.781 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US2WC11M.000
2012-10-18T04:12:21.783Z,1350533541.783 [NavChartDb](INFO): Setup scan of Resources/US1WC07M.000
2012-10-18T04:12:40.617Z,1350533560.617 [NavChartDb](INFO): Done scanning features of Resources/US1WC07M.000
2012-10-18T04:13:14.573Z,1350533594.573 [NavChartDb](INFO): # of records loaded: 5000
2012-10-18T04:13:39.345Z,1350533619.345 [NavChartDb](INFO): # of records loaded: 10000
2012-10-18T04:14:03.053Z,1350533643.053 [NavChartDb](INFO): # of records loaded: 15000
2012-10-18T04:14:28.549Z,1350533668.549 [NavChartDb](INFO): # of records loaded: 20000
2012-10-18T04:14:32.397Z,1350533672.397 [NavChartDb](INFO): Calculating coverage of Resources/US1WC07M.000
2012-10-18T04:14:40.214Z,1350533680.214 [NavChartDb](INFO): Done scanning edges of Resources/US1WC07M.000
2012-10-18T04:15:01.004Z,1350533701.004 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T04:15:01.004Z,1350533701.004 [NAL9602] Data Fault, FailCount= 2
2012-10-18T04:15:01.004Z,1350533701.004 [NAL9602](ERROR): Data Fault
2012-10-18T04:15:01.058Z,1350533701.058 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T04:15:01.058Z,1350533701.058 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T04:15:01.356Z,1350533701.356 [NAL9602](INFO): Powering down
2012-10-18T04:15:37.752Z,1350533737.752 [NavChartDb](INFO): Done scanning nodes of Resources/US1WC07M.000
2012-10-18T04:15:39.369Z,1350533739.369 [NavChartDb](INFO): # of records loaded: 24424
2012-10-18T04:15:39.379Z,1350533739.379 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US1WC07M.000
2012-10-18T04:15:42.730Z,1350533742.730 [NavChartDb](INFO): Creating index for soundings
2012-10-18T04:15:54.627Z,1350533754.627 [NavChartDb](INFO): Creating index for 0p0
2012-10-18T04:15:58.124Z,1350533758.124 [NavChartDb](INFO): Creating index for 1p8
2012-10-18T04:15:58.207Z,1350533758.207 [NavChartDb](INFO): Creating index for 3p6
2012-10-18T04:16:00.209Z,1350533760.209 [NavChartDb](INFO): Creating index for 5p4
2012-10-18T04:16:01.284Z,1350533761.284 [NavChartDb](INFO): Creating index for 9p1
2012-10-18T04:16:01.306Z,1350533761.306 [NavChartDb](INFO): Creating index for 10p9
2012-10-18T04:16:03.716Z,1350533763.716 [NavChartDb](INFO): Creating index for 18p2
2012-10-18T04:16:07.503Z,1350533767.503 [NavChartDb](INFO): Creating index for 36p5
2012-10-18T04:16:12.068Z,1350533772.068 [NavChartDb](INFO): Creating index for 54p8
2012-10-18T04:16:14.587Z,1350533774.587 [NavChartDb](INFO): Creating index for 73p1
2012-10-18T04:16:18.777Z,1350533778.777 [NavChartDb](INFO): Creating index for 91p4
2012-10-18T04:16:25.971Z,1350533785.971 [NavChartDb](INFO): Creating index for 182p8
2012-10-18T04:16:29.756Z,1350533789.756 [NavChartDb](INFO): Creating index for 365p7
2012-10-18T04:16:34.313Z,1350533794.313 [NavChartDb](INFO): Creating index for 548p6
2012-10-18T04:16:37.504Z,1350533797.504 [NavChartDb](INFO): Creating index for 731p5
2012-10-18T04:16:43.607Z,1350533803.607 [NavChartDb](INFO): Creating index for 914p4
2012-10-18T04:16:49.648Z,1350533809.648 [NavChartDb](INFO): Creating index for 1097p2
2012-10-18T04:16:55.039Z,1350533815.039 [NavChartDb](INFO): Creating index for 1280p1
2012-10-18T04:16:57.156Z,1350533817.156 [NavChartDb](INFO): Creating index for 1463p0
2012-10-18T04:16:59.461Z,1350533819.461 [NavChartDb](INFO): Creating index for 1645p9
2012-10-18T04:17:01.178Z,1350533821.178 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T04:17:01.178Z,1350533821.178 [NAL9602] No Fault, FailCount= 2
2012-10-18T04:17:01.389Z,1350533821.389 [NAL9602](INFO): Powering up NAL9602
2012-10-18T04:17:05.674Z,1350533825.674 [NavChartDb](INFO): Creating index for 1828p8
2012-10-18T04:17:09.901Z,1350533829.901 [NavChartDb](INFO): Creating index for 2011p6
2012-10-18T04:17:11.316Z,1350533831.316 [NavChartDb](INFO): Creating index for 2194p5
2012-10-18T04:17:12.067Z,1350533832.067 [NavChartDb](INFO): Creating index for 2377p4
2012-10-18T04:17:12.147Z,1350533832.147 [NAL9602](INFO): NAL9602 initialized
2012-10-18T04:17:13.539Z,1350533833.539 [NavChartDb](INFO): Creating index for 2560p3
2012-10-18T04:17:15.958Z,1350533835.958 [NavChartDb](INFO): Creating index for 2743p2
2012-10-18T04:17:17.466Z,1350533837.466 [NavChartDb](INFO): Creating index for 2926p0
2012-10-18T04:17:19.300Z,1350533839.300 [NavChartDb](INFO): Creating index for 3108p9
2012-10-18T04:17:19.668Z,1350533839.668 [NavChartDb](INFO): Creating index for 3291p8
2012-10-18T04:17:19.843Z,1350533839.843 [NavChartDb](INFO): Creating index for 3474p7
2012-10-18T04:17:31.149Z,1350533851.149 [NavChartDb](INFO): Creating index for 3657p6
2012-10-18T04:27:16.343Z,1350534436.342 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T04:27:16.343Z,1350534436.343 [NAL9602] Data Fault, FailCount= 1
2012-10-18T04:27:16.343Z,1350534436.343 [NAL9602](ERROR): Data Fault
2012-10-18T04:27:16.366Z,1350534436.366 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T04:27:16.740Z,1350534436.740 [NAL9602](INFO): Powering down
2012-10-18T04:27:16.764Z,1350534436.764 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T04:27:16.764Z,1350534436.764 [NAL9602] No Fault, FailCount= 1
2012-10-18T04:27:21.941Z,1350534441.941 [NAL9602](INFO): Powering up NAL9602
2012-10-18T04:27:32.359Z,1350534452.359 [NAL9602](INFO): NAL9602 initialized
2012-10-18T04:37:34.876Z,1350535054.876 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T04:37:34.876Z,1350535054.876 [NAL9602] Data Fault, FailCount= 2
2012-10-18T04:37:34.876Z,1350535054.876 [NAL9602](ERROR): Data Fault
2012-10-18T04:37:34.899Z,1350535054.899 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T04:37:34.899Z,1350535054.899 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T04:37:35.296Z,1350535055.296 [NAL9602](INFO): Powering down
2012-10-18T04:39:34.898Z,1350535174.898 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T04:39:34.899Z,1350535174.898 [NAL9602] No Fault, FailCount= 2
2012-10-18T04:39:35.297Z,1350535175.297 [NAL9602](INFO): Powering up NAL9602
2012-10-18T04:39:46.095Z,1350535186.095 [NAL9602](INFO): NAL9602 initialized
2012-10-18T04:49:47.447Z,1350535787.447 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T04:49:47.447Z,1350535787.447 [NAL9602] Data Fault, FailCount= 1
2012-10-18T04:49:47.447Z,1350535787.447 [NAL9602](ERROR): Data Fault
2012-10-18T04:49:47.519Z,1350535787.519 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T04:49:47.848Z,1350535787.848 [NAL9602](INFO): Powering down
2012-10-18T04:49:47.901Z,1350535787.901 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T04:49:47.901Z,1350535787.901 [NAL9602] No Fault, FailCount= 1
2012-10-18T04:49:53.065Z,1350535793.065 [NAL9602](INFO): Powering up NAL9602
2012-10-18T04:50:03.468Z,1350535803.468 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:00:04.271Z,1350536404.271 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:00:04.271Z,1350536404.271 [NAL9602] Data Fault, FailCount= 2
2012-10-18T05:00:04.271Z,1350536404.271 [NAL9602](ERROR): Data Fault
2012-10-18T05:00:04.295Z,1350536404.295 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:00:04.295Z,1350536404.295 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T05:00:04.675Z,1350536404.675 [NAL9602](INFO): Powering down
2012-10-18T05:02:04.293Z,1350536524.293 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T05:02:04.294Z,1350536524.293 [NAL9602] No Fault, FailCount= 2
2012-10-18T05:02:04.685Z,1350536524.685 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:02:15.499Z,1350536535.499 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:12:16.384Z,1350537136.384 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:12:16.384Z,1350537136.384 [NAL9602] Data Fault, FailCount= 1
2012-10-18T05:12:16.384Z,1350537136.384 [NAL9602](ERROR): Data Fault
2012-10-18T05:12:16.409Z,1350537136.409 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:12:16.801Z,1350537136.801 [NAL9602](INFO): Powering down
2012-10-18T05:12:16.825Z,1350537136.825 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T05:12:16.826Z,1350537136.826 [NAL9602] No Fault, FailCount= 1
2012-10-18T05:12:21.985Z,1350537141.985 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:12:32.823Z,1350537152.823 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:12:33.646Z,1350537153.646 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T05:22:35.932Z,1350537755.932 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:22:35.932Z,1350537755.932 [NAL9602] Data Fault, FailCount= 2
2012-10-18T05:22:35.932Z,1350537755.932 [NAL9602](ERROR): Data Fault
2012-10-18T05:22:35.955Z,1350537755.955 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:22:35.956Z,1350537755.955 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T05:22:36.332Z,1350537756.332 [NAL9602](INFO): Powering down
2012-10-18T05:24:35.948Z,1350537875.948 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T05:24:35.949Z,1350537875.949 [NAL9602] No Fault, FailCount= 2
2012-10-18T05:24:36.333Z,1350537876.333 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:24:46.751Z,1350537886.751 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:34:50.664Z,1350538490.664 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:34:50.664Z,1350538490.664 [NAL9602] Data Fault, FailCount= 1
2012-10-18T05:34:50.664Z,1350538490.664 [NAL9602](ERROR): Data Fault
2012-10-18T05:34:50.689Z,1350538490.689 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:34:51.060Z,1350538491.060 [NAL9602](INFO): Powering down
2012-10-18T05:34:51.084Z,1350538491.084 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T05:34:51.084Z,1350538491.084 [NAL9602] No Fault, FailCount= 1
2012-10-18T05:34:56.255Z,1350538496.255 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:35:06.691Z,1350538506.691 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:45:08.504Z,1350539108.504 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:45:08.504Z,1350539108.504 [NAL9602] Data Fault, FailCount= 2
2012-10-18T05:45:08.504Z,1350539108.504 [NAL9602](ERROR): Data Fault
2012-10-18T05:45:08.528Z,1350539108.528 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:45:08.528Z,1350539108.528 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T05:45:08.879Z,1350539108.879 [NAL9602](INFO): Powering down
2012-10-18T05:47:08.582Z,1350539228.582 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T05:47:08.582Z,1350539228.582 [NAL9602] No Fault, FailCount= 2
2012-10-18T05:47:08.961Z,1350539228.961 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:47:19.779Z,1350539239.779 [NAL9602](INFO): NAL9602 initialized
2012-10-18T05:48:57.255Z,1350539337.256 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2012-10-18T05:57:21.561Z,1350539841.561 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T05:57:21.561Z,1350539841.561 [NAL9602] Data Fault, FailCount= 1
2012-10-18T05:57:21.561Z,1350539841.561 [NAL9602](ERROR): Data Fault
2012-10-18T05:57:21.584Z,1350539841.584 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T05:57:21.948Z,1350539841.948 [NAL9602](INFO): Powering down
2012-10-18T05:57:21.972Z,1350539841.972 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T05:57:21.972Z,1350539841.972 [NAL9602] No Fault, FailCount= 1
2012-10-18T05:57:27.143Z,1350539847.143 [NAL9602](INFO): Powering up NAL9602
2012-10-18T05:57:33.959Z,1350539853.959 [Default:Iridium:Read_Iridium](INFO): Timed out from 2012-10-18T03:57:33.0Z
2012-10-18T05:57:33.959Z,1350539853.959 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1
2012-10-18T05:57:33.959Z,1350539853.959 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T05:57:33.959Z,1350539853.959 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1
2012-10-18T05:57:33.959Z,1350539853.959 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300
2012-10-18T05:57:33.965Z,1350539853.965 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped
2012-10-18T05:57:33.965Z,1350539853.965 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1
2012-10-18T05:57:34.051Z,1350539854.051 [CommandLine](IMPORTANT): got command burn 300.000000
2012-10-18T05:57:34.378Z,1350539854.378 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout
2012-10-18T05:57:34.380Z,1350539854.380 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped
2012-10-18T05:57:34.380Z,1350539854.380 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T05:57:34.380Z,1350539854.380 [Default:Iridium:Read_Iridium] Stopped
2012-10-18T05:57:34.381Z,1350539854.381 [Default:Iridium](INFO): Completed Default:Iridium
2012-10-18T05:57:34.381Z,1350539854.381 [Default:Iridium] Stopped
2012-10-18T05:57:34.381Z,1350539854.381 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-18T05:57:34.381Z,1350539854.381 [Default:Iridium:A.SetSpeed] Stopped
2012-10-18T05:57:34.381Z,1350539854.381 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-18T05:57:34.381Z,1350539854.381 [Default:F.Wait] Running Loop=1
2012-10-18T05:57:34.381Z,1350539854.381 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-10-18T05:57:34.757Z,1350539854.757 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-10-18T05:57:34.757Z,1350539854.757 [Default:CallIridium:B] Stopped
2012-10-18T05:57:34.757Z,1350539854.757 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-10-18T05:57:34.757Z,1350539854.757 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-10-18T05:57:34.757Z,1350539854.757 [Default:CallIridium] Stopped
2012-10-18T05:57:34.758Z,1350539854.758 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-10-18T05:57:35.162Z,1350539855.162 [Default:CallIridium] Running Loop=1
2012-10-18T05:57:35.163Z,1350539855.163 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T05:57:35.163Z,1350539855.163 [Default:CallIridium:A] Running Loop=1
2012-10-18T05:57:35.163Z,1350539855.163 [Default:CallIridium:A] Stopped
2012-10-18T05:57:35.163Z,1350539855.163 [Default:CallIridium:B] Running Loop=1
2012-10-18T05:57:35.163Z,1350539855.163 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T05:57:35.554Z,1350539855.554 [Default:Iridium] Running Loop=1
2012-10-18T05:57:35.554Z,1350539855.554 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T05:57:35.554Z,1350539855.554 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T05:57:35.554Z,1350539855.555 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T05:57:35.555Z,1350539855.555 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T05:57:35.555Z,1350539855.555 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T05:57:35.555Z,1350539855.555 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T05:57:35.555Z,1350539855.556 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T05:57:35.556Z,1350539855.556 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T05:57:37.963Z,1350539857.963 [NAL9602](INFO): NAL9602 initialized
2012-10-18T06:07:40.716Z,1350540460.716 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T06:07:40.716Z,1350540460.716 [NAL9602] Data Fault, FailCount= 2
2012-10-18T06:07:40.716Z,1350540460.716 [NAL9602](ERROR): Data Fault
2012-10-18T06:07:40.797Z,1350540460.796 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T06:07:40.797Z,1350540460.797 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T06:07:41.191Z,1350540461.191 [NAL9602](INFO): Powering down
2012-10-18T06:09:40.883Z,1350540580.883 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T06:09:40.883Z,1350540580.883 [NAL9602] No Fault, FailCount= 2
2012-10-18T06:09:41.129Z,1350540581.129 [NAL9602](INFO): Powering up NAL9602
2012-10-18T06:09:51.543Z,1350540591.543 [NAL9602](INFO): NAL9602 initialized
2012-10-18T06:10:01.373Z,1350540601.373 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2012-10-18T06:19:52.443Z,1350541192.443 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T06:19:52.443Z,1350541192.443 [NAL9602] Data Fault, FailCount= 1
2012-10-18T06:19:52.443Z,1350541192.443 [NAL9602](ERROR): Data Fault
2012-10-18T06:19:52.467Z,1350541192.467 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T06:19:52.852Z,1350541192.852 [NAL9602](INFO): Powering down
2012-10-18T06:19:52.876Z,1350541192.876 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T06:19:52.876Z,1350541192.876 [NAL9602] No Fault, FailCount= 1
2012-10-18T06:19:58.049Z,1350541198.049 [NAL9602](INFO): Powering up NAL9602
2012-10-18T06:20:08.743Z,1350541208.743 [NAL9602](INFO): NAL9602 initialized
2012-10-18T06:30:10.676Z,1350541810.676 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T06:30:10.676Z,1350541810.676 [NAL9602] Data Fault, FailCount= 2
2012-10-18T06:30:10.676Z,1350541810.676 [NAL9602](ERROR): Data Fault
2012-10-18T06:30:10.700Z,1350541810.700 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T06:30:10.700Z,1350541810.700 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T06:30:11.089Z,1350541811.089 [NAL9602](INFO): Powering down
2012-10-18T06:32:10.715Z,1350541930.715 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T06:32:10.715Z,1350541930.716 [NAL9602] No Fault, FailCount= 2
2012-10-18T06:32:11.073Z,1350541931.073 [NAL9602](INFO): Powering up NAL9602
2012-10-18T06:32:21.895Z,1350541941.895 [NAL9602](INFO): NAL9602 initialized
2012-10-18T06:33:36.634Z,1350542016.634 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#5 STATUS: 65535
2012-10-18T06:42:22.793Z,1350542542.793 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T06:42:22.793Z,1350542542.793 [NAL9602] Data Fault, FailCount= 1
2012-10-18T06:42:22.793Z,1350542542.793 [NAL9602](ERROR): Data Fault
2012-10-18T06:42:22.817Z,1350542542.817 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T06:42:23.196Z,1350542543.196 [NAL9602](INFO): Powering down
2012-10-18T06:42:23.221Z,1350542543.221 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T06:42:23.221Z,1350542543.221 [NAL9602] No Fault, FailCount= 1
2012-10-18T06:42:28.391Z,1350542548.391 [NAL9602](INFO): Powering up NAL9602
2012-10-18T06:42:30.010Z,1350542550.010 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:42:32.412Z,1350542552.412 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:42:34.808Z,1350542554.808 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:42:37.229Z,1350542557.229 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:42:39.219Z,1350542559.219 [NAL9602](INFO): NAL9602 initialized
2012-10-18T06:42:39.608Z,1350542559.608 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:42:40.058Z,1350542560.058 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T06:42:42.010Z,1350542562.010 [Batt_Ocean_Server](INFO): Not Initialized - Battery Bank #10 STATUS: 0
2012-10-18T06:52:40.049Z,1350543160.049 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T06:52:40.049Z,1350543160.049 [NAL9602] Data Fault, FailCount= 2
2012-10-18T06:52:40.049Z,1350543160.049 [NAL9602](ERROR): Data Fault
2012-10-18T06:52:40.073Z,1350543160.073 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T06:52:40.074Z,1350543160.074 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T06:52:40.416Z,1350543160.416 [NAL9602](INFO): Powering down
2012-10-18T06:54:40.431Z,1350543280.431 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T06:54:40.431Z,1350543280.431 [NAL9602] No Fault, FailCount= 2
2012-10-18T06:54:40.821Z,1350543280.821 [NAL9602](INFO): Powering up NAL9602
2012-10-18T06:54:51.631Z,1350543291.631 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:04:52.788Z,1350543892.788 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T07:04:52.788Z,1350543892.788 [NAL9602] Data Fault, FailCount= 1
2012-10-18T07:04:52.788Z,1350543892.788 [NAL9602](ERROR): Data Fault
2012-10-18T07:04:52.812Z,1350543892.812 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T07:04:53.183Z,1350543893.182 [NAL9602](INFO): Powering down
2012-10-18T07:04:53.207Z,1350543893.207 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T07:04:53.207Z,1350543893.207 [NAL9602] No Fault, FailCount= 1
2012-10-18T07:04:58.417Z,1350543898.417 [NAL9602](INFO): Powering up NAL9602
2012-10-18T07:05:09.211Z,1350543909.211 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:15:10.677Z,1350544510.677 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T07:15:10.677Z,1350544510.677 [NAL9602] Data Fault, FailCount= 2
2012-10-18T07:15:10.677Z,1350544510.677 [NAL9602](ERROR): Data Fault
2012-10-18T07:15:10.700Z,1350544510.700 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T07:15:10.701Z,1350544510.701 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T07:15:11.056Z,1350544511.056 [NAL9602](INFO): Powering down
2012-10-18T07:17:11.079Z,1350544631.079 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T07:17:11.079Z,1350544631.079 [NAL9602] No Fault, FailCount= 2
2012-10-18T07:17:11.451Z,1350544631.451 [NAL9602](INFO): Powering up NAL9602
2012-10-18T07:17:21.879Z,1350544641.879 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:27:24.031Z,1350545244.031 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T07:27:24.031Z,1350545244.031 [NAL9602] Data Fault, FailCount= 1
2012-10-18T07:27:24.031Z,1350545244.031 [NAL9602](ERROR): Data Fault
2012-10-18T07:27:24.054Z,1350545244.054 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T07:27:24.436Z,1350545244.436 [NAL9602](INFO): Powering down
2012-10-18T07:27:24.460Z,1350545244.460 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T07:27:24.460Z,1350545244.460 [NAL9602] No Fault, FailCount= 1
2012-10-18T07:27:29.631Z,1350545249.631 [NAL9602](INFO): Powering up NAL9602
2012-10-18T07:27:40.087Z,1350545260.087 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:37:41.032Z,1350545861.032 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T07:37:41.032Z,1350545861.032 [NAL9602] Data Fault, FailCount= 2
2012-10-18T07:37:41.032Z,1350545861.032 [NAL9602](ERROR): Data Fault
2012-10-18T07:37:41.055Z,1350545861.055 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T07:37:41.056Z,1350545861.056 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T07:37:41.426Z,1350545861.427 [NAL9602](INFO): Powering down
2012-10-18T07:39:41.055Z,1350545981.055 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T07:39:41.055Z,1350545981.055 [NAL9602] No Fault, FailCount= 2
2012-10-18T07:39:41.433Z,1350545981.433 [NAL9602](INFO): Powering up NAL9602
2012-10-18T07:39:51.891Z,1350545991.891 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:49:54.040Z,1350546594.040 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T07:49:54.040Z,1350546594.040 [NAL9602] Data Fault, FailCount= 1
2012-10-18T07:49:54.040Z,1350546594.040 [NAL9602](ERROR): Data Fault
2012-10-18T07:49:54.064Z,1350546594.064 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T07:49:54.452Z,1350546594.453 [NAL9602](INFO): Powering down
2012-10-18T07:49:54.477Z,1350546594.477 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T07:49:54.477Z,1350546594.477 [NAL9602] No Fault, FailCount= 1
2012-10-18T07:49:59.637Z,1350546599.637 [NAL9602](INFO): Powering up NAL9602
2012-10-18T07:50:10.475Z,1350546610.475 [NAL9602](INFO): NAL9602 initialized
2012-10-18T07:57:35.677Z,1350547055.677 [Default:Iridium:Read_Iridium](INFO): Timed out from 2012-10-18T05:57:35.6Z
2012-10-18T07:57:35.677Z,1350547055.677 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1
2012-10-18T07:57:35.677Z,1350547055.677 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T07:57:35.677Z,1350547055.677 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1
2012-10-18T07:57:35.678Z,1350547055.678 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300
2012-10-18T07:57:35.679Z,1350547055.679 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped
2012-10-18T07:57:35.679Z,1350547055.679 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1
2012-10-18T07:57:35.691Z,1350547055.691 [CommandLine](IMPORTANT): got command burn 300.000000
2012-10-18T07:57:36.099Z,1350547056.099 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout
2012-10-18T07:57:36.099Z,1350547056.099 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped
2012-10-18T07:57:36.099Z,1350547056.099 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T07:57:36.099Z,1350547056.099 [Default:Iridium:Read_Iridium] Stopped
2012-10-18T07:57:36.100Z,1350547056.100 [Default:Iridium](INFO): Completed Default:Iridium
2012-10-18T07:57:36.100Z,1350547056.100 [Default:Iridium] Stopped
2012-10-18T07:57:36.100Z,1350547056.100 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-18T07:57:36.100Z,1350547056.100 [Default:Iridium:A.SetSpeed] Stopped
2012-10-18T07:57:36.100Z,1350547056.100 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-18T07:57:36.478Z,1350547056.478 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-10-18T07:57:36.478Z,1350547056.478 [Default:CallIridium:B] Stopped
2012-10-18T07:57:36.478Z,1350547056.478 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-10-18T07:57:36.479Z,1350547056.479 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-10-18T07:57:36.479Z,1350547056.479 [Default:CallIridium] Stopped
2012-10-18T07:57:36.479Z,1350547056.479 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-10-18T07:57:36.879Z,1350547056.879 [Default:CallIridium] Running Loop=1
2012-10-18T07:57:36.879Z,1350547056.879 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T07:57:36.879Z,1350547056.879 [Default:CallIridium:A] Running Loop=1
2012-10-18T07:57:36.880Z,1350547056.880 [Default:CallIridium:A] Stopped
2012-10-18T07:57:36.880Z,1350547056.880 [Default:CallIridium:B] Running Loop=1
2012-10-18T07:57:36.880Z,1350547056.880 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T07:57:37.278Z,1350547057.278 [Default:Iridium] Running Loop=1
2012-10-18T07:57:37.278Z,1350547057.279 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T07:57:37.279Z,1350547057.279 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T07:57:37.279Z,1350547057.279 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T07:57:37.279Z,1350547057.279 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T07:57:37.279Z,1350547057.279 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T07:57:37.280Z,1350547057.280 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T07:57:37.280Z,1350547057.280 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T07:57:37.280Z,1350547057.280 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T08:00:13.207Z,1350547213.207 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:00:13.207Z,1350547213.207 [NAL9602] Data Fault, FailCount= 2
2012-10-18T08:00:13.207Z,1350547213.207 [NAL9602](ERROR): Data Fault
2012-10-18T08:00:13.232Z,1350547213.232 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:00:13.232Z,1350547213.232 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T08:00:13.613Z,1350547213.612 [NAL9602](INFO): Powering down
2012-10-18T08:02:13.252Z,1350547333.252 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T08:02:13.252Z,1350547333.252 [NAL9602] No Fault, FailCount= 2
2012-10-18T08:02:13.617Z,1350547333.617 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:02:24.435Z,1350547344.435 [NAL9602](INFO): NAL9602 initialized
2012-10-18T08:12:25.311Z,1350547945.311 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:12:25.311Z,1350547945.311 [NAL9602] Data Fault, FailCount= 1
2012-10-18T08:12:25.311Z,1350547945.311 [NAL9602](ERROR): Data Fault
2012-10-18T08:12:25.337Z,1350547945.337 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:12:25.716Z,1350547945.716 [NAL9602](INFO): Powering down
2012-10-18T08:12:25.740Z,1350547945.740 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T08:12:25.740Z,1350547945.740 [NAL9602] No Fault, FailCount= 1
2012-10-18T08:12:30.911Z,1350547950.911 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:12:41.735Z,1350547961.735 [NAL9602](INFO): NAL9602 initialized
2012-10-18T08:22:43.508Z,1350548563.508 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:22:43.508Z,1350548563.508 [NAL9602] Data Fault, FailCount= 2
2012-10-18T08:22:43.508Z,1350548563.508 [NAL9602](ERROR): Data Fault
2012-10-18T08:22:43.532Z,1350548563.532 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:22:43.533Z,1350548563.533 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T08:22:43.921Z,1350548563.921 [NAL9602](INFO): Powering down
2012-10-18T08:24:43.532Z,1350548683.532 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T08:24:43.532Z,1350548683.532 [NAL9602] No Fault, FailCount= 2
2012-10-18T08:24:43.966Z,1350548683.966 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:24:54.727Z,1350548694.727 [NAL9602](INFO): NAL9602 initialized
2012-10-18T08:33:33.994Z,1350549213.994 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2012-10-18T08:34:57.539Z,1350549297.539 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:34:57.539Z,1350549297.539 [NAL9602] Data Fault, FailCount= 1
2012-10-18T08:34:57.539Z,1350549297.539 [NAL9602](ERROR): Data Fault
2012-10-18T08:34:57.563Z,1350549297.563 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:34:57.948Z,1350549297.948 [NAL9602](INFO): Powering down
2012-10-18T08:34:57.972Z,1350549297.972 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T08:34:57.972Z,1350549297.972 [NAL9602] No Fault, FailCount= 1
2012-10-18T08:35:03.149Z,1350549303.149 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:35:13.967Z,1350549313.967 [NAL9602](INFO): NAL9602 initialized
2012-10-18T08:45:16.687Z,1350549916.687 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:45:16.687Z,1350549916.687 [NAL9602] Data Fault, FailCount= 2
2012-10-18T08:45:16.687Z,1350549916.687 [NAL9602](ERROR): Data Fault
2012-10-18T08:45:16.711Z,1350549916.711 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:45:16.711Z,1350549916.711 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T08:45:17.096Z,1350549917.096 [NAL9602](INFO): Powering down
2012-10-18T08:47:16.709Z,1350550036.709 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T08:47:16.709Z,1350550036.709 [NAL9602] No Fault, FailCount= 2
2012-10-18T08:47:17.093Z,1350550037.093 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:47:27.515Z,1350550047.515 [NAL9602](INFO): NAL9602 initialized
2012-10-18T08:57:32.091Z,1350550652.091 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T08:57:32.091Z,1350550652.091 [NAL9602] Data Fault, FailCount= 1
2012-10-18T08:57:32.091Z,1350550652.091 [NAL9602](ERROR): Data Fault
2012-10-18T08:57:32.115Z,1350550652.115 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T08:57:32.500Z,1350550652.500 [NAL9602](INFO): Powering down
2012-10-18T08:57:32.525Z,1350550652.524 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T08:57:32.525Z,1350550652.525 [NAL9602] No Fault, FailCount= 1
2012-10-18T08:57:37.697Z,1350550657.697 [NAL9602](INFO): Powering up NAL9602
2012-10-18T08:57:48.515Z,1350550668.515 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:07:51.980Z,1350551271.980 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T09:07:51.980Z,1350551271.980 [NAL9602] Data Fault, FailCount= 2
2012-10-18T09:07:51.980Z,1350551271.980 [NAL9602](ERROR): Data Fault
2012-10-18T09:07:52.007Z,1350551272.007 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T09:07:52.007Z,1350551272.007 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T09:07:52.359Z,1350551272.359 [NAL9602](INFO): Powering down
2012-10-18T09:09:52.035Z,1350551392.035 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T09:09:52.035Z,1350551392.035 [NAL9602] No Fault, FailCount= 2
2012-10-18T09:09:52.413Z,1350551392.413 [NAL9602](INFO): Powering up NAL9602
2012-10-18T09:10:03.235Z,1350551403.235 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:16:44.601Z,1350551804.601 [NAL9602](ERROR): parseGSV uart error: serial timeout
2012-10-18T09:17:15.375Z,1350551835.375 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout
2012-10-18T09:17:47.078Z,1350551867.078 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T09:18:17.344Z,1350551897.344 [NAL9602](ERROR): parseGSV uart error: serial timeout
2012-10-18T09:18:48.143Z,1350551928.143 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout
2012-10-18T09:19:19.450Z,1350551959.450 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T09:19:50.068Z,1350551990.068 [NAL9602](ERROR): parseGSV uart error: serial timeout
2012-10-18T09:20:20.936Z,1350552020.936 [NAL9602](ERROR): Queried for signal strength and failed to receive response. serial timeout
2012-10-18T09:20:21.688Z,1350552021.688 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T09:20:21.688Z,1350552021.688 [NAL9602] Data Fault, FailCount= 1
2012-10-18T09:20:21.688Z,1350552021.688 [NAL9602](ERROR): Data Fault
2012-10-18T09:20:21.815Z,1350552021.815 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T09:20:22.064Z,1350552022.064 [NAL9602](INFO): Powering down
2012-10-18T09:20:22.149Z,1350552022.149 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T09:20:22.149Z,1350552022.149 [NAL9602] No Fault, FailCount= 1
2012-10-18T09:20:27.293Z,1350552027.293 [NAL9602](INFO): Powering up NAL9602
2012-10-18T09:20:38.123Z,1350552038.123 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:30:39.607Z,1350552639.607 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T09:30:39.607Z,1350552639.607 [NAL9602] Data Fault, FailCount= 2
2012-10-18T09:30:39.607Z,1350552639.607 [NAL9602](ERROR): Data Fault
2012-10-18T09:30:39.631Z,1350552639.631 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T09:30:39.631Z,1350552639.631 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T09:30:40.012Z,1350552640.012 [NAL9602](INFO): Powering down
2012-10-18T09:32:39.629Z,1350552759.629 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T09:32:39.629Z,1350552759.629 [NAL9602] No Fault, FailCount= 2
2012-10-18T09:32:40.033Z,1350552760.033 [NAL9602](INFO): Powering up NAL9602
2012-10-18T09:32:50.839Z,1350552770.839 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:42:52.024Z,1350553372.024 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T09:42:52.024Z,1350553372.024 [NAL9602] Data Fault, FailCount= 1
2012-10-18T09:42:52.024Z,1350553372.024 [NAL9602](ERROR): Data Fault
2012-10-18T09:42:52.048Z,1350553372.048 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T09:42:52.440Z,1350553372.441 [NAL9602](INFO): Powering down
2012-10-18T09:42:52.464Z,1350553372.464 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T09:42:52.464Z,1350553372.464 [NAL9602] No Fault, FailCount= 1
2012-10-18T09:42:57.623Z,1350553377.623 [NAL9602](INFO): Powering up NAL9602
2012-10-18T09:43:08.447Z,1350553388.447 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:43:09.286Z,1350553389.286 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T09:53:12.243Z,1350553992.243 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T09:53:12.243Z,1350553992.243 [NAL9602] Data Fault, FailCount= 2
2012-10-18T09:53:12.243Z,1350553992.243 [NAL9602](ERROR): Data Fault
2012-10-18T09:53:12.267Z,1350553992.267 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T09:53:12.267Z,1350553992.267 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T09:53:12.673Z,1350553992.672 [NAL9602](INFO): Powering down
2012-10-18T09:55:01.908Z,1350554101.908 [CBIT](IMPORTANT): Beginning GF scan
2012-10-18T09:55:02.647Z,1350554102.647 [Radio_Freewave](INFO): Powering down
2012-10-18T09:55:03.053Z,1350554103.053 [Radio_Freewave](INFO): Powering up
2012-10-18T09:55:12.308Z,1350554112.308 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T09:55:12.308Z,1350554112.308 [NAL9602] No Fault, FailCount= 2
2012-10-18T09:55:12.646Z,1350554112.645 [NAL9602](INFO): Powering up NAL9602
2012-10-18T09:55:23.471Z,1350554123.471 [NAL9602](INFO): NAL9602 initialized
2012-10-18T09:55:28.201Z,1350554128.201 [CBIT](INFO): No ground fault detected
2012-10-18T09:57:37.621Z,1350554257.621 [Default:Iridium:Read_Iridium](INFO): Timed out from 2012-10-18T07:57:37.3Z
2012-10-18T09:57:37.621Z,1350554257.621 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1
2012-10-18T09:57:37.621Z,1350554257.621 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T09:57:37.621Z,1350554257.621 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1
2012-10-18T09:57:37.622Z,1350554257.622 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300
2012-10-18T09:57:37.623Z,1350554257.623 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped
2012-10-18T09:57:37.623Z,1350554257.623 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1
2012-10-18T09:57:37.719Z,1350554257.719 [CommandLine](IMPORTANT): got command burn 300.000000
2012-10-18T09:57:37.849Z,1350554257.849 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout
2012-10-18T09:57:37.849Z,1350554257.849 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped
2012-10-18T09:57:37.849Z,1350554257.849 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T09:57:37.849Z,1350554257.849 [Default:Iridium:Read_Iridium] Stopped
2012-10-18T09:57:37.850Z,1350554257.850 [Default:Iridium](INFO): Completed Default:Iridium
2012-10-18T09:57:37.850Z,1350554257.850 [Default:Iridium] Stopped
2012-10-18T09:57:37.850Z,1350554257.850 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-18T09:57:37.850Z,1350554257.850 [Default:Iridium:A.SetSpeed] Stopped
2012-10-18T09:57:37.850Z,1350554257.850 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-18T09:57:38.244Z,1350554258.244 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-10-18T09:57:38.245Z,1350554258.245 [Default:CallIridium:B] Stopped
2012-10-18T09:57:38.245Z,1350554258.245 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-10-18T09:57:38.245Z,1350554258.245 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-10-18T09:57:38.245Z,1350554258.245 [Default:CallIridium] Stopped
2012-10-18T09:57:38.245Z,1350554258.245 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-10-18T09:57:38.655Z,1350554258.655 [Default:CallIridium] Running Loop=1
2012-10-18T09:57:38.655Z,1350554258.655 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T09:57:38.655Z,1350554258.655 [Default:CallIridium:A] Running Loop=1
2012-10-18T09:57:38.656Z,1350554258.656 [Default:CallIridium:A] Stopped
2012-10-18T09:57:38.656Z,1350554258.656 [Default:CallIridium:B] Running Loop=1
2012-10-18T09:57:38.656Z,1350554258.656 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T09:57:39.052Z,1350554259.052 [Default:Iridium] Running Loop=1
2012-10-18T09:57:39.052Z,1350554259.052 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T09:57:39.053Z,1350554259.053 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T09:57:39.053Z,1350554259.053 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T09:57:39.053Z,1350554259.053 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T09:57:39.053Z,1350554259.053 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T09:57:39.054Z,1350554259.054 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T09:57:39.054Z,1350554259.054 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T09:57:39.054Z,1350554259.054 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T10:05:24.284Z,1350554724.284 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T10:05:24.285Z,1350554724.284 [NAL9602] Data Fault, FailCount= 1
2012-10-18T10:05:24.285Z,1350554724.285 [NAL9602](ERROR): Data Fault
2012-10-18T10:05:24.308Z,1350554724.308 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T10:05:24.643Z,1350554724.643 [NAL9602](INFO): Powering down
2012-10-18T10:05:24.670Z,1350554724.670 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T10:05:24.670Z,1350554724.670 [NAL9602] No Fault, FailCount= 1
2012-10-18T10:05:29.849Z,1350554729.849 [NAL9602](INFO): Powering up NAL9602
2012-10-18T10:05:40.671Z,1350554740.671 [NAL9602](INFO): NAL9602 initialized
2012-10-18T10:15:42.436Z,1350555342.436 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T10:15:42.436Z,1350555342.436 [NAL9602] Data Fault, FailCount= 2
2012-10-18T10:15:42.436Z,1350555342.436 [NAL9602](ERROR): Data Fault
2012-10-18T10:15:42.460Z,1350555342.460 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T10:15:42.460Z,1350555342.460 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T10:15:42.836Z,1350555342.836 [NAL9602](INFO): Powering down
2012-10-18T10:17:42.459Z,1350555462.459 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T10:17:42.459Z,1350555462.459 [NAL9602] No Fault, FailCount= 2
2012-10-18T10:17:42.837Z,1350555462.837 [NAL9602](INFO): Powering up NAL9602
2012-10-18T10:17:53.699Z,1350555473.699 [NAL9602](INFO): NAL9602 initialized
2012-10-18T10:27:57.462Z,1350556077.462 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T10:27:57.463Z,1350556077.463 [NAL9602] Data Fault, FailCount= 1
2012-10-18T10:27:57.463Z,1350556077.463 [NAL9602](ERROR): Data Fault
2012-10-18T10:27:57.486Z,1350556077.486 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T10:27:57.868Z,1350556077.868 [NAL9602](INFO): Powering down
2012-10-18T10:27:57.892Z,1350556077.892 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T10:27:57.892Z,1350556077.892 [NAL9602] No Fault, FailCount= 1
2012-10-18T10:28:03.069Z,1350556083.069 [NAL9602](INFO): Powering up NAL9602
2012-10-18T10:28:13.887Z,1350556093.887 [NAL9602](INFO): NAL9602 initialized
2012-10-18T10:38:18.148Z,1350556698.148 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T10:38:18.148Z,1350556698.148 [NAL9602] Data Fault, FailCount= 2
2012-10-18T10:38:18.148Z,1350556698.148 [NAL9602](ERROR): Data Fault
2012-10-18T10:38:18.172Z,1350556698.172 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T10:38:18.172Z,1350556698.172 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T10:38:18.532Z,1350556698.532 [NAL9602](INFO): Powering down
2012-10-18T10:40:18.227Z,1350556818.227 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T10:40:18.227Z,1350556818.227 [NAL9602] No Fault, FailCount= 2
2012-10-18T10:40:18.609Z,1350556818.609 [NAL9602](INFO): Powering up NAL9602
2012-10-18T10:40:29.427Z,1350556829.427 [NAL9602](INFO): NAL9602 initialized
2012-10-18T10:50:31.956Z,1350557431.956 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T10:50:31.956Z,1350557431.956 [NAL9602] Data Fault, FailCount= 1
2012-10-18T10:50:31.956Z,1350557431.956 [NAL9602](ERROR): Data Fault
2012-10-18T10:50:31.979Z,1350557431.979 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T10:50:32.354Z,1350557432.354 [NAL9602](INFO): Powering down
2012-10-18T10:50:32.379Z,1350557432.379 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T10:50:32.379Z,1350557432.379 [NAL9602] No Fault, FailCount= 1
2012-10-18T10:50:37.557Z,1350557437.557 [NAL9602](INFO): Powering up NAL9602
2012-10-18T10:50:48.379Z,1350557448.379 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:00:50.544Z,1350558050.544 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:00:50.544Z,1350558050.545 [NAL9602] Data Fault, FailCount= 2
2012-10-18T11:00:50.544Z,1350558050.545 [NAL9602](ERROR): Data Fault
2012-10-18T11:00:50.568Z,1350558050.568 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:00:50.568Z,1350558050.568 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T11:00:50.927Z,1350558050.927 [NAL9602](INFO): Powering down
2012-10-18T11:02:50.551Z,1350558170.551 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T11:02:50.551Z,1350558170.551 [NAL9602] No Fault, FailCount= 2
2012-10-18T11:02:50.973Z,1350558170.973 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:03:01.751Z,1350558181.751 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:07:56.864Z,1350558476.864 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#3 STATUS: 65535
2012-10-18T11:13:05.135Z,1350558785.135 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:13:05.135Z,1350558785.135 [NAL9602] Data Fault, FailCount= 1
2012-10-18T11:13:05.135Z,1350558785.135 [NAL9602](ERROR): Data Fault
2012-10-18T11:13:05.158Z,1350558785.158 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:13:05.536Z,1350558785.536 [NAL9602](INFO): Powering down
2012-10-18T11:13:05.560Z,1350558785.560 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T11:13:05.560Z,1350558785.560 [NAL9602] No Fault, FailCount= 1
2012-10-18T11:13:10.733Z,1350558790.733 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:13:21.559Z,1350558801.559 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:23:23.003Z,1350559403.003 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:23:23.003Z,1350559403.003 [NAL9602] Data Fault, FailCount= 2
2012-10-18T11:23:23.003Z,1350559403.003 [NAL9602](ERROR): Data Fault
2012-10-18T11:23:23.027Z,1350559403.027 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:23:23.027Z,1350559403.027 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T11:23:23.408Z,1350559403.408 [NAL9602](INFO): Powering down
2012-10-18T11:25:23.059Z,1350559523.059 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T11:25:23.059Z,1350559523.059 [NAL9602] No Fault, FailCount= 2
2012-10-18T11:25:23.441Z,1350559523.441 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:25:34.259Z,1350559534.259 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:33:21.634Z,1350560001.634 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#4 STATUS: 65535
2012-10-18T11:35:35.120Z,1350560135.120 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:35:35.120Z,1350560135.120 [NAL9602] Data Fault, FailCount= 1
2012-10-18T11:35:35.120Z,1350560135.120 [NAL9602](ERROR): Data Fault
2012-10-18T11:35:35.144Z,1350560135.144 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:35:35.524Z,1350560135.524 [NAL9602](INFO): Powering down
2012-10-18T11:35:35.548Z,1350560135.548 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T11:35:35.548Z,1350560135.548 [NAL9602] No Fault, FailCount= 1
2012-10-18T11:35:40.729Z,1350560140.729 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:35:51.143Z,1350560151.143 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:35:51.986Z,1350560151.986 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T11:45:56.048Z,1350560756.048 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:45:56.048Z,1350560756.048 [NAL9602] Data Fault, FailCount= 2
2012-10-18T11:45:56.048Z,1350560756.048 [NAL9602](ERROR): Data Fault
2012-10-18T11:45:56.072Z,1350560756.072 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:45:56.072Z,1350560756.072 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T11:45:56.488Z,1350560756.489 [NAL9602](INFO): Powering down
2012-10-18T11:47:56.065Z,1350560876.065 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T11:47:56.065Z,1350560876.065 [NAL9602] No Fault, FailCount= 2
2012-10-18T11:47:56.443Z,1350560876.443 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:48:06.915Z,1350560886.915 [NAL9602](INFO): NAL9602 initialized
2012-10-18T11:57:39.113Z,1350561459.113 [Default:Iridium:Read_Iridium](INFO): Timed out from 2012-10-18T09:57:39.1Z
2012-10-18T11:57:39.113Z,1350561459.113 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1
2012-10-18T11:57:39.113Z,1350561459.113 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T11:57:39.113Z,1350561459.113 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1
2012-10-18T11:57:39.113Z,1350561459.113 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300
2012-10-18T11:57:39.115Z,1350561459.115 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped
2012-10-18T11:57:39.115Z,1350561459.115 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1
2012-10-18T11:57:39.183Z,1350561459.183 [CommandLine](IMPORTANT): got command burn 300.000000
2012-10-18T11:57:39.493Z,1350561459.493 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout
2012-10-18T11:57:39.493Z,1350561459.493 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped
2012-10-18T11:57:39.493Z,1350561459.493 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T11:57:39.493Z,1350561459.493 [Default:Iridium:Read_Iridium] Stopped
2012-10-18T11:57:39.493Z,1350561459.493 [Default:Iridium](INFO): Completed Default:Iridium
2012-10-18T11:57:39.494Z,1350561459.494 [Default:Iridium] Stopped
2012-10-18T11:57:39.494Z,1350561459.494 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-18T11:57:39.494Z,1350561459.494 [Default:Iridium:A.SetSpeed] Stopped
2012-10-18T11:57:39.494Z,1350561459.494 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium:B] Stopped
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium] Stopped
2012-10-18T11:57:39.890Z,1350561459.890 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-10-18T11:57:40.287Z,1350561460.287 [Default:CallIridium] Running Loop=1
2012-10-18T11:57:40.288Z,1350561460.288 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T11:57:40.288Z,1350561460.288 [Default:CallIridium:A] Running Loop=1
2012-10-18T11:57:40.288Z,1350561460.288 [Default:CallIridium:A] Stopped
2012-10-18T11:57:40.288Z,1350561460.288 [Default:CallIridium:B] Running Loop=1
2012-10-18T11:57:40.288Z,1350561460.288 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T11:57:40.694Z,1350561460.694 [Default:Iridium] Running Loop=1
2012-10-18T11:57:40.694Z,1350561460.694 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T11:57:40.694Z,1350561460.694 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T11:57:40.694Z,1350561460.694 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T11:57:40.695Z,1350561460.694 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T11:57:40.695Z,1350561460.695 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T11:57:40.695Z,1350561460.695 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T11:57:40.695Z,1350561460.695 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T11:57:40.696Z,1350561460.696 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T11:58:11.756Z,1350561491.756 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T11:58:11.756Z,1350561491.756 [NAL9602] Data Fault, FailCount= 1
2012-10-18T11:58:11.756Z,1350561491.756 [NAL9602](ERROR): Data Fault
2012-10-18T11:58:11.779Z,1350561491.779 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T11:58:12.150Z,1350561492.151 [NAL9602](INFO): Powering down
2012-10-18T11:58:12.175Z,1350561492.175 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T11:58:12.175Z,1350561492.175 [NAL9602] No Fault, FailCount= 1
2012-10-18T11:58:17.357Z,1350561497.357 [NAL9602](INFO): Powering up NAL9602
2012-10-18T11:58:27.779Z,1350561507.779 [NAL9602](INFO): NAL9602 initialized
2012-10-18T12:08:29.700Z,1350562109.700 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T12:08:29.700Z,1350562109.700 [NAL9602] Data Fault, FailCount= 2
2012-10-18T12:08:29.700Z,1350562109.700 [NAL9602](ERROR): Data Fault
2012-10-18T12:08:29.723Z,1350562109.723 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T12:08:29.723Z,1350562109.723 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T12:08:30.100Z,1350562110.100 [NAL9602](INFO): Powering down
2012-10-18T12:10:29.723Z,1350562229.723 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T12:10:29.723Z,1350562229.723 [NAL9602] No Fault, FailCount= 2
2012-10-18T12:10:30.121Z,1350562230.121 [NAL9602](INFO): Powering up NAL9602
2012-10-18T12:10:40.923Z,1350562240.923 [NAL9602](INFO): NAL9602 initialized
2012-10-18T12:19:32.771Z,1350562772.771 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2012-10-18T12:20:45.488Z,1350562845.488 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T12:20:45.488Z,1350562845.488 [NAL9602] Data Fault, FailCount= 1
2012-10-18T12:20:45.488Z,1350562845.488 [NAL9602](ERROR): Data Fault
2012-10-18T12:20:45.511Z,1350562845.511 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T12:20:45.883Z,1350562845.883 [NAL9602](INFO): Powering down
2012-10-18T12:20:45.907Z,1350562845.907 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T12:20:45.907Z,1350562845.907 [NAL9602] No Fault, FailCount= 1
2012-10-18T12:20:51.089Z,1350562851.089 [NAL9602](INFO): Powering up NAL9602
2012-10-18T12:21:01.911Z,1350562861.911 [NAL9602](INFO): NAL9602 initialized
2012-10-18T12:31:05.800Z,1350563465.800 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T12:31:05.800Z,1350563465.800 [NAL9602] Data Fault, FailCount= 2
2012-10-18T12:31:05.800Z,1350563465.800 [NAL9602](ERROR): Data Fault
2012-10-18T12:31:05.854Z,1350563465.854 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T12:31:05.854Z,1350563465.854 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T12:31:06.172Z,1350563466.172 [NAL9602](INFO): Powering down
2012-10-18T12:31:38.540Z,1350563498.540 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2012-10-18T12:33:06.260Z,1350563586.260 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T12:33:06.260Z,1350563586.260 [NAL9602] No Fault, FailCount= 2
2012-10-18T12:33:06.541Z,1350563586.541 [NAL9602](INFO): Powering up NAL9602
2012-10-18T12:33:17.367Z,1350563597.367 [NAL9602](INFO): NAL9602 initialized
2012-10-18T12:43:20.536Z,1350564200.536 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T12:43:20.536Z,1350564200.536 [NAL9602] Data Fault, FailCount= 1
2012-10-18T12:43:20.536Z,1350564200.536 [NAL9602](ERROR): Data Fault
2012-10-18T12:43:20.560Z,1350564200.560 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T12:43:20.936Z,1350564200.936 [NAL9602](INFO): Powering down
2012-10-18T12:43:20.961Z,1350564200.961 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T12:43:20.961Z,1350564200.961 [NAL9602] No Fault, FailCount= 1
2012-10-18T12:43:26.141Z,1350564206.141 [NAL9602](INFO): Powering up NAL9602
2012-10-18T12:43:36.959Z,1350564216.959 [NAL9602](INFO): NAL9602 initialized
2012-10-18T12:53:41.617Z,1350564821.617 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T12:53:41.617Z,1350564821.617 [NAL9602] Data Fault, FailCount= 2
2012-10-18T12:53:41.617Z,1350564821.617 [NAL9602](ERROR): Data Fault
2012-10-18T12:53:41.641Z,1350564821.641 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T12:53:41.641Z,1350564821.641 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T12:53:42.053Z,1350564822.053 [NAL9602](INFO): Powering down
2012-10-18T12:55:41.634Z,1350564941.634 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T12:55:41.634Z,1350564941.634 [NAL9602] No Fault, FailCount= 2
2012-10-18T12:55:42.017Z,1350564942.017 [NAL9602](INFO): Powering up NAL9602
2012-10-18T12:55:52.839Z,1350564952.839 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:05:54.631Z,1350565554.631 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T13:05:54.631Z,1350565554.631 [NAL9602] Data Fault, FailCount= 1
2012-10-18T13:05:54.631Z,1350565554.631 [NAL9602](ERROR): Data Fault
2012-10-18T13:05:54.657Z,1350565554.657 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T13:05:55.036Z,1350565555.036 [NAL9602](INFO): Powering down
2012-10-18T13:05:55.060Z,1350565555.060 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T13:05:55.060Z,1350565555.060 [NAL9602] No Fault, FailCount= 1
2012-10-18T13:06:00.281Z,1350565560.281 [NAL9602](INFO): Powering up NAL9602
2012-10-18T13:06:11.059Z,1350565571.059 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:16:13.523Z,1350566173.523 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T13:16:13.523Z,1350566173.523 [NAL9602] Data Fault, FailCount= 2
2012-10-18T13:16:13.523Z,1350566173.523 [NAL9602](ERROR): Data Fault
2012-10-18T13:16:13.546Z,1350566173.546 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T13:16:13.547Z,1350566173.547 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T13:16:13.928Z,1350566173.928 [NAL9602](INFO): Powering down
2012-10-18T13:18:13.545Z,1350566293.545 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T13:18:13.545Z,1350566293.545 [NAL9602] No Fault, FailCount= 2
2012-10-18T13:18:13.929Z,1350566293.929 [NAL9602](INFO): Powering up NAL9602
2012-10-18T13:18:24.751Z,1350566304.751 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:28:25.584Z,1350566905.584 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T13:28:25.584Z,1350566905.584 [NAL9602] Data Fault, FailCount= 1
2012-10-18T13:28:25.584Z,1350566905.584 [NAL9602](ERROR): Data Fault
2012-10-18T13:28:25.609Z,1350566905.609 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T13:28:25.988Z,1350566905.988 [NAL9602](INFO): Powering down
2012-10-18T13:28:26.012Z,1350566906.012 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T13:28:26.012Z,1350566906.012 [NAL9602] No Fault, FailCount= 1
2012-10-18T13:28:31.179Z,1350566911.179 [NAL9602](INFO): Powering up NAL9602
2012-10-18T13:28:41.607Z,1350566921.607 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:28:42.478Z,1350566922.478 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T13:29:04.948Z,1350566944.948 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2012-10-18T13:38:45.493Z,1350567525.493 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T13:38:45.493Z,1350567525.493 [NAL9602] Data Fault, FailCount= 2
2012-10-18T13:38:45.493Z,1350567525.493 [NAL9602](ERROR): Data Fault
2012-10-18T13:38:45.516Z,1350567525.516 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T13:38:45.516Z,1350567525.516 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T13:38:45.876Z,1350567525.876 [NAL9602](INFO): Powering down
2012-10-18T13:40:45.493Z,1350567645.493 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T13:40:45.493Z,1350567645.493 [NAL9602] No Fault, FailCount= 2
2012-10-18T13:40:45.881Z,1350567645.881 [NAL9602](INFO): Powering up NAL9602
2012-10-18T13:40:56.699Z,1350567656.699 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:51:00.475Z,1350568260.475 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T13:51:00.475Z,1350568260.475 [NAL9602] Data Fault, FailCount= 1
2012-10-18T13:51:00.475Z,1350568260.475 [NAL9602](ERROR): Data Fault
2012-10-18T13:51:00.499Z,1350568260.499 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T13:51:00.873Z,1350568260.872 [NAL9602](INFO): Powering down
2012-10-18T13:51:00.896Z,1350568260.897 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T13:51:00.897Z,1350568260.897 [NAL9602] No Fault, FailCount= 1
2012-10-18T13:51:06.068Z,1350568266.068 [NAL9602](INFO): Powering up NAL9602
2012-10-18T13:51:16.891Z,1350568276.891 [NAL9602](INFO): NAL9602 initialized
2012-10-18T13:57:40.733Z,1350568660.733 [Default:Iridium:Read_Iridium](INFO): Timed out from 2012-10-18T11:57:40.7Z
2012-10-18T13:57:40.733Z,1350568660.733 [Default:Iridium:Read_Iridium:A_Timeout] Running Loop=1
2012-10-18T13:57:40.733Z,1350568660.733 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Aggregate::initialize Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T13:57:40.733Z,1350568660.733 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Running Loop=1
2012-10-18T13:57:40.734Z,1350568660.734 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](INFO): Executing command Burn 300
2012-10-18T13:57:40.735Z,1350568660.735 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute] Stopped
2012-10-18T13:57:40.735Z,1350568660.735 [Default:Iridium:Read_Iridium:A_Timeout:B] Running Loop=1
2012-10-18T13:57:40.783Z,1350568660.783 [CommandLine](IMPORTANT): got command burn 300.000000
2012-10-18T13:57:40.961Z,1350568660.961 [Default:Iridium:Read_Iridium:A_Timeout:B](CRITICAL): Dropped drop weight due to communications timeout
2012-10-18T13:57:40.961Z,1350568660.961 [Default:Iridium:Read_Iridium:A_Timeout:B] Stopped
2012-10-18T13:57:40.961Z,1350568660.961 [Default:Iridium:Read_Iridium:A_Timeout](INFO): Completed Default:Iridium:Read_Iridium:A_Timeout
2012-10-18T13:57:40.961Z,1350568660.961 [Default:Iridium:Read_Iridium] Stopped
2012-10-18T13:57:40.962Z,1350568660.962 [Default:Iridium](INFO): Completed Default:Iridium
2012-10-18T13:57:40.962Z,1350568660.962 [Default:Iridium] Stopped
2012-10-18T13:57:40.962Z,1350568660.962 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-10-18T13:57:40.962Z,1350568660.962 [Default:Iridium:A.SetSpeed] Stopped
2012-10-18T13:57:40.962Z,1350568660.962 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-10-18T13:57:41.354Z,1350568661.354 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-10-18T13:57:41.354Z,1350568661.354 [Default:CallIridium:B] Stopped
2012-10-18T13:57:41.354Z,1350568661.354 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-10-18T13:57:41.354Z,1350568661.354 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-10-18T13:57:41.354Z,1350568661.355 [Default:CallIridium] Stopped
2012-10-18T13:57:41.355Z,1350568661.355 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-10-18T13:57:41.792Z,1350568661.792 [Default:CallIridium] Running Loop=1
2012-10-18T13:57:41.793Z,1350568661.793 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-10-18T13:57:41.793Z,1350568661.793 [Default:CallIridium:A] Running Loop=1
2012-10-18T13:57:41.793Z,1350568661.793 [Default:CallIridium:A] Stopped
2012-10-18T13:57:41.793Z,1350568661.793 [Default:CallIridium:B] Running Loop=1
2012-10-18T13:57:41.793Z,1350568661.793 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-10-18T13:57:42.160Z,1350568662.160 [Default:Iridium] Running Loop=1
2012-10-18T13:57:42.161Z,1350568662.161 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-10-18T13:57:42.161Z,1350568662.161 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-10-18T13:57:42.161Z,1350568662.161 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-10-18T13:57:42.161Z,1350568662.161 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-10-18T13:57:42.161Z,1350568662.161 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-10-18T13:57:42.162Z,1350568662.162 [Default:Iridium:B.GoToSurface] Stopped
2012-10-18T13:57:42.162Z,1350568662.162 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-10-18T13:57:42.162Z,1350568662.162 [Default:Iridium:Read_Iridium] Running Loop=1
2012-10-18T13:58:02.589Z,1350568682.589 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#5 STATUS: 65535
2012-10-18T14:01:17.711Z,1350568877.711 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T14:01:17.711Z,1350568877.711 [NAL9602] Data Fault, FailCount= 2
2012-10-18T14:01:17.711Z,1350568877.711 [NAL9602](ERROR): Data Fault
2012-10-18T14:01:17.735Z,1350568877.735 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T14:01:17.735Z,1350568877.735 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T14:01:18.116Z,1350568878.116 [NAL9602](INFO): Powering down
2012-10-18T14:03:17.739Z,1350568997.739 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T14:03:17.739Z,1350568997.739 [NAL9602] No Fault, FailCount= 2
2012-10-18T14:03:18.145Z,1350568998.145 [NAL9602](INFO): Powering up NAL9602
2012-10-18T14:03:28.939Z,1350569008.939 [NAL9602](INFO): NAL9602 initialized
2012-10-18T14:13:32.405Z,1350569612.405 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T14:13:32.405Z,1350569612.405 [NAL9602] Data Fault, FailCount= 1
2012-10-18T14:13:32.405Z,1350569612.405 [NAL9602](ERROR): Data Fault
2012-10-18T14:13:32.428Z,1350569612.428 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T14:13:32.803Z,1350569612.803 [NAL9602](INFO): Powering down
2012-10-18T14:13:32.828Z,1350569612.828 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T14:13:32.828Z,1350569612.828 [NAL9602] No Fault, FailCount= 1
2012-10-18T14:13:38.009Z,1350569618.009 [NAL9602](INFO): Powering up NAL9602
2012-10-18T14:13:48.831Z,1350569628.831 [NAL9602](INFO): NAL9602 initialized
2012-10-18T14:23:49.676Z,1350570229.676 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T14:23:49.676Z,1350570229.676 [NAL9602] Data Fault, FailCount= 2
2012-10-18T14:23:49.676Z,1350570229.676 [NAL9602](ERROR): Data Fault
2012-10-18T14:23:49.700Z,1350570229.700 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T14:23:49.700Z,1350570229.700 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T14:23:50.076Z,1350570230.076 [NAL9602](INFO): Powering down
2012-10-18T14:25:49.736Z,1350570349.736 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T14:25:49.736Z,1350570349.736 [NAL9602] No Fault, FailCount= 2
2012-10-18T14:25:50.077Z,1350570350.077 [NAL9602](INFO): Powering up NAL9602
2012-10-18T14:26:00.515Z,1350570360.515 [NAL9602](INFO): NAL9602 initialized
2012-10-18T14:26:01.338Z,1350570361.338 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T14:36:01.448Z,1350570961.448 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T14:36:01.448Z,1350570961.448 [NAL9602] Data Fault, FailCount= 1
2012-10-18T14:36:01.448Z,1350570961.448 [NAL9602](ERROR): Data Fault
2012-10-18T14:36:01.473Z,1350570961.473 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T14:36:01.905Z,1350570961.905 [NAL9602](INFO): Powering down
2012-10-18T14:36:01.928Z,1350570961.928 [CBIT](INFO): Clearing failed state for component NAL9602
2012-10-18T14:36:01.928Z,1350570961.928 [NAL9602] No Fault, FailCount= 1
2012-10-18T14:36:07.045Z,1350570967.045 [NAL9602](INFO): Powering up NAL9602
2012-10-18T14:36:17.467Z,1350570977.467 [NAL9602](INFO): NAL9602 initialized
2012-10-18T14:36:18.334Z,1350570978.334 [NAL9602](ERROR): getFix uart error: serial timeout
2012-10-18T14:36:37.183Z,1350570997.183 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#7 STATUS: 65535
2012-10-18T14:43:27.426Z,1350571407.427 [CommandLine](IMPORTANT): got command load
2012-10-18T14:43:27.427Z,1350571407.427 [CommandLine](FAULT): Incomplete syntax. Try: help load
2012-10-18T14:46:22.332Z,1350571582.332 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-10-18T14:46:22.333Z,1350571582.332 [NAL9602] Data Fault, FailCount= 2
2012-10-18T14:46:22.333Z,1350571582.332 [NAL9602](ERROR): Data Fault
2012-10-18T14:46:22.356Z,1350571582.356 [CBIT](ERROR): Data Fault in component: NAL9602
2012-10-18T14:46:22.356Z,1350571582.356 [CBIT](CRITICAL): Data Fault in component: NAL9602
2012-10-18T14:46:22.706Z,1350571582.706 [NAL9602](INFO): Powering down
2012-10-18T14:46:45.807Z,1350571605.807 [CommandLine](IMPORTANT): got command ibit
2012-10-18T14:46:45.931Z,1350571605.931 [IBIT](IMPORTANT): Beginning Initiated BIT
2012-10-18T14:46:45.931Z,1350571605.931 [IBIT](IMPORTANT): Beginning control surface checks.

2012-10-18T14:46:45.933Z,1350571605.932 [CBIT](IMPORTANT): Beginning GF scan
2012-10-18T14:46:46.707Z,1350571606.707 [Radio_Freewave](INFO): Powering down
2012-10-18T14:46:47.113Z,1350571607.113 [Radio_Freewave](INFO): Powering up
2012-10-18T14:47:00.949Z,1350571620.949 [IBIT](FAULT): Rudder: EXPECTED:15.000000 ACTUAL:14.795477
2012-10-18T14:47:00.949Z,1350571620.949 [IBIT](FAULT): Control surface position failure.
2012-10-18T14:47:12.547Z,1350571632.547 [CBIT](IMPORTANT): No ground fault detected
2012-10-18T14:47:29.771Z,1350571649.771 [CommandLine](IMPORTANT): got command failComponent
2012-10-18T14:47:29.771Z,1350571649.771 [CommandLine](IMPORTANT): Failed components:
2012-10-18T14:47:29.771Z,1350571649.771 [CommandLine](IMPORTANT): NAL9602: Data Fault
2012-10-18T14:48:22.495Z,1350571702.495 [CBIT](INFO): Clearing failed count for component NAL9602
2012-10-18T14:48:22.495Z,1350571702.495 [NAL9602] No Fault, FailCount= 2
2012-10-18T14:48:22.876Z,1350571702.875 [NAL9602](INFO): Powering up NAL9602
2012-10-18T14:48:33.303Z,1350571713.303 [NAL9602](INFO): NAL9602 initialized
2012-10-18T14:48:37.042Z,1350571717.042 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2012-10-18T14:48:37.255Z,1350571717.255 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2012-10-18T14:48:37.255Z,1350571717.255 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2012-10-18T14:48:37.256Z,1350571717.256 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 240.769989
Voltage: 16.324127
2012-10-18T14:48:37.677Z,1350571717.677 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2012-10-18T14:48:37.677Z,1350571717.677 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2012-10-18T14:48:37.677Z,1350571717.677 [IBIT](IMPORTANT): Pressure:17.637238 PSI
2012-10-18T14:48:37.678Z,1350571717.678 [IBIT](IMPORTANT): Humidity:27.026796 %
2012-10-18T14:48:38.058Z,1350571718.058 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2012-10-18T14:48:38.058Z,1350571718.058 [IBIT](IMPORTANT): buoyancyDefault: 945.000000 cc
2012-10-18T14:48:38.059Z,1350571718.059 [IBIT](IMPORTANT): stopDepth: 125.000000 m
2012-10-18T14:48:38.059Z,1350571718.059 [IBIT](IMPORTANT): abortDepth: 150.000000 m
2012-10-18T14:48:38.059Z,1350571718.059 [IBIT](IMPORTANT): IBIT FAILED
2012-10-18T14:48:45.151Z,1350571725.151 [CommandLine](IMPORTANT): got command burn 5.000000
2012-10-18T14:49:29.903Z,1350571769.903 [CommandLine](IMPORTANT): got command show variable battery
2012-10-18T14:49:29.970Z,1350571769.970 [CommandLine](INFO): platform_battery_charge (ampere_hour)
2012-10-18T14:49:29.971Z,1350571769.971 [CommandLine](INFO): platform_battery_charge_usage (ampere_hour)
2012-10-18T14:49:29.971Z,1350571769.971 [CommandLine](INFO): platform_battery_energy_usage (unknown)
2012-10-18T14:49:29.971Z,1350571769.971 [CommandLine](INFO): platform_battery_voltage (volt)
2012-10-18T14:49:29.972Z,1350571769.972 [CommandLine](INFO): platform_battery_fully_charged (bool)
2012-10-18T14:49:29.972Z,1350571769.972 [CommandLine](INFO): platform_battery_discharging (bool)
2012-10-18T14:49:29.990Z,1350571769.990 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_ad (none)
2012-10-18T14:49:29.995Z,1350571769.995 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_vref (volt)
2012-10-18T14:49:29.995Z,1350571769.995 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_res (bit)
2012-10-18T14:49:29.996Z,1350571769.996 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_ad (none)
2012-10-18T14:49:29.996Z,1350571769.996 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_vref (volt)
2012-10-18T14:49:29.996Z,1350571769.996 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_res (bit)
2012-10-18T14:49:30.007Z,1350571770.007 [CommandLine](INFO): IBIT.batteryCapacityThreshold (ampere_hour)
2012-10-18T14:49:30.007Z,1350571770.007 [CommandLine](INFO): IBIT.batteryVoltageThreshold (volt)
2012-10-18T14:49:30.061Z,1350571770.061 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_charge (ampere_hour)
2012-10-18T14:49:30.061Z,1350571770.061 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_voltage (volt)
2012-10-18T14:49:30.062Z,1350571770.062 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_discharging (bool)
2012-10-18T14:49:30.062Z,1350571770.062 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_fully_charged (bool)
2012-10-18T14:49:30.065Z,1350571770.065 [CommandLine](INFO): Onboard.platform_battery_charge_usage (ampere_hour)
2012-10-18T14:49:58.439Z,1350571798.439 [CommandLine](IMPORTANT): got command get platform_battery_voltage
2012-10-18T14:49:58.439Z,1350571798.439 [CommandLine](IMPORTANT): platform_battery_voltage 16.321377 volt