2013-12-20T22:17:52.113Z,1387577872.113 [Supervisor](DEBUG): Initializing supervisor.
2013-12-20T22:17:52.116Z,1387577872.116 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-12-20T22:17:52.116Z,1387577872.116 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-12-20T22:17:52.117Z,1387577872.117 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-12-20T22:17:52.121Z,1387577872.121 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-12-20T22:17:52.132Z,1387577872.132 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-12-20T22:17:52.134Z,1387577872.134 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-12-20T22:17:52.135Z,1387577872.135 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-12-20T22:17:52.136Z,1387577872.136 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-12-20T22:17:52.138Z,1387577872.138 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2013-12-20T22:17:52.138Z,1387577872.138 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-12-20T22:17:52.140Z,1387577872.140 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-12-20T22:17:52.418Z,1387577872.418 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-12-20T22:17:52.419Z,1387577872.418 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-12-20T22:17:52.611Z,1387577872.611 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-12-20T22:17:52.611Z,1387577872.611 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-12-20T22:17:52.691Z,1387577872.691 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-12-20T22:17:52.691Z,1387577872.691 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-12-20T22:17:52.802Z,1387577872.802 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-12-20T22:17:52.803Z,1387577872.803 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-12-20T22:17:52.937Z,1387577872.937 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-12-20T22:17:52.937Z,1387577872.937 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-12-20T22:17:53.174Z,1387577873.174 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-12-20T22:17:53.174Z,1387577873.174 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-12-20T22:17:53.337Z,1387577873.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-12-20T22:17:53.338Z,1387577873.338 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-12-20T22:17:53.597Z,1387577873.597 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-12-20T22:17:53.597Z,1387577873.597 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-12-20T22:17:53.699Z,1387577873.699 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-12-20T22:17:53.700Z,1387577873.700 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-12-20T22:17:54.459Z,1387577874.459 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-12-20T22:17:54.460Z,1387577874.460 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-12-20T22:17:54.565Z,1387577874.565 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-12-20T22:17:54.566Z,1387577874.566 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-12-20T22:17:54.645Z,1387577874.645 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2013-12-20T22:17:54.740Z,1387577874.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2013-12-20T22:17:54.742Z,1387577874.742 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-12-20T22:17:54.743Z,1387577874.743 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-12-20T22:17:54.833Z,1387577874.833 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-12-20T22:17:54.967Z,1387577874.967 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-12-20T22:17:55.066Z,1387577875.066 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-12-20T22:17:55.165Z,1387577875.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-12-20T22:17:55.255Z,1387577875.255 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-12-20T22:17:55.365Z,1387577875.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-12-20T22:17:55.455Z,1387577875.455 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-12-20T22:17:55.535Z,1387577875.535 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2013-12-20T22:17:55.624Z,1387577875.624 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2013-12-20T22:17:55.624Z,1387577875.624 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2013-12-20T22:17:55.625Z,1387577875.625 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-12-20T22:17:55.992Z,1387577875.992 [InternalSim] Loaded
2013-12-20T22:17:55.992Z,1387577875.992 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-12-20T22:17:55.993Z,1387577875.993 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-12-20T22:17:55.994Z,1387577875.994 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-12-20T22:17:56.108Z,1387577876.108 [SBIT](DEBUG): Construct Startup Built In Test.
2013-12-20T22:17:56.140Z,1387577876.140 [SBIT] Loaded
2013-12-20T22:17:56.140Z,1387577876.140 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-12-20T22:17:56.141Z,1387577876.141 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-12-20T22:17:56.171Z,1387577876.171 [IBIT] Loaded
2013-12-20T22:17:56.172Z,1387577876.172 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-12-20T22:17:56.174Z,1387577876.174 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-12-20T22:17:56.293Z,1387577876.293 [CBIT] Loaded
2013-12-20T22:17:56.293Z,1387577876.293 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-12-20T22:17:56.294Z,1387577876.294 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-12-20T22:17:56.294Z,1387577876.294 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-12-20T22:17:56.487Z,1387577876.487 [BuoyancyServo] Loaded
2013-12-20T22:17:56.488Z,1387577876.488 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-12-20T22:17:56.500Z,1387577876.500 [ElevatorServo] Loaded
2013-12-20T22:17:56.500Z,1387577876.500 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-12-20T22:17:56.512Z,1387577876.512 [MassServo] Loaded
2013-12-20T22:17:56.512Z,1387577876.512 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-12-20T22:17:56.524Z,1387577876.524 [RudderServo] Loaded
2013-12-20T22:17:56.524Z,1387577876.524 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-12-20T22:17:56.535Z,1387577876.535 [ThrusterServo] Loaded
2013-12-20T22:17:56.536Z,1387577876.536 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-12-20T22:17:56.536Z,1387577876.536 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-12-20T22:17:56.537Z,1387577876.537 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-12-20T22:17:56.588Z,1387577876.588 [DepthRateCalculator] Loaded
2013-12-20T22:17:56.588Z,1387577876.588 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-12-20T22:17:59.243Z,1387577879.243 [HFRadarModelCalc] Loaded
2013-12-20T22:17:59.243Z,1387577879.243 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-12-20T22:17:59.260Z,1387577879.260 [NavChart] Loaded
2013-12-20T22:17:59.260Z,1387577879.260 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-12-20T22:17:59.266Z,1387577879.266 [PitchRateCalculator] Loaded
2013-12-20T22:17:59.266Z,1387577879.266 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-12-20T22:17:59.277Z,1387577879.277 [SpeedCalculator] Loaded
2013-12-20T22:17:59.278Z,1387577879.278 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-12-20T22:17:59.295Z,1387577879.295 [TempGradientCalculator] Loaded
2013-12-20T22:17:59.295Z,1387577879.295 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-12-20T22:17:59.301Z,1387577879.301 [YawRateCalculator] Loaded
2013-12-20T22:17:59.301Z,1387577879.301 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-12-20T22:17:59.349Z,1387577879.349 [Navigation] Loaded
2013-12-20T22:17:59.350Z,1387577879.350 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-12-20T22:17:59.350Z,1387577879.350 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-12-20T22:17:59.351Z,1387577879.351 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-12-20T22:17:59.649Z,1387577879.649 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-12-20T22:17:59.650Z,1387577879.650 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-12-20T22:17:59.690Z,1387577879.690 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-12-20T22:17:59.691Z,1387577879.691 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-12-20T22:17:59.761Z,1387577879.761 [VerticalControl](DEBUG): Construct VerticalControl.
2013-12-20T22:17:59.859Z,1387577879.859 [VerticalControl] Loaded
2013-12-20T22:17:59.859Z,1387577879.859 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-12-20T22:17:59.860Z,1387577879.860 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-12-20T22:17:59.920Z,1387577879.920 [HorizontalControl] Loaded
2013-12-20T22:17:59.920Z,1387577879.920 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-12-20T22:17:59.921Z,1387577879.921 [SpeedControl](DEBUG): Construct SpeedControl.
2013-12-20T22:17:59.923Z,1387577879.923 [SpeedControl] Loaded
2013-12-20T22:17:59.923Z,1387577879.923 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-12-20T22:17:59.923Z,1387577879.923 [LoopControl](DEBUG): Construct LoopControl.
2013-12-20T22:17:59.924Z,1387577879.924 [LoopControl] Loaded
2013-12-20T22:17:59.924Z,1387577879.924 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-12-20T22:17:59.925Z,1387577879.925 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-12-20T22:17:59.925Z,1387577879.925 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-12-20T22:17:59.938Z,1387577879.938 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-12-20T22:17:59.945Z,1387577879.945 [AsyncPiEstimator] Loaded
2013-12-20T22:17:59.945Z,1387577879.945 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-12-20T22:17:59.946Z,1387577879.946 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-12-20T22:17:59.947Z,1387577879.947 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-12-20T22:17:59.948Z,1387577879.948 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-12-20T22:18:00.400Z,1387577880.400 [AHRS_sp3003D] Loaded
2013-12-20T22:18:00.401Z,1387577880.401 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-12-20T22:18:00.663Z,1387577880.663 [Batt_Ocean_Server] Loaded
2013-12-20T22:18:00.663Z,1387577880.663 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-12-20T22:18:00.765Z,1387577880.765 [DataOverHttps] Loaded
2013-12-20T22:18:00.765Z,1387577880.765 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2013-12-20T22:18:00.779Z,1387577880.779 [Depth_Keller] Loaded
2013-12-20T22:18:00.780Z,1387577880.780 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-12-20T22:18:00.972Z,1387577880.972 [DVL_micro] Loaded
2013-12-20T22:18:00.973Z,1387577880.973 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-12-20T22:18:00.974Z,1387577880.974 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 408554E0
2013-12-20T22:18:01.067Z,1387577881.067 [NAL9602] Loaded
2013-12-20T22:18:01.068Z,1387577881.068 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-12-20T22:18:01.111Z,1387577881.111 [Onboard] Loaded
2013-12-20T22:18:01.112Z,1387577881.112 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-12-20T22:18:01.118Z,1387577881.118 [Radio_Freewave] Loaded
2013-12-20T22:18:01.119Z,1387577881.119 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-12-20T22:18:01.271Z,1387577881.271 [DAT] Loaded
2013-12-20T22:18:01.271Z,1387577881.271 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-12-20T22:18:01.272Z,1387577881.272 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-12-20T22:18:01.272Z,1387577881.272 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-12-20T22:18:01.398Z,1387577881.398 [CTD_NeilBrown] Loaded
2013-12-20T22:18:01.398Z,1387577881.398 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-12-20T22:18:01.400Z,1387577881.400 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408B24E0
2013-12-20T22:18:01.433Z,1387577881.433 [WetLabsBB2FL] Loaded
2013-12-20T22:18:01.434Z,1387577881.434 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-12-20T22:18:01.435Z,1387577881.435 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408E24E0
2013-12-20T22:18:01.436Z,1387577881.436 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-12-20T22:18:01.438Z,1387577881.438 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-12-20T22:18:01.439Z,1387577881.439 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-12-20T22:18:01.446Z,1387577881.446 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-12-20T22:18:01.448Z,1387577881.448 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 409124E0
2013-12-20T22:18:01.453Z,1387577881.453 [Supervisor](DEBUG): Running supervisor.
2013-12-20T22:18:01.454Z,1387577881.454 [CommandLine](INFO): Thread ID is 2535
2013-12-20T22:18:01.458Z,1387577881.458 [controlThread](INFO): Thread ID is 2534
2013-12-20T22:18:01.458Z,1387577881.458 [controlThread](DEBUG): Initializing ControlThread
2013-12-20T22:18:01.458Z,1387577881.458 [CycleStarter](INFO): Thread ID is 2533
2013-12-20T22:18:01.459Z,1387577881.459 [InternalSim](DEBUG):  InternalSim initializing...
2013-12-20T22:18:01.557Z,1387577881.557 [logger](INFO): Thread ID is 2536
2013-12-20T22:18:01.634Z,1387577881.634 [AsyncPiEstimator](INFO): Thread ID is 2603
2013-12-20T22:18:01.634Z,1387577881.634 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-12-20T22:18:01.642Z,1387577881.642 [DVL_micro](INFO): Thread ID is 2604
2013-12-20T22:18:01.785Z,1387577881.785 [CTD_NeilBrown](INFO): Thread ID is 2605
2013-12-20T22:18:01.785Z,1387577881.785 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-12-20T22:18:01.794Z,1387577881.794 [WetLabsBB2FL](INFO): Thread ID is 2606
2013-12-20T22:18:01.794Z,1387577881.794 [WetLabsBB2FL](INFO): Powering down
2013-12-20T22:18:01.813Z,1387577881.813 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-12-20T22:18:01.830Z,1387577881.830 [DVL_micro](INFO): Initializing
2013-12-20T22:18:01.831Z,1387577881.831 [DVL_micro](INFO): start:Powering up
2013-12-20T22:18:01.831Z,1387577881.831 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-12-20T22:18:01.832Z,1387577881.832 [DVL_micro](INFO): Cycling power to configure device.
2013-12-20T22:18:01.834Z,1387577881.834 [NavChartDb](INFO): Thread ID is 2607
2013-12-20T22:18:01.905Z,1387577881.905 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-12-20T22:18:01.906Z,1387577881.906 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-12-20T22:18:01.906Z,1387577881.906 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-12-20T22:18:01.906Z,1387577881.906 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-12-20T22:18:01.907Z,1387577881.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-12-20T22:18:01.907Z,1387577881.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-12-20T22:18:01.907Z,1387577881.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-12-20T22:18:01.907Z,1387577881.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-12-20T22:18:01.908Z,1387577881.908 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-12-20T22:18:01.932Z,1387577881.932 [SBIT](INFO): Initialize SBIT Component.
2013-12-20T22:18:01.932Z,1387577881.932 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:10713
2013-12-20T22:18:01.934Z,1387577881.934 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-12-20T22:18:01.934Z,1387577881.934 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-12-20T22:18:01.937Z,1387577881.937 [IBIT](INFO): Initialize IBIT Component.
2013-12-20T22:18:01.938Z,1387577881.938 [CBIT](DEBUG): Initialize CBIT Component.
2013-12-20T22:18:01.938Z,1387577881.938 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2013-12-20T22:18:01.939Z,1387577881.939 [CBIT](CRITICAL): Watchdog Timer failed to initialize.
2013-12-20T22:18:01.939Z,1387577881.939 [CBIT] Hardware Fault, FailCount= 1
2013-12-20T22:18:01.939Z,1387577881.939 [CBIT](ERROR): Hardware Fault
2013-12-20T22:18:01.967Z,1387577881.967 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-12-20T22:18:01.967Z,1387577881.967 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-12-20T22:18:01.968Z,1387577881.968 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-12-20T22:18:01.968Z,1387577881.968 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-12-20T22:18:01.972Z,1387577881.972 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-12-20T22:18:01.972Z,1387577881.972 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-12-20T22:18:01.973Z,1387577881.973 [Navigation](DEBUG): Initializing Navigation.
2013-12-20T22:18:01.973Z,1387577881.973 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-12-20T22:18:01.975Z,1387577881.975 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-12-20T22:18:01.975Z,1387577881.975 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-12-20T22:18:01.976Z,1387577881.976 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-12-20T22:18:03.730Z,1387577883.730 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-12-20T22:18:03.762Z,1387577883.762 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-12-20T22:18:03.777Z,1387577883.777 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-12-20T22:18:03.809Z,1387577883.809 [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>


2013-12-20T22:18:03.810Z,1387577883.810 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-12-20T22:18:03.883Z,1387577883.883 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-12-20T22:18:03.885Z,1387577883.885 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-12-20T22:18:03.888Z,1387577883.888 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-12-20T22:18:03.920Z,1387577883.920 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-12-20T22:18:03.923Z,1387577883.923 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-12-20T22:18:03.946Z,1387577883.946 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-12-20T22:18:03.948Z,1387577883.948 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-12-20T22:18:03.949Z,1387577883.949 [DVL_micro](INFO): Querying output modes
2013-12-20T22:18:03.949Z,1387577883.949 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-12-20T22:18:03.966Z,1387577883.966 [Default:D.SetSpeed](DEBUG): Construct.
2013-12-20T22:18:03.974Z,1387577883.974 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-12-20T22:18:03.986Z,1387577883.986 [Default:F.Wait](DEBUG): Construct Wait.
2013-12-20T22:18:03.990Z,1387577883.990 [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>


2013-12-20T22:18:04.003Z,1387577884.003 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,DataOverHttps,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2013-12-20T22:18:04.062Z,1387577884.062 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-12-20T22:18:04.088Z,1387577884.088 [DataOverHttps](INFO): tcpConnect
2013-12-20T22:18:04.146Z,1387577884.146 [Depth_Keller](ERROR): Pressure reading out of range: 1831.078247 decibar
2013-12-20T22:18:04.181Z,1387577884.181 [Radio_Freewave](INFO): Powering up
2013-12-20T22:18:04.186Z,1387577884.186 [DAT](INFO): Powering up
2013-12-20T22:18:04.186Z,1387577884.186 [DAT](DEBUG): Initializing DAT.
2013-12-20T22:18:04.389Z,1387577884.389 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-12-20T22:18:04.413Z,1387577884.413 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-12-20T22:18:04.419Z,1387577884.419 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-12-20T22:18:04.425Z,1387577884.425 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-12-20T22:18:04.443Z,1387577884.443 [MassServo](DEBUG): Initializing EZServoServo.
2013-12-20T22:18:04.445Z,1387577884.445 [MassServo](DEBUG): Initializing MassServo.
2013-12-20T22:18:04.455Z,1387577884.455 [RudderServo](DEBUG): Initializing EZServoServo.
2013-12-20T22:18:04.461Z,1387577884.461 [RudderServo](DEBUG): Initializing RudderServo.
2013-12-20T22:18:04.467Z,1387577884.467 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-12-20T22:18:04.473Z,1387577884.473 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-12-20T22:18:04.529Z,1387577884.529 [CBIT](DEBUG): Uninitialize CBIT Component.
2013-12-20T22:18:04.612Z,1387577884.612 [DataOverHttps](INFO): tcpConnecting
2013-12-20T22:18:04.613Z,1387577884.613 [DataOverHttps](INFO): sslConnect
2013-12-20T22:18:04.624Z,1387577884.624 [DataOverHttps](INFO): sslConnecting
2013-12-20T22:18:05.322Z,1387577885.322 [AHRS_sp3003D](ERROR): readHeadingMagBin UART error: serial timeout
2013-12-20T22:18:05.322Z,1387577885.322 [AHRS_sp3003D](ERROR): SP3003D failed to initialize
2013-12-20T22:18:05.323Z,1387577885.323 [AHRS_sp3003D] Hardware Fault, FailCount= 1
2013-12-20T22:18:05.323Z,1387577885.323 [AHRS_sp3003D](ERROR): Hardware Fault
2013-12-20T22:18:05.324Z,1387577885.324 [DataOverHttps](INFO): sslConnecting
2013-12-20T22:18:05.959Z,1387577885.959 [DVL_micro](DEBUG): cmdResponse: 
2013-12-20T22:18:05.959Z,1387577885.959 [DVL_micro](INFO): Output Modes: No Response
2013-12-20T22:18:05.960Z,1387577885.960 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-12-20