2012-05-10T03:18:12.402Z,1336619892.402 [Supervisor](DEBUG): Initializing supervisor.
2012-05-10T03:18:12.405Z,1336619892.405 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-05-10T03:18:12.405Z,1336619892.405 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-05-10T03:18:12.407Z,1336619892.407 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-05-10T03:18:12.407Z,1336619892.407 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-05-10T03:18:12.417Z,1336619892.418 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-05-10T03:18:12.419Z,1336619892.418 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-05-10T03:18:12.419Z,1336619892.419 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-05-10T03:18:12.420Z,1336619892.420 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-05-10T03:18:12.421Z,1336619892.421 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-05-10T03:18:12.688Z,1336619892.688 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-05-10T03:18:12.688Z,1336619892.688 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-05-10T03:18:12.868Z,1336619892.868 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-05-10T03:18:12.869Z,1336619892.869 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-05-10T03:18:12.954Z,1336619892.954 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-05-10T03:18:12.954Z,1336619892.954 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-05-10T03:18:13.138Z,1336619893.138 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-05-10T03:18:13.139Z,1336619893.139 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-05-10T03:18:13.263Z,1336619893.263 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-05-10T03:18:13.264Z,1336619893.264 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-05-10T03:18:13.477Z,1336619893.477 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-05-10T03:18:13.477Z,1336619893.477 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-05-10T03:18:13.623Z,1336619893.623 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-05-10T03:18:13.624Z,1336619893.624 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-05-10T03:18:13.833Z,1336619893.833 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-05-10T03:18:13.834Z,1336619893.833 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-05-10T03:18:13.931Z,1336619893.931 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-05-10T03:18:13.931Z,1336619893.931 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-05-10T03:18:14.312Z,1336619894.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-05-10T03:18:14.313Z,1336619894.313 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-05-10T03:18:14.423Z,1336619894.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-05-10T03:18:14.424Z,1336619894.424 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-05-10T03:18:14.510Z,1336619894.510 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-05-10T03:18:14.511Z,1336619894.511 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-05-10T03:18:14.613Z,1336619894.613 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-05-10T03:18:14.739Z,1336619894.739 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-05-10T03:18:14.839Z,1336619894.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-05-10T03:18:14.935Z,1336619894.935 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-05-10T03:18:15.046Z,1336619895.046 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-05-10T03:18:15.137Z,1336619895.137 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-05-10T03:18:15.224Z,1336619895.224 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-05-10T03:18:15.339Z,1336619895.339 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-05-10T03:18:15.462Z,1336619895.462 [InternalSim] Loaded
2012-05-10T03:18:15.462Z,1336619895.462 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-05-10T03:18:15.463Z,1336619895.463 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-05-10T03:18:15.463Z,1336619895.463 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-05-10T03:18:15.504Z,1336619895.504 [SBIT](DEBUG): Construct Startup Built In Test.
2012-05-10T03:18:15.515Z,1336619895.515 [SBIT] Loaded
2012-05-10T03:18:15.515Z,1336619895.515 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-05-10T03:18:15.516Z,1336619895.516 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-05-10T03:18:15.539Z,1336619895.539 [IBIT] Loaded
2012-05-10T03:18:15.540Z,1336619895.540 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-05-10T03:18:15.547Z,1336619895.547 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-05-10T03:18:15.656Z,1336619895.656 [CBIT] Loaded
2012-05-10T03:18:15.656Z,1336619895.656 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-05-10T03:18:15.657Z,1336619895.657 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-05-10T03:18:15.657Z,1336619895.657 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-05-10T03:18:15.785Z,1336619895.785 [BuoyancyServo] Loaded
2012-05-10T03:18:15.785Z,1336619895.785 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-05-10T03:18:15.792Z,1336619895.792 [ElevatorServo] Loaded
2012-05-10T03:18:15.792Z,1336619895.792 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-05-10T03:18:15.798Z,1336619895.798 [MassServo] Loaded
2012-05-10T03:18:15.799Z,1336619895.799 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-05-10T03:18:15.807Z,1336619895.807 [RudderServo] Loaded
2012-05-10T03:18:15.807Z,1336619895.807 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-05-10T03:18:15.813Z,1336619895.813 [ThrusterServo] Loaded
2012-05-10T03:18:15.814Z,1336619895.814 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-05-10T03:18:15.814Z,1336619895.814 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-05-10T03:18:15.815Z,1336619895.815 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-05-10T03:18:15.829Z,1336619895.829 [DepthRateCalculator] Loaded
2012-05-10T03:18:15.830Z,1336619895.829 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-05-10T03:18:15.845Z,1336619895.845 [NavChart] Loaded
2012-05-10T03:18:15.845Z,1336619895.845 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-05-10T03:18:15.850Z,1336619895.850 [PitchRateCalculator] Loaded
2012-05-10T03:18:15.851Z,1336619895.851 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-05-10T03:18:15.856Z,1336619895.856 [SpeedCalculator] Loaded
2012-05-10T03:18:15.856Z,1336619895.856 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-05-10T03:18:15.870Z,1336619895.870 [TempGradientCalculator] Loaded
2012-05-10T03:18:15.871Z,1336619895.871 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-05-10T03:18:15.876Z,1336619895.876 [YawRateCalculator] Loaded
2012-05-10T03:18:15.877Z,1336619895.876 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-05-10T03:18:15.906Z,1336619895.906 [Navigation] Loaded
2012-05-10T03:18:15.906Z,1336619895.906 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-05-10T03:18:15.906Z,1336619895.907 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-05-10T03:18:15.907Z,1336619895.907 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-05-10T03:18:16.112Z,1336619896.112 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-05-10T03:18:16.112Z,1336619896.112 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-05-10T03:18:16.132Z,1336619896.132 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-05-10T03:18:16.132Z,1336619896.132 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-05-10T03:18:16.168Z,1336619896.168 [VerticalControl](DEBUG): Construct VerticalControl.
2012-05-10T03:18:16.211Z,1336619896.211 [VerticalControl] Loaded
2012-05-10T03:18:16.211Z,1336619896.211 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-05-10T03:18:16.212Z,1336619896.212 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-05-10T03:18:16.232Z,1336619896.232 [HorizontalControl] Loaded
2012-05-10T03:18:16.232Z,1336619896.232 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-05-10T03:18:16.233Z,1336619896.233 [SpeedControl](DEBUG): Construct SpeedControl.
2012-05-10T03:18:16.235Z,1336619896.235 [SpeedControl] Loaded
2012-05-10T03:18:16.235Z,1336619896.235 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-05-10T03:18:16.236Z,1336619896.236 [LoopControl](DEBUG): Construct LoopControl.
2012-05-10T03:18:16.236Z,1336619896.236 [LoopControl] Loaded
2012-05-10T03:18:16.236Z,1336619896.237 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-05-10T03:18:16.237Z,1336619896.237 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-05-10T03:18:16.238Z,1336619896.238 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-05-10T03:18:16.243Z,1336619896.243 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-05-10T03:18:16.247Z,1336619896.247 [AsyncPiEstimator] Loaded
2012-05-10T03:18:16.248Z,1336619896.248 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-05-10T03:18:16.249Z,1336619896.249 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078994144
2012-05-10T03:18:16.249Z,1336619896.249 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-05-10T03:18:16.250Z,1336619896.250 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-05-10T03:18:16.341Z,1336619896.341 [AHRS_sp3003D] Loaded
2012-05-10T03:18:16.342Z,1336619896.342 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-05-10T03:18:16.582Z,1336619896.582 [Batt_Ocean_Server] Loaded
2012-05-10T03:18:16.582Z,1336619896.582 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-05-10T03:18:16.588Z,1336619896.588 [DropWeight] Loaded
2012-05-10T03:18:16.588Z,1336619896.588 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-05-10T03:18:16.676Z,1336619896.676 [DVL_micro] Loaded
2012-05-10T03:18:16.676Z,1336619896.676 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-05-10T03:18:16.752Z,1336619896.752 [NAL9601] Loaded
2012-05-10T03:18:16.753Z,1336619896.753 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-05-10T03:18:16.800Z,1336619896.800 [Onboard] Loaded
2012-05-10T03:18:16.801Z,1336619896.801 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-05-10T03:18:16.809Z,1336619896.809 [Radio_Freewave] Loaded
2012-05-10T03:18:16.809Z,1336619896.809 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-05-10T03:18:16.810Z,1336619896.810 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-05-10T03:18:16.811Z,1336619896.810 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-05-10T03:18:16.854Z,1336619896.854 [CTD_NeilBrown] Loaded
2012-05-10T03:18:16.854Z,1336619896.854 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-05-10T03:18:16.855Z,1336619896.855 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079645408
2012-05-10T03:18:16.885Z,1336619896.885 [WetLabsBB2FL] Loaded
2012-05-10T03:18:16.885Z,1336619896.885 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-05-10T03:18:16.885Z,1336619896.885 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-05-10T03:18:16.887Z,1336619896.888 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-05-10T03:18:16.888Z,1336619896.888 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-05-10T03:18:16.889Z,1336619896.889 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-05-10T03:18:16.894Z,1336619896.894 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-05-10T03:18:16.895Z,1336619896.895 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079842016
2012-05-10T03:18:16.896Z,1336619896.896 [Supervisor](DEBUG): Running supervisor.
2012-05-10T03:18:16.899Z,1336619896.899 [controlThread](DEBUG): Initializing ControlThread
2012-05-10T03:18:16.900Z,1336619896.900 [InternalSim](DEBUG):  InternalSim initializing...
2012-05-10T03:18:16.927Z,1336619896.927 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-05-10T03:18:16.943Z,1336619896.943 [SBIT](INFO): Initialize SBIT Component.
2012-05-10T03:18:16.944Z,1336619896.944 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9636 $
2012-05-10T03:18:16.945Z,1336619896.945 [IBIT](INFO): Initialize IBIT Component.
2012-05-10T03:18:16.949Z,1336619896.949 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-05-10T03:18:16.951Z,1336619896.951 [CBIT](DEBUG): Initialize CBIT Component.
2012-05-10T03:18:16.951Z,1336619896.951 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-05-10T03:18:16.976Z,1336619896.976 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-10T03:18:16.976Z,1336619896.976 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-05-10T03:18:16.976Z,1336619896.977 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-05-10T03:18:16.977Z,1336619896.977 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-05-10T03:18:16.978Z,1336619896.977 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-05-10T03:18:16.979Z,1336619896.979 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-05-10T03:18:16.979Z,1336619896.979 [Navigation](DEBUG): Initializing Navigation.
2012-05-10T03:18:16.980Z,1336619896.980 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-05-10T03:18:16.982Z,1336619896.982 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-05-10T03:18:16.983Z,1336619896.983 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-05-10T03:18:16.983Z,1336619896.983 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-05-10T03:18:17.067Z,1336619897.067 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-05-10T03:18:17.072Z,1336619897.072 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-05-10T03:18:17.076Z,1336619897.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-05-10T03:18:17.081Z,1336619897.081 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-05-10T03:18:17.085Z,1336619897.085 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-05-10T03:18:17.085Z,1336619897.085 [NavChartDb](INFO): Creating index for Soundings
2012-05-10T03:18:17.089Z,1336619897.089 [NavChartDb](INFO): Creating index for Contour 0p0
2012-05-10T03:18:17.091Z,1336619897.091 [NavChartDb](INFO): Creating index for Contour 1p8
2012-05-10T03:18:17.093Z,1336619897.093 [NavChartDb](INFO): Creating index for Contour 3p6
2012-05-10T03:18:17.096Z,1336619897.096 [NavChartDb](INFO): Creating index for Contour 5p4
2012-05-10T03:18:17.097Z,1336619897.098 [NavChartDb](INFO): Creating index for Contour 9p1
2012-05-10T03:18:17.100Z,1336619897.100 [NavChartDb](INFO): Creating index for Contour 10p9
2012-05-10T03:18:17.102Z,1336619897.102 [NavChartDb](INFO): Creating index for Contour 18p2
2012-05-10T03:18:17.104Z,1336619897.104 [NavChartDb](INFO): Creating index for Contour 36p5
2012-05-10T03:18:17.106Z,1336619897.106 [NavChartDb](INFO): Creating index for Contour 54p8
2012-05-10T03:18:17.108Z,1336619897.108 [NavChartDb](INFO): Creating index for Contour 73p1
2012-05-10T03:18:17.110Z,1336619897.110 [NavChartDb](INFO): Creating index for Contour 91p4
2012-05-10T03:18:17.112Z,1336619897.112 [NavChartDb](INFO): Creating index for Contour 182p8
2012-05-10T03:18:17.114Z,1336619897.114 [NavChartDb](INFO): Creating index for Contour 365p7
2012-05-10T03:18:17.116Z,1336619897.116 [NavChartDb](INFO): Creating index for Contour 548p6
2012-05-10T03:18:17.118Z,1336619897.118 [NavChartDb](INFO): Creating index for Contour 731p5
2012-05-10T03:18:17.120Z,1336619897.120 [NavChartDb](INFO): Creating index for Contour 914p4
2012-05-10T03:18:17.122Z,1336619897.122 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-05-10T03:18:17.124Z,1336619897.124 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-05-10T03:18:17.126Z,1336619897.126 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-05-10T03:18:17.128Z,1336619897.128 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-05-10T03:18:17.130Z,1336619897.130 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-05-10T03:18:17.132Z,1336619897.132 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-05-10T03:18:17.134Z,1336619897.134 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-05-10T03:18:17.136Z,1336619897.136 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-05-10T03:18:17.138Z,1336619897.138 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-05-10T03:18:17.140Z,1336619897.140 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-05-10T03:18:17.142Z,1336619897.142 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-05-10T03:18:17.144Z,1336619897.144 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-05-10T03:18:17.147Z,1336619897.147 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-05-10T03:18:17.148Z,1336619897.148 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-05-10T03:18:17.151Z,1336619897.151 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-05-10T03:18:18.363Z,1336619898.363 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2012-05-10T03:18:18.363Z,1336619898.363 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2012-05-10T03:18:18.363Z,1336619898.363 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2012-05-10T03:18:18.363Z,1336619898.363 [Batt_Ocean_Server](ERROR): Communications Fault
2012-05-10T03:18:18.366Z,1336619898.366 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-05-10T03:18:18.378Z,1336619898.378 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T03:18:18.387Z,1336619898.388 [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-10T03:18:18.388Z,1336619898.388 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-05-10T03:18:18.417Z,1336619898.417 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-05-10T03:18:18.419Z,1336619898.419 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-05-10T03:18:18.422Z,1336619898.422 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T03:18:18.430Z,1336619898.430 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-05-10T03:18:18.435Z,1336619898.435 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T03:18:18.441Z,1336619898.441 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-05-10T03:18:18.450Z,1336619898.450 [Default:D.SetSpeed](DEBUG): Construct.
2012-05-10T03:18:18.453Z,1336619898.453 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T03:18:18.458Z,1336619898.457 [Default:F.Wait](DEBUG): Construct Wait.
2012-05-10T03:18:18.461Z,1336619898.461 [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-10T03:18:18.466Z,1336619898.466 [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-10T03:18:18.486Z,1336619898.486 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-10T03:18:18.507Z,1336619898.507 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-10T03:18:18.527Z,1336619898.527 [Radio_Freewave](INFO): Powering up
2012-05-10T03:18:18.533Z,1336619898.533 [WetLabsBB2FL](INFO): Powering down
2012-05-10T03:18:18.606Z,1336619898.606 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:18:18.607Z,1336619898.607 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-05-10T03:18:18.616Z,1336619898.616 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:18:18.617Z,1336619898.617 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-05-10T03:18:18.625Z,1336619898.625 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:18:18.626Z,1336619898.626 [MassServo](DEBUG): Initializing MassServo.
2012-05-10T03:18:18.633Z,1336619898.633 [RudderServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:18:18.634Z,1336619898.634 [RudderServo](DEBUG): Initializing RudderServo.
2012-05-10T03:18:18.642Z,1336619898.642 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:18:18.643Z,1336619898.643 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-10T03:18:18.662Z,1336619898.662 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2012-05-10T03:18:18.662Z,1336619898.662 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2012-05-10T03:18:18.662Z,1336619898.662 [Batt_Ocean_Server] No Fault, FailCount= 1
2012-05-10T03:18:22.423Z,1336619902.423 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-05-10T03:18:22.426Z,1336619902.426 [NAL9601](INFO): Powering up NAL9601
2012-05-10T03:18:32.757Z,1336619912.757 [SBIT](IMPORTANT): Beginning Startup BIT
2012-05-10T03:18:32.759Z,1336619912.759 [CBIT](IMPORTANT): Beginning GF scan
2012-05-10T03:18:58.848Z,1336619938.848 [CBIT](IMPORTANT): No ground fault detected
2012-05-10T03:19:14.771Z,1336619954.771 [SBIT](IMPORTANT): SBIT PASSED
2012-05-10T03:19:15.146Z,1336619955.146 [MissionManager](IMPORTANT): Started mission Startup
2012-05-10T03:19:15.146Z,1336619955.146 [Startup] Running Loop=1
2012-05-10T03:19:15.146Z,1336619955.146 [Startup](INFO): Aggregate::initialize Startup
2012-05-10T03:19:15.146Z,1336619955.146 [Startup:A.GoToSurface] Running Loop=1
2012-05-10T03:19:15.146Z,1336619955.146 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:19:17.060Z,1336619957.060 [Startup:StartupSatComms] Running Loop=1
2012-05-10T03:19:17.060Z,1336619957.060 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-05-10T03:19:17.060Z,1336619957.060 [Startup:StartupSatComms:A] Running Loop=1
2012-05-10T03:19:17.504Z,1336619957.504 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-10T03:19:21.493Z,1336619961.493 [Radio_Freewave](INFO): Powering down
2012-05-10T03:19:21.897Z,1336619961.898 [Radio_Freewave](INFO): Powering up
2012-05-10T03:19:28.003Z,1336619968.003 [NAL9601](INFO): NAL9601 initialized
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:A](INFO): Timed out from 2012-05-10T03:19:17.1Z
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:A] Stopped
2012-05-10T03:20:17.097Z,1336620017.097 [Startup:StartupSatComms:B] Running Loop=1
2012-05-10T03:20:17.499Z,1336620017.499 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T03:20:32.976Z,1336620032.976 [NAL9601](INFO): SBD MO Status=1, MOMSN=6371, MT Status=0, MTMSN=0
2012-05-10T03:20:33.187Z,1336620033.187 [NAL9601](INFO): Sent 201 bytes from file Logs/20120510T021825/shore0013.lzma
2012-05-10T03:20:33.187Z,1336620033.187 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:20:33.188Z,1336620033.188 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-05-10T03:20:40.692Z,1336620040.692 [NAL9601](INFO): SBD MO Status=1, MOMSN=6372, MT Status=0, MTMSN=0
2012-05-10T03:20:40.879Z,1336620040.879 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0000.lzma
2012-05-10T03:20:40.879Z,1336620040.879 [NAL9601](INFO): Packets left to send: 1
2012-05-10T03:20:40.880Z,1336620040.880 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-05-10T03:20:49.636Z,1336620049.636 [NAL9601](INFO): SBD MO Status=1, MOMSN=6373, MT Status=0, MTMSN=0
2012-05-10T03:20:49.763Z,1336620049.763 [NAL9601](INFO): Sent 139 bytes from file Logs/20120510T031812/shore0000.lzma
2012-05-10T03:20:49.763Z,1336620049.763 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:20:50.515Z,1336620050.515 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-05-10T03:20:57.419Z,1336620057.420 [NAL9601](INFO): SBD MO Status=0, MOMSN=6374, MT Status=0, MTMSN=0
2012-05-10T03:20:57.563Z,1336620057.563 [Startup:StartupSatComms:B] Stopped
2012-05-10T03:20:57.563Z,1336620057.563 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-05-10T03:20:57.563Z,1336620057.563 [Startup:StartupSatComms] Stopped
2012-05-10T03:20:57.564Z,1336620057.564 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-05-10T03:20:57.564Z,1336620057.564 [Startup](INFO): Completed Startup
2012-05-10T03:20:57.564Z,1336620057.565 [Startup] Stopped
2012-05-10T03:20:57.565Z,1336620057.565 [Startup](INFO): Aggregate::uninitialize Startup
2012-05-10T03:20:57.565Z,1336620057.565 [Startup:A.GoToSurface] Stopped
2012-05-10T03:20:57.565Z,1336620057.565 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:20:57.825Z,1336620057.825 [MissionManager](IMPORTANT): Started mission Default
2012-05-10T03:20:57.825Z,1336620057.825 [Default] Running Loop=1
2012-05-10T03:20:57.825Z,1336620057.825 [Default](INFO): Aggregate::initialize Default
2012-05-10T03:20:57.825Z,1336620057.825 [Default:D.SetSpeed] Running Loop=1
2012-05-10T03:20:57.825Z,1336620057.825 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-10T03:20:57.825Z,1336620057.825 [Default:E.GoToSurface] Running Loop=1
2012-05-10T03:20:57.825Z,1336620057.825 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:20:57.826Z,1336620057.826 [Default:Iridium] Running Loop=1
2012-05-10T03:20:57.826Z,1336620057.826 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T03:20:57.826Z,1336620057.826 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T03:20:57.826Z,1336620057.826 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:20:57.827Z,1336620057.827 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T03:20:57.827Z,1336620057.827 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:20:57.827Z,1336620057.827 [Default:E.GoToSurface] Running Loop=1
2012-05-10T03:20:57.833Z,1336620057.833 [Default:D.SetSpeed] Running Loop=1
2012-05-10T03:20:57.844Z,1336620057.844 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T03:20:57.844Z,1336620057.844 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:20:57.844Z,1336620057.844 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T03:20:57.844Z,1336620057.844 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T03:20:57.849Z,1336620057.849 [Default:GPS] Running Loop=1
2012-05-10T03:20:57.849Z,1336620057.849 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T03:20:57.849Z,1336620057.849 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T03:20:57.850Z,1336620057.849 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:20:57.850Z,1336620057.850 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T03:20:57.850Z,1336620057.850 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:20:57.855Z,1336620057.855 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T03:20:57.855Z,1336620057.855 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:20:57.856Z,1336620057.856 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T03:20:57.856Z,1336620057.856 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T03:20:58.228Z,1336620058.227 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T03:20:58.230Z,1336620058.230 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-10T03:20:59.763Z,1336620059.763 [CTD_NeilBrown](ERROR): Bad response: 
-357.10
2012-05-10T03:21:08.139Z,1336620068.139 [NAL9601](INFO): SBD MO Status=1, MOMSN=6375, MT Status=0, MTMSN=0
2012-05-10T03:21:08.335Z,1336620068.335 [NAL9601](INFO): Sent 95 bytes from file Logs/20120510T031812/shore0001.lzma
2012-05-10T03:21:08.335Z,1336620068.335 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:21:08.336Z,1336620068.336 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-05-10T03:21:11.340Z,1336620071.339 [NAL9601](INFO): SBD MO Status=0, MOMSN=6376, MT Status=0, MTMSN=0
2012-05-10T03:21:11.540Z,1336620071.540 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T03:21:11.541Z,1336620071.541 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T03:21:11.541Z,1336620071.541 [Default:Iridium] Stopped
2012-05-10T03:21:11.541Z,1336620071.541 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T03:21:11.541Z,1336620071.541 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T03:21:11.541Z,1336620071.541 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:21:11.541Z,1336620071.541 [Default:F.Wait] Running Loop=1
2012-05-10T03:21:11.541Z,1336620071.541 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-10T03:22:29.376Z,1336620149.376 [CTD_NeilBrown](ERROR): Bad response: 7
2012-05-10T03:22:52.557Z,1336620172.557 [NAL9601](IMPORTANT): GPS fix at: 1336620215.00
2012-05-10T03:22:52.571Z,1336620172.571 [Default:GPS:Read_GPS] Stopped
2012-05-10T03:22:52.571Z,1336620172.571 [Default:GPS:D] Running Loop=1
2012-05-10T03:22:52.966Z,1336620172.967 [Default:GPS:D] Stopped
2012-05-10T03:22:52.967Z,1336620172.967 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T03:22:52.967Z,1336620172.967 [Default:GPS] Stopped
2012-05-10T03:22:52.967Z,1336620172.967 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T03:22:52.967Z,1336620172.967 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T03:22:52.967Z,1336620172.967 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:23:08.684Z,1336620188.684 [NAL9601](INFO): Powering down
2012-05-10T03:26:13.550Z,1336620373.550 [Default:CallIridium] Running Loop=1
2012-05-10T03:26:13.551Z,1336620373.551 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T03:26:13.551Z,1336620373.551 [Default:CallIridium:A] Running Loop=1
2012-05-10T03:26:13.553Z,1336620373.553 [Default:CallIridium:A] Stopped
2012-05-10T03:26:13.553Z,1336620373.553 [Default:CallIridium:B] Running Loop=1
2012-05-10T03:26:13.553Z,1336620373.553 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T03:26:18.535Z,1336620378.534 [Default:Iridium] Running Loop=1
2012-05-10T03:26:18.535Z,1336620378.535 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T03:26:18.535Z,1336620378.535 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T03:26:18.535Z,1336620378.535 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:26:18.535Z,1336620378.535 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T03:26:18.535Z,1336620378.535 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:26:18.536Z,1336620378.536 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T03:26:18.536Z,1336620378.536 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:26:18.536Z,1336620378.536 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS] Running Loop=1
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T03:26:18.537Z,1336620378.537 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:26:18.538Z,1336620378.538 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T03:26:18.539Z,1336620378.539 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:26:18.539Z,1336620378.539 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T03:26:19.142Z,1336620379.142 [NAL9601](INFO): Powering up
2012-05-10T03:27:24.867Z,1336620444.867 [NAL9601](INFO): NAL9601 initialized
2012-05-10T03:27:43.530Z,1336620463.530 [NAL9601](INFO): SBD MO Status=1, MOMSN=6377, MT Status=0, MTMSN=0
2012-05-10T03:27:43.727Z,1336620463.727 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0002.lzma
2012-05-10T03:27:43.727Z,1336620463.727 [NAL9601](INFO): Packets left to send: 1
2012-05-10T03:27:43.729Z,1336620463.729 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-05-10T03:27:51.261Z,1336620471.261 [NAL9601](INFO): SBD MO Status=1, MOMSN=6378, MT Status=0, MTMSN=0
2012-05-10T03:27:51.415Z,1336620471.415 [NAL9601](INFO): Sent 128 bytes from file Logs/20120510T031812/shore0002.lzma
2012-05-10T03:27:51.415Z,1336620471.415 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:27:51.416Z,1336620471.416 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-05-10T03:27:56.060Z,1336620476.060 [NAL9601](INFO): SBD MO Status=0, MOMSN=6379, MT Status=0, MTMSN=0
2012-05-10T03:27:56.221Z,1336620476.221 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T03:27:56.222Z,1336620476.222 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T03:27:56.222Z,1336620476.222 [Default:Iridium] Stopped
2012-05-10T03:27:56.222Z,1336620476.222 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T03:27:56.222Z,1336620476.222 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T03:27:56.222Z,1336620476.223 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:27:56.499Z,1336620476.499 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T03:27:56.499Z,1336620476.499 [Default:CallIridium:B] Stopped
2012-05-10T03:27:56.499Z,1336620476.499 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T03:27:56.500Z,1336620476.500 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T03:27:56.500Z,1336620476.500 [Default:CallIridium] Stopped
2012-05-10T03:27:56.500Z,1336620476.500 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T03:28:15.285Z,1336620495.284 [NAL9601](IMPORTANT): GPS fix at: 1336620539.00
2012-05-10T03:28:15.318Z,1336620495.318 [Default:GPS:Read_GPS] Stopped
2012-05-10T03:28:15.318Z,1336620495.318 [Default:GPS:D] Running Loop=1
2012-05-10T03:28:15.677Z,1336620495.677 [Default:GPS:D] Stopped
2012-05-10T03:28:15.678Z,1336620495.678 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T03:28:15.678Z,1336620495.678 [Default:GPS] Stopped
2012-05-10T03:28:15.678Z,1336620495.678 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T03:28:15.678Z,1336620495.678 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T03:28:15.678Z,1336620495.678 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:28:31.307Z,1336620511.307 [NAL9601](INFO): Powering down
2012-05-10T03:32:56.213Z,1336620776.213 [Default:CallIridium] Running Loop=1
2012-05-10T03:32:56.213Z,1336620776.213 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T03:32:56.213Z,1336620776.214 [Default:CallIridium:A] Running Loop=1
2012-05-10T03:32:56.214Z,1336620776.214 [Default:CallIridium:A] Stopped
2012-05-10T03:32:56.214Z,1336620776.214 [Default:CallIridium:B] Running Loop=1
2012-05-10T03:32:56.214Z,1336620776.214 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium] Running Loop=1
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T03:33:01.268Z,1336620781.268 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:33:01.269Z,1336620781.269 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T03:33:01.269Z,1336620781.270 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:33:01.270Z,1336620781.270 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T03:33:01.270Z,1336620781.270 [Default:GPS] Running Loop=1
2012-05-10T03:33:01.271Z,1336620781.271 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T03:33:01.271Z,1336620781.271 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T03:33:01.271Z,1336620781.271 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:33:01.271Z,1336620781.271 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T03:33:01.271Z,1336620781.271 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:33:01.272Z,1336620781.272 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T03:33:01.272Z,1336620781.272 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:33:01.273Z,1336620781.273 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T03:33:01.859Z,1336620781.859 [NAL9601](INFO): Powering up
2012-05-10T03:34:07.555Z,1336620847.555 [NAL9601](INFO): NAL9601 initialized
2012-05-10T03:34:25.772Z,1336620865.772 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6380, MT Status=1, MTMSN=2613
2012-05-10T03:34:25.915Z,1336620865.915 [NAL9601](INFO): Sent 154 bytes from file Logs/20120510T031812/shore0003.lzma
2012-05-10T03:34:25.915Z,1336620865.915 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:34:25.916Z,1336620865.916 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-05-10T03:34:26.348Z,1336620866.348 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-05-10T03:34:26.391Z,1336620866.391 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T03:34:26.391Z,1336620866.391 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T03:34:26.471Z,1336620866.471 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-05-10T03:34:26.475Z,1336620866.474 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-05-10T03:34:26.478Z,1336620866.478 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-05-10T03:34:26.481Z,1336620866.481 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-05-10T03:34:26.484Z,1336620866.484 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 5.000000 s
2012-05-10T03:34:26.489Z,1336620866.489 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-05-10T03:34:26.497Z,1336620866.497 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-10T03:34:26.504Z,1336620866.504 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-10T03:34:26.514Z,1336620866.514 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-10T03:34:26.521Z,1336620866.521 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-05-10T03:34:26.570Z,1336620866.569 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-05-10T03:34:26.583Z,1336620866.583 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-05-10T03:34:26.586Z,1336620866.586 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-05-10T03:34:26.589Z,1336620866.589 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-05-10T03:34:26.590Z,1336620866.590 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T03:34:26.619Z,1336620866.619 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-05-10T03:34:26.628Z,1336620866.628 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-05-10T03:34:26.637Z,1336620866.637 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-05-10T03:34:26.646Z,1336620866.646 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-05-10T03:34:26.669Z,1336620866.669 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Construct Wait.
2012-05-10T03:34:26.673Z,1336620866.673 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-05-10T03:34:26.676Z,1336620866.676 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-05-10T03:34:26.692Z,1336620866.692 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-05-10T03:34:26.700Z,1336620866.700 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       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/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

<!-- The following arguments are input arguments -->

    <DefineArg Name="BallastDepth"><Units:meter/><Value>25.0</Value></DefineArg>

    <DefineArg Name="HoldDuration"><Units:minute/><Value>25</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Units:meter/><Value>4.0</Value></DefineArg>

    <DefineArg Name="BuoyPeriod"><Units:second/><Value>5.0</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><Control:VerticalControl.buoyancyDefault/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Assign RunIn="Parallel"><Control:VerticalControl.kpPitchMass/><Units:count/><Value>0.01</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kdPitchMass/><Units:second/><Value>0</Value></Assign>

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

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth/><Units:meter/><Value>52</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>2.0</Value></Setting>
        <Setting><Guidance:OffshoreEnvelope.maxOffshore/><Units:kilometer/><Value>30.0</Value></Setting>
    </Guidance:OffshoreEnvelope>

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

    <Guidance:SetSpeed>
        <While><Universal:platform_propeller_rotation_rate/>
            <Eq><Units:radian_per_second/><Value>0</Value></Eq>
        </While>
        <Setting><Guidance:SetSpeed.period/><Arg Name="BuoyPeriod"/></Setting>
    </Guidance:SetSpeed>

    <Aggregate Id="ballast">

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

        <Assign RunIn="Parallel"><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

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

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Arg Name="HoldDuration"/></Setting>
        </Guidance:Wait>

        <Aggregate Id="ReportPositions" Repeat="5" >

            <Syslog Severity="Important">Buoyancy:<Universal:platform_buoyancy_position/><Units:cubic_centimeter/>
            </Syslog>

            <Syslog Severity="Important">Mass:<Universal:platform_mass_position/><Units:centimeter/>
            </Syslog>

            <Syslog Severity="Important">Pitch:<Universal:platform_pitch_angle/><Units:degree/>
            </Syslog>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P1M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="Float_Up">

            <Until><Universal:depth/>
                <Lt><Units:meter/><Value>1</Value></Lt>
            </Until>

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

            <Guidance:Buoyancy RunIn="Parallel">
                <Setting><Guidance:Buoyancy.position /><Arg Name="BuoyancyDefault"/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P15M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

    </Aggregate>

</Mission>


2012-05-10T03:34:26.700Z,1336620866.700 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T03:34:26.987Z,1336620866.987 [Default] Stopped
2012-05-10T03:34:26.988Z,1336620866.987 [Default](INFO): Aggregate::uninitialize Default
2012-05-10T03:34:26.988Z,1336620866.988 [Default:GPS] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T03:34:26.988Z,1336620866.988 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:34:26.988Z,1336620866.988 [Default:GPS:Read_GPS] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:Iridium] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T03:34:26.988Z,1336620866.988 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:34:26.988Z,1336620866.988 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T03:34:26.988Z,1336620866.988 [Default:CallIridium] Stopped
2012-05-10T03:34:26.989Z,1336620866.989 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T03:34:26.989Z,1336620866.989 [Default:CallIridium:B] Stopped
2012-05-10T03:34:26.989Z,1336620866.989 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T03:34:26.989Z,1336620866.989 [Default:D.SetSpeed] Stopped
2012-05-10T03:34:26.989Z,1336620866.989 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:34:26.989Z,1336620866.989 [Default:E.GoToSurface] Stopped
2012-05-10T03:34:26.989Z,1336620866.989 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:34:26.989Z,1336620866.989 [Default:F.Wait] Stopped
2012-05-10T03:34:26.989Z,1336620866.989 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-10T03:34:26.989Z,1336620866.989 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-05-10T03:34:26.989Z,1336620866.989 [ballast_and_trim] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:A] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:B] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:C] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-10T03:34:26.990Z,1336620866.990 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-10T03:34:26.991Z,1336620866.991 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-10T03:34:26.991Z,1336620866.991 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-10T03:34:26.992Z,1336620866.991 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T03:34:26.992Z,1336620866.992 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-05-10T03:34:26.992Z,1336620866.992 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-05-10T03:34:26.992Z,1336620866.992 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-05-10T03:34:26.992Z,1336620866.992 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-05-10T03:34:26.992Z,1336620866.992 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:34:26.993Z,1336620866.993 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T03:34:27.004Z,1336620867.004 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-05-10T03:34:27.004Z,1336620867.004 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-05-10T03:34:27.004Z,1336620867.004 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-05-10T03:34:27.004Z,1336620867.004 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-10T03:34:27.009Z,1336620867.009 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-10T03:34:27.015Z,1336620867.015 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-10T03:34:27.020Z,1336620867.020 [ballast_and_trim:C] Running Loop=1
2012-05-10T03:34:27.022Z,1336620867.022 [ballast_and_trim:B] Running Loop=1
2012-05-10T03:34:27.023Z,1336620867.023 [ballast_and_trim:A] Running Loop=1
2012-05-10T03:34:32.333Z,1336620872.333 [ballast_and_trim:H.SetSpeed] Preempted
2012-05-10T03:34:32.339Z,1336620872.339 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T03:36:20.238Z,1336620980.238 [NAL9601](IMPORTANT): GPS fix at: 1336621024.00
2012-05-10T03:36:20.252Z,1336620980.252 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-05-10T03:36:20.252Z,1336620980.252 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-05-10T03:36:20.640Z,1336620980.640 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T03:36:48.887Z,1336621008.886 [NAL9601](INFO): SBD MO Status=2, MOMSN=6381, MT Status=2, MTMSN=0
2012-05-10T03:36:48.887Z,1336621008.887 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-10T03:37:01.044Z,1336621021.044 [NAL9601](INFO): SBD MO Status=0, MOMSN=6381, MT Status=0, MTMSN=0
2012-05-10T03:37:20.300Z,1336621040.300 [NAL9601](INFO): SBD MO Status=1, MOMSN=6382, MT Status=0, MTMSN=0
2012-05-10T03:37:20.447Z,1336621040.447 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0004.lzma
2012-05-10T03:37:20.447Z,1336621040.447 [NAL9601](INFO): Packets left to send: 1
2012-05-10T03:37:20.449Z,1336621040.449 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-05-10T03:37:30.416Z,1336621050.416 [NAL9601](INFO): SBD MO Status=1, MOMSN=6383, MT Status=0, MTMSN=0
2012-05-10T03:37:30.639Z,1336621050.639 [NAL9601](INFO): Sent 41 bytes from file Logs/20120510T031812/shore0004.lzma
2012-05-10T03:37:30.639Z,1336621050.639 [NAL9601](INFO): Packets left to send: 0
2012-05-10T03:37:30.640Z,1336621050.640 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-05-10T03:37:40.020Z,1336621060.020 [NAL9601](INFO): SBD MO Status=0, MOMSN=6384, MT Status=0, MTMSN=0
2012-05-10T03:37:40.228Z,1336621060.228 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-05-10T03:37:40.228Z,1336621060.228 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-05-10T03:37:40.450Z,1336621060.450 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T03:37:42.417Z,1336621062.417 [NAL9601](IMPORTANT): GPS fix at: 1336621107.00
2012-05-10T03:37:42.433Z,1336621062.433 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-05-10T03:37:42.433Z,1336621062.433 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-05-10T03:37:42.433Z,1336621062.433 [ballast_and_trim:SurfaceComms:B] Stopped
2012-05-10T03:37:42.433Z,1336621062.433 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:SurfaceComms] Stopped
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:ballast] Running Loop=1
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-05-10T03:37:42.435Z,1336621062.435 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-05-10T03:37:42.436Z,1336621062.436 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-05-10T03:37:42.864Z,1336621062.864 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-10T03:37:42.874Z,1336621062.874 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-10T03:37:42.882Z,1336621062.882 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-10T03:37:42.895Z,1336621062.895 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T03:38:02.964Z,1336621082.964 [NAL9601](INFO): Powering down
2012-05-10T03:43:18.218Z,1336621398.217 [Radio_Freewave](INFO): Powering down
2012-05-10T03:54:48.083Z,1336622088.083 [VerticalControl](CRITICAL): Can not stop descending, stopping mission at depth excursion=5.190613, upwardsErrorDepth_=29.528469, depthRate=0.013026
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim] Stopped
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:A] Stopped
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:B] Stopped
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:C] Stopped
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-10T03:54:53.136Z,1336622093.136 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-05-10T03:54:53.137Z,1336622093.136 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:H.SetSpeed] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:B] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:D.Wait] Stopped
2012-05-10T03:54:53.137Z,1336622093.137 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-10T03:54:58.056Z,1336622098.056 [MissionManager](IMPORTANT): Started mission Default
2012-05-10T03:54:58.056Z,1336622098.056 [Default] Running Loop=1
2012-05-10T03:54:58.056Z,1336622098.056 [Default](INFO): Aggregate::initialize Default
2012-05-10T03:54:58.056Z,1336622098.056 [Default:D.SetSpeed] Running Loop=1
2012-05-10T03:54:58.056Z,1336622098.056 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-10T03:54:58.056Z,1336622098.056 [Default:E.GoToSurface] Running Loop=1
2012-05-10T03:54:58.056Z,1336622098.056 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium] Running Loop=1
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T03:54:58.057Z,1336622098.057 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:54:58.059Z,1336622098.059 [Default:CallIridium] Running Loop=1
2012-05-10T03:54:58.059Z,1336622098.059 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T03:54:58.059Z,1336622098.059 [Default:CallIridium:A] Running Loop=1
2012-05-10T03:54:58.060Z,1336622098.059 [Default:CallIridium:A] Stopped
2012-05-10T03:54:58.060Z,1336622098.060 [Default:CallIridium:B] Running Loop=1
2012-05-10T03:54:58.060Z,1336622098.060 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS] Running Loop=1
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T03:54:58.061Z,1336622098.061 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T03:54:59.299Z,1336622099.299 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2012-05-10T03:54:59.299Z,1336622099.299 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2012-05-10T03:54:59.299Z,1336622099.299 [ThrusterServo] Communications Fault, FailCount= 1
2012-05-10T03:54:59.299Z,1336622099.299 [ThrusterServo](ERROR): Communications Fault
2012-05-10T03:54:59.301Z,1336622099.301 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-05-10T03:54:59.548Z,1336622099.548 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-10T03:54:59.548Z,1336622099.548 [ThrusterServo](INFO): Powering down
2012-05-10T03:54:59.551Z,1336622099.551 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-05-10T03:54:59.551Z,1336622099.551 [ThrusterServo] No Fault, FailCount= 1
2012-05-10T03:55:00.281Z,1336622100.281 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-10T03:55:00.403Z,1336622100.403 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-10T03:55:02.823Z,1336622102.823 [CTD_NeilBrown](ERROR): Pressure reading out of range: -211.320007 decibar
2012-05-10T04:00:15.161Z,1336622415.161 [Radio_Freewave](INFO): Powering up
2012-05-10T04:00:15.171Z,1336622415.171 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:00:15.171Z,1336622415.171 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:00:15.171Z,1336622415.171 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:00:15.172Z,1336622415.172 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:00:15.172Z,1336622415.172 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:00:15.173Z,1336622415.173 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:00:15.922Z,1336622415.922 [NAL9601](INFO): Powering up
2012-05-10T04:01:21.579Z,1336622481.579 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:01:46.460Z,1336622506.460 [NAL9601](INFO): SBD MO Status=1, MOMSN=6385, MT Status=0, MTMSN=0
2012-05-10T04:01:46.627Z,1336622506.627 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0005.lzma
2012-05-10T04:01:46.627Z,1336622506.627 [NAL9601](INFO): Packets left to send: 2
2012-05-10T04:01:46.628Z,1336622506.628 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-05-10T04:01:56.075Z,1336622516.075 [NAL9601](INFO): SBD MO Status=1, MOMSN=6386, MT Status=0, MTMSN=0
2012-05-10T04:01:56.215Z,1336622516.215 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0005.lzma
2012-05-10T04:01:56.215Z,1336622516.215 [NAL9601](INFO): Packets left to send: 1
2012-05-10T04:01:56.216Z,1336622516.216 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000010
2012-05-10T04:02:08.567Z,1336622528.567 [NAL9601](INFO): SBD MO Status=1, MOMSN=6387, MT Status=0, MTMSN=0
2012-05-10T04:02:08.695Z,1336622528.695 [NAL9601](INFO): Sent 185 bytes from file Logs/20120510T031812/shore0005.lzma
2012-05-10T04:02:08.695Z,1336622528.695 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:02:08.696Z,1336622528.696 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000011
2012-05-10T04:02:17.368Z,1336622537.368 [NAL9601](INFO): SBD MO Status=0, MOMSN=6388, MT Status=0, MTMSN=0
2012-05-10T04:02:17.613Z,1336622537.613 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:02:17.613Z,1336622537.613 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:02:17.613Z,1336622537.613 [Default:Iridium] Stopped
2012-05-10T04:02:17.613Z,1336622537.614 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:02:17.613Z,1336622537.614 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:02:17.614Z,1336622537.614 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:02:17.614Z,1336622537.614 [Default:F.Wait] Running Loop=1
2012-05-10T04:02:17.614Z,1336622537.614 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-10T04:02:17.805Z,1336622537.805 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:02:17.805Z,1336622537.805 [Default:CallIridium:B] Stopped
2012-05-10T04:02:17.805Z,1336622537.806 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:02:17.806Z,1336622537.806 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:02:17.806Z,1336622537.806 [Default:CallIridium] Stopped
2012-05-10T04:02:17.806Z,1336622537.806 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:02:59.815Z,1336622579.815 [CTD_NeilBrown](ERROR): Bad response: ,34.79475
2012-05-10T04:03:48.575Z,1336622628.575 [NAL9601](IMPORTANT): GPS fix at: 1336622675.00
2012-05-10T04:03:48.592Z,1336622628.592 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:03:48.592Z,1336622628.592 [Default:GPS:D] Running Loop=1
2012-05-10T04:03:49.012Z,1336622629.012 [Default:GPS:D] Stopped
2012-05-10T04:03:49.012Z,1336622629.012 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T04:03:49.013Z,1336622629.013 [Default:GPS] Stopped
2012-05-10T04:03:49.013Z,1336622629.013 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:03:49.013Z,1336622629.013 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:03:49.013Z,1336622629.013 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:04:04.529Z,1336622644.529 [NAL9601](INFO): Powering down
2012-05-10T04:07:19.574Z,1336622839.574 [Default:CallIridium] Running Loop=1
2012-05-10T04:07:19.574Z,1336622839.574 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:07:19.574Z,1336622839.574 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:07:19.575Z,1336622839.575 [Default:CallIridium:A] Stopped
2012-05-10T04:07:19.575Z,1336622839.575 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:07:19.575Z,1336622839.575 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:07:24.565Z,1336622844.565 [Default:Iridium] Running Loop=1
2012-05-10T04:07:24.565Z,1336622844.565 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:07:24.566Z,1336622844.566 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:07:24.566Z,1336622844.566 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:07:24.566Z,1336622844.566 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:07:24.566Z,1336622844.566 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:07:24.567Z,1336622844.567 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:07:24.567Z,1336622844.567 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:07:24.567Z,1336622844.567 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS] Running Loop=1
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:07:24.568Z,1336622844.568 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:07:24.569Z,1336622844.569 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:07:24.569Z,1336622844.569 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:07:24.570Z,1336622844.569 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:07:25.187Z,1336622845.187 [NAL9601](INFO): Powering up
2012-05-10T04:08:30.883Z,1336622910.883 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:08:49.117Z,1336622929.117 [NAL9601](INFO): SBD MO Status=1, MOMSN=6389, MT Status=0, MTMSN=0
2012-05-10T04:08:49.243Z,1336622929.243 [NAL9601](INFO): Sent 249 bytes from file Logs/20120510T031812/shore0006.lzma
2012-05-10T04:08:49.244Z,1336622929.244 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:08:49.245Z,1336622929.245 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000012
2012-05-10T04:08:55.937Z,1336622935.937 [NAL9601](INFO): SBD MO Status=0, MOMSN=6390, MT Status=0, MTMSN=0
2012-05-10T04:08:56.153Z,1336622936.153 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:08:56.153Z,1336622936.153 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:08:56.153Z,1336622936.153 [Default:Iridium] Stopped
2012-05-10T04:08:56.154Z,1336622936.154 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:08:56.154Z,1336622936.154 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:08:56.154Z,1336622936.154 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium:B] Stopped
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium] Stopped
2012-05-10T04:08:56.328Z,1336622936.328 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:12:55.597Z,1336623175.597 [CTD_NeilBrown](ERROR): Bad response: 2.00140
2012-05-10T04:13:56.324Z,1336623236.324 [Default:CallIridium] Running Loop=1
2012-05-10T04:13:56.324Z,1336623236.324 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:13:56.324Z,1336623236.325 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:13:56.325Z,1336623236.325 [Default:CallIridium:A] Stopped
2012-05-10T04:13:56.325Z,1336623236.325 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:13:56.325Z,1336623236.325 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium] Running Loop=1
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:13:56.725Z,1336623236.725 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:13:56.727Z,1336623236.727 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:13:56.727Z,1336623236.727 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:13:56.727Z,1336623236.727 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:14:12.653Z,1336623252.653 [NAL9601](INFO): SBD MO Status=1, MOMSN=6391, MT Status=0, MTMSN=0
2012-05-10T04:14:12.843Z,1336623252.843 [NAL9601](INFO): Sent 124 bytes from file Logs/20120510T031812/shore0007.lzma
2012-05-10T04:14:12.843Z,1336623252.843 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:14:12.845Z,1336623252.845 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000013
2012-05-10T04:14:21.853Z,1336623261.852 [NAL9601](INFO): SBD MO Status=0, MOMSN=6392, MT Status=0, MTMSN=0
2012-05-10T04:14:22.046Z,1336623262.046 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:14:22.047Z,1336623262.046 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:14:22.047Z,1336623262.046 [Default:Iridium] Stopped
2012-05-10T04:14:22.047Z,1336623262.047 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:14:22.047Z,1336623262.047 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:14:22.047Z,1336623262.047 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium:B] Stopped
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium] Stopped
2012-05-10T04:14:22.269Z,1336623262.269 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:15:49.053Z,1336623349.053 [NAL9601](IMPORTANT): GPS fix at: 1336623397.00
2012-05-10T04:15:49.068Z,1336623349.068 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:15:49.068Z,1336623349.068 [Default:GPS:D] Running Loop=1
2012-05-10T04:15:49.473Z,1336623349.473 [Default:GPS:D] Stopped
2012-05-10T04:15:49.474Z,1336623349.474 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T04:15:49.474Z,1336623349.474 [Default:GPS] Stopped
2012-05-10T04:15:49.474Z,1336623349.474 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:15:49.477Z,1336623349.477 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:15:49.477Z,1336623349.477 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:16:05.133Z,1336623365.134 [NAL9601](INFO): Powering down
2012-05-10T04:19:25.010Z,1336623565.010 [Default:CallIridium] Running Loop=1
2012-05-10T04:19:25.010Z,1336623565.010 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:19:25.010Z,1336623565.010 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:19:25.011Z,1336623565.011 [Default:CallIridium:A] Stopped
2012-05-10T04:19:25.011Z,1336623565.011 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:19:25.011Z,1336623565.011 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:19:30.107Z,1336623570.107 [Default:Iridium] Running Loop=1
2012-05-10T04:19:30.107Z,1336623570.107 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:19:30.107Z,1336623570.107 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:19:30.108Z,1336623570.108 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:19:30.108Z,1336623570.108 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:19:30.108Z,1336623570.108 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:19:30.109Z,1336623570.109 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:19:30.109Z,1336623570.109 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:19:30.109Z,1336623570.109 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:19:30.109Z,1336623570.109 [Default:GPS] Running Loop=1
2012-05-10T04:19:30.109Z,1336623570.109 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:19:30.109Z,1336623570.109 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:19:30.110Z,1336623570.110 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:19:30.110Z,1336623570.110 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:19:30.110Z,1336623570.110 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:19:30.111Z,1336623570.111 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:19:30.111Z,1336623570.111 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:19:30.111Z,1336623570.111 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:19:30.786Z,1336623570.786 [NAL9601](INFO): Powering up
2012-05-10T04:20:36.511Z,1336623636.511 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:21:00.331Z,1336623660.331 [NAL9601](INFO): SBD MO Status=1, MOMSN=6393, MT Status=0, MTMSN=0
2012-05-10T04:21:00.463Z,1336623660.463 [NAL9601](INFO): Sent 259 bytes from file Logs/20120510T031812/shore0008.lzma
2012-05-10T04:21:00.463Z,1336623660.463 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:21:00.464Z,1336623660.464 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000014
2012-05-10T04:21:10.364Z,1336623670.364 [NAL9601](INFO): SBD MO Status=2, MOMSN=6394, MT Status=2, MTMSN=0
2012-05-10T04:21:10.364Z,1336623670.364 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-10T04:21:19.352Z,1336623679.352 [NAL9601](INFO): SBD MO Status=0, MOMSN=6394, MT Status=0, MTMSN=0
2012-05-10T04:21:19.545Z,1336623679.545 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:21:19.546Z,1336623679.546 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:21:19.546Z,1336623679.546 [Default:Iridium] Stopped
2012-05-10T04:21:19.546Z,1336623679.546 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:21:19.546Z,1336623679.546 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:21:19.546Z,1336623679.546 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:21:19.782Z,1336623679.782 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:21:19.782Z,1336623679.782 [Default:CallIridium:B] Stopped
2012-05-10T04:21:19.782Z,1336623679.782 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:21:19.783Z,1336623679.783 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:21:19.783Z,1336623679.783 [Default:CallIridium] Stopped
2012-05-10T04:21:19.783Z,1336623679.783 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:22:34.553Z,1336623754.553 [NAL9601](IMPORTANT): GPS fix at: 1336623803.00
2012-05-10T04:22:34.568Z,1336623754.568 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:22:34.568Z,1336623754.568 [Default:GPS:D] Running Loop=1
2012-05-10T04:22:34.973Z,1336623754.973 [Default:GPS:D] Stopped
2012-05-10T04:22:34.973Z,1336623754.973 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T04:22:34.973Z,1336623754.973 [Default:GPS] Stopped
2012-05-10T04:22:34.973Z,1336623754.973 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:22:34.974Z,1336623754.974 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:22:34.974Z,1336623754.974 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:22:50.528Z,1336623770.528 [NAL9601](INFO): Powering down
2012-05-10T04:26:20.727Z,1336623980.727 [Default:CallIridium] Running Loop=1
2012-05-10T04:26:20.727Z,1336623980.727 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:26:20.728Z,1336623980.728 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:26:20.728Z,1336623980.728 [Default:CallIridium:A] Stopped
2012-05-10T04:26:20.728Z,1336623980.728 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:26:20.728Z,1336623980.728 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:26:25.503Z,1336623985.503 [Default:Iridium] Running Loop=1
2012-05-10T04:26:25.503Z,1336623985.503 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:26:25.503Z,1336623985.503 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:26:25.503Z,1336623985.503 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:26:25.504Z,1336623985.504 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:26:25.504Z,1336623985.504 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:26:25.505Z,1336623985.505 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:26:25.505Z,1336623985.505 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:26:25.505Z,1336623985.505 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:26:25.505Z,1336623985.505 [Default:GPS] Running Loop=1
2012-05-10T04:26:25.505Z,1336623985.505 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:26:25.506Z,1336623985.506 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:26:25.506Z,1336623985.506 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:26:25.506Z,1336623985.506 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:26:25.506Z,1336623985.506 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:26:25.507Z,1336623985.507 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:26:25.507Z,1336623985.507 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:26:25.507Z,1336623985.507 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:26:26.154Z,1336623986.154 [NAL9601](INFO): Powering up
2012-05-10T04:27:31.831Z,1336624051.831 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:27:56.972Z,1336624076.972 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6395, MT Status=1, MTMSN=2614
2012-05-10T04:27:57.179Z,1336624077.179 [NAL9601](INFO): Sent 276 bytes from file Logs/20120510T031812/shore0009.lzma
2012-05-10T04:27:57.179Z,1336624077.179 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:27:57.180Z,1336624077.180 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000015
2012-05-10T04:27:57.512Z,1336624077.511 [NAL9601](INFO): Received command:run Maintenance/ballast_and_trim.xml
2012-05-10T04:27:57.551Z,1336624077.551 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T04:27:57.551Z,1336624077.551 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T04:27:57.626Z,1336624077.626 [MissionManager](INFO): DefineArg ballast_and_trim.BallastDepth = 25.000000 m
2012-05-10T04:27:57.637Z,1336624077.637 [MissionManager](INFO): DefineArg ballast_and_trim.HoldDuration = 25.000000 min
2012-05-10T04:27:57.644Z,1336624077.644 [MissionManager](INFO): DefineArg ballast_and_trim.Speed = 1.000000 m/s
2012-05-10T04:27:57.653Z,1336624077.653 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 4.000000 m
2012-05-10T04:27:57.659Z,1336624077.659 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyPeriod = 5.000000 s
2012-05-10T04:27:57.662Z,1336624077.662 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyancyDefault = 0.000945 n/a
2012-05-10T04:27:57.669Z,1336624077.669 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-05-10T04:27:57.687Z,1336624077.687 [ballast_and_trim:E.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-05-10T04:27:57.705Z,1336624077.705 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-05-10T04:27:57.716Z,1336624077.716 [MissionManager](INFO): Inserting Stack: Missions/Insert/Surface.xml
2012-05-10T04:27:57.765Z,1336624077.765 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceDepthRate = nan m/s
2012-05-10T04:27:57.771Z,1336624077.771 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfacePitch = nan arcdeg
2012-05-10T04:27:57.773Z,1336624077.773 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.SurfaceSpeed = 0.500000 m/s
2012-05-10T04:27:57.781Z,1336624077.781 [MissionManager](INFO): DefineArg ballast_and_trim:SurfaceComms.IridiumTimeout = 30.000000 min
2012-05-10T04:27:57.782Z,1336624077.782 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-10T04:27:57.803Z,1336624077.803 [ballast_and_trim:H.SetSpeed](DEBUG): Construct.
2012-05-10T04:27:57.811Z,1336624077.810 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Construct.
2012-05-10T04:27:57.814Z,1336624077.814 [ballast_and_trim:ballast:C.Pitch](DEBUG): Construct.
2012-05-10T04:27:57.827Z,1336624077.828 [ballast_and_trim:ballast:D.Wait](DEBUG): Construct Wait.
2012-05-10T04:27:57.843Z,1336624077.843 [ballast_and_trim:ballast:ReportPositions:D.Wait](DEBUG): Construct Wait.
2012-05-10T04:27:57.852Z,1336624077.852 [ballast_and_trim:ballast:Float_Up:A.SetSpeed](DEBUG): Construct.
2012-05-10T04:27:57.861Z,1336624077.861 [ballast_and_trim:ballast:Float_Up:B.Buoyancy](DEBUG): Construct Buoyancy.
2012-05-10T04:27:57.868Z,1336624077.868 [ballast_and_trim:ballast:Float_Up:C.Wait](DEBUG): Construct Wait.
2012-05-10T04:27:57.883Z,1336624077.884 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       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/Trigger http://aosn.mbari.org/tethys/Xml/Trigger.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

<!-- The following arguments are input arguments -->

    <DefineArg Name="BallastDepth"><Units:meter/><Value>25.0</Value></DefineArg>

    <DefineArg Name="HoldDuration"><Units:minute/><Value>25</Value></DefineArg>

    <DefineArg Name="Speed"><Units:meter_per_second/><Value>1</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Units:meter/><Value>4.0</Value></DefineArg>

    <DefineArg Name="BuoyPeriod"><Units:second/><Value>5.0</Value></DefineArg>

    <DefineArg Name="BuoyancyDefault"><Control:VerticalControl.buoyancyDefault/></DefineArg>

<!-- The timeout -->

    <Timeout Duration="P90M"/>

<!-- And now the mission -->

    <Assign RunIn="Parallel"><Control:VerticalControl.kpPitchMass/><Units:count/><Value>0.01</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kiPitchMass/><Units:reciprocal_second/><Value>0.0015</Value></Assign>

    <Assign RunIn="Parallel"><Control:VerticalControl.kdPitchMass/><Units:second/><Value>0</Value></Assign>

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

    <Guidance:DepthEnvelope RunIn="Parallel">
        <Setting><Guidance:DepthEnvelope.maxDepth/><Units:meter/><Value>52</Value></Setting>
    </Guidance:DepthEnvelope>

    <Guidance:OffshoreEnvelope RunIn="Parallel">
        <Setting><Guidance:OffshoreEnvelope.minOffshore/><Units:kilometer/><Value>2.0</Value></Setting>
        <Setting><Guidance:OffshoreEnvelope.maxOffshore/><Units:kilometer/><Value>30.0</Value></Setting>
    </Guidance:OffshoreEnvelope>

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

    <Guidance:SetSpeed>
        <While><Universal:platform_propeller_rotation_rate/>
            <Eq><Units:radian_per_second/><Value>0</Value></Eq>
        </While>
        <Setting><Guidance:SetSpeed.period/><Arg Name="BuoyPeriod"/></Setting>
    </Guidance:SetSpeed>

    <Aggregate Id="ballast">

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

        <Assign RunIn="Parallel"><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

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

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Arg Name="HoldDuration"/></Setting>
        </Guidance:Wait>

        <Aggregate Id="ReportPositions" Repeat="5" >

            <Syslog Severity="Important">Buoyancy:<Universal:platform_buoyancy_position/><Units:cubic_centimeter/>
            </Syslog>

            <Syslog Severity="Important">Mass:<Universal:platform_mass_position/><Units:centimeter/>
            </Syslog>

            <Syslog Severity="Important">Pitch:<Universal:platform_pitch_angle/><Units:degree/>
            </Syslog>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P1M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="Float_Up">

            <Until><Universal:depth/>
                <Lt><Units:meter/><Value>1</Value></Lt>
            </Until>

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

            <Guidance:Buoyancy RunIn="Parallel">
                <Setting><Guidance:Buoyancy.position /><Arg Name="BuoyancyDefault"/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Wait RunIn="Sequence">
                <Timeout Duration="P15M"></Timeout>
            </Guidance:Wait>

        </Aggregate>

    </Aggregate>

</Mission>


2012-05-10T04:27:57.884Z,1336624077.884 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/ballast_and_trim.xml
2012-05-10T04:27:58.157Z,1336624078.157 [Default] Stopped
2012-05-10T04:27:58.157Z,1336624078.157 [Default](INFO): Aggregate::uninitialize Default
2012-05-10T04:27:58.157Z,1336624078.157 [Default:GPS] Stopped
2012-05-10T04:27:58.157Z,1336624078.157 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:27:58.157Z,1336624078.157 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:27:58.157Z,1336624078.157 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:27:58.157Z,1336624078.157 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:27:58.157Z,1336624078.158 [Default:Iridium] Stopped
2012-05-10T04:27:58.158Z,1336624078.158 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:27:58.158Z,1336624078.158 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:27:58.158Z,1336624078.158 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:27:58.158Z,1336624078.158 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:27:58.158Z,1336624078.158 [Default:CallIridium] Stopped
2012-05-10T04:27:58.158Z,1336624078.158 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:27:58.158Z,1336624078.158 [Default:CallIridium:B] Stopped
2012-05-10T04:27:58.162Z,1336624078.162 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:27:58.163Z,1336624078.163 [Default:D.SetSpeed] Stopped
2012-05-10T04:27:58.163Z,1336624078.163 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:27:58.163Z,1336624078.163 [Default:E.GoToSurface] Stopped
2012-05-10T04:27:58.163Z,1336624078.163 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:27:58.163Z,1336624078.163 [Default:F.Wait] Stopped
2012-05-10T04:27:58.163Z,1336624078.163 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-10T04:27:58.163Z,1336624078.163 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2012-05-10T04:27:58.163Z,1336624078.163 [ballast_and_trim] Running Loop=1
2012-05-10T04:27:58.163Z,1336624078.163 [ballast_and_trim](INFO): Aggregate::initialize ballast_and_trim
2012-05-10T04:27:58.163Z,1336624078.163 [ballast_and_trim:A] Running Loop=1
2012-05-10T04:27:58.163Z,1336624078.163 [ballast_and_trim:B] Running Loop=1
2012-05-10T04:27:58.163Z,1336624078.164 [ballast_and_trim:C] Running Loop=1
2012-05-10T04:27:58.163Z,1336624078.164 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:E.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-05-10T04:27:58.164Z,1336624078.164 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T04:27:58.165Z,1336624078.165 [ballast_and_trim:H.SetSpeed](DEBUG): Initialize.
2012-05-10T04:27:58.165Z,1336624078.165 [ballast_and_trim:SurfaceComms] Running Loop=1
2012-05-10T04:27:58.165Z,1336624078.165 [ballast_and_trim:SurfaceComms](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms
2012-05-10T04:27:58.165Z,1336624078.165 [ballast_and_trim:SurfaceComms:A.GoToSurface] Running Loop=1
2012-05-10T04:27:58.165Z,1336624078.165 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:27:58.166Z,1336624078.166 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T04:27:58.172Z,1336624078.172 [ballast_and_trim:SurfaceComms:B] Running Loop=1
2012-05-10T04:27:58.172Z,1336624078.172 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::initialize ballast_and_trim:SurfaceComms:B
2012-05-10T04:27:58.173Z,1336624078.173 [ballast_and_trim:SurfaceComms:B:A] Running Loop=1
2012-05-10T04:27:58.173Z,1336624078.173 [ballast_and_trim:F.OffshoreEnvelope] Running Loop=1
2012-05-10T04:27:58.174Z,1336624078.174 [ballast_and_trim:E.DepthEnvelope] Running Loop=1
2012-05-10T04:27:58.179Z,1336624078.179 [ballast_and_trim:D.AltitudeEnvelope] Running Loop=1
2012-05-10T04:27:58.180Z,1336624078.180 [ballast_and_trim:C] Running Loop=1
2012-05-10T04:27:58.181Z,1336624078.181 [ballast_and_trim:B] Running Loop=1
2012-05-10T04:27:58.182Z,1336624078.182 [ballast_and_trim:A] Running Loop=1
2012-05-10T04:28:03.329Z,1336624083.329 [ballast_and_trim:H.SetSpeed] Preempted
2012-05-10T04:28:03.330Z,1336624083.330 [ballast_and_trim:SurfaceComms:B:A](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T04:29:15.182Z,1336624155.182 [NAL9601](IMPORTANT): GPS fix at: 1336624204.00
2012-05-10T04:29:15.208Z,1336624155.208 [ballast_and_trim:SurfaceComms:B:A] Stopped
2012-05-10T04:29:15.208Z,1336624155.208 [ballast_and_trim:SurfaceComms:B:B] Running Loop=1
2012-05-10T04:29:15.639Z,1336624155.639 [ballast_and_trim:SurfaceComms:B:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-10T04:29:22.580Z,1336624162.580 [NAL9601](INFO): SBD MO Status=0, MOMSN=6396, MT Status=0, MTMSN=0
2012-05-10T04:29:35.328Z,1336624175.328 [NAL9601](INFO): SBD MO Status=1, MOMSN=6397, MT Status=0, MTMSN=0
2012-05-10T04:29:35.527Z,1336624175.527 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0010.lzma
2012-05-10T04:29:35.527Z,1336624175.527 [NAL9601](INFO): Packets left to send: 1
2012-05-10T04:29:35.528Z,1336624175.528 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000016
2012-05-10T04:29:45.049Z,1336624185.049 [NAL9601](INFO): SBD MO Status=1, MOMSN=6398, MT Status=0, MTMSN=0
2012-05-10T04:29:45.211Z,1336624185.211 [NAL9601](INFO): Sent 146 bytes from file Logs/20120510T031812/shore0010.lzma
2012-05-10T04:29:45.211Z,1336624185.211 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:29:45.212Z,1336624185.212 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000017
2012-05-10T04:29:53.419Z,1336624193.420 [NAL9601](INFO): SBD MO Status=0, MOMSN=6399, MT Status=0, MTMSN=0
2012-05-10T04:29:53.613Z,1336624193.613 [ballast_and_trim:SurfaceComms:B:B] Stopped
2012-05-10T04:29:53.613Z,1336624193.613 [ballast_and_trim:SurfaceComms:B:C] Running Loop=1
2012-05-10T04:29:53.833Z,1336624193.833 [ballast_and_trim:SurfaceComms:B:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2012-05-10T04:29:56.561Z,1336624196.561 [NAL9601](IMPORTANT): GPS fix at: 1336624246.00
2012-05-10T04:29:56.575Z,1336624196.575 [ballast_and_trim:SurfaceComms:B:C] Stopped
2012-05-10T04:29:56.575Z,1336624196.575 [ballast_and_trim:SurfaceComms:B](INFO): Completed ballast_and_trim:SurfaceComms:B
2012-05-10T04:29:56.576Z,1336624196.576 [ballast_and_trim:SurfaceComms:B] Stopped
2012-05-10T04:29:56.576Z,1336624196.576 [ballast_and_trim:SurfaceComms:B](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms:B
2012-05-10T04:29:56.576Z,1336624196.576 [ballast_and_trim:SurfaceComms](INFO): Completed ballast_and_trim:SurfaceComms
2012-05-10T04:29:56.576Z,1336624196.576 [ballast_and_trim:SurfaceComms] Stopped
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:SurfaceComms](INFO): Aggregate::uninitialize ballast_and_trim:SurfaceComms
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:SurfaceComms:A.GoToSurface] Stopped
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:SurfaceComms:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast] Running Loop=1
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast](INFO): Aggregate::initialize ballast_and_trim:ballast
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-10T04:29:56.577Z,1336624196.577 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-10T04:29:56.577Z,1336624196.578 [ballast_and_trim:ballast:C.Pitch](DEBUG): Initialize.
2012-05-10T04:29:56.578Z,1336624196.578 [ballast_and_trim:ballast:D.Wait] Running Loop=1
2012-05-10T04:29:56.578Z,1336624196.578 [ballast_and_trim:ballast:D.Wait](DEBUG): Initialize Wait Component.
2012-05-10T04:29:56.983Z,1336624196.983 [ballast_and_trim:ballast:C.Pitch] Running Loop=1
2012-05-10T04:29:56.984Z,1336624196.984 [ballast_and_trim:ballast:B] Running Loop=1
2012-05-10T04:29:56.985Z,1336624196.985 [ballast_and_trim:ballast:A.SetSpeed] Running Loop=1
2012-05-10T04:29:56.985Z,1336624196.986 [ballast_and_trim:H.SetSpeed] Running Loop=1
2012-05-10T04:30:17.223Z,1336624217.223 [NAL9601](INFO): Powering down
2012-05-10T04:34:47.089Z,1336624487.089 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2012-05-10T04:35:32.225Z,1336624532.225 [Radio_Freewave](INFO): Powering down
2012-05-10T04:37:17.083Z,1336624637.083 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2012-05-10T04:39:37.179Z,1336624777.180 [VerticalControl](CRITICAL): Can not stop descending, stopping mission at depth excursion=5.339869, upwardsErrorDepth_=14.720097, depthRate=0.034901
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim](INFO): Aggregate::uninitialize ballast_and_trim
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:A] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:B] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:C] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:D.AltitudeEnvelope] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:D.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:E.DepthEnvelope] Stopped
2012-05-10T04:39:42.409Z,1336624782.409 [ballast_and_trim:E.DepthEnvelope](DEBUG): Uninitialize.
2012-05-10T04:39:42.410Z,1336624782.409 [ballast_and_trim:F.OffshoreEnvelope] Stopped
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:F.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:H.SetSpeed] Stopped
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:H.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:ballast] Stopped
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:ballast](INFO): Aggregate::uninitialize ballast_and_trim:ballast
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:ballast:A.SetSpeed] Stopped
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:ballast:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:39:42.410Z,1336624782.410 [ballast_and_trim:ballast:B] Stopped
2012-05-10T04:39:42.414Z,1336624782.414 [ballast_and_trim:ballast:C.Pitch] Stopped
2012-05-10T04:39:42.414Z,1336624782.414 [ballast_and_trim:ballast:D.Wait] Stopped
2012-05-10T04:39:42.415Z,1336624782.415 [ballast_and_trim:ballast:D.Wait](DEBUG): Uninitialize Wait Component.
2012-05-10T04:39:47.132Z,1336624787.132 [MissionManager](IMPORTANT): Started mission Default
2012-05-10T04:39:47.132Z,1336624787.132 [Default] Running Loop=1
2012-05-10T04:39:47.132Z,1336624787.132 [Default](INFO): Aggregate::initialize Default
2012-05-10T04:39:47.132Z,1336624787.132 [Default:D.SetSpeed] Running Loop=1
2012-05-10T04:39:47.132Z,1336624787.132 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-10T04:39:47.132Z,1336624787.132 [Default:E.GoToSurface] Running Loop=1
2012-05-10T04:39:47.132Z,1336624787.132 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium] Running Loop=1
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:39:47.133Z,1336624787.133 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:39:47.135Z,1336624787.135 [Default:CallIridium] Running Loop=1
2012-05-10T04:39:47.135Z,1336624787.135 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:39:47.135Z,1336624787.135 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:39:47.136Z,1336624787.136 [Default:CallIridium:A] Stopped
2012-05-10T04:39:47.136Z,1336624787.136 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:39:47.136Z,1336624787.136 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS] Running Loop=1
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:39:47.137Z,1336624787.137 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:39:51.787Z,1336624791.787 [CTD_NeilBrown](ERROR): Salinity reading out of range: 26.362181 psu
2012-05-10T04:39:51.985Z,1336624791.986 [VerticalControl](CRITICAL): Can not stop descending, dropping drop weight at depth excursion=12.019470
2012-05-10T04:43:53.141Z,1336625033.141 [Radio_Freewave](INFO): Powering up
2012-05-10T04:43:53.171Z,1336625033.171 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:43:53.171Z,1336625033.171 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:43:53.172Z,1336625033.172 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:43:53.173Z,1336625033.173 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:43:53.173Z,1336625033.173 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:43:53.173Z,1336625033.173 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:43:53.922Z,1336625033.922 [NAL9601](INFO): Powering up
2012-05-10T04:44:59.531Z,1336625099.531 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:45:15.029Z,1336625115.029 [NAL9601](INFO): SBD MO Status=1, MOMSN=6400, MT Status=0, MTMSN=0
2012-05-10T04:45:15.195Z,1336625115.195 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0011.lzma
2012-05-10T04:45:15.195Z,1336625115.195 [NAL9601](INFO): Packets left to send: 2
2012-05-10T04:45:15.196Z,1336625115.196 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000018
2012-05-10T04:45:24.695Z,1336625124.695 [NAL9601](INFO): SBD MO Status=1, MOMSN=6401, MT Status=0, MTMSN=0
2012-05-10T04:45:24.879Z,1336625124.879 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0011.lzma
2012-05-10T04:45:24.879Z,1336625124.879 [NAL9601](INFO): Packets left to send: 1
2012-05-10T04:45:24.880Z,1336625124.880 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000019
2012-05-10T04:45:35.284Z,1336625135.284 [NAL9601](INFO): SBD MO Status=1, MOMSN=6402, MT Status=0, MTMSN=0
2012-05-10T04:45:35.463Z,1336625135.463 [NAL9601](INFO): Sent 59 bytes from file Logs/20120510T031812/shore0011.lzma
2012-05-10T04:45:35.463Z,1336625135.463 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:45:35.464Z,1336625135.464 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000020
2012-05-10T04:45:43.212Z,1336625143.211 [NAL9601](INFO): SBD MO Status=0, MOMSN=6403, MT Status=0, MTMSN=0
2012-05-10T04:45:43.369Z,1336625143.369 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:45:43.369Z,1336625143.369 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:45:43.369Z,1336625143.369 [Default:Iridium] Stopped
2012-05-10T04:45:43.370Z,1336625143.369 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:45:43.370Z,1336625143.369 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:45:43.370Z,1336625143.370 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:45:43.370Z,1336625143.370 [Default:F.Wait] Running Loop=1
2012-05-10T04:45:43.370Z,1336625143.370 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-10T04:45:43.631Z,1336625143.631 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:45:43.631Z,1336625143.631 [Default:CallIridium:B] Stopped
2012-05-10T04:45:43.631Z,1336625143.631 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:45:43.631Z,1336625143.631 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:45:43.631Z,1336625143.631 [Default:CallIridium] Stopped
2012-05-10T04:45:43.632Z,1336625143.632 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:49:02.413Z,1336625342.413 [NAL9601](IMPORTANT): GPS fix at: 1336625393.00
2012-05-10T04:49:02.451Z,1336625342.451 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:49:02.451Z,1336625342.451 [Default:GPS:D] Running Loop=1
2012-05-10T04:49:02.842Z,1336625342.842 [Default:GPS:D] Stopped
2012-05-10T04:49:02.847Z,1336625342.847 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T04:49:02.847Z,1336625342.847 [Default:GPS] Stopped
2012-05-10T04:49:02.847Z,1336625342.847 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:49:02.847Z,1336625342.847 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:49:02.847Z,1336625342.847 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:49:18.408Z,1336625358.408 [NAL9601](INFO): Powering down
2012-05-10T04:50:43.400Z,1336625443.400 [Default:CallIridium] Running Loop=1
2012-05-10T04:50:43.400Z,1336625443.400 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:50:43.400Z,1336625443.400 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:50:43.400Z,1336625443.400 [Default:CallIridium:A] Stopped
2012-05-10T04:50:43.400Z,1336625443.401 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:50:43.401Z,1336625443.401 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:50:48.436Z,1336625448.436 [Default:Iridium] Running Loop=1
2012-05-10T04:50:48.436Z,1336625448.436 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:50:48.437Z,1336625448.437 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:50:48.437Z,1336625448.437 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:50:48.437Z,1336625448.437 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:50:48.437Z,1336625448.437 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:50:48.438Z,1336625448.438 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:50:48.438Z,1336625448.438 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:50:48.438Z,1336625448.438 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:50:48.438Z,1336625448.438 [Default:GPS] Running Loop=1
2012-05-10T04:50:48.439Z,1336625448.439 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:50:48.439Z,1336625448.439 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:50:48.439Z,1336625448.439 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:50:48.439Z,1336625448.439 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:50:48.439Z,1336625448.439 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:50:48.440Z,1336625448.440 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:50:48.440Z,1336625448.441 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:50:48.441Z,1336625448.441 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:50:49.010Z,1336625449.010 [NAL9601](INFO): Powering up
2012-05-10T04:51:54.735Z,1336625514.735 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:52:09.748Z,1336625529.748 [NAL9601](INFO): SBD MO Status=1, MOMSN=6404, MT Status=0, MTMSN=0
2012-05-10T04:52:09.903Z,1336625529.903 [NAL9601](INFO): Sent 237 bytes from file Logs/20120510T031812/shore0012.lzma
2012-05-10T04:52:09.903Z,1336625529.903 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:52:09.904Z,1336625529.904 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000021
2012-05-10T04:52:20.149Z,1336625540.149 [NAL9601](INFO): SBD MO Status=0, MOMSN=6405, MT Status=0, MTMSN=0
2012-05-10T04:52:20.301Z,1336625540.301 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:52:20.301Z,1336625540.301 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:52:20.301Z,1336625540.301 [Default:Iridium] Stopped
2012-05-10T04:52:20.302Z,1336625540.302 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:52:20.302Z,1336625540.302 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:52:20.302Z,1336625540.302 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:52:20.562Z,1336625540.562 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:52:20.562Z,1336625540.562 [Default:CallIridium:B] Stopped
2012-05-10T04:52:20.562Z,1336625540.562 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:52:20.563Z,1336625540.563 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:52:20.563Z,1336625540.563 [Default:CallIridium] Stopped
2012-05-10T04:52:20.563Z,1336625540.563 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T04:54:25.802Z,1336625665.802 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-05-10T04:54:25.803Z,1336625665.803 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-05-10T04:54:25.803Z,1336625665.803 [AHRS_sp3003D](ERROR): Communications Fault
2012-05-10T04:54:25.830Z,1336625665.830 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-05-10T04:54:26.121Z,1336625666.121 [AHRS_sp3003D](INFO): Powering down
2012-05-10T04:54:26.234Z,1336625666.234 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-05-10T04:54:26.234Z,1336625666.234 [AHRS_sp3003D] No Fault, FailCount= 1
2012-05-10T04:54:27.321Z,1336625667.321 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-10T04:55:13.349Z,1336625713.349 [NAL9601](IMPORTANT): GPS fix at: 1336625765.00
2012-05-10T04:55:13.363Z,1336625713.363 [Default:GPS:Read_GPS] Stopped
2012-05-10T04:55:13.363Z,1336625713.364 [Default:GPS:D] Running Loop=1
2012-05-10T04:55:13.764Z,1336625713.764 [Default:GPS:D] Stopped
2012-05-10T04:55:13.765Z,1336625713.765 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T04:55:13.765Z,1336625713.765 [Default:GPS] Stopped
2012-05-10T04:55:13.765Z,1336625713.765 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T04:55:13.765Z,1336625713.765 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T04:55:13.765Z,1336625713.765 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:55:29.312Z,1336625729.312 [NAL9601](INFO): Powering down
2012-05-10T04:57:24.402Z,1336625844.402 [Default:CallIridium] Running Loop=1
2012-05-10T04:57:24.403Z,1336625844.403 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T04:57:24.403Z,1336625844.403 [Default:CallIridium:A] Running Loop=1
2012-05-10T04:57:24.403Z,1336625844.403 [Default:CallIridium:A] Stopped
2012-05-10T04:57:24.403Z,1336625844.403 [Default:CallIridium:B] Running Loop=1
2012-05-10T04:57:24.403Z,1336625844.403 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T04:57:29.307Z,1336625849.307 [Default:Iridium] Running Loop=1
2012-05-10T04:57:29.307Z,1336625849.307 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T04:57:29.308Z,1336625849.307 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T04:57:29.308Z,1336625849.307 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:57:29.308Z,1336625849.308 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T04:57:29.308Z,1336625849.308 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:57:29.309Z,1336625849.309 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T04:57:29.309Z,1336625849.309 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:57:29.309Z,1336625849.309 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T04:57:29.309Z,1336625849.309 [Default:GPS] Running Loop=1
2012-05-10T04:57:29.309Z,1336625849.309 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T04:57:29.310Z,1336625849.309 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T04:57:29.310Z,1336625849.310 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T04:57:29.310Z,1336625849.310 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T04:57:29.310Z,1336625849.310 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T04:57:29.311Z,1336625849.311 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T04:57:29.311Z,1336625849.311 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T04:57:29.311Z,1336625849.311 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T04:57:29.950Z,1336625849.950 [NAL9601](INFO): Powering up
2012-05-10T04:58:35.675Z,1336625915.675 [NAL9601](INFO): NAL9601 initialized
2012-05-10T04:58:51.955Z,1336625931.955 [NAL9601](INFO): SBD MO Status=1, MOMSN=6406, MT Status=0, MTMSN=0
2012-05-10T04:58:52.139Z,1336625932.139 [NAL9601](INFO): Sent 261 bytes from file Logs/20120510T031812/shore0013.lzma
2012-05-10T04:58:52.139Z,1336625932.139 [NAL9601](INFO): Packets left to send: 0
2012-05-10T04:58:52.140Z,1336625932.140 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000022
2012-05-10T04:58:59.152Z,1336625939.152 [NAL9601](INFO): SBD MO Status=0, MOMSN=6407, MT Status=0, MTMSN=0
2012-05-10T04:58:59.349Z,1336625939.349 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T04:58:59.350Z,1336625939.349 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T04:58:59.350Z,1336625939.350 [Default:Iridium] Stopped
2012-05-10T04:58:59.350Z,1336625939.350 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T04:58:59.350Z,1336625939.350 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T04:58:59.350Z,1336625939.350 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium:B] Stopped
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium] Stopped
2012-05-10T04:58:59.569Z,1336625939.569 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:01:42.400Z,1336626102.401 [NAL9601](IMPORTANT): GPS fix at: 1336626154.00
2012-05-10T05:01:42.415Z,1336626102.415 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:01:42.415Z,1336626102.415 [Default:GPS:D] Running Loop=1
2012-05-10T05:01:42.789Z,1336626102.789 [Default:GPS:D] Stopped
2012-05-10T05:01:42.789Z,1336626102.789 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:01:42.789Z,1336626102.789 [Default:GPS] Stopped
2012-05-10T05:01:42.789Z,1336626102.789 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:01:42.789Z,1336626102.789 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:01:42.790Z,1336626102.790 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:01:58.304Z,1336626118.304 [NAL9601](INFO): Powering down
2012-05-10T05:04:03.330Z,1336626243.330 [Default:CallIridium] Running Loop=1
2012-05-10T05:04:03.330Z,1336626243.330 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:04:03.331Z,1336626243.332 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:04:03.332Z,1336626243.332 [Default:CallIridium:A] Stopped
2012-05-10T05:04:03.332Z,1336626243.332 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:04:03.332Z,1336626243.332 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:04:08.369Z,1336626248.369 [Default:Iridium] Running Loop=1
2012-05-10T05:04:08.369Z,1336626248.369 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:04:08.370Z,1336626248.369 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:04:08.370Z,1336626248.370 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:04:08.370Z,1336626248.370 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:04:08.370Z,1336626248.370 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:04:08.371Z,1336626248.371 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:04:08.371Z,1336626248.371 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:04:08.371Z,1336626248.371 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:04:08.371Z,1336626248.371 [Default:GPS] Running Loop=1
2012-05-10T05:04:08.371Z,1336626248.372 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:04:08.372Z,1336626248.372 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:04:08.372Z,1336626248.372 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:04:08.372Z,1336626248.372 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:04:08.372Z,1336626248.372 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:04:08.373Z,1336626248.373 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:04:08.373Z,1336626248.373 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:04:08.373Z,1336626248.373 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:04:08.971Z,1336626248.971 [NAL9601](INFO): Powering up
2012-05-10T05:05:14.595Z,1336626314.595 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:05:31.312Z,1336626331.312 [NAL9601](INFO): SBD MO Status=1, MOMSN=6408, MT Status=0, MTMSN=0
2012-05-10T05:05:31.459Z,1336626331.459 [NAL9601](INFO): Sent 209 bytes from file Logs/20120510T031812/shore0014.lzma
2012-05-10T05:05:31.459Z,1336626331.459 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:05:31.460Z,1336626331.460 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000023
2012-05-10T05:05:42.112Z,1336626342.112 [NAL9601](INFO): SBD MO Status=0, MOMSN=6409, MT Status=0, MTMSN=0
2012-05-10T05:05:42.253Z,1336626342.253 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:05:42.254Z,1336626342.254 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:05:42.254Z,1336626342.254 [Default:Iridium] Stopped
2012-05-10T05:05:42.254Z,1336626342.254 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:05:42.254Z,1336626342.254 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:05:42.254Z,1336626342.254 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium:B] Stopped
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium] Stopped
2012-05-10T05:05:42.525Z,1336626342.525 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:07:35.325Z,1336626455.325 [NAL9601](IMPORTANT): GPS fix at: 1336626508.00
2012-05-10T05:07:35.354Z,1336626455.354 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:07:35.354Z,1336626455.354 [Default:GPS:D] Running Loop=1
2012-05-10T05:07:35.742Z,1336626455.742 [Default:GPS:D] Stopped
2012-05-10T05:07:35.743Z,1336626455.743 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:07:35.743Z,1336626455.743 [Default:GPS] Stopped
2012-05-10T05:07:35.743Z,1336626455.743 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:07:35.743Z,1336626455.743 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:07:35.743Z,1336626455.743 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:07:51.312Z,1336626471.312 [NAL9601](INFO): Powering down
2012-05-10T05:10:46.317Z,1336626646.316 [Default:CallIridium] Running Loop=1
2012-05-10T05:10:46.317Z,1336626646.317 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:10:46.317Z,1336626646.317 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:10:46.317Z,1336626646.317 [Default:CallIridium:A] Stopped
2012-05-10T05:10:46.317Z,1336626646.317 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:10:46.317Z,1336626646.317 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium] Running Loop=1
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:10:51.297Z,1336626651.297 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:10:51.299Z,1336626651.299 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:10:51.299Z,1336626651.299 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:10:51.299Z,1336626651.299 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS] Running Loop=1
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:10:51.300Z,1336626651.300 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:10:51.302Z,1336626651.302 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:10:51.302Z,1336626651.302 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:10:51.302Z,1336626651.302 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:10:51.925Z,1336626651.925 [NAL9601](INFO): Powering up
2012-05-10T05:11:28.371Z,1336626688.371 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-05-10T05:11:28.371Z,1336626688.371 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-05-10T05:11:28.371Z,1336626688.371 [AHRS_sp3003D](ERROR): Communications Fault
2012-05-10T05:11:28.398Z,1336626688.398 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-05-10T05:11:28.684Z,1336626688.684 [AHRS_sp3003D](INFO): Powering down
2012-05-10T05:11:28.804Z,1336626688.804 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-05-10T05:11:28.804Z,1336626688.804 [AHRS_sp3003D] No Fault, FailCount= 1
2012-05-10T05:11:29.884Z,1336626689.884 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-10T05:11:57.611Z,1336626717.611 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:12:18.728Z,1336626738.728 [NAL9601](INFO): SBD MO Status=1, MOMSN=6410, MT Status=0, MTMSN=0
2012-05-10T05:12:18.871Z,1336626738.871 [NAL9601](INFO): Sent 231 bytes from file Logs/20120510T031812/shore0015.lzma
2012-05-10T05:12:18.871Z,1336626738.871 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:12:18.872Z,1336626738.872 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000024
2012-05-10T05:12:25.930Z,1336626745.931 [NAL9601](INFO): SBD MO Status=0, MOMSN=6411, MT Status=0, MTMSN=0
2012-05-10T05:12:26.073Z,1336626746.073 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:12:26.074Z,1336626746.074 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:12:26.074Z,1336626746.074 [Default:Iridium] Stopped
2012-05-10T05:12:26.074Z,1336626746.074 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:12:26.074Z,1336626746.074 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:12:26.074Z,1336626746.074 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:12:26.340Z,1336626746.340 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:12:26.340Z,1336626746.340 [Default:CallIridium:B] Stopped
2012-05-10T05:12:26.341Z,1336626746.341 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:12:26.341Z,1336626746.341 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:12:26.341Z,1336626746.341 [Default:CallIridium] Stopped
2012-05-10T05:12:26.341Z,1336626746.341 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:15:11.129Z,1336626911.129 [NAL9601](IMPORTANT): GPS fix at: 1336626964.00
2012-05-10T05:15:11.144Z,1336626911.144 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:15:11.144Z,1336626911.144 [Default:GPS:D] Running Loop=1
2012-05-10T05:15:11.542Z,1336626911.542 [Default:GPS:D] Stopped
2012-05-10T05:15:11.542Z,1336626911.542 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:15:11.543Z,1336626911.543 [Default:GPS] Stopped
2012-05-10T05:15:11.543Z,1336626911.543 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:15:11.543Z,1336626911.543 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:15:11.543Z,1336626911.543 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:15:27.119Z,1336626927.119 [NAL9601](INFO): Powering down
2012-05-10T05:17:27.106Z,1336627047.106 [Default:CallIridium] Running Loop=1
2012-05-10T05:17:27.107Z,1336627047.107 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:17:27.107Z,1336627047.107 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:17:27.107Z,1336627047.107 [Default:CallIridium:A] Stopped
2012-05-10T05:17:27.107Z,1336627047.107 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:17:27.107Z,1336627047.107 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium] Running Loop=1
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:17:32.155Z,1336627052.155 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:17:32.156Z,1336627052.156 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:17:32.156Z,1336627052.156 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:17:32.156Z,1336627052.157 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS] Running Loop=1
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:17:32.157Z,1336627052.157 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:17:32.163Z,1336627052.163 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:17:32.163Z,1336627052.163 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:17:32.163Z,1336627052.163 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:17:32.942Z,1336627052.942 [NAL9601](INFO): Powering up
2012-05-10T05:18:38.567Z,1336627118.567 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:18:57.188Z,1336627137.188 [NAL9601](INFO): SBD MO Status=1, MOMSN=6412, MT Status=0, MTMSN=0
2012-05-10T05:18:57.327Z,1336627137.327 [NAL9601](INFO): Sent 190 bytes from file Logs/20120510T031812/shore0016.lzma
2012-05-10T05:18:57.327Z,1336627137.327 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:18:57.328Z,1336627137.328 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000025
2012-05-10T05:19:04.428Z,1336627144.428 [NAL9601](INFO): SBD MO Status=0, MOMSN=6413, MT Status=0, MTMSN=0
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium] Stopped
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:19:04.629Z,1336627144.629 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium:B] Stopped
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium] Stopped
2012-05-10T05:19:04.839Z,1336627144.839 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:22:58.161Z,1336627378.161 [NAL9601](IMPORTANT): GPS fix at: 1336627432.00
2012-05-10T05:22:58.176Z,1336627378.176 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:22:58.176Z,1336627378.176 [Default:GPS:D] Running Loop=1
2012-05-10T05:22:58.617Z,1336627378.617 [Default:GPS:D] Stopped
2012-05-10T05:22:58.618Z,1336627378.618 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:22:58.618Z,1336627378.618 [Default:GPS] Stopped
2012-05-10T05:22:58.618Z,1336627378.618 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:22:58.618Z,1336627378.618 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:22:58.618Z,1336627378.618 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:23:14.101Z,1336627394.101 [NAL9601](INFO): Powering down
2012-05-10T05:24:09.186Z,1336627449.186 [Default:CallIridium] Running Loop=1
2012-05-10T05:24:09.186Z,1336627449.186 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:24:09.187Z,1336627449.187 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:24:09.187Z,1336627449.187 [Default:CallIridium:A] Stopped
2012-05-10T05:24:09.187Z,1336627449.187 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:24:09.187Z,1336627449.187 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:24:14.293Z,1336627454.293 [Default:Iridium] Running Loop=1
2012-05-10T05:24:14.293Z,1336627454.293 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:24:14.293Z,1336627454.293 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:24:14.293Z,1336627454.293 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:24:14.294Z,1336627454.293 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:24:14.294Z,1336627454.294 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:24:14.299Z,1336627454.299 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:24:14.299Z,1336627454.299 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:24:14.299Z,1336627454.299 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:24:14.299Z,1336627454.299 [Default:GPS] Running Loop=1
2012-05-10T05:24:14.300Z,1336627454.300 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:24:14.300Z,1336627454.300 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:24:14.300Z,1336627454.300 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:24:14.300Z,1336627454.300 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:24:14.300Z,1336627454.300 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:24:14.301Z,1336627454.301 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:24:14.301Z,1336627454.301 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:24:14.301Z,1336627454.301 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:24:14.998Z,1336627454.998 [NAL9601](INFO): Powering up
2012-05-10T05:25:20.723Z,1336627520.723 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:25:44.248Z,1336627544.248 [NAL9601](INFO): SBD MO Status=1, MOMSN=6414, MT Status=0, MTMSN=0
2012-05-10T05:25:44.375Z,1336627544.375 [NAL9601](INFO): Sent 188 bytes from file Logs/20120510T031812/shore0017.lzma
2012-05-10T05:25:44.375Z,1336627544.375 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:25:44.376Z,1336627544.376 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000026
2012-05-10T05:25:50.653Z,1336627550.653 [NAL9601](INFO): SBD MO Status=0, MOMSN=6415, MT Status=0, MTMSN=0
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium] Stopped
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:25:50.887Z,1336627550.887 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:25:51.125Z,1336627551.125 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:25:51.125Z,1336627551.125 [Default:CallIridium:B] Stopped
2012-05-10T05:25:51.125Z,1336627551.125 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:25:51.126Z,1336627551.126 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:25:51.126Z,1336627551.126 [Default:CallIridium] Stopped
2012-05-10T05:25:51.126Z,1336627551.126 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:26:10.281Z,1336627570.281 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T05:26:10.281Z,1336627570.281 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T05:26:10.281Z,1336627570.281 [DropWeight](ERROR): Hardware Fault
2012-05-10T05:26:10.327Z,1336627570.327 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T05:26:10.327Z,1336627570.327 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T05:27:34.152Z,1336627654.152 [NAL9601](IMPORTANT): GPS fix at: 1336627709.00
2012-05-10T05:27:34.167Z,1336627654.167 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:27:34.167Z,1336627654.167 [Default:GPS:D] Running Loop=1
2012-05-10T05:27:34.585Z,1336627654.585 [Default:GPS:D] Stopped
2012-05-10T05:27:34.586Z,1336627654.586 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:27:34.586Z,1336627654.586 [Default:GPS] Stopped
2012-05-10T05:27:34.586Z,1336627654.586 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:27:34.586Z,1336627654.586 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:27:34.586Z,1336627654.586 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:27:50.110Z,1336627670.110 [NAL9601](INFO): Powering down
2012-05-10T05:30:55.122Z,1336627855.122 [Default:CallIridium] Running Loop=1
2012-05-10T05:30:55.123Z,1336627855.123 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:30:55.123Z,1336627855.123 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:30:55.123Z,1336627855.123 [Default:CallIridium:A] Stopped
2012-05-10T05:30:55.123Z,1336627855.123 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:30:55.123Z,1336627855.123 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium] Running Loop=1
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:31:00.121Z,1336627860.121 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:31:00.123Z,1336627860.123 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:31:00.123Z,1336627860.123 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:31:00.123Z,1336627860.123 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:31:00.123Z,1336627860.123 [Default:GPS] Running Loop=1
2012-05-10T05:31:00.123Z,1336627860.123 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:31:00.123Z,1336627860.124 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:31:00.123Z,1336627860.124 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:31:00.124Z,1336627860.124 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:31:00.124Z,1336627860.124 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:31:00.125Z,1336627860.125 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:31:00.125Z,1336627860.125 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:31:00.125Z,1336627860.125 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:31:00.750Z,1336627860.750 [NAL9601](INFO): Powering up
2012-05-10T05:31:10.405Z,1336627870.405 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T05:31:10.405Z,1336627870.405 [DropWeight] No Fault, FailCount= 1
2012-05-10T05:32:06.475Z,1336627926.475 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:32:23.556Z,1336627943.556 [NAL9601](INFO): SBD MO Status=1, MOMSN=6416, MT Status=0, MTMSN=0
2012-05-10T05:32:23.735Z,1336627943.735 [NAL9601](INFO): Sent 274 bytes from file Logs/20120510T031812/shore0018.lzma
2012-05-10T05:32:23.735Z,1336627943.735 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:32:23.736Z,1336627943.736 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000027
2012-05-10T05:32:26.752Z,1336627946.752 [NAL9601](INFO): SBD MO Status=0, MOMSN=6417, MT Status=0, MTMSN=0
2012-05-10T05:32:26.945Z,1336627946.945 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:32:26.945Z,1336627946.945 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:32:26.945Z,1336627946.945 [Default:Iridium] Stopped
2012-05-10T05:32:26.945Z,1336627946.945 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:32:26.946Z,1336627946.945 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:32:26.946Z,1336627946.945 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:32:27.210Z,1336627947.210 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:32:27.210Z,1336627947.210 [Default:CallIridium:B] Stopped
2012-05-10T05:32:27.210Z,1336627947.210 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:32:27.210Z,1336627947.210 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:32:27.236Z,1336627947.237 [Default:CallIridium] Stopped
2012-05-10T05:32:27.237Z,1336627947.237 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:32:29.954Z,1336627949.954 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T05:32:29.954Z,1336627949.954 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T05:32:29.954Z,1336627949.954 [DropWeight](ERROR): Hardware Fault
2012-05-10T05:32:30.001Z,1336627950.001 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T05:32:30.002Z,1336627950.001 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T05:34:09.957Z,1336628049.957 [NAL9601](IMPORTANT): GPS fix at: 1336628105.00
2012-05-10T05:34:09.975Z,1336628049.974 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:34:09.975Z,1336628049.975 [Default:GPS:D] Running Loop=1
2012-05-10T05:34:10.368Z,1336628050.368 [Default:GPS:D] Stopped
2012-05-10T05:34:10.369Z,1336628050.369 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:34:10.369Z,1336628050.369 [Default:GPS] Stopped
2012-05-10T05:34:10.369Z,1336628050.369 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:34:10.369Z,1336628050.369 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:34:10.369Z,1336628050.369 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:34:25.920Z,1336628065.920 [NAL9601](INFO): Powering down
2012-05-10T05:37:30.946Z,1336628250.946 [Default:CallIridium] Running Loop=1
2012-05-10T05:37:30.946Z,1336628250.946 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:37:30.951Z,1336628250.951 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:37:30.951Z,1336628250.951 [Default:CallIridium:A] Stopped
2012-05-10T05:37:30.951Z,1336628250.951 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:37:30.951Z,1336628250.951 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:37:30.969Z,1336628250.969 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T05:37:30.969Z,1336628250.969 [DropWeight] No Fault, FailCount= 1
2012-05-10T05:37:35.939Z,1336628255.940 [Default:Iridium] Running Loop=1
2012-05-10T05:37:35.940Z,1336628255.940 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:37:35.940Z,1336628255.940 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:37:35.940Z,1336628255.940 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:37:35.940Z,1336628255.940 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:37:35.940Z,1336628255.940 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:37:35.941Z,1336628255.941 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:37:35.941Z,1336628255.941 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:37:35.941Z,1336628255.941 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS] Running Loop=1
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:37:35.942Z,1336628255.942 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:37:35.943Z,1336628255.943 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:37:35.943Z,1336628255.944 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:37:35.944Z,1336628255.944 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:37:36.550Z,1336628256.550 [NAL9601](INFO): Powering up
2012-05-10T05:37:56.174Z,1336628276.174 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T05:37:56.174Z,1336628276.174 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T05:37:56.174Z,1336628276.174 [DropWeight](ERROR): Hardware Fault
2012-05-10T05:37:56.233Z,1336628276.233 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T05:37:56.233Z,1336628276.233 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T05:38:42.275Z,1336628322.275 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:38:59.333Z,1336628339.333 [NAL9601](INFO): SBD MO Status=1, MOMSN=6418, MT Status=0, MTMSN=0
2012-05-10T05:38:59.539Z,1336628339.539 [NAL9601](INFO): Sent 263 bytes from file Logs/20120510T031812/shore0019.lzma
2012-05-10T05:38:59.539Z,1336628339.539 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:38:59.540Z,1336628339.540 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000028
2012-05-10T05:39:06.131Z,1336628346.131 [NAL9601](INFO): SBD MO Status=0, MOMSN=6419, MT Status=0, MTMSN=0
2012-05-10T05:39:06.387Z,1336628346.388 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:39:06.388Z,1336628346.388 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:39:06.388Z,1336628346.388 [Default:Iridium] Stopped
2012-05-10T05:39:06.388Z,1336628346.388 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:39:06.388Z,1336628346.388 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:39:06.388Z,1336628346.388 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:39:06.524Z,1336628346.524 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:39:06.524Z,1336628346.524 [Default:CallIridium:B] Stopped
2012-05-10T05:39:06.524Z,1336628346.524 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:39:06.524Z,1336628346.524 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:39:06.524Z,1336628346.524 [Default:CallIridium] Stopped
2012-05-10T05:39:06.525Z,1336628346.524 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:41:03.326Z,1336628463.326 [NAL9601](IMPORTANT): GPS fix at: 1336628519.00
2012-05-10T05:41:03.344Z,1336628463.344 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:41:03.344Z,1336628463.344 [Default:GPS:D] Running Loop=1
2012-05-10T05:41:03.740Z,1336628463.740 [Default:GPS:D] Stopped
2012-05-10T05:41:03.741Z,1336628463.741 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:41:03.741Z,1336628463.741 [Default:GPS] Stopped
2012-05-10T05:41:03.741Z,1336628463.741 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:41:03.741Z,1336628463.741 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:41:03.741Z,1336628463.741 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:41:19.299Z,1336628479.299 [NAL9601](INFO): Powering down
2012-05-10T05:42:59.329Z,1336628579.329 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T05:42:59.329Z,1336628579.329 [DropWeight] No Fault, FailCount= 1
2012-05-10T05:44:09.285Z,1336628649.285 [Default:CallIridium] Running Loop=1
2012-05-10T05:44:09.285Z,1336628649.285 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:44:09.285Z,1336628649.285 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:44:09.286Z,1336628649.286 [Default:CallIridium:A] Stopped
2012-05-10T05:44:09.286Z,1336628649.286 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:44:09.286Z,1336628649.286 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:44:14.322Z,1336628654.322 [Default:Iridium] Running Loop=1
2012-05-10T05:44:14.322Z,1336628654.322 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:44:14.322Z,1336628654.322 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:44:14.323Z,1336628654.323 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:44:14.323Z,1336628654.323 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:44:14.323Z,1336628654.323 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:44:14.324Z,1336628654.324 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:44:14.324Z,1336628654.324 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:44:14.324Z,1336628654.324 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:44:14.324Z,1336628654.324 [Default:GPS] Running Loop=1
2012-05-10T05:44:14.324Z,1336628654.325 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:44:14.325Z,1336628654.325 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:44:14.325Z,1336628654.325 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:44:14.325Z,1336628654.325 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:44:14.325Z,1336628654.325 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:44:14.326Z,1336628654.326 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:44:14.326Z,1336628654.326 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:44:14.326Z,1336628654.326 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:44:15.930Z,1336628655.930 [NAL9601](INFO): Powering up
2012-05-10T05:45:21.699Z,1336628721.699 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:46:48.483Z,1336628808.483 [NAL9601](INFO): SBD MO Status=2, MOMSN=6420, MT Status=2, MTMSN=0
2012-05-10T05:46:48.484Z,1336628808.484 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-10T05:47:10.447Z,1336628830.447 [NAL9601](INFO): SBD MO Status=1, MOMSN=6420, MT Status=0, MTMSN=0
2012-05-10T05:47:10.615Z,1336628830.615 [NAL9601](INFO): Sent 233 bytes from file Logs/20120510T031812/shore0020.lzma
2012-05-10T05:47:10.615Z,1336628830.615 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:47:10.617Z,1336628830.617 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000029
2012-05-10T05:47:18.448Z,1336628838.448 [NAL9601](INFO): SBD MO Status=0, MOMSN=6421, MT Status=0, MTMSN=0
2012-05-10T05:47:18.619Z,1336628838.619 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:47:18.619Z,1336628838.619 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:47:18.619Z,1336628838.619 [Default:Iridium] Stopped
2012-05-10T05:47:18.619Z,1336628838.619 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:47:18.620Z,1336628838.620 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:47:18.620Z,1336628838.620 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:47:18.864Z,1336628838.864 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:47:18.864Z,1336628838.864 [Default:CallIridium:B] Stopped
2012-05-10T05:47:18.864Z,1336628838.864 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:47:18.864Z,1336628838.864 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:47:18.864Z,1336628838.865 [Default:CallIridium] Stopped
2012-05-10T05:47:18.865Z,1336628838.865 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:47:19.649Z,1336628839.649 [NAL9601](IMPORTANT): GPS fix at: 1336628896.00
2012-05-10T05:47:19.666Z,1336628839.666 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:47:19.666Z,1336628839.666 [Default:GPS:D] Running Loop=1
2012-05-10T05:47:20.061Z,1336628840.061 [Default:GPS:D] Stopped
2012-05-10T05:47:20.062Z,1336628840.062 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:47:20.062Z,1336628840.062 [Default:GPS] Stopped
2012-05-10T05:47:20.062Z,1336628840.062 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:47:20.062Z,1336628840.062 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:47:20.062Z,1336628840.062 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:47:35.631Z,1336628855.631 [NAL9601](INFO): Powering down
2012-05-10T05:52:20.603Z,1336629140.603 [Default:CallIridium] Running Loop=1
2012-05-10T05:52:20.603Z,1336629140.603 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:52:20.603Z,1336629140.603 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:52:20.604Z,1336629140.604 [Default:CallIridium:A] Stopped
2012-05-10T05:52:20.604Z,1336629140.604 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:52:20.604Z,1336629140.604 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:52:25.656Z,1336629145.656 [Default:Iridium] Running Loop=1
2012-05-10T05:52:25.656Z,1336629145.657 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:52:25.657Z,1336629145.657 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:52:25.657Z,1336629145.657 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:52:25.657Z,1336629145.657 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:52:25.657Z,1336629145.657 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:52:25.658Z,1336629145.658 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:52:25.658Z,1336629145.658 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:52:25.658Z,1336629145.658 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS] Running Loop=1
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:52:25.659Z,1336629145.659 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:52:25.660Z,1336629145.660 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:52:25.660Z,1336629145.660 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:52:25.661Z,1336629145.661 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:52:26.246Z,1336629146.246 [NAL9601](INFO): Powering up
2012-05-10T05:53:31.971Z,1336629211.971 [NAL9601](INFO): NAL9601 initialized
2012-05-10T05:53:51.384Z,1336629231.384 [NAL9601](INFO): SBD MO Status=1, MOMSN=6422, MT Status=0, MTMSN=0
2012-05-10T05:53:51.527Z,1336629231.527 [NAL9601](INFO): Sent 224 bytes from file Logs/20120510T031812/shore0021.lzma
2012-05-10T05:53:51.527Z,1336629231.527 [NAL9601](INFO): Packets left to send: 0
2012-05-10T05:53:51.528Z,1336629231.528 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000030
2012-05-10T05:54:04.223Z,1336629244.223 [NAL9601](INFO): SBD MO Status=0, MOMSN=6423, MT Status=0, MTMSN=0
2012-05-10T05:54:04.425Z,1336629244.425 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T05:54:04.425Z,1336629244.425 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T05:54:04.425Z,1336629244.425 [Default:Iridium] Stopped
2012-05-10T05:54:04.425Z,1336629244.425 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T05:54:04.426Z,1336629244.425 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T05:54:04.426Z,1336629244.426 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:54:04.603Z,1336629244.603 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T05:54:04.603Z,1336629244.603 [Default:CallIridium:B] Stopped
2012-05-10T05:54:04.603Z,1336629244.603 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T05:54:04.604Z,1336629244.603 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T05:54:04.604Z,1336629244.603 [Default:CallIridium] Stopped
2012-05-10T05:54:04.604Z,1336629244.604 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T05:55:25.429Z,1336629325.429 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T05:55:25.429Z,1336629325.429 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T05:55:25.429Z,1336629325.429 [DropWeight](ERROR): Hardware Fault
2012-05-10T05:55:25.455Z,1336629325.455 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T05:55:25.456Z,1336629325.456 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T05:55:40.483Z,1336629340.483 [AHRS_sp3003D](FAULT): Read Magnetics Failure.
2012-05-10T05:55:40.483Z,1336629340.483 [AHRS_sp3003D] Communications Fault, FailCount= 1
2012-05-10T05:55:40.483Z,1336629340.483 [AHRS_sp3003D](ERROR): Communications Fault
2012-05-10T05:55:40.545Z,1336629340.545 [CBIT](ERROR): Communications Fault in component: AHRS_sp3003D
2012-05-10T05:55:40.663Z,1336629340.663 [AHRS_sp3003D](INFO): Powering down
2012-05-10T05:55:40.907Z,1336629340.907 [CBIT](INFO): Clearing failed state for component AHRS_sp3003D
2012-05-10T05:55:40.907Z,1336629340.907 [AHRS_sp3003D] No Fault, FailCount= 1
2012-05-10T05:55:41.854Z,1336629341.854 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-10T05:56:31.503Z,1336629391.503 [NAL9601](IMPORTANT): GPS fix at: 1336629449.00
2012-05-10T05:56:31.521Z,1336629391.521 [Default:GPS:Read_GPS] Stopped
2012-05-10T05:56:31.521Z,1336629391.521 [Default:GPS:D] Running Loop=1
2012-05-10T05:56:31.940Z,1336629391.940 [Default:GPS:D] Stopped
2012-05-10T05:56:31.941Z,1336629391.941 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T05:56:31.941Z,1336629391.941 [Default:GPS] Stopped
2012-05-10T05:56:31.941Z,1336629391.941 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T05:56:31.941Z,1336629391.941 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T05:56:31.941Z,1336629391.941 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T05:56:47.482Z,1336629407.482 [NAL9601](INFO): Powering down
2012-05-10T05:59:07.473Z,1336629547.473 [Default:CallIridium] Running Loop=1
2012-05-10T05:59:07.473Z,1336629547.473 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T05:59:07.473Z,1336629547.473 [Default:CallIridium:A] Running Loop=1
2012-05-10T05:59:07.474Z,1336629547.474 [Default:CallIridium:A] Stopped
2012-05-10T05:59:07.474Z,1336629547.474 [Default:CallIridium:B] Running Loop=1
2012-05-10T05:59:07.474Z,1336629547.474 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T05:59:12.624Z,1336629552.625 [Default:Iridium] Running Loop=1
2012-05-10T05:59:12.625Z,1336629552.625 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T05:59:12.625Z,1336629552.625 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T05:59:12.625Z,1336629552.625 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:59:12.625Z,1336629552.625 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T05:59:12.625Z,1336629552.625 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:59:12.626Z,1336629552.626 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T05:59:12.626Z,1336629552.626 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:59:12.631Z,1336629552.631 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T05:59:12.631Z,1336629552.631 [Default:GPS] Running Loop=1
2012-05-10T05:59:12.631Z,1336629552.631 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T05:59:12.631Z,1336629552.631 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T05:59:12.631Z,1336629552.631 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T05:59:12.632Z,1336629552.632 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T05:59:12.632Z,1336629552.632 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T05:59:12.633Z,1336629552.633 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T05:59:12.633Z,1336629552.633 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T05:59:12.633Z,1336629552.633 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T05:59:13.358Z,1336629553.358 [NAL9601](INFO): Powering up
2012-05-10T06:00:19.003Z,1336629619.003 [NAL9601](INFO): NAL9601 initialized
2012-05-10T06:00:25.848Z,1336629625.848 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T06:00:25.848Z,1336629625.848 [DropWeight] No Fault, FailCount= 1
2012-05-10T06:00:43.005Z,1336629643.005 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T06:00:43.005Z,1336629643.005 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T06:00:43.005Z,1336629643.005 [DropWeight](ERROR): Hardware Fault
2012-05-10T06:00:43.035Z,1336629643.035 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T06:00:43.036Z,1336629643.036 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T06:02:32.699Z,1336629752.699 [CTD_NeilBrown](ERROR): Bad response:  -1.30
2012-05-10T06:03:02.194Z,1336629782.194 [NAL9601](IMPORTANT): GPS fix at: 1336629840.00
2012-05-10T06:03:02.212Z,1336629782.212 [Default:GPS:Read_GPS] Stopped
2012-05-10T06:03:02.213Z,1336629782.213 [Default:GPS:D] Running Loop=1
2012-05-10T06:03:02.635Z,1336629782.635 [Default:GPS:D] Stopped
2012-05-10T06:03:02.636Z,1336629782.635 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T06:03:02.636Z,1336629782.636 [Default:GPS] Stopped
2012-05-10T06:03:02.636Z,1336629782.636 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T06:03:02.636Z,1336629782.636 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T06:03:02.636Z,1336629782.636 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:04:20.925Z,1336629860.925 [NAL9601](INFO): SBD MO Status=1, MOMSN=6424, MT Status=0, MTMSN=0
2012-05-10T06:04:21.119Z,1336629861.119 [NAL9601](INFO): Sent 320 bytes from file Logs/20120510T031812/shore0022.lzma
2012-05-10T06:04:21.119Z,1336629861.119 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:04:21.120Z,1336629861.120 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000031
2012-05-10T06:04:43.704Z,1336629883.704 [NAL9601](INFO): SBD MO Status=2, MOMSN=6425, MT Status=2, MTMSN=0
2012-05-10T06:04:43.704Z,1336629883.704 [NAL9601](ERROR): Failed to initiate SBD session. Error code: 2
2012-05-10T06:04:51.120Z,1336629891.120 [NAL9601](INFO): SBD MO Status=0, MOMSN=6425, MT Status=0, MTMSN=0
2012-05-10T06:04:51.285Z,1336629891.285 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T06:04:51.286Z,1336629891.286 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T06:04:51.286Z,1336629891.286 [Default:Iridium] Stopped
2012-05-10T06:04:51.286Z,1336629891.286 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T06:04:51.286Z,1336629891.286 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T06:04:51.286Z,1336629891.286 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium:B] Stopped
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium] Stopped
2012-05-10T06:04:51.535Z,1336629891.535 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T06:05:01.661Z,1336629901.661 [NAL9601](INFO): Powering down
2012-05-10T06:05:46.827Z,1336629946.827 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T06:05:46.827Z,1336629946.828 [DropWeight] No Fault, FailCount= 1
2012-05-10T06:06:36.544Z,1336629996.544 [CTD_NeilBrown](ERROR): Bad response: 97070
2012-05-10T06:09:51.695Z,1336630191.695 [Default:CallIridium] Running Loop=1
2012-05-10T06:09:51.695Z,1336630191.695 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T06:09:51.695Z,1336630191.695 [Default:CallIridium:A] Running Loop=1
2012-05-10T06:09:51.695Z,1336630191.695 [Default:CallIridium:A] Stopped
2012-05-10T06:09:51.695Z,1336630191.695 [Default:CallIridium:B] Running Loop=1
2012-05-10T06:09:51.696Z,1336630191.695 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium] Running Loop=1
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T06:09:56.748Z,1336630196.748 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:09:56.749Z,1336630196.749 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T06:09:56.749Z,1336630196.749 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:09:56.750Z,1336630196.750 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T06:09:56.750Z,1336630196.750 [Default:GPS] Running Loop=1
2012-05-10T06:09:56.750Z,1336630196.750 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T06:09:56.750Z,1336630196.750 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T06:09:56.750Z,1336630196.750 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:09:56.751Z,1336630196.751 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T06:09:56.751Z,1336630196.751 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:09:56.752Z,1336630196.752 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T06:09:56.752Z,1336630196.752 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:09:56.752Z,1336630196.752 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T06:09:57.438Z,1336630197.438 [NAL9601](INFO): Powering up
2012-05-10T06:10:56.238Z,1336630256.238 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T06:10:56.238Z,1336630256.238 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T06:10:56.238Z,1336630256.238 [DropWeight](ERROR): Hardware Fault
2012-05-10T06:10:56.264Z,1336630256.264 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T06:10:56.264Z,1336630256.264 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T06:11:03.167Z,1336630263.167 [NAL9601](INFO): NAL9601 initialized
2012-05-10T06:11:24.991Z,1336630284.991 [NAL9601](INFO): SBD MO Status=1, MOMSN=6426, MT Status=0, MTMSN=0
2012-05-10T06:11:25.115Z,1336630285.115 [NAL9601](INFO): Sent 310 bytes from file Logs/20120510T031812/shore0023.lzma
2012-05-10T06:11:25.115Z,1336630285.115 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:11:25.116Z,1336630285.116 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000032
2012-05-10T06:11:36.992Z,1336630296.992 [NAL9601](INFO): SBD MO Status=0, MOMSN=6427, MT Status=0, MTMSN=0
2012-05-10T06:11:37.236Z,1336630297.237 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T06:11:37.237Z,1336630297.237 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T06:11:37.237Z,1336630297.237 [Default:Iridium] Stopped
2012-05-10T06:11:37.237Z,1336630297.237 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T06:11:37.237Z,1336630297.237 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T06:11:37.237Z,1336630297.237 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:11:37.441Z,1336630297.441 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T06:11:37.441Z,1336630297.441 [Default:CallIridium:B] Stopped
2012-05-10T06:11:37.442Z,1336630297.441 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T06:11:37.442Z,1336630297.442 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T06:11:37.442Z,1336630297.442 [Default:CallIridium] Stopped
2012-05-10T06:11:37.442Z,1336630297.442 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T06:11:38.197Z,1336630298.197 [NAL9601](IMPORTANT): GPS fix at: 1336630357.00
2012-05-10T06:11:38.211Z,1336630298.211 [Default:GPS:Read_GPS] Stopped
2012-05-10T06:11:38.211Z,1336630298.211 [Default:GPS:D] Running Loop=1
2012-05-10T06:11:38.607Z,1336630298.607 [Default:GPS:D] Stopped
2012-05-10T06:11:38.607Z,1336630298.607 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T06:11:38.608Z,1336630298.608 [Default:GPS] Stopped
2012-05-10T06:11:38.608Z,1336630298.608 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T06:11:38.608Z,1336630298.608 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T06:11:38.608Z,1336630298.608 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:11:54.152Z,1336630314.152 [NAL9601](INFO): Powering down
2012-05-10T06:15:59.149Z,1336630559.149 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T06:15:59.149Z,1336630559.149 [DropWeight] No Fault, FailCount= 1
2012-05-10T06:16:39.164Z,1336630599.164 [Default:CallIridium] Running Loop=1
2012-05-10T06:16:39.165Z,1336630599.165 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T06:16:39.165Z,1336630599.165 [Default:CallIridium:A] Running Loop=1
2012-05-10T06:16:39.165Z,1336630599.165 [Default:CallIridium:A] Stopped
2012-05-10T06:16:39.165Z,1336630599.165 [Default:CallIridium:B] Running Loop=1
2012-05-10T06:16:39.165Z,1336630599.165 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium] Running Loop=1
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T06:16:44.185Z,1336630604.185 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:16:44.187Z,1336630604.187 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T06:16:44.187Z,1336630604.187 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:16:44.188Z,1336630604.188 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T06:16:44.188Z,1336630604.188 [Default:GPS] Running Loop=1
2012-05-10T06:16:44.188Z,1336630604.188 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T06:16:44.188Z,1336630604.188 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T06:16:44.188Z,1336630604.188 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:16:44.188Z,1336630604.188 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T06:16:44.189Z,1336630604.188 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:16:44.190Z,1336630604.190 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T06:16:44.190Z,1336630604.190 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:16:44.190Z,1336630604.190 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T06:16:44.791Z,1336630604.791 [NAL9601](INFO): Powering up
2012-05-10T06:16:56.010Z,1336630616.010 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T06:16:56.010Z,1336630616.010 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T06:16:56.010Z,1336630616.010 [DropWeight](ERROR): Hardware Fault
2012-05-10T06:16:56.072Z,1336630616.072 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T06:16:56.072Z,1336630616.072 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T06:17:50.519Z,1336630670.519 [NAL9601](INFO): NAL9601 initialized
2012-05-10T06:18:11.123Z,1336630691.124 [NAL9601](INFO): SBD MO Status=1, MOMSN=6428, MT Status=0, MTMSN=0
2012-05-10T06:18:11.275Z,1336630691.275 [NAL9601](INFO): Sent 282 bytes from file Logs/20120510T031812/shore0024.lzma
2012-05-10T06:18:11.275Z,1336630691.275 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:18:11.277Z,1336630691.277 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000033
2012-05-10T06:18:20.724Z,1336630700.724 [NAL9601](INFO): SBD MO Status=0, MOMSN=6429, MT Status=0, MTMSN=0
2012-05-10T06:18:20.885Z,1336630700.885 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T06:18:20.886Z,1336630700.886 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T06:18:20.886Z,1336630700.886 [Default:Iridium] Stopped
2012-05-10T06:18:20.886Z,1336630700.886 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T06:18:20.886Z,1336630700.886 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T06:18:20.886Z,1336630700.886 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium:B] Stopped
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium] Stopped
2012-05-10T06:18:21.133Z,1336630701.133 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T06:20:35.943Z,1336630835.943 [NAL9601](IMPORTANT): GPS fix at: 1336630895.00
2012-05-10T06:20:35.957Z,1336630835.957 [Default:GPS:Read_GPS] Stopped
2012-05-10T06:20:35.957Z,1336630835.957 [Default:GPS:D] Running Loop=1
2012-05-10T06:20:36.333Z,1336630836.333 [Default:GPS:D] Stopped
2012-05-10T06:20:36.334Z,1336630836.334 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T06:20:36.334Z,1336630836.334 [Default:GPS] Stopped
2012-05-10T06:20:36.334Z,1336630836.334 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T06:20:36.334Z,1336630836.334 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T06:20:36.334Z,1336630836.334 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:20:51.848Z,1336630851.848 [NAL9601](INFO): Powering down
2012-05-10T06:21:56.946Z,1336630916.946 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T06:21:56.946Z,1336630916.946 [DropWeight] No Fault, FailCount= 1
2012-05-10T06:23:21.902Z,1336631001.902 [Default:CallIridium] Running Loop=1
2012-05-10T06:23:21.902Z,1336631001.902 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T06:23:21.903Z,1336631001.903 [Default:CallIridium:A] Running Loop=1
2012-05-10T06:23:21.903Z,1336631001.903 [Default:CallIridium:A] Stopped
2012-05-10T06:23:21.903Z,1336631001.903 [Default:CallIridium:B] Running Loop=1
2012-05-10T06:23:21.903Z,1336631001.903 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T06:23:26.915Z,1336631006.915 [Default:Iridium] Running Loop=1
2012-05-10T06:23:26.915Z,1336631006.915 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T06:23:26.915Z,1336631006.915 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T06:23:26.916Z,1336631006.916 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:23:26.916Z,1336631006.916 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T06:23:26.916Z,1336631006.916 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:23:26.917Z,1336631006.917 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T06:23:26.917Z,1336631006.917 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:23:26.917Z,1336631006.917 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T06:23:26.917Z,1336631006.917 [Default:GPS] Running Loop=1
2012-05-10T06:23:26.918Z,1336631006.918 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T06:23:26.918Z,1336631006.918 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T06:23:26.918Z,1336631006.918 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:23:26.918Z,1336631006.918 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T06:23:26.918Z,1336631006.918 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:23:26.922Z,1336631006.922 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T06:23:26.922Z,1336631006.922 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:23:26.922Z,1336631006.922 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T06:23:27.518Z,1336631007.518 [NAL9601](INFO): Powering up
2012-05-10T06:24:33.243Z,1336631073.243 [NAL9601](INFO): NAL9601 initialized
2012-05-10T06:24:53.088Z,1336631093.088 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6430, MT Status=1, MTMSN=2615
2012-05-10T06:24:53.299Z,1336631093.299 [NAL9601](INFO): Sent 196 bytes from file Logs/20120510T031812/shore0025.lzma
2012-05-10T06:24:53.299Z,1336631093.299 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:24:53.300Z,1336631093.300 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000034
2012-05-10T06:24:53.743Z,1336631093.743 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-daphne/Sensor.cfg
2012-05-10T06:24:56.433Z,1336631096.433 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4FAB5DE2.part | gunzip -f -d | cat `cp Config/lrauv-daphne/.svn/text-base/Sensor.cfg.svn-base Config/lrauv-daphne/Sensor.cfg` | vim -e Config/lrauv-daphne/Sensor.cfg
2012-05-10T06:24:56.497Z,1336631096.497 [CommandLine](IMPORTANT): 47b7fd624f5247dc3636b61dc21ca3e6  Config/lrauv-daphne/Sensor.cfg

2012-05-10T06:24:56.512Z,1336631096.512 [CTD_NeilBrown](ERROR): Bad response: 1.22
2012-05-10T06:25:04.922Z,1336631104.922 [NAL9601](INFO): SBD MO Status=0, MOMSN=6431, MT Status=0, MTMSN=0
2012-05-10T06:25:18.511Z,1336631118.511 [NAL9601](INFO): SBD MO Status=1, MOMSN=6432, MT Status=0, MTMSN=0
2012-05-10T06:25:18.659Z,1336631118.659 [NAL9601](INFO): Sent 332 bytes from file Logs/20120510T031812/shore0026.lzma
2012-05-10T06:25:18.659Z,1336631118.659 [NAL9601](INFO): Packets left to send: 1
2012-05-10T06:25:18.660Z,1336631118.660 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000035
2012-05-10T06:25:29.854Z,1336631129.854 [NAL9601](INFO): SBD MO Status=1, MOMSN=6433, MT Status=0, MTMSN=0
2012-05-10T06:25:30.043Z,1336631130.043 [NAL9601](INFO): Sent 16 bytes from file Logs/20120510T031812/shore0026.lzma
2012-05-10T06:25:30.043Z,1336631130.043 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:25:30.044Z,1336631130.044 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000036
2012-05-10T06:25:39.034Z,1336631139.034 [NAL9601](INFO): SBD MO Status=0, MOMSN=6434, MT Status=0, MTMSN=0
2012-05-10T06:25:39.244Z,1336631139.244 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T06:25:39.245Z,1336631139.245 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-10T06:25:39.245Z,1336631139.245 [Default:Iridium] Stopped
2012-05-10T06:25:39.245Z,1336631139.245 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T06:25:39.245Z,1336631139.245 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T06:25:39.245Z,1336631139.245 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:25:39.464Z,1336631139.464 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-10T06:25:39.464Z,1336631139.464 [Default:CallIridium:B] Stopped
2012-05-10T06:25:39.465Z,1336631139.465 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T06:25:39.465Z,1336631139.465 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-10T06:25:39.465Z,1336631139.465 [Default:CallIridium] Stopped
2012-05-10T06:25:39.465Z,1336631139.465 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T06:26:40.645Z,1336631200.645 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2012-05-10T06:26:40.645Z,1336631200.645 [DropWeight] Hardware Fault, FailCount= 1
2012-05-10T06:26:40.645Z,1336631200.645 [DropWeight](ERROR): Hardware Fault
2012-05-10T06:26:40.674Z,1336631200.674 [CBIT](ERROR): Hardware Fault in component: DropWeight
2012-05-10T06:26:40.675Z,1336631200.675 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2012-05-10T06:28:34.229Z,1336631314.229 [NAL9601](IMPORTANT): GPS fix at: 1336631374.00
2012-05-10T06:28:34.257Z,1336631314.257 [Default:GPS:Read_GPS] Stopped
2012-05-10T06:28:34.258Z,1336631314.258 [Default:GPS:D] Running Loop=1
2012-05-10T06:28:34.640Z,1336631314.640 [Default:GPS:D] Stopped
2012-05-10T06:28:34.641Z,1336631314.641 [Default:GPS](INFO): Completed Default:GPS
2012-05-10T06:28:34.641Z,1336631314.641 [Default:GPS] Stopped
2012-05-10T06:28:34.641Z,1336631314.641 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T06:28:34.641Z,1336631314.641 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T06:28:34.641Z,1336631314.641 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:28:50.300Z,1336631330.300 [NAL9601](INFO): Powering down
2012-05-10T06:30:40.241Z,1336631440.241 [Default:CallIridium] Running Loop=1
2012-05-10T06:30:40.241Z,1336631440.241 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-10T06:30:40.241Z,1336631440.241 [Default:CallIridium:A] Running Loop=1
2012-05-10T06:30:40.242Z,1336631440.241 [Default:CallIridium:A] Stopped
2012-05-10T06:30:40.242Z,1336631440.242 [Default:CallIridium:B] Running Loop=1
2012-05-10T06:30:40.242Z,1336631440.242 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium] Running Loop=1
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-10T06:30:45.181Z,1336631445.181 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:30:45.182Z,1336631445.182 [Default:Iridium:B.GoToSurface] Stopped
2012-05-10T06:30:45.182Z,1336631445.182 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:30:45.183Z,1336631445.183 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-10T06:30:45.183Z,1336631445.183 [Default:GPS] Running Loop=1
2012-05-10T06:30:45.183Z,1336631445.183 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-10T06:30:45.183Z,1336631445.183 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-10T06:30:45.183Z,1336631445.183 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-10T06:30:45.183Z,1336631445.183 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-10T06:30:45.184Z,1336631445.184 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-10T06:30:45.184Z,1336631445.184 [Default:GPS:B.GoToSurface] Stopped
2012-05-10T06:30:45.184Z,1336631445.184 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:30:45.185Z,1336631445.185 [Default:GPS:Read_GPS] Running Loop=1
2012-05-10T06:30:45.825Z,1336631445.825 [NAL9601](INFO): Powering up
2012-05-10T06:31:40.656Z,1336631500.656 [CBIT](INFO): Clearing failed count for component DropWeight
2012-05-10T06:31:40.656Z,1336631500.656 [DropWeight] No Fault, FailCount= 1
2012-05-10T06:31:51.463Z,1336631511.463 [NAL9601](INFO): NAL9601 initialized
2012-05-10T06:32:11.032Z,1336631531.032 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=6435, MT Status=1, MTMSN=2616
2012-05-10T06:32:11.223Z,1336631531.223 [NAL9601](INFO): Sent 265 bytes from file Logs/20120510T031812/shore0027.lzma
2012-05-10T06:32:11.223Z,1336631531.223 [NAL9601](INFO): Packets left to send: 0
2012-05-10T06:32:11.224Z,1336631531.224 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000037
2012-05-10T06:32:11.640Z,1336631531.640 [NAL9601](INFO): Received command:restart application
2012-05-10T06:32:11.711Z,1336631531.711 [CommandLine](IMPORTANT): got command restart application
2012-05-10T06:32:11.878Z,1336631531.878 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-05-10T06:32:11.879Z,1336631531.879 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-05-10T06:32:11.962Z,1336631531.962 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-05-10T06:32:12.150Z,1336631532.151 [CTD_NeilBrown](INFO): Powering down
2012-05-10T06:32:12.151Z,1336631532.151 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-05-10T06:32:12.253Z,1336631532.253 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-05-10T06:32:12.253Z,1336631532.253 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-05-10T06:32:12.253Z,1336631532.253 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-05-10T06:32:12.283Z,1336631532.283 [controlThread](DEBUG): Uninitializing ControlThread
2012-05-10T06:32:12.283Z,1336631532.283 [AHRS_sp3003D](INFO): Powering down
2012-05-10T06:32:12.371Z,1336631532.372 [DVL_micro](INFO): Powering down
2012-05-10T06:32:12.372Z,1336631532.372 [NAL9601](INFO): Powering down
2012-05-10T06:32:12.373Z,1336631532.373 [WetLabsBB2FL](INFO): Powering down
2012-05-10T06:32:12.373Z,1336631532.373 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-05-10T06:32:12.375Z,1336631532.375 [Default] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default](INFO): Aggregate::uninitialize Default
2012-05-10T06:32:12.375Z,1336631532.375 [Default:GPS] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-10T06:32:12.375Z,1336631532.375 [Default:GPS:A.SetSpeed] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:32:12.375Z,1336631532.375 [Default:GPS:Read_GPS] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default:Iridium] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-10T06:32:12.375Z,1336631532.375 [Default:Iridium:A.SetSpeed] Stopped
2012-05-10T06:32:12.375Z,1336631532.375 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:32:12.376Z,1336631532.376 [Default:Iridium:Read_Iridium] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:CallIridium] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-10T06:32:12.376Z,1336631532.376 [Default:CallIridium:B] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-10T06:32:12.376Z,1336631532.376 [Default:D.SetSpeed] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-10T06:32:12.376Z,1336631532.376 [Default:E.GoToSurface] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-10T06:32:12.376Z,1336631532.376 [Default:F.Wait] Stopped
2012-05-10T06:32:12.376Z,1336631532.376 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-10T06:32:12.381Z,1336631532.381 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-05-10T06:32:12.381Z,1336631532.381 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-05-10T06:32:12.382Z,1336631532.382 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-05-10T06:32:12.382Z,1336631532.382 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-05-10T06:32:12.383Z,1336631532.383 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-05-10T06:32:12.383Z,1336631532.383 [BuoyancyServo](INFO): Powering down
2012-05-10T06:32:12.383Z,1336631532.383 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-05-10T06:32:12.383Z,1336631532.383 [ElevatorServo](INFO): Powering down
2012-05-10T06:32:12.384Z,1336631532.384 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-10T06:32:12.384Z,1336631532.384 [MassServo](INFO): Powering down
2012-05-10T06:32:12.384Z,1336631532.384 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-05-10T06:32:12.384Z,1336631532.384 [RudderServo](INFO): Powering down
2012-05-10T06:32:12.385Z,1336631532.385 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-10T06:32:12.385Z,1336631532.385 [ThrusterServo](INFO): Powering down
2012-05-10T06:32:12.385Z,1336631532.385 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-05-10T06:32:12.385Z,1336631532.385 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-05-10T06:32:12.386Z,1336631532.386 [CBIT](DEBUG): Uninitialize CBIT Component.