2012-05-10T16:09:38.550Z,1336666178.550 [Supervisor](DEBUG): Initializing supervisor.
2012-05-10T16:09:38.553Z,1336666178.553 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-05-10T16:09:38.553Z,1336666178.553 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-05-10T16:09:38.554Z,1336666178.554 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-05-10T16:09:38.555Z,1336666178.555 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-05-10T16:09:38.565Z,1336666178.565 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-05-10T16:09:38.566Z,1336666178.566 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-05-10T16:09:38.567Z,1336666178.567 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-05-10T16:09:38.568Z,1336666178.568 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-05-10T16:09:38.570Z,1336666178.570 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-05-10T16:09:38.915Z,1336666178.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-05-10T16:09:38.915Z,1336666178.915 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-05-10T16:09:39.100Z,1336666179.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-05-10T16:09:39.100Z,1336666179.100 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-05-10T16:09:39.188Z,1336666179.188 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-05-10T16:09:39.189Z,1336666179.189 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-05-10T16:09:39.376Z,1336666179.376 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-05-10T16:09:39.376Z,1336666179.376 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-05-10T16:09:39.503Z,1336666179.503 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-05-10T16:09:39.503Z,1336666179.503 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-05-10T16:09:39.721Z,1336666179.721 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-05-10T16:09:39.722Z,1336666179.722 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-05-10T16:09:39.869Z,1336666179.869 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-05-10T16:09:39.870Z,1336666179.870 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-05-10T16:09:40.082Z,1336666180.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-05-10T16:09:40.083Z,1336666180.083 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-05-10T16:09:40.182Z,1336666180.182 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-05-10T16:09:40.182Z,1336666180.182 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-05-10T16:09:40.568Z,1336666180.569 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-05-10T16:09:40.569Z,1336666180.569 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-05-10T16:09:40.681Z,1336666180.681 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-05-10T16:09:40.682Z,1336666180.681 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-05-10T16:09:40.768Z,1336666180.768 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-05-10T16:09:40.771Z,1336666180.771 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-05-10T16:09:40.874Z,1336666180.874 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-05-10T16:09:41.003Z,1336666181.003 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-05-10T16:09:41.105Z,1336666181.105 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-05-10T16:09:41.203Z,1336666181.203 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-05-10T16:09:41.312Z,1336666181.312 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-05-10T16:09:41.406Z,1336666181.406 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-05-10T16:09:41.496Z,1336666181.497 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-05-10T16:09:46.484Z,1336666186.484 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-05-10T16:09:46.892Z,1336666186.892 [InternalSim] Loaded
2012-05-10T16:09:46.892Z,1336666186.892 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-05-10T16:09:46.893Z,1336666186.893 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-05-10T16:09:46.894Z,1336666186.894 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-05-10T16:09:47.328Z,1336666187.328 [SBIT](DEBUG): Construct Startup Built In Test.
2012-05-10T16:09:47.339Z,1336666187.339 [SBIT] Loaded
2012-05-10T16:09:47.339Z,1336666187.339 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-05-10T16:09:47.340Z,1336666187.340 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-05-10T16:09:47.364Z,1336666187.364 [IBIT] Loaded
2012-05-10T16:09:47.364Z,1336666187.364 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-05-10T16:09:47.372Z,1336666187.372 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-05-10T16:09:47.479Z,1336666187.479 [CBIT] Loaded
2012-05-10T16:09:47.479Z,1336666187.479 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-05-10T16:09:47.479Z,1336666187.479 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-05-10T16:09:47.480Z,1336666187.480 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-05-10T16:09:47.693Z,1336666187.693 [BuoyancyServo] Loaded
2012-05-10T16:09:47.693Z,1336666187.693 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-05-10T16:09:47.700Z,1336666187.700 [ElevatorServo] Loaded
2012-05-10T16:09:47.700Z,1336666187.700 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-05-10T16:09:47.706Z,1336666187.707 [MassServo] Loaded
2012-05-10T16:09:47.707Z,1336666187.707 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-05-10T16:09:47.713Z,1336666187.713 [RudderServo] Loaded
2012-05-10T16:09:47.713Z,1336666187.713 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-05-10T16:09:47.720Z,1336666187.720 [ThrusterServo] Loaded
2012-05-10T16:09:47.720Z,1336666187.720 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-05-10T16:09:47.721Z,1336666187.721 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-05-10T16:09:47.721Z,1336666187.721 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-05-10T16:09:47.743Z,1336666187.743 [DepthRateCalculator] Loaded
2012-05-10T16:09:47.743Z,1336666187.743 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-05-10T16:09:47.758Z,1336666187.759 [NavChart] Loaded
2012-05-10T16:09:47.759Z,1336666187.759 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-05-10T16:09:47.764Z,1336666187.764 [PitchRateCalculator] Loaded
2012-05-10T16:09:47.765Z,1336666187.765 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-05-10T16:09:47.770Z,1336666187.770 [SpeedCalculator] Loaded
2012-05-10T16:09:47.770Z,1336666187.770 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-05-10T16:09:47.785Z,1336666187.784 [TempGradientCalculator] Loaded
2012-05-10T16:09:47.785Z,1336666187.785 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-05-10T16:09:47.790Z,1336666187.790 [YawRateCalculator] Loaded
2012-05-10T16:09:47.791Z,1336666187.791 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-05-10T16:09:47.820Z,1336666187.820 [Navigation] Loaded
2012-05-10T16:09:47.820Z,1336666187.820 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-05-10T16:09:47.821Z,1336666187.821 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-05-10T16:09:47.821Z,1336666187.821 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-05-10T16:09:48.050Z,1336666188.050 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-05-10T16:09:48.051Z,1336666188.051 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-05-10T16:09:48.083Z,1336666188.083 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-05-10T16:09:48.083Z,1336666188.083 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-05-10T16:09:48.129Z,1336666188.129 [VerticalControl](DEBUG): Construct VerticalControl.
2012-05-10T16:09:48.171Z,1336666188.171 [VerticalControl] Loaded
2012-05-10T16:09:48.172Z,1336666188.172 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-05-10T16:09:48.173Z,1336666188.173 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-05-10T16:09:48.192Z,1336666188.192 [HorizontalControl] Loaded
2012-05-10T16:09:48.192Z,1336666188.192 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-05-10T16:09:48.193Z,1336666188.193 [SpeedControl](DEBUG): Construct SpeedControl.
2012-05-10T16:09:48.195Z,1336666188.195 [SpeedControl] Loaded
2012-05-10T16:09:48.195Z,1336666188.195 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-05-10T16:09:48.196Z,1336666188.196 [LoopControl](DEBUG): Construct LoopControl.
2012-05-10T16:09:48.197Z,1336666188.197 [LoopControl] Loaded
2012-05-10T16:09:48.197Z,1336666188.197 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-05-10T16:09:48.198Z,1336666188.198 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-05-10T16:09:48.198Z,1336666188.198 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-05-10T16:09:48.209Z,1336666188.210 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-05-10T16:09:48.215Z,1336666188.215 [AsyncPiEstimator] Loaded
2012-05-10T16:09:48.216Z,1336666188.216 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-05-10T16:09:48.217Z,1336666188.217 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078994144
2012-05-10T16:09:48.218Z,1336666188.218 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-05-10T16:09:48.218Z,1336666188.218 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-05-10T16:09:48.343Z,1336666188.343 [AHRS_sp3003D] Loaded
2012-05-10T16:09:48.344Z,1336666188.344 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-05-10T16:09:48.588Z,1336666188.588 [Batt_Ocean_Server] Loaded
2012-05-10T16:09:48.588Z,1336666188.588 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-05-10T16:09:48.595Z,1336666188.595 [DropWeight] Loaded
2012-05-10T16:09:48.595Z,1336666188.595 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-05-10T16:09:48.684Z,1336666188.684 [DVL_micro] Loaded
2012-05-10T16:09:48.685Z,1336666188.685 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-05-10T16:09:48.764Z,1336666188.764 [NAL9601] Loaded
2012-05-10T16:09:48.764Z,1336666188.764 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-05-10T16:09:48.813Z,1336666188.813 [Onboard] Loaded
2012-05-10T16:09:48.813Z,1336666188.813 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-05-10T16:09:48.819Z,1336666188.819 [Radio_Freewave] Loaded
2012-05-10T16:09:48.820Z,1336666188.820 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-05-10T16:09:48.820Z,1336666188.820 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-05-10T16:09:48.821Z,1336666188.821 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-05-10T16:09:48.881Z,1336666188.881 [CTD_NeilBrown] Loaded
2012-05-10T16:09:48.881Z,1336666188.881 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-05-10T16:09:48.882Z,1336666188.882 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079645408
2012-05-10T16:09:48.912Z,1336666188.912 [WetLabsBB2FL] Loaded
2012-05-10T16:09:48.912Z,1336666188.912 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-05-10T16:09:48.913Z,1336666188.913 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-05-10T16:09:48.915Z,1336666188.915 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-05-10T16:09:48.915Z,1336666188.915 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-05-10T16:09:48.916Z,1336666188.916 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-05-10T16:09:48.922Z,1336666188.921 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-05-10T16:09:48.923Z,1336666188.923 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079842016
2012-05-10T16:09:48.923Z,1336666188.923 [Supervisor](DEBUG): Running supervisor.
2012-05-10T16:09:48.926Z,1336666188.926 [controlThread](DEBUG): Initializing ControlThread
2012-05-10T16:09:48.927Z,1336666188.927 [InternalSim](DEBUG):  InternalSim initializing...
2012-05-10T16:09:48.962Z,1336666188.963 [SBIT](INFO): Initialize SBIT Component.
2012-05-10T16:09:48.964Z,1336666188.964 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9636 $
2012-05-10T16:09:48.964Z,1336666188.964 [IBIT](INFO): Initialize IBIT Component.
2012-05-10T16:09:48.967Z,1336666188.967 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-05-10T16:09:48.975Z,1336666188.975 [CBIT](DEBUG): Initialize CBIT Component.
2012-05-10T16:09:48.975Z,1336666188.975 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-05-10T16:09:48.976Z,1336666188.977 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-05-10T16:09:48.000Z,1336666189.000 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-10T16:09:49.000Z,1336666189.000 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-05-10T16:09:49.001Z,1336666189.000 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-05-10T16:09:49.001Z,1336666189.001 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-05-10T16:09:49.002Z,1336666189.001 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-05-10T16:09:49.003Z,1336666189.003 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-05-10T16:09:49.003Z,1336666189.003 [Navigation](DEBUG): Initializing Navigation.
2012-05-10T16:09:49.004Z,1336666189.004 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-05-10T16:09:49.006Z,1336666189.006 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-05-10T16:09:49.007Z,1336666189.007 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-05-10T16:09:49.007Z,1336666189.007 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-05-10T16:09:49.095Z,1336666189.095 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-05-10T16:09:49.102Z,1336666189.102 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-05-10T16:09:49.106Z,1336666189.106 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-05-10T16:09:49.110Z,1336666189.110 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-05-10T16:09:49.114Z,1336666189.114 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-05-10T16:09:49.115Z,1336666189.115 [NavChartDb](INFO): Creating index for Soundings
2012-05-10T16:09:49.119Z,1336666189.118 [NavChartDb](INFO): Creating index for Contour 0p0
2012-05-10T16:09:49.120Z,1336666189.120 [NavChartDb](INFO): Creating index for Contour 1p8
2012-05-10T16:09:49.123Z,1336666189.123 [NavChartDb](INFO): Creating index for Contour 3p6
2012-05-10T16:09:49.125Z,1336666189.125 [NavChartDb](INFO): Creating index for Contour 5p4
2012-05-10T16:09:49.127Z,1336666189.127 [NavChartDb](INFO): Creating index for Contour 9p1
2012-05-10T16:09:49.128Z,1336666189.128 [NavChartDb](INFO): Creating index for Contour 10p9
2012-05-10T16:09:49.131Z,1336666189.131 [NavChartDb](INFO): Creating index for Contour 18p2
2012-05-10T16:09:49.132Z,1336666189.132 [NavChartDb](INFO): Creating index for Contour 36p5
2012-05-10T16:09:49.134Z,1336666189.134 [NavChartDb](INFO): Creating index for Contour 54p8
2012-05-10T16:09:49.136Z,1336666189.136 [NavChartDb](INFO): Creating index for Contour 73p1
2012-05-10T16:09:49.138Z,1336666189.138 [NavChartDb](INFO): Creating index for Contour 91p4
2012-05-10T16:09:49.141Z,1336666189.141 [NavChartDb](INFO): Creating index for Contour 182p8
2012-05-10T16:09:49.143Z,1336666189.143 [NavChartDb](INFO): Creating index for Contour 365p7
2012-05-10T16:09:49.145Z,1336666189.145 [NavChartDb](INFO): Creating index for Contour 548p6
2012-05-10T16:09:49.147Z,1336666189.147 [NavChartDb](INFO): Creating index for Contour 731p5
2012-05-10T16:09:49.149Z,1336666189.149 [NavChartDb](INFO): Creating index for Contour 914p4
2012-05-10T16:09:49.150Z,1336666189.151 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-05-10T16:09:49.152Z,1336666189.152 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-05-10T16:09:49.154Z,1336666189.155 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-05-10T16:09:49.156Z,1336666189.156 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-05-10T16:09:49.158Z,1336666189.158 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-05-10T16:09:49.160Z,1336666189.160 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-05-10T16:09:49.162Z,1336666189.162 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-05-10T16:09:49.164Z,1336666189.164 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-05-10T16:09:49.166Z,1336666189.166 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-05-10T16:09:49.168Z,1336666189.168 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-05-10T16:09:49.170Z,1336666189.170 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-05-10T16:09:49.172Z,1336666189.172 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-05-10T16:09:49.174Z,1336666189.174 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-05-10T16:09:49.176Z,1336666189.176 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-05-10T16:09:49.178Z,1336666189.178 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-05-10T16:09:50.739Z,1336666190.739 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-05-10T16:09:50.742Z,1336666190.742 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-05-10T16:09:50.753Z,1336666190.753 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T16:09:50.763Z,1336666190.763 [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-05-10T16:09:50.763Z,1336666190.763 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-05-10T16:09:50.792Z,1336666190.792 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-05-10T16:09:50.794Z,1336666190.795 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-05-10T16:09:50.798Z,1336666190.798 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T16:09:50.806Z,1336666190.806 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-05-10T16:09:50.809Z,1336666190.809 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T16:09:50.815Z,1336666190.815 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-05-10T16:09:50.824Z,1336666190.824 [Default:D.SetSpeed](DEBUG): Construct.
2012-05-10T16:09:50.827Z,1336666190.827 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T16:09:50.832Z,1336666190.832 [Default:F.Wait](DEBUG): Construct Wait.
2012-05-10T16:09:50.835Z,1336666190.835 [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 on</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-05-10T16:09:50.840Z,1336666190.841 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,WetLabsBB2FL,DepthRateCalculator,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-05-10T16:09:50.859Z,1336666190.859 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-10T16:09:50.884Z,1336666190.884 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-10T16:09:50.906Z,1336666190.906 [Radio_Freewave](INFO): Powering up
2012-05-10T16:09:50.911Z,1336666190.911 [WetLabsBB2FL](INFO): Powering down
2012-05-10T16:09:50.981Z,1336666190.981 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-05-10T16:09:50.983Z,1336666190.983 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-05-10T16:09:50.991Z,1336666190.991 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-05-10T16:09:50.992Z,1336666190.992 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-05-10T16:09:51.000Z,1336666191.000 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-10T16:09:51.001Z,1336666191.001 [MassServo](DEBUG): Initializing MassServo.
2012-05-10T16:09:51.009Z,1336666191.009 [RudderServo](DEBUG): Initializing EZServoServo.
2012-05-10T16:09:51.010Z,1336666191.010 [RudderServo](DEBUG): Initializing RudderServo.
2012-05-10T16:09:51.018Z,1336666191.018 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-10T16:09:51.019Z,1336666191.019 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-10T16:09:53.887Z,1336666193.887 [NAL9601](INFO): Powering up NAL9601
2012-05-10T16:10:04.684Z,1336666204.684 [SBIT](IMPORTANT): Beginning Startup BIT
2012-05-10T16:10:04.686Z,1336666204.686 [CBIT](IMPORTANT): Beginning GF scan
2012-05-10T16:10:30.924Z,1336666230.924 [CBIT](IMPORTANT): No ground fault detected
2012-05-10T16:10:46.833Z,1336666246.833 [SBIT](IMPORTANT): SBIT PASSED
2012-05-10T16:10:47.258Z,1336666247.258 [MissionManager](IMPORTANT): Started mission Startup
2012-05-10T16:10:47.259Z,1336666247.259 [Startup] Running Loop=1
2012-05-10T16:10:47.259Z,1336666247.259 [Startup](INFO): Aggregate::initialize Startup
2012-05-10T16:10:47.259Z,1336666247.259 [Startup:A.GoToSurface] Running Loop=1
2012-05-10T16:10:47.259Z,1336666247.259 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:10:49.148Z,1336666249.148 [Startup:StartupSatComms] Running Loop=1
2012-05-10T16:10:49.148Z,1336666249.148 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-05-10T16:10:49.148Z,1336666249.148 [Startup:StartupSatComms:A] Running Loop=1
2012-05-10T16:10:49.521Z,1336666249.521 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-10T16:10:54.379Z,1336666254.379 [CTD_NeilBrown](ERROR): Salinity reading out of range: 104.641220 psu
2012-05-10T16:10:54.535Z,1336666254.535 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.037440 psu
2012-05-10T16:10:54.714Z,1336666254.714 [Radio_Freewave](INFO): Powering down
2012-05-10T16:10:55.112Z,1336666255.112 [Radio_Freewave](INFO): Powering up
2012-05-10T16:10:59.583Z,1336666259.583 [NAL9601](INFO): NAL9601 initialized
2012-05-10T16:11:49.523Z,1336666309.523 [Startup:StartupSatComms:A](INFO): Timed out from 2012-05-10T16:10:49.1Z
2012-05-10T16:11:49.523Z,1336666309.523 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-05-10T16:11:49.524Z,1336666309.523 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-05-10T16:11:49.524Z,1336666309.524 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-05-10T16:11:49.524Z,1336666309.524 [Startup:StartupSatComms:A] Stopped
2012-05-10T16:11:49.524Z,1336666309.524 [Startup:StartupSatComms:B] Running Loop=1
2012-05-10T16:11:49.943Z,1336666309.943 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T16:12:07.065Z,1336666327.065 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6600, MT Status=1, MTMSN=2622
2012-05-10T16:12:07.267Z,1336666327.267 [NAL9601](INFO): Sent 201 bytes from file Logs/20120510T063213/shore0075.lzma
2012-05-10T16:12:07.267Z,1336666327.267 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:12:07.269Z,1336666327.269 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-05-10T16:12:07.720Z,1336666327.720 [NAL9601](INFO): Received command:load Transport/transit_1km.xml;set transit_1km:SURFACECOMMS.IridiumTimeout 35 minute;run 
2012-05-10T16:12:07.732Z,1336666327.732 [CommandLine](IMPORTANT): got command load ./Missions/Transport/transit_1km.xml
2012-05-10T16:12:07.733Z,1336666327.733 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_1km.xml
2012-05-10T16:12:07.763Z,1336666327.763 [MissionManager](INFO): DefineArg transit_1km.ApproachDepth = 10.000000 m
2012-05-10T16:12:07.766Z,1336666327.766 [MissionManager](INFO): DefineArg transit_1km.Wpt1Lat = 36.815600 arcdeg
2012-05-10T16:12:07.769Z,1336666327.769 [MissionManager](INFO): DefineArg transit_1km.Wpt1Lon = -121.806000 arcdeg
2012-05-10T16:12:07.772Z,1336666327.773 [MissionManager](INFO): DefineArg transit_1km.MaxDepth = 20.000000 m
2012-05-10T16:12:07.775Z,1336666327.775 [transit_1km:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-10T16:12:07.783Z,1336666327.783 [transit_1km:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-10T16:12:07.792Z,1336666327.792 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-05-10T16:12:07.814Z,1336666327.814 [MissionManager](INFO): DefineArg transit_1km:SURFACECOMMS.SurfaceDepthRate = nan m/s
2012-05-10T16:12:07.817Z,1336666327.817 [MissionManager](INFO): DefineArg transit_1km:SURFACECOMMS.SurfacePitch = nan arcdeg
2012-05-10T16:12:07.820Z,1336666327.820 [MissionManager](INFO): DefineArg transit_1km:SURFACECOMMS.SurfaceSpeed = 0.500000 m/s
2012-05-10T16:12:07.824Z,1336666327.824 [MissionManager](INFO): DefineArg transit_1km:SURFACECOMMS.IridiumTimeout = 30.000000 min
2012-05-10T16:12:07.825Z,1336666327.825 [transit_1km:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T16:12:07.840Z,1336666327.840 [transit_1km:WaypointOne:A.Pitch](DEBUG): Construct.
2012-05-10T16:12:07.846Z,1336666327.846 [transit_1km:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-05-10T16:12:07.849Z,1336666327.849 [transit_1km:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-05-10T16:12:07.861Z,1336666327.861 [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="transit_1km">

<!-- To be used within 6km of waypoint. No science collection.  -->

    <DefineArg Name="ApproachDepth"><Units:meter/><Value>10.0</Value></DefineArg>

    <DefineArg Name="Wpt1Lat"><Units:degree/><Value>36.8156</Value></DefineArg>

    <DefineArg Name="Wpt1Lon"><Units:degree/><Value>-121.806</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum depth for the entire mission.
    </Description><Units:meter/><Value>20</Value></DefineArg>

    <Timeout Duration="P130M"/>

    <Guidance:AltitudeEnvelope RunIn="Parallel">
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Units:meter/><Value>7</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth/><Arg Name="MaxDepth"/></Setting>
    </Guidance:DepthEnvelope>

    <Insert Filename="Insert/Surface.xml" Id="SURFACECOMMS" />

<!-- GPS Update.  Don't go too long w/o a GPS fix. -->

    <Aggregate Id="NeedComms">

        <When>
            <Elapsed><Universal:time_fix/></Elapsed>
            <Gt><Units:minute/><Value>35</Value></Gt>
        </When>

        <Call Id="NEEDCOMMS" RefId="SURFACECOMMS"/>

    </Aggregate>

    <Aggregate Id="WaypointOne">

<!-- Go to Wpt1 -->

        <Guidance:Pitch RunIn="Parallel">
            <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
        </Guidance:Pitch>

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>1</Value></Setting>
        </Guidance:SetSpeed>

        <Guidance:Waypoint Id="WaypointW1" RunIn="Sequence">
            <Setting><Guidance:Waypoint.latitude/><Arg Name="Wpt1Lat"/></Setting>
            <Setting><Guidance:Waypoint.longitude/><Arg Name="Wpt1Lon"/></Setting>
        </Guidance:Waypoint>

        <Call Id="PHONEHOMEWPT1" RefId="SURFACECOMMS"/>

    </Aggregate>

</Mission>


2012-05-10T16:12:07.861Z,1336666327.861 [CommandLine](IMPORTANT): Loaded ./Missions/Transport/transit_1km.xml
2012-05-10T16:12:08.029Z,1336666328.029 [CommandLine](IMPORTANT): got command set transit_1km:SURFACECOMMS.IridiumTimeout 35.000000 minute
2012-05-10T16:12:08.031Z,1336666328.031 [CommandLine](IMPORTANT): got command run 
2012-05-10T16:12:08.031Z,1336666328.031 [CommandLine](IMPORTANT): Running 
2012-05-10T16:12:25.763Z,1336666345.763 [NAL9601](INFO): SBD MO Status=1, MOMSN=6601, MT Status=0, MTMSN=0
2012-05-10T16:12:25.939Z,1336666345.939 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T160938/shore0000.lzma
2012-05-10T16:12:25.939Z,1336666345.939 [NAL9601](INFO): Packets left to send: 1
2012-05-10T16:12:25.940Z,1336666345.940 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-05-10T16:12:33.067Z,1336666353.067 [NAL9601](INFO): SBD MO Status=1, MOMSN=6602, MT Status=0, MTMSN=0
2012-05-10T16:12:33.227Z,1336666353.227 [NAL9601](INFO): Sent 199 bytes from file Logs/20120510T160938/shore0000.lzma
2012-05-10T16:12:33.227Z,1336666353.227 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:12:33.228Z,1336666353.228 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-05-10T16:12:42.268Z,1336666362.268 [NAL9601](INFO): SBD MO Status=0, MOMSN=6603, MT Status=0, MTMSN=0
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms:B](INFO): Timed out from 2012-05-10T16:11:49.5Z
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms:B] Stopped
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-05-10T16:12:50.091Z,1336666370.091 [Startup:StartupSatComms] Stopped
2012-05-10T16:12:50.092Z,1336666370.092 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-05-10T16:12:50.092Z,1336666370.092 [Startup](INFO): Completed Startup
2012-05-10T16:12:50.093Z,1336666370.092 [Startup] Stopped
2012-05-10T16:12:50.093Z,1336666370.093 [Startup](INFO): Aggregate::uninitialize Startup
2012-05-10T16:12:50.093Z,1336666370.093 [Startup:A.GoToSurface] Stopped
2012-05-10T16:12:50.093Z,1336666370.093 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T16:12:50.299Z,1336666370.299 [MissionManager](IMPORTANT): Started mission transit_1km
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km] Running Loop=1
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km](INFO): Aggregate::initialize transit_1km
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km:A.AltitudeEnvelope] Running Loop=1
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km:B.DepthEnvelope] Running Loop=1
2012-05-10T16:12:50.299Z,1336666370.299 [transit_1km:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-10T16:12:50.301Z,1336666370.301 [transit_1km:SURFACECOMMS] Running Loop=1
2012-05-10T16:12:50.301Z,1336666370.301 [transit_1km:SURFACECOMMS](INFO): Aggregate::initialize transit_1km:SURFACECOMMS
2012-05-10T16:12:50.301Z,1336666370.301 [transit_1km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-10T16:12:50.301Z,1336666370.301 [transit_1km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:12:50.302Z,1336666370.302 [transit_1km:NeedComms] Running Loop=1
2012-05-10T16:12:50.302Z,1336666370.302 [transit_1km:NeedComms](INFO): Aggregate::initialize transit_1km:NeedComms
2012-05-10T16:12:50.302Z,1336666370.302 [transit_1km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-10T16:12:50.305Z,1336666370.305 [transit_1km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_1km:NeedComms:NEEDCOMMS
2012-05-10T16:12:50.310Z,1336666370.310 [transit_1km:SURFACECOMMS:B] Running Loop=1
2012-05-10T16:12:50.310Z,1336666370.310 [transit_1km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_1km:SURFACECOMMS:B
2012-05-10T16:12:50.310Z,1336666370.310 [transit_1km:SURFACECOMMS:B:A] Running Loop=1
2012-05-10T16:12:50.310Z,1336666370.310 [transit_1km:B.DepthEnvelope] Running Loop=1
2012-05-10T16:12:50.316Z,1336666370.316 [transit_1km:A.AltitudeEnvelope] Running Loop=1
2012-05-10T16:12:50.640Z,1336666370.640 [transit_1km:SURFACECOMMS:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T16:12:54.696Z,1336666374.696 [NAL9601](INFO): SBD MO Status=1, MOMSN=6604, MT Status=0, MTMSN=0
2012-05-10T16:12:54.895Z,1336666374.895 [NAL9601](INFO): Sent 297 bytes from file Logs/20120510T160938/shore0001.lzma
2012-05-10T16:12:54.895Z,1336666374.895 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:12:54.896Z,1336666374.896 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-05-10T16:12:58.632Z,1336666378.632 [NAL9601](INFO): SBD MO Status=0, MOMSN=6605, MT Status=0, MTMSN=0
2012-05-10T16:12:59.868Z,1336666379.868 [NAL9601](IMPORTANT): GPS fix at: 1336666494.00
2012-05-10T16:12:59.881Z,1336666379.881 [transit_1km:SURFACECOMMS:B:A] Stopped
2012-05-10T16:12:59.882Z,1336666379.882 [transit_1km:SURFACECOMMS:B:B] Running Loop=1
2012-05-10T16:13:00.244Z,1336666380.244 [transit_1km:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T16:13:20.369Z,1336666400.369 [NAL9601](INFO): SBD MO Status=1, MOMSN=6606, MT Status=0, MTMSN=0
2012-05-10T16:13:20.551Z,1336666400.551 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T160938/shore0002.lzma
2012-05-10T16:13:20.551Z,1336666400.551 [NAL9601](INFO): Packets left to send: 1
2012-05-10T16:13:20.552Z,1336666400.552 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-05-10T16:13:28.976Z,1336666408.976 [NAL9601](INFO): SBD MO Status=1, MOMSN=6607, MT Status=0, MTMSN=0
2012-05-10T16:13:29.139Z,1336666409.139 [NAL9601](INFO): Sent 10 bytes from file Logs/20120510T160938/shore0002.lzma
2012-05-10T16:13:29.139Z,1336666409.139 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:13:29.141Z,1336666409.141 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-05-10T16:13:37.378Z,1336666417.378 [NAL9601](INFO): SBD MO Status=0, MOMSN=6608, MT Status=0, MTMSN=0
2012-05-10T16:13:37.559Z,1336666417.559 [transit_1km:SURFACECOMMS:B:B] Stopped
2012-05-10T16:13:37.559Z,1336666417.559 [transit_1km:SURFACECOMMS:B:C] Running Loop=1
2012-05-10T16:13:37.789Z,1336666417.789 [transit_1km:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T16:13:39.791Z,1336666419.791 [NAL9601](IMPORTANT): GPS fix at: 1336666534.00
2012-05-10T16:13:39.813Z,1336666419.813 [transit_1km:SURFACECOMMS:B:C] Stopped
2012-05-10T16:13:39.813Z,1336666419.813 [transit_1km:SURFACECOMMS:B](INFO): Completed transit_1km:SURFACECOMMS:B
2012-05-10T16:13:39.813Z,1336666419.813 [transit_1km:SURFACECOMMS:B] Stopped
2012-05-10T16:13:39.813Z,1336666419.813 [transit_1km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_1km:SURFACECOMMS:B
2012-05-10T16:13:39.814Z,1336666419.814 [transit_1km:SURFACECOMMS](INFO): Completed transit_1km:SURFACECOMMS
2012-05-10T16:13:39.814Z,1336666419.814 [transit_1km:SURFACECOMMS] Stopped
2012-05-10T16:13:39.819Z,1336666419.819 [transit_1km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_1km:SURFACECOMMS
2012-05-10T16:13:39.819Z,1336666419.819 [transit_1km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-10T16:13:39.819Z,1336666419.819 [transit_1km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T16:13:39.819Z,1336666419.819 [transit_1km:WaypointOne] Running Loop=1
2012-05-10T16:13:39.820Z,1336666419.819 [transit_1km:WaypointOne](INFO): Aggregate::initialize transit_1km:WaypointOne
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:A.Pitch] Running Loop=1
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-05-10T16:13:39.820Z,1336666419.820 [transit_1km:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-05-10T16:13:40.204Z,1336666420.204 [transit_1km:WaypointOne:B.SetSpeed] Running Loop=1
2012-05-10T16:13:40.213Z,1336666420.213 [transit_1km:WaypointOne:A.Pitch] Running Loop=1
2012-05-10T16:13:40.222Z,1336666420.222 [transit_1km:NeedComms:NEEDCOMMS](INFO): Completed transit_1km:NeedComms:NEEDCOMMS
2012-05-10T16:13:40.227Z,1336666420.227 [transit_1km:NeedComms:NEEDCOMMS] Stopped
2012-05-10T16:13:40.227Z,1336666420.227 [transit_1km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_1km:NeedComms:NEEDCOMMS
2012-05-10T16:13:40.227Z,1336666420.227 [transit_1km:NeedComms](INFO): Completed transit_1km:NeedComms
2012-05-10T16:13:40.227Z,1336666420.227 [transit_1km:NeedComms] Stopped
2012-05-10T16:13:40.227Z,1336666420.227 [transit_1km:NeedComms](INFO): Aggregate::uninitialize transit_1km:NeedComms
2012-05-10T16:13:46.004Z,1336666426.004 [NAL9601](INFO): Powering down
2012-05-10T16:14:40.153Z,1336666480.153 [Radio_Freewave](INFO): Powering down
2012-05-10T16:14:57.052Z,1336666497.052 [CTD_NeilBrown](ERROR): Bad response:   0.50
2012-05-10T16:15:09.213Z,1336666509.214 [CTD_NeilBrown](ERROR): Bad response:  .27399
2012-05-10T16:15:21.841Z,1336666521.841 [Radio_Freewave](INFO): Powering up
2012-05-10T16:16:47.552Z,1336666607.552 [CTD_NeilBrown](ERROR): Bad response:  -1.49
2012-05-10T16:17:17.877Z,1336666637.877 [Radio_Freewave](INFO): Powering down
2012-05-10T16:19:44.047Z,1336666784.047 [CTD_NeilBrown](ERROR): Bad response: 7.37086
2012-05-10T16:22:09.275Z,1336666929.275 [CTD_NeilBrown](ERROR): Bad response:   8.21
2012-05-10T16:25:46.911Z,1336667146.911 [CTD_NeilBrown](ERROR): Bad response:   8.41
2012-05-10T16:29:07.599Z,1336667347.599 [CTD_NeilBrown](ERROR): Bad response:   8.37
2012-05-10T16:44:31.863Z,1336668271.863 [CTD_NeilBrown](ERROR): Bad response: .37579
2012-05-10T16:48:39.928Z,1336668519.928 [transit_1km:NeedComms] Running Loop=1
2012-05-10T16:48:39.929Z,1336668519.929 [transit_1km:NeedComms](INFO): Aggregate::initialize transit_1km:NeedComms
2012-05-10T16:48:39.929Z,1336668519.929 [transit_1km:NeedComms:NEEDCOMMS] Running Loop=1
2012-05-10T16:48:39.929Z,1336668519.929 [transit_1km:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_1km:NeedComms:NEEDCOMMS
2012-05-10T16:48:40.319Z,1336668520.319 [transit_1km:SURFACECOMMS] Running Loop=1
2012-05-10T16:48:40.319Z,1336668520.319 [transit_1km:SURFACECOMMS](INFO): Aggregate::initialize transit_1km:SURFACECOMMS
2012-05-10T16:48:40.319Z,1336668520.319 [transit_1km:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-05-10T16:48:40.319Z,1336668520.319 [transit_1km:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:49:36.803Z,1336668576.803 [CTD_NeilBrown](ERROR): Bad response:   5.24
2012-05-10T16:50:39.533Z,1336668639.533 [Radio_Freewave](INFO): Powering up
2012-05-10T16:50:39.544Z,1336668639.544 [transit_1km:SURFACECOMMS:B] Running Loop=1
2012-05-10T16:50:39.544Z,1336668639.544 [transit_1km:SURFACECOMMS:B](INFO): Aggregate::initialize transit_1km:SURFACECOMMS:B
2012-05-10T16:50:39.544Z,1336668639.544 [transit_1km:SURFACECOMMS:B:A] Running Loop=1
2012-05-10T16:50:40.404Z,1336668640.404 [NAL9601](INFO): Powering up
2012-05-10T16:51:46.079Z,1336668706.079 [NAL9601](INFO): NAL9601 initialized
2012-05-10T16:53:36.679Z,1336668816.679 [CTD_NeilBrown](ERROR): Salinity reading out of range: 24.786449 psu
2012-05-10T16:54:35.186Z,1336668875.186 [NAL9601](IMPORTANT): GPS fix at: 1336668994.00
2012-05-10T16:54:35.217Z,1336668875.217 [Navigation](IMPORTANT): Navigation Error 1.0 %DT

2012-05-10T16:54:35.218Z,1336668875.218 [transit_1km:SURFACECOMMS:B:A] Stopped
2012-05-10T16:54:35.223Z,1336668875.223 [transit_1km:SURFACECOMMS:B:B] Running Loop=1
2012-05-10T16:54:48.768Z,1336668888.768 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6609, MT Status=1, MTMSN=2623
2012-05-10T16:54:48.887Z,1336668888.887 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T160938/shore0003.lzma
2012-05-10T16:54:48.887Z,1336668888.887 [NAL9601](INFO): Packets left to send: 3
2012-05-10T16:54:48.888Z,1336668888.888 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-05-10T16:54:49.400Z,1336668889.400 [NAL9601](INFO): Received command:stop
2012-05-10T16:54:49.483Z,1336668889.483 [CommandLine](IMPORTANT): got command stop
2012-05-10T16:54:49.639Z,1336668889.639 [transit_1km] Stopped
2012-05-10T16:54:49.640Z,1336668889.639 [transit_1km](INFO): Aggregate::uninitialize transit_1km
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:A.AltitudeEnvelope] Stopped
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:B.DepthEnvelope] Stopped
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:B.DepthEnvelope](DEBUG): Uninitialize.
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS] Stopped
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS](INFO): Aggregate::uninitialize transit_1km:SURFACECOMMS
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS:A.GoToSurface] Stopped
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS:B] Stopped
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_1km:SURFACECOMMS:B
2012-05-10T16:54:49.640Z,1336668889.640 [transit_1km:SURFACECOMMS:B:B] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:NeedComms] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:NeedComms](INFO): Aggregate::uninitialize transit_1km:NeedComms
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:NeedComms:NEEDCOMMS] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_1km:NeedComms:NEEDCOMMS
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne](INFO): Aggregate::uninitialize transit_1km:WaypointOne
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne:A.Pitch] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne:B.SetSpeed] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne:WaypointW1.Waypoint] Stopped
2012-05-10T16:54:49.641Z,1336668889.641 [transit_1km:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-05-10T16:54:49.996Z,1336668889.996 [MissionManager](IMPORTANT): Started mission Default
2012-05-10T16:54:49.996Z,1336668889.996 [Default] Running Loop=1
2012-05-10T16:54:49.996Z,1336668889.996 [Default](INFO): Aggregate::initialize Default
2012-05-10T16:54:49.996Z,1336668889.996 [Default:D.SetSpeed] Running Loop=1
2012-05-10T16:54:49.996Z,1336668889.996 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-10T16:54:49.996Z,1336668889.996 [Default:E.GoToSurface] Running Loop=1
2012-05-10T16:54:49.996Z,1336668889.996 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium] Running Loop=1
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T16:54:49.997Z,1336668889.997 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:54:49.998Z,1336668889.998 [Default:E.GoToSurface] Running Loop=1
2012-05-10T16:54:50.004Z,1336668890.004 [Default:D.SetSpeed] Running Loop=1
2012-05-10T16:54:50.010Z,1336668890.010 [Default:CallIridium] Running Loop=1
2012-05-10T16:54:50.010Z,1336668890.010 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T16:54:50.010Z,1336668890.010 [Default:CallIridium:A] Running Loop=1
2012-05-10T16:54:50.012Z,1336668890.012 [Default:CallIridium:A] Stopped
2012-05-10T16:54:50.012Z,1336668890.012 [Default:CallIridium:B] Running Loop=1
2012-05-10T16:54:50.012Z,1336668890.012 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T16:54:50.034Z,1336668890.033 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T16:54:50.034Z,1336668890.034 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T16:54:50.034Z,1336668890.034 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T16:54:50.034Z,1336668890.034 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS] Running Loop=1
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T16:54:50.047Z,1336668890.047 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T16:54:50.056Z,1336668890.056 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T16:54:50.056Z,1336668890.056 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T16:54:50.056Z,1336668890.056 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T16:54:50.056Z,1336668890.056 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T16:54:50.383Z,1336668890.383 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T16:54:50.386Z,1336668890.386 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-10T16:54:52.369Z,1336668892.369 [NAL9601](IMPORTANT): GPS fix at: 1336669011.00
2012-05-10T16:54:52.385Z,1336668892.385 [Default:GPS:Read_GPS] Stopped
2012-05-10T16:54:52.385Z,1336668892.385 [Default:GPS:D] Running Loop=1
2012-05-10T16:54:52.435Z,1336668892.435 [CTD_NeilBrown](ERROR): Salinity reading out of range: 0.037480 psu
2012-05-10T16:54:52.595Z,1336668892.595 [CTD_NeilBrown](ERROR): Salinity reading out of range: 62.108551 psu
2012-05-10T16:54:52.596Z,1336668892.596 [CTD_NeilBrown](ERROR): Pressure reading out of range: 758.650024 decibar
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS:D] Stopped
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS] Stopped
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T16:54:52.869Z,1336668892.869 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T16:55:05.564Z,1336668905.564 [NAL9601](INFO): SBD MO Status=1, MOMSN=6610, MT Status=0, MTMSN=0
2012-05-10T16:55:05.759Z,1336668905.759 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T160938/shore0003.lzma
2012-05-10T16:55:05.759Z,1336668905.759 [NAL9601](INFO): Packets left to send: 2
2012-05-10T16:55:05.760Z,1336668905.760 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-05-10T16:55:17.284Z,1336668917.284 [NAL9601](INFO): SBD MO Status=1, MOMSN=6611, MT Status=0, MTMSN=0
2012-05-10T16:55:17.443Z,1336668917.443 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T160938/shore0003.lzma
2012-05-10T16:55:17.443Z,1336668917.443 [NAL9601](INFO): Packets left to send: 1
2012-05-10T16:55:17.444Z,1336668917.444 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-05-10T16:55:23.028Z,1336668923.028 [NAL9601](INFO): SBD MO Status=1, MOMSN=6612, MT Status=0, MTMSN=0
2012-05-10T16:55:23.235Z,1336668923.235 [NAL9601](INFO): Sent 27 bytes from file Logs/20120510T160938/shore0003.lzma
2012-05-10T16:55:23.235Z,1336668923.235 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:55:23.236Z,1336668923.236 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-05-10T16:55:32.736Z,1336668932.736 [NAL9601](INFO): SBD MO Status=1, MOMSN=6613, MT Status=0, MTMSN=0
2012-05-10T16:55:32.919Z,1336668932.919 [NAL9601](INFO): Sent 265 bytes from file Logs/20120510T160938/shore0004.lzma
2012-05-10T16:55:32.919Z,1336668932.919 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:55:32.920Z,1336668932.920 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-05-10T16:55:39.937Z,1336668939.937 [NAL9601](INFO): SBD MO Status=0, MOMSN=6614, MT Status=0, MTMSN=0
2012-05-10T16:55:50.823Z,1336668950.823 [NAL9601](INFO): SBD MO Status=1, MOMSN=6615, MT Status=0, MTMSN=0
2012-05-10T16:55:50.991Z,1336668950.991 [NAL9601](INFO): Sent 115 bytes from file Logs/20120510T160938/shore0005.lzma
2012-05-10T16:55:50.991Z,1336668950.991 [NAL9601](INFO): Packets left to send: 0
2012-05-10T16:55:50.992Z,1336668950.992 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-05-10T16:55:57.248Z,1336668957.248 [NAL9601](INFO): SBD MO Status=0, MOMSN=6616, MT Status=0, MTMSN=0
2012-05-10T16:55:57.406Z,1336668957.406 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T16:55:57.411Z,1336668957.411 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T16:55:57.411Z,1336668957.411 [Default:Iridium] Stopped
2012-05-10T16:55:57.411Z,1336668957.411 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T16:55:57.411Z,1336668957.411 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T16:55:57.411Z,1336668957.411 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T16:55:57.412Z,1336668957.411 [Default:F.Wait] Running Loop=1
2012-05-10T16:55:57.412Z,1336668957.412 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium:B] Stopped
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium] Stopped
2012-05-10T16:55:57.708Z,1336668957.708 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T16:56:08.008Z,1336668968.008 [NAL9601](INFO): Powering down
2012-05-10T17:00:57.822Z,1336669257.822 [Default:CallIridium] Running Loop=1
2012-05-10T17:00:57.822Z,1336669257.822 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T17:00:57.823Z,1336669257.823 [Default:CallIridium:A] Running Loop=1
2012-05-10T17:00:57.823Z,1336669257.823 [Default:CallIridium:A] Stopped
2012-05-10T17:00:57.823Z,1336669257.823 [Default:CallIridium:B] Running Loop=1
2012-05-10T17:00:57.823Z,1336669257.823 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T17:01:02.860Z,1336669262.860 [Default:Iridium] Running Loop=1
2012-05-10T17:01:02.860Z,1336669262.861 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T17:01:02.861Z,1336669262.861 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T17:01:02.861Z,1336669262.861 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T17:01:02.861Z,1336669262.861 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T17:01:02.861Z,1336669262.861 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T17:01:02.862Z,1336669262.862 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T17:01:02.862Z,1336669262.862 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T17:01:02.862Z,1336669262.862 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS] Running Loop=1
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T17:01:02.863Z,1336669262.863 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T17:01:02.864Z,1336669262.864 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T17:01:02.864Z,1336669262.864 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T17:01:02.864Z,1336669262.865 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T17:01:03.566Z,1336669263.566 [NAL9601](INFO): Powering up
2012-05-10T17:02:09.291Z,1336669329.291 [NAL9601](INFO): NAL9601 initialized
2012-05-10T17:02:25.624Z,1336669345.624 [NAL9601](INFO): SBD MO Status=1, MOMSN=6617, MT Status=0, MTMSN=0
2012-05-10T17:02:25.755Z,1336669345.755 [NAL9601](INFO): Sent 114 bytes from file Logs/20120510T160938/shore0006.lzma
2012-05-10T17:02:25.755Z,1336669345.755 [NAL9601](INFO): Packets left to send: 0
2012-05-10T17:02:25.756Z,1336669345.756 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-05-10T17:02:34.428Z,1336669354.428 [NAL9601](INFO): SBD MO Status=0, MOMSN=6618, MT Status=0, MTMSN=0
2012-05-10T17:02:34.653Z,1336669354.653 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T17:02:34.654Z,1336669354.654 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T17:02:34.654Z,1336669354.654 [Default:Iridium] Stopped
2012-05-10T17:02:34.654Z,1336669354.654 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T17:02:34.654Z,1336669354.654 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T17:02:34.654Z,1336669354.654 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T17:02:34.844Z,1336669354.844 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T17:02:34.845Z,1336669354.845 [Default:CallIridium:B] Stopped
2012-05-10T17:02:34.845Z,1336669354.845 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T17:02:34.845Z,1336669354.845 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T17:02:34.845Z,1336669354.845 [Default:CallIridium] Stopped
2012-05-10T17:02:34.845Z,1336669354.845 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T17:04:35.802Z,1336669475.802 [NAL9601](IMPORTANT): GPS fix at: 1336669595.00
2012-05-10T17:04:35.820Z,1336669475.820 [Default:GPS:Read_GPS] Stopped
2012-05-10T17:04:35.820Z,1336669475.820 [Default:GPS:D] Running Loop=1
2012-05-10T17:04:36.214Z,1336669476.214 [Default:GPS:D] Stopped
2012-05-10T17:04:36.215Z,1336669476.215 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T17:04:36.215Z,1336669476.215 [Default:GPS] Stopped
2012-05-10T17:04:36.215Z,1336669476.216 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T17:04:36.216Z,1336669476.216 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T17:04:36.216Z,1336669476.216 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T17:04:51.757Z,1336669491.757 [NAL9601](INFO): Powering down
2012-05-10T17:07:36.742Z,1336669656.742 [Default:CallIridium] Running Loop=1
2012-05-10T17:07:36.742Z,1336669656.742 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T17:07:36.743Z,1336669656.743 [Default:CallIridium:A] Running Loop=1
2012-05-10T17:07:36.743Z,1336669656.743 [Default:CallIridium:A] Stopped
2012-05-10T17:07:36.743Z,1336669656.743 [Default:CallIridium:B] Running Loop=1
2012-05-10T17:07:36.743Z,1336669656.743 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T17:07:41.796Z,1336669661.796 [Default:Iridium] Running Loop=1
2012-05-10T17:07:41.796Z,1336669661.796 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T17:07:41.796Z,1336669661.796 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T17:07:41.796Z,1336669661.796 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T17:07:41.796Z,1336669661.796 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T17:07:41.797Z,1336669661.796 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T17:07:41.798Z,1336669661.797 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T17:07:41.798Z,1336669661.797 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T17:07:41.798Z,1336669661.798 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T17:07:41.798Z,1336669661.798 [Default:GPS] Running Loop=1
2012-05-10T17:07:41.798Z,1336669661.798 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T17:07:41.799Z,1336669661.799 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T17:07:41.799Z,1336669661.799 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T17:07:41.799Z,1336669661.799 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T17:07:41.799Z,1336669661.799 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T17:07:41.800Z,1336669661.800 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T17:07:41.800Z,1336669661.800 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T17:07:41.800Z,1336669661.800 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T17:07:42.418Z,1336669662.418 [NAL9601](INFO): Powering up
2012-05-10T17:08:48.075Z,1336669728.075 [NAL9601](INFO): NAL9601 initialized
2012-05-10T17:09:07.520Z,1336669747.520 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6619, MT Status=1, MTMSN=2624
2012-05-10T17:09:07.735Z,1336669747.735 [NAL9601](INFO): Sent 205 bytes from file Logs/20120510T160938/shore0007.lzma
2012-05-10T17:09:07.735Z,1336669747.735 [NAL9601](INFO): Packets left to send: 0
2012-05-10T17:09:07.736Z,1336669747.736 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-05-10T17:09:08.148Z,1336669748.148 [NAL9601](INFO): Received command:Restart logs
2012-05-10T17:09:08.211Z,1336669748.211 [CommandLine](IMPORTANT): got command restart logs