2014-04-20T09:27:29.722Z,1397986049.722 [Supervisor](DEBUG): Initializing supervisor.
2014-04-20T09:27:29.725Z,1397986049.725 [SyncHandler](DEBUG): Created PCaller Thread at 4033C4E0
2014-04-20T09:27:29.726Z,1397986049.726 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-04-20T09:27:29.727Z,1397986049.727 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036C4E0
2014-04-20T09:27:29.730Z,1397986049.730 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-04-20T09:27:29.741Z,1397986049.741 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-04-20T09:27:29.742Z,1397986049.742 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039C4E0
2014-04-20T09:27:29.743Z,1397986049.743 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-04-20T09:27:29.744Z,1397986049.744 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CC4E0
2014-04-20T09:27:29.746Z,1397986049.746 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-04-20T09:27:29.747Z,1397986049.747 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-04-20T09:27:29.751Z,1397986049.751 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-04-20T09:27:30.095Z,1397986050.095 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-04-20T09:27:30.096Z,1397986050.096 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-04-20T09:27:30.360Z,1397986050.360 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-04-20T09:27:30.361Z,1397986050.361 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-04-20T09:27:30.448Z,1397986050.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-04-20T09:27:30.451Z,1397986050.451 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-04-20T09:27:30.656Z,1397986050.656 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-04-20T09:27:30.657Z,1397986050.657 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-04-20T09:27:30.814Z,1397986050.814 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-04-20T09:27:30.817Z,1397986050.817 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-04-20T09:27:31.106Z,1397986051.106 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-04-20T09:27:31.107Z,1397986051.107 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-04-20T09:27:31.287Z,1397986051.287 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-04-20T09:27:31.290Z,1397986051.290 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-04-20T09:27:31.619Z,1397986051.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-04-20T09:27:31.621Z,1397986051.621 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-04-20T09:27:31.731Z,1397986051.731 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-04-20T09:27:31.732Z,1397986051.732 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-04-20T09:27:32.233Z,1397986052.233 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-04-20T09:27:32.233Z,1397986052.233 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-04-20T09:27:32.343Z,1397986052.343 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-04-20T09:27:32.344Z,1397986052.344 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-04-20T09:27:32.431Z,1397986052.431 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-04-20T09:27:32.540Z,1397986052.540 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-04-20T09:27:32.543Z,1397986052.543 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-04-20T09:27:32.650Z,1397986052.650 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-04-20T09:27:32.651Z,1397986052.651 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-04-20T09:27:32.844Z,1397986052.844 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-04-20T09:27:32.846Z,1397986052.846 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-04-20T09:27:32.850Z,1397986052.850 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-04-20T09:27:32.957Z,1397986052.957 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-04-20T09:27:33.087Z,1397986053.087 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-04-20T09:27:33.184Z,1397986053.184 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-04-20T09:27:33.278Z,1397986053.278 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-04-20T09:27:33.431Z,1397986053.431 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-04-20T09:27:33.548Z,1397986053.548 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-04-20T09:27:33.636Z,1397986053.636 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-04-20T09:27:33.740Z,1397986053.740 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-04-20T09:27:33.842Z,1397986053.842 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-04-20T09:27:33.940Z,1397986053.940 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-04-20T09:27:34.030Z,1397986054.030 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-04-20T09:27:34.128Z,1397986054.128 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2014-04-20T09:27:34.131Z,1397986054.131 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-04-20T09:27:34.826Z,1397986054.826 [AHRS_sp3003D] Loaded
2014-04-20T09:27:34.826Z,1397986054.826 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-04-20T09:27:35.119Z,1397986055.119 [Batt_Ocean_Server] Loaded
2014-04-20T09:27:35.119Z,1397986055.119 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-04-20T09:27:35.133Z,1397986055.133 [Depth_Keller] Loaded
2014-04-20T09:27:35.133Z,1397986055.133 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-04-20T09:27:35.138Z,1397986055.138 [DropWeight] Loaded
2014-04-20T09:27:35.138Z,1397986055.138 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-04-20T09:27:35.279Z,1397986055.279 [DVL_micro] Loaded
2014-04-20T09:27:35.279Z,1397986055.279 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-04-20T09:27:35.380Z,1397986055.380 [NAL9602] Loaded
2014-04-20T09:27:35.380Z,1397986055.380 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-04-20T09:27:35.432Z,1397986055.432 [Onboard] Loaded
2014-04-20T09:27:35.432Z,1397986055.432 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-04-20T09:27:35.440Z,1397986055.440 [Radio_Freewave] Loaded
2014-04-20T09:27:35.440Z,1397986055.440 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2014-04-20T09:27:35.446Z,1397986055.446 [SCPI] Loaded
2014-04-20T09:27:35.447Z,1397986055.447 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-04-20T09:27:35.447Z,1397986055.447 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-04-20T09:27:35.448Z,1397986055.448 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-04-20T09:27:35.641Z,1397986055.641 [InternalSim] Loaded
2014-04-20T09:27:35.641Z,1397986055.641 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-04-20T09:27:35.642Z,1397986055.642 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-04-20T09:27:35.642Z,1397986055.642 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-04-20T09:27:35.929Z,1397986055.929 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-04-20T09:27:35.929Z,1397986055.929 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-04-20T09:27:35.938Z,1397986055.938 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-04-20T09:27:35.943Z,1397986055.943 [AsyncPiEstimator] Loaded
2014-04-20T09:27:35.943Z,1397986055.943 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-04-20T09:27:35.944Z,1397986055.944 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A24E0
2014-04-20T09:27:35.945Z,1397986055.945 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-04-20T09:27:35.946Z,1397986055.946 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-04-20T09:27:36.042Z,1397986056.042 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-04-20T09:27:36.042Z,1397986056.042 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-04-20T09:27:36.059Z,1397986056.059 [NavChart] Loaded
2014-04-20T09:27:36.059Z,1397986056.059 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-04-20T09:27:36.063Z,1397986056.063 [UniversalFixResidualReporter] Loaded
2014-04-20T09:27:36.064Z,1397986056.064 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-04-20T09:27:36.064Z,1397986056.064 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-04-20T09:27:36.065Z,1397986056.065 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-04-20T09:27:36.132Z,1397986056.132 [VerticalControl](DEBUG): Construct VerticalControl.
2014-04-20T09:27:36.242Z,1397986056.242 [VerticalControl] Loaded
2014-04-20T09:27:36.242Z,1397986056.242 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-04-20T09:27:36.243Z,1397986056.243 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-04-20T09:27:36.310Z,1397986056.310 [HorizontalControl] Loaded
2014-04-20T09:27:36.310Z,1397986056.310 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-04-20T09:27:36.311Z,1397986056.311 [SpeedControl](DEBUG): Construct SpeedControl.
2014-04-20T09:27:36.313Z,1397986056.313 [SpeedControl] Loaded
2014-04-20T09:27:36.313Z,1397986056.313 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-04-20T09:27:36.314Z,1397986056.314 [LoopControl](DEBUG): Construct LoopControl.
2014-04-20T09:27:36.314Z,1397986056.314 [LoopControl] Loaded
2014-04-20T09:27:36.315Z,1397986056.315 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-04-20T09:27:36.315Z,1397986056.315 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-04-20T09:27:36.316Z,1397986056.316 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-04-20T09:27:36.345Z,1397986056.345 [DepthRateCalculator] Loaded
2014-04-20T09:27:36.345Z,1397986056.345 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-04-20T09:27:36.350Z,1397986056.350 [PitchRateCalculator] Loaded
2014-04-20T09:27:36.351Z,1397986056.351 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-04-20T09:27:36.358Z,1397986056.358 [SpeedCalculator] Loaded
2014-04-20T09:27:36.359Z,1397986056.359 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-04-20T09:27:36.375Z,1397986056.375 [TempGradientCalculator] Loaded
2014-04-20T09:27:36.375Z,1397986056.375 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-04-20T09:27:36.380Z,1397986056.380 [YawRateCalculator] Loaded
2014-04-20T09:27:36.380Z,1397986056.380 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-04-20T09:27:36.381Z,1397986056.381 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-04-20T09:27:36.381Z,1397986056.381 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-04-20T09:27:36.510Z,1397986056.510 [CTD_NeilBrown] Loaded
2014-04-20T09:27:36.510Z,1397986056.510 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-04-20T09:27:36.511Z,1397986056.511 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407444E0
2014-04-20T09:27:36.524Z,1397986056.524 [ISUS] Loaded
2014-04-20T09:27:36.525Z,1397986056.525 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-04-20T09:27:36.540Z,1397986056.540 [PAR_Licor] Loaded
2014-04-20T09:27:36.540Z,1397986056.540 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-04-20T09:27:36.576Z,1397986056.576 [WetLabsBB2FL] Loaded
2014-04-20T09:27:36.577Z,1397986056.577 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-04-20T09:27:36.578Z,1397986056.578 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407744E0
2014-04-20T09:27:36.578Z,1397986056.578 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-04-20T09:27:36.580Z,1397986056.580 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-04-20T09:27:36.698Z,1397986056.698 [SBIT](DEBUG): Construct Startup Built In Test.
2014-04-20T09:27:36.710Z,1397986056.710 [SBIT] Loaded
2014-04-20T09:27:36.710Z,1397986056.710 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-04-20T09:27:36.711Z,1397986056.711 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-04-20T09:27:36.723Z,1397986056.723 [IBIT] Loaded
2014-04-20T09:27:36.723Z,1397986056.723 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-04-20T09:27:36.725Z,1397986056.725 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-04-20T09:27:36.795Z,1397986056.795 [CBIT] Loaded
2014-04-20T09:27:36.795Z,1397986056.795 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-04-20T09:27:36.795Z,1397986056.795 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-04-20T09:27:36.798Z,1397986056.798 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-04-20T09:27:36.867Z,1397986056.867 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-04-20T09:27:36.867Z,1397986056.867 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-04-20T09:27:36.990Z,1397986056.990 [BuoyancyServo] Loaded
2014-04-20T09:27:36.990Z,1397986056.990 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-04-20T09:27:37.003Z,1397986057.003 [ElevatorServo] Loaded
2014-04-20T09:27:37.003Z,1397986057.003 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-04-20T09:27:37.014Z,1397986057.014 [MassServo] Loaded
2014-04-20T09:27:37.014Z,1397986057.014 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-04-20T09:27:37.026Z,1397986057.026 [RudderServo] Loaded
2014-04-20T09:27:37.027Z,1397986057.027 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-04-20T09:27:37.038Z,1397986057.038 [ThrusterServo] Loaded
2014-04-20T09:27:37.038Z,1397986057.038 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-04-20T09:27:37.039Z,1397986057.039 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-04-20T09:27:37.039Z,1397986057.039 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-04-20T09:27:37.078Z,1397986057.078 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-04-20T09:27:37.080Z,1397986057.080 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-04-20T09:27:37.080Z,1397986057.080 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-04-20T09:27:37.087Z,1397986057.087 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-04-20T09:27:37.088Z,1397986057.088 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408424E0
2014-04-20T09:27:37.092Z,1397986057.092 [Supervisor](DEBUG): Running supervisor.
2014-04-20T09:27:37.094Z,1397986057.094 [CommandLine](INFO): Thread ID is 773
2014-04-20T09:27:37.097Z,1397986057.097 [controlThread](INFO): Thread ID is 772
2014-04-20T09:27:37.097Z,1397986057.097 [controlThread](DEBUG): Initializing ControlThread
2014-04-20T09:27:37.097Z,1397986057.097 [CycleStarter](INFO): Thread ID is 771
2014-04-20T09:27:37.100Z,1397986057.100 [logger](INFO): Thread ID is 774
2014-04-20T09:27:37.118Z,1397986057.118 [AsyncPiEstimator](INFO): Thread ID is 856
2014-04-20T09:27:37.119Z,1397986057.119 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-04-20T09:27:37.147Z,1397986057.147 [CTD_NeilBrown](INFO): Thread ID is 857
2014-04-20T09:27:37.147Z,1397986057.147 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-04-20T09:27:37.150Z,1397986057.150 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-04-20T09:27:37.160Z,1397986057.160 [WetLabsBB2FL](INFO): Thread ID is 858
2014-04-20T09:27:37.161Z,1397986057.161 [WetLabsBB2FL](INFO): Powering down
2014-04-20T09:27:37.189Z,1397986057.189 [NavChartDb](INFO): Thread ID is 859
2014-04-20T09:27:37.201Z,1397986057.201 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-04-20T09:27:37.203Z,1397986057.203 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-04-20T09:27:37.204Z,1397986057.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-04-20T09:27:37.204Z,1397986057.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-04-20T09:27:37.204Z,1397986057.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-04-20T09:27:37.204Z,1397986057.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-04-20T09:27:37.204Z,1397986057.204 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-04-20T09:27:37.205Z,1397986057.205 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-04-20T09:27:37.205Z,1397986057.205 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-04-20T09:27:38.781Z,1397986058.781 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-04-20T09:27:38.812Z,1397986058.812 [InternalSim](DEBUG):  InternalSim initializing...
2014-04-20T09:27:39.109Z,1397986059.109 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-20T09:27:39.109Z,1397986059.109 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-04-20T09:27:39.110Z,1397986059.110 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-20T09:27:39.110Z,1397986059.110 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-04-20T09:27:39.112Z,1397986059.112 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-04-20T09:27:39.112Z,1397986059.112 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-04-20T09:27:39.123Z,1397986059.123 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-04-20T09:27:39.124Z,1397986059.124 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-04-20T09:27:39.124Z,1397986059.124 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-04-20T09:27:39.125Z,1397986059.125 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-04-20T09:27:39.133Z,1397986059.133 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-04-20T09:27:39.134Z,1397986059.134 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-04-20T09:27:39.149Z,1397986059.149 [SBIT](INFO): Initialize SBIT Component.
2014-04-20T09:27:39.150Z,1397986059.150 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11231
2014-04-20T09:27:39.150Z,1397986059.150 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-04-20T09:27:39.150Z,1397986059.150 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-04-20T09:27:39.151Z,1397986059.151 [IBIT](INFO): Initialize IBIT Component.
2014-04-20T09:27:39.152Z,1397986059.152 [CBIT](DEBUG): Initialize CBIT Component.
2014-04-20T09:27:39.152Z,1397986059.152 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2014-04-20T09:27:39.152Z,1397986059.152 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2014-04-20T09:27:39.179Z,1397986059.179 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-04-20T09:27:39.206Z,1397986059.206 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-20T09:27:39.231Z,1397986059.231 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2014-04-20T09:27:39.232Z,1397986059.232 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-04-20T09:27:39.316Z,1397986059.316 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-04-20T09:27:39.318Z,1397986059.318 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-04-20T09:27:39.338Z,1397986059.338 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-20T09:27:39.362Z,1397986059.362 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-04-20T09:27:39.365Z,1397986059.365 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-20T09:27:39.392Z,1397986059.392 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-04-20T09:27:39.406Z,1397986059.406 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-04-20T09:27:39.433Z,1397986059.433 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-20T09:27:39.459Z,1397986059.459 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS">

        <When>
            <Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface>
            <Sequence/>
        </Guidance:GoToSurface>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium">

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or><Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Sequence/><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

        <Guidance:GoToSurface>
            <Parallel/>
        </Guidance:GoToSurface>

    </Aggregate>

</Mission>


2014-04-20T09:27:39.478Z,1397986059.478 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,Radio_Freewave,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-04-20T09:27:39.574Z,1397986059.574 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-04-20T09:27:39.622Z,1397986059.622 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2014-04-20T09:27:39.677Z,1397986059.677 [DVL_micro](INFO): Initializing
2014-04-20T09:27:39.839Z,1397986059.839 [Radio_Freewave](INFO): Powering up
2014-04-20T09:27:40.244Z,1397986060.244 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:40.251Z,1397986060.251 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-04-20T09:27:40.273Z,1397986060.273 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:40.279Z,1397986060.279 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-04-20T09:27:40.293Z,1397986060.293 [MassServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:40.299Z,1397986060.299 [MassServo](DEBUG): Initializing MassServo.
2014-04-20T09:27:40.313Z,1397986060.313 [RudderServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:40.319Z,1397986060.319 [RudderServo](DEBUG): Initializing RudderServo.
2014-04-20T09:27:40.341Z,1397986060.341 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:40.347Z,1397986060.347 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-04-20T09:27:40.383Z,1397986060.383 [CommandLine](FAULT): Scheduling is paused
2014-04-20T09:27:40.683Z,1397986060.683 [NAL9602](INFO): Powering up NAL9602
2014-04-20T09:27:41.160Z,1397986061.160 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2014-04-20T09:27:41.160Z,1397986061.160 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2014-04-20T09:27:41.160Z,1397986061.160 [BuoyancyServo] Communications Fault, FailCount= 1
2014-04-20T09:27:41.160Z,1397986061.160 [BuoyancyServo](ERROR): Communications Fault
2014-04-20T09:27:41.371Z,1397986061.371 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2014-04-20T09:27:41.737Z,1397986061.737 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-20T09:27:41.852Z,1397986061.852 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-04-20T09:27:41.852Z,1397986061.852 [BuoyancyServo](INFO): Powering down
2014-04-20T09:27:42.522Z,1397986062.522 [Radio_Freewave](INFO): Powering down
2014-04-20T09:27:44.460Z,1397986064.460 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2014-04-20T09:27:44.460Z,1397986064.460 [BuoyancyServo] No Fault, FailCount= 1
2014-04-20T09:27:44.892Z,1397986064.892 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-04-20T09:27:45.011Z,1397986065.011 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-04-20T09:27:51.480Z,1397986071.480 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:27:55.105Z,1397986075.105 [SBIT](IMPORTANT): Beginning Startup BIT
2014-04-20T09:27:55.108Z,1397986075.108 [CBIT](IMPORTANT): Beginning GF scan
2014-04-20T09:28:22.178Z,1397986102.178 [CBIT](FAULT): Low side GF detected
mA:
CHAN 5 (24V): 0.391695
CHAN 4 (Batt): 0.318330
CHAN 2 (12V): 0.125209
CHAN 1 (5V): 0.043139
CHAN 0 (3.3V): 0.035487
OPEN: 0.000765
Full Scale Calc: 0.392
2014-04-20T09:28:49.224Z,1397986129.224 [SBIT](IMPORTANT): SBIT PASSED
2014-04-20T09:28:49.614Z,1397986129.614 [MissionManager](IMPORTANT): Started mission Startup
2014-04-20T09:28:49.614Z,1397986129.614 [Startup] Running Loop=1
2014-04-20T09:28:49.614Z,1397986129.614 [Startup](INFO): Aggregate::initialize Startup
2014-04-20T09:28:49.614Z,1397986129.614 [Startup:A.GoToSurface] Running Loop=1
2014-04-20T09:28:49.614Z,1397986129.614 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:30:54.869Z,1397986254.869 [Radio_Freewave](INFO): Powering up
2014-04-20T09:30:54.921Z,1397986254.921 [Startup:StartupSatComms] Running Loop=1
2014-04-20T09:30:54.922Z,1397986254.922 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-04-20T09:30:54.922Z,1397986254.922 [Startup:StartupSatComms:A] Running Loop=1
2014-04-20T09:30:55.358Z,1397986255.358 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-20T09:30:55.903Z,1397986255.903 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-20T09:31:55.070Z,1397986315.070 [Startup:StartupSatComms:A](INFO): Timed out from 2014-04-20T09:30:54.9Z
2014-04-20T09:31:55.070Z,1397986315.070 [Startup:StartupSatComms:A] Stopped
2014-04-20T09:31:55.071Z,1397986315.071 [Startup:StartupSatComms:B] Running Loop=1
2014-04-20T09:31:55.479Z,1397986315.479 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-20T09:32:43.883Z,1397986363.883 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:46.447Z,1397986366.447 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:48.895Z,1397986368.895 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:51.447Z,1397986371.447 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:53.498Z,1397986373.498 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:55.192Z,1397986375.192 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2014-04-20T09:32:55.207Z,1397986375.207 [Startup:StartupSatComms:B](INFO): Timed out from 2014-04-20T09:31:55.1Z
2014-04-20T09:32:55.208Z,1397986375.208 [Startup:StartupSatComms:B] Stopped
2014-04-20T09:32:55.208Z,1397986375.208 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-04-20T09:32:55.208Z,1397986375.208 [Startup:StartupSatComms] Stopped
2014-04-20T09:32:55.208Z,1397986375.208 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-04-20T09:32:55.209Z,1397986375.209 [Startup](INFO): Completed Startup
2014-04-20T09:32:55.209Z,1397986375.209 [Startup] Stopped
2014-04-20T09:32:55.209Z,1397986375.209 [Startup](INFO): Aggregate::uninitialize Startup
2014-04-20T09:32:55.209Z,1397986375.209 [Startup:A.GoToSurface] Stopped
2014-04-20T09:32:55.209Z,1397986375.209 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:32:55.609Z,1397986375.609 [MissionManager](IMPORTANT): Started mission Default
2014-04-20T09:32:55.609Z,1397986375.609 [Default] Running Loop=1
2014-04-20T09:32:55.609Z,1397986375.609 [Default](INFO): Aggregate::initialize Default
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium] Running Loop=1
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T09:32:55.610Z,1397986375.610 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:32:55.611Z,1397986375.611 [Default:CallIridium] Running Loop=1
2014-04-20T09:32:55.611Z,1397986375.611 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T09:32:55.611Z,1397986375.611 [Default:CallIridium:A] Running Loop=1
2014-04-20T09:32:55.613Z,1397986375.613 [Default:CallIridium:A] Stopped
2014-04-20T09:32:55.614Z,1397986375.614 [Default:CallIridium:B] Running Loop=1
2014-04-20T09:32:55.614Z,1397986375.614 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T09:32:55.620Z,1397986375.620 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T09:32:55.620Z,1397986375.620 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:32:55.621Z,1397986375.621 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T09:32:55.621Z,1397986375.621 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T09:32:55.642Z,1397986375.642 [Default:GPS] Running Loop=1
2014-04-20T09:32:55.642Z,1397986375.642 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T09:32:55.642Z,1397986375.642 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T09:32:55.642Z,1397986375.642 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:32:55.642Z,1397986375.642 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T09:32:55.643Z,1397986375.643 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:32:55.661Z,1397986375.661 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T09:32:55.661Z,1397986375.661 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:32:55.661Z,1397986375.661 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T09:32:55.661Z,1397986375.661 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T09:32:56.050Z,1397986376.050 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:32:56.103Z,1397986376.103 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-20T09:32:56.106Z,1397986376.106 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-20T09:32:58.712Z,1397986378.712 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:00.829Z,1397986380.829 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:03.277Z,1397986383.277 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:05.910Z,1397986385.910 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:08.366Z,1397986388.366 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:10.883Z,1397986390.883 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:12.905Z,1397986392.905 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:15.357Z,1397986395.357 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:17.856Z,1397986397.856 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:20.308Z,1397986400.308 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:22.816Z,1397986402.816 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:25.264Z,1397986405.264 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:27.374Z,1397986407.374 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:29.815Z,1397986409.815 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:31.513Z,1397986411.513 [NAL9602](FAULT): Queried for signal strength and failed to receive proper response. serial timeout
2014-04-20T09:33:32.032Z,1397986412.032 [NAL9602](ERROR): received: 
2014-04-20T09:33:32.032Z,1397986412.032 [NAL9602] Data Fault, FailCount= 1
2014-04-20T09:33:32.032Z,1397986412.032 [NAL9602](ERROR): Data Fault
2014-04-20T09:33:32.073Z,1397986412.073 [CBIT](ERROR): Data Fault in component: NAL9602
2014-04-20T09:33:32.461Z,1397986412.461 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:32.476Z,1397986412.476 [NAL9602](INFO): Powering down
2014-04-20T09:33:33.321Z,1397986413.321 [CBIT](INFO): Clearing failed state for component NAL9602
2014-04-20T09:33:33.321Z,1397986413.321 [NAL9602] No Fault, FailCount= 1
2014-04-20T09:33:34.906Z,1397986414.906 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:37.390Z,1397986417.390 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:37.800Z,1397986417.800 [NAL9602](INFO): Powering up NAL9602
2014-04-20T09:33:39.826Z,1397986419.826 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:41.941Z,1397986421.941 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:44.377Z,1397986424.377 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#11 STATUS: 65535
2014-04-20T09:33:48.562Z,1397986428.562 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:34:42.814Z,1397986482.814 [NAL9602](INFO): SBD MO Status=2, MOMSN=27534, MT Status=0, MTMSN=0
2014-04-20T09:34:42.814Z,1397986482.814 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T09:34:44.115Z,1397986484.115 [NAL9602](IMPORTANT): GPS fix at: 1397986470.00
2014-04-20T09:34:44.164Z,1397986484.164 [Default:GPS:Read_GPS] Stopped
2014-04-20T09:34:44.165Z,1397986484.165 [Default:GPS:D] Running Loop=1
2014-04-20T09:34:44.629Z,1397986484.629 [Default:GPS:D] Stopped
2014-04-20T09:34:44.629Z,1397986484.629 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T09:34:44.629Z,1397986484.629 [Default:GPS] Stopped
2014-04-20T09:34:44.629Z,1397986484.629 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T09:34:44.629Z,1397986484.629 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T09:34:44.630Z,1397986484.630 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:35:41.617Z,1397986541.617 [NAL9602](INFO): SBD MO Status=2, MOMSN=27534, MT Status=2, MTMSN=0
2014-04-20T09:35:41.617Z,1397986541.617 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T09:35:59.616Z,1397986559.616 [NAL9602](INFO): SBD MO Status=1, MOMSN=27534, MT Status=0, MTMSN=0
2014-04-20T09:35:59.665Z,1397986559.665 [NAL9602](INFO): Sent 25 bytes from file Logs/20140420T051638/Courier0056.lzma
2014-04-20T09:35:59.665Z,1397986559.665 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:35:59.667Z,1397986559.667 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T051638/Courier0056.lzma.parts/0000.sbd
2014-04-20T09:35:59.668Z,1397986559.668 [NAL9602](INFO): Completed sending Logs/20140420T051638/Courier0056.lzma
2014-04-20T09:36:11.667Z,1397986571.667 [NAL9602](INFO): SBD MO Status=1, MOMSN=27535, MT Status=0, MTMSN=0
2014-04-20T09:36:11.720Z,1397986571.720 [NAL9602](INFO): Sent 256 bytes from file Logs/20140420T092729/Courier0000.lzma
2014-04-20T09:36:11.720Z,1397986571.720 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:36:11.722Z,1397986571.722 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0000.lzma.parts/0000.sbd
2014-04-20T09:36:11.722Z,1397986571.722 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0000.lzma
2014-04-20T09:36:20.012Z,1397986580.012 [NAL9602](INFO): SBD MO Status=1, MOMSN=27536, MT Status=0, MTMSN=0
2014-04-20T09:36:20.061Z,1397986580.061 [NAL9602](INFO): Sent 45 bytes from file Logs/20140420T092729/Courier0004.lzma
2014-04-20T09:36:20.061Z,1397986580.061 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:36:20.063Z,1397986580.063 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0004.lzma.parts/0000.sbd
2014-04-20T09:36:20.063Z,1397986580.063 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0004.lzma
2014-04-20T09:36:31.002Z,1397986591.002 [NAL9602](INFO): SBD MO Status=1, MOMSN=27537, MT Status=0, MTMSN=0
2014-04-20T09:36:31.058Z,1397986591.058 [NAL9602](INFO): Sent 100 bytes from file Logs/20140420T051638/Express0057.lzma
2014-04-20T09:36:31.058Z,1397986591.058 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:36:31.060Z,1397986591.060 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T051638/Express0057.lzma.parts/0000.sbd
2014-04-20T09:36:31.060Z,1397986591.060 [NAL9602](INFO): Completed sending Logs/20140420T051638/Express0057.lzma
2014-04-20T09:36:42.700Z,1397986602.700 [NAL9602](INFO): SBD MO Status=1, MOMSN=27538, MT Status=0, MTMSN=0
2014-04-20T09:36:42.752Z,1397986602.752 [NAL9602](INFO): Sent 332 bytes from file Logs/20140420T092729/Express0001.lzma
2014-04-20T09:36:42.752Z,1397986602.752 [NAL9602](INFO): Packets left to send: 2
2014-04-20T09:36:42.754Z,1397986602.754 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0001.lzma.parts/0002.sbd
2014-04-20T09:36:55.588Z,1397986615.588 [NAL9602](INFO): SBD MO Status=1, MOMSN=27539, MT Status=0, MTMSN=0
2014-04-20T09:36:55.640Z,1397986615.640 [NAL9602](INFO): Sent 332 bytes from file Logs/20140420T092729/Express0001.lzma
2014-04-20T09:36:55.640Z,1397986615.640 [NAL9602](INFO): Packets left to send: 1
2014-04-20T09:36:55.641Z,1397986615.641 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0001.lzma.parts/0001.sbd
2014-04-20T09:37:08.676Z,1397986628.676 [NAL9602](INFO): SBD MO Status=1, MOMSN=27540, MT Status=0, MTMSN=0
2014-04-20T09:37:08.732Z,1397986628.732 [NAL9602](INFO): Sent 194 bytes from file Logs/20140420T092729/Express0001.lzma
2014-04-20T09:37:08.733Z,1397986628.733 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:37:08.734Z,1397986628.734 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0001.lzma.parts/0000.sbd
2014-04-20T09:37:08.734Z,1397986628.734 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0001.lzma
2014-04-20T09:37:20.886Z,1397986640.886 [NAL9602](INFO): SBD MO Status=1, MOMSN=27541, MT Status=0, MTMSN=0
2014-04-20T09:37:20.947Z,1397986640.947 [NAL9602](INFO): Sent 180 bytes from file Logs/20140420T092729/Express0005.lzma
2014-04-20T09:37:20.947Z,1397986640.947 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:37:20.949Z,1397986640.949 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0005.lzma.parts/0000.sbd
2014-04-20T09:37:20.949Z,1397986640.949 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0005.lzma
2014-04-20T09:37:29.048Z,1397986649.048 [NAL9602](INFO): SBD MO Status=0, MOMSN=27542, MT Status=0, MTMSN=0
2014-04-20T09:37:29.146Z,1397986649.146 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T09:37:29.147Z,1397986649.147 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T09:37:29.147Z,1397986649.147 [Default:Iridium] Stopped
2014-04-20T09:37:29.147Z,1397986649.147 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T09:37:29.147Z,1397986649.147 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T09:37:29.147Z,1397986649.147 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:37:29.147Z,1397986649.147 [Default:WaitAtTheSurface] Running Loop=1
2014-04-20T09:37:29.147Z,1397986649.147 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-04-20T09:37:29.148Z,1397986649.148 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-20T09:37:29.148Z,1397986649.148 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-04-20T09:37:29.148Z,1397986649.148 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-20T09:37:29.148Z,1397986649.148 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:37:29.593Z,1397986649.593 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-20T09:37:29.599Z,1397986649.599 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium:B] Stopped
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium] Stopped
2014-04-20T09:37:29.604Z,1397986649.604 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T09:37:39.672Z,1397986659.672 [NAL9602](INFO): Powering down
2014-04-20T09:42:29.686Z,1397986949.686 [Default:CallIridium] Running Loop=1
2014-04-20T09:42:29.686Z,1397986949.686 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T09:42:29.686Z,1397986949.686 [Default:CallIridium:A] Running Loop=1
2014-04-20T09:42:29.687Z,1397986949.687 [Default:CallIridium:A] Stopped
2014-04-20T09:42:29.687Z,1397986949.687 [Default:CallIridium:B] Running Loop=1
2014-04-20T09:42:29.687Z,1397986949.687 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium] Running Loop=1
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T09:42:34.716Z,1397986954.716 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:42:34.717Z,1397986954.717 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T09:42:34.717Z,1397986954.717 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:42:34.717Z,1397986954.717 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS] Running Loop=1
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T09:42:34.718Z,1397986954.718 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:42:34.719Z,1397986954.719 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T09:42:34.719Z,1397986954.719 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:42:34.719Z,1397986954.719 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T09:42:35.830Z,1397986955.830 [NAL9602](INFO): Powering up
2014-04-20T09:42:46.454Z,1397986966.454 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:43:39.518Z,1397987019.518 [NAL9602](INFO): SBD MO Status=2, MOMSN=27543, MT Status=2, MTMSN=0
2014-04-20T09:43:39.518Z,1397987019.518 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T09:44:21.900Z,1397987061.900 [NAL9602](INFO): SBD MO Status=2, MOMSN=27543, MT Status=2, MTMSN=0
2014-04-20T09:44:21.900Z,1397987061.900 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T09:44:23.188Z,1397987063.188 [NAL9602](IMPORTANT): GPS fix at: 1397987050.00
2014-04-20T09:44:23.206Z,1397987063.206 [Default:GPS:Read_GPS] Stopped
2014-04-20T09:44:23.206Z,1397987063.206 [Default:GPS:D] Running Loop=1
2014-04-20T09:44:23.658Z,1397987063.658 [Default:GPS:D] Stopped
2014-04-20T09:44:23.659Z,1397987063.659 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T09:44:23.659Z,1397987063.659 [Default:GPS] Stopped
2014-04-20T09:44:23.659Z,1397987063.659 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T09:44:23.659Z,1397987063.659 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T09:44:23.659Z,1397987063.659 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:44:42.259Z,1397987082.259 [NAL9602](INFO): SBD MO Status=1, MOMSN=27543, MT Status=0, MTMSN=0
2014-04-20T09:44:42.308Z,1397987082.308 [NAL9602](INFO): Sent 225 bytes from file Logs/20140420T092729/Courier0008.lzma
2014-04-20T09:44:42.308Z,1397987082.308 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:44:42.309Z,1397987082.309 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0008.lzma.parts/0000.sbd
2014-04-20T09:44:42.310Z,1397987082.310 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0008.lzma
2014-04-20T09:44:52.607Z,1397987092.607 [NAL9602](INFO): SBD MO Status=1, MOMSN=27544, MT Status=0, MTMSN=0
2014-04-20T09:44:52.658Z,1397987092.658 [NAL9602](INFO): Sent 332 bytes from file Logs/20140420T092729/Express0009.lzma
2014-04-20T09:44:52.658Z,1397987092.658 [NAL9602](INFO): Packets left to send: 1
2014-04-20T09:44:52.660Z,1397987092.660 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0009.lzma.parts/0001.sbd
2014-04-20T09:45:00.973Z,1397987100.973 [NAL9602](INFO): SBD MO Status=1, MOMSN=27545, MT Status=0, MTMSN=0
2014-04-20T09:45:01.033Z,1397987101.033 [NAL9602](INFO): Sent 36 bytes from file Logs/20140420T092729/Express0009.lzma
2014-04-20T09:45:01.033Z,1397987101.033 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:45:01.034Z,1397987101.034 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0009.lzma.parts/0000.sbd
2014-04-20T09:45:01.034Z,1397987101.034 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0009.lzma
2014-04-20T09:45:11.333Z,1397987111.333 [NAL9602](INFO): SBD MO Status=0, MOMSN=27546, MT Status=0, MTMSN=0
2014-04-20T09:45:11.418Z,1397987111.418 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T09:45:11.419Z,1397987111.419 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T09:45:11.419Z,1397987111.419 [Default:Iridium] Stopped
2014-04-20T09:45:11.419Z,1397987111.419 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T09:45:11.419Z,1397987111.419 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T09:45:11.419Z,1397987111.419 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium:B] Stopped
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium] Stopped
2014-04-20T09:45:11.830Z,1397987111.830 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T09:45:21.969Z,1397987121.969 [NAL9602](INFO): Powering down
2014-04-20T09:50:11.983Z,1397987411.983 [Default:CallIridium] Running Loop=1
2014-04-20T09:50:11.983Z,1397987411.983 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T09:50:11.983Z,1397987411.983 [Default:CallIridium:A] Running Loop=1
2014-04-20T09:50:11.984Z,1397987411.984 [Default:CallIridium:A] Stopped
2014-04-20T09:50:11.984Z,1397987411.984 [Default:CallIridium:B] Running Loop=1
2014-04-20T09:50:11.984Z,1397987411.984 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T09:50:16.985Z,1397987416.985 [Default:Iridium] Running Loop=1
2014-04-20T09:50:16.985Z,1397987416.985 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T09:50:16.985Z,1397987416.985 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T09:50:16.986Z,1397987416.986 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:50:16.986Z,1397987416.986 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T09:50:16.986Z,1397987416.986 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:50:16.987Z,1397987416.987 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T09:50:16.987Z,1397987416.987 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:50:16.987Z,1397987416.987 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T09:50:16.987Z,1397987416.987 [Default:GPS] Running Loop=1
2014-04-20T09:50:16.987Z,1397987416.987 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T09:50:16.987Z,1397987416.987 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T09:50:16.987Z,1397987416.987 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:50:16.988Z,1397987416.988 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T09:50:16.988Z,1397987416.988 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:50:16.988Z,1397987416.988 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T09:50:16.988Z,1397987416.988 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:50:16.989Z,1397987416.989 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T09:50:18.006Z,1397987418.006 [NAL9602](INFO): Powering up
2014-04-20T09:50:28.617Z,1397987428.617 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:50:54.849Z,1397987454.849 [NAL9602](INFO): SBD MO Status=1, MOMSN=27547, MT Status=0, MTMSN=0
2014-04-20T09:50:54.905Z,1397987454.905 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0012.lzma
2014-04-20T09:50:54.905Z,1397987454.905 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:50:54.907Z,1397987454.907 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0012.lzma.parts/0000.sbd
2014-04-20T09:50:54.907Z,1397987454.907 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0012.lzma
2014-04-20T09:51:05.716Z,1397987465.716 [NAL9602](INFO): SBD MO Status=1, MOMSN=27548, MT Status=0, MTMSN=0
2014-04-20T09:51:05.774Z,1397987465.774 [NAL9602](INFO): Sent 115 bytes from file Logs/20140420T092729/Express0013.lzma
2014-04-20T09:51:05.774Z,1397987465.774 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:51:05.776Z,1397987465.776 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0013.lzma.parts/0000.sbd
2014-04-20T09:51:05.776Z,1397987465.776 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0013.lzma
2014-04-20T09:52:11.370Z,1397987531.370 [NAL9602](FAULT): Verify xmit timeout failure.
2014-04-20T09:52:11.370Z,1397987531.370 [NAL9602] Data Fault, FailCount= 1
2014-04-20T09:52:11.370Z,1397987531.370 [NAL9602](ERROR): Data Fault
2014-04-20T09:52:11.398Z,1397987531.398 [CBIT](ERROR): Data Fault in component: NAL9602
2014-04-20T09:52:11.775Z,1397987531.775 [NAL9602](INFO): Powering down
2014-04-20T09:52:12.650Z,1397987532.650 [CBIT](INFO): Clearing failed state for component NAL9602
2014-04-20T09:52:12.650Z,1397987532.650 [NAL9602] No Fault, FailCount= 1
2014-04-20T09:52:16.846Z,1397987536.846 [NAL9602](INFO): Powering up NAL9602
2014-04-20T09:52:27.449Z,1397987547.449 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:52:48.485Z,1397987568.485 [NAL9602](INFO): SBD MO Status=0, MOMSN=27549, MT Status=0, MTMSN=0
2014-04-20T09:52:48.612Z,1397987568.612 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T09:52:48.613Z,1397987568.613 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T09:52:48.613Z,1397987568.613 [Default:Iridium] Stopped
2014-04-20T09:52:48.613Z,1397987568.613 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T09:52:48.613Z,1397987568.613 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T09:52:48.613Z,1397987568.613 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium:B] Stopped
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium] Stopped
2014-04-20T09:52:49.048Z,1397987569.048 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T09:52:49.885Z,1397987569.885 [NAL9602](IMPORTANT): GPS fix at: 1397987556.00
2014-04-20T09:52:49.904Z,1397987569.904 [Default:GPS:Read_GPS] Stopped
2014-04-20T09:52:49.904Z,1397987569.904 [Default:GPS:D] Running Loop=1
2014-04-20T09:52:50.371Z,1397987570.371 [Default:GPS:D] Stopped
2014-04-20T09:52:50.371Z,1397987570.371 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T09:52:50.371Z,1397987570.371 [Default:GPS] Stopped
2014-04-20T09:52:50.371Z,1397987570.371 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T09:52:50.372Z,1397987570.372 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T09:52:50.392Z,1397987570.392 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:53:10.967Z,1397987590.967 [NAL9602](INFO): Powering down
2014-04-20T09:57:51.029Z,1397987871.029 [Default:CallIridium] Running Loop=1
2014-04-20T09:57:51.029Z,1397987871.029 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T09:57:51.030Z,1397987871.030 [Default:CallIridium:A] Running Loop=1
2014-04-20T09:57:51.030Z,1397987871.030 [Default:CallIridium:A] Stopped
2014-04-20T09:57:51.030Z,1397987871.030 [Default:CallIridium:B] Running Loop=1
2014-04-20T09:57:51.030Z,1397987871.030 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T09:57:55.978Z,1397987875.978 [Default:Iridium] Running Loop=1
2014-04-20T09:57:55.979Z,1397987875.979 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T09:57:55.979Z,1397987875.979 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T09:57:55.979Z,1397987875.979 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:57:55.979Z,1397987875.979 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T09:57:55.979Z,1397987875.979 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:57:55.980Z,1397987875.980 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T09:57:55.980Z,1397987875.980 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:57:55.980Z,1397987875.980 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T09:57:55.980Z,1397987875.980 [Default:GPS] Running Loop=1
2014-04-20T09:57:55.981Z,1397987875.981 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T09:57:55.981Z,1397987875.981 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T09:57:55.981Z,1397987875.981 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T09:57:55.981Z,1397987875.981 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T09:57:55.981Z,1397987875.981 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T09:57:55.982Z,1397987875.982 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T09:57:55.982Z,1397987875.982 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T09:57:55.982Z,1397987875.982 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T09:57:57.074Z,1397987877.074 [NAL9602](INFO): Powering up
2014-04-20T09:58:07.716Z,1397987887.716 [NAL9602](INFO): NAL9602 initialized
2014-04-20T09:58:22.444Z,1397987902.444 [NAL9602](INFO): SBD MO Status=1, MOMSN=27550, MT Status=0, MTMSN=0
2014-04-20T09:58:22.507Z,1397987902.507 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0016.lzma
2014-04-20T09:58:22.507Z,1397987902.507 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:58:22.509Z,1397987902.509 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0016.lzma.parts/0000.sbd
2014-04-20T09:58:22.509Z,1397987902.509 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0016.lzma
2014-04-20T09:58:41.937Z,1397987921.937 [NAL9602](INFO): SBD MO Status=1, MOMSN=27551, MT Status=0, MTMSN=0
2014-04-20T09:58:41.993Z,1397987921.993 [NAL9602](INFO): Sent 140 bytes from file Logs/20140420T092729/Express0017.lzma
2014-04-20T09:58:41.994Z,1397987921.994 [NAL9602](INFO): Packets left to send: 0
2014-04-20T09:58:41.995Z,1397987921.995 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0017.lzma.parts/0000.sbd
2014-04-20T09:58:41.995Z,1397987921.995 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0017.lzma
2014-04-20T09:58:53.139Z,1397987933.139 [NAL9602](INFO): SBD MO Status=0, MOMSN=27552, MT Status=0, MTMSN=0
2014-04-20T09:58:53.222Z,1397987933.222 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T09:58:53.222Z,1397987933.222 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T09:58:53.222Z,1397987933.222 [Default:Iridium] Stopped
2014-04-20T09:58:53.222Z,1397987933.222 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T09:58:53.223Z,1397987933.223 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T09:58:53.223Z,1397987933.223 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:58:53.671Z,1397987933.671 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T09:58:53.672Z,1397987933.672 [Default:CallIridium:B] Stopped
2014-04-20T09:58:53.672Z,1397987933.672 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T09:58:53.672Z,1397987933.672 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T09:58:53.672Z,1397987933.672 [Default:CallIridium] Stopped
2014-04-20T09:58:53.672Z,1397987933.672 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T09:58:54.518Z,1397987934.518 [NAL9602](IMPORTANT): GPS fix at: 1397987921.00
2014-04-20T09:58:54.537Z,1397987934.537 [Default:GPS:Read_GPS] Stopped
2014-04-20T09:58:54.537Z,1397987934.537 [Default:GPS:D] Running Loop=1
2014-04-20T09:58:54.985Z,1397987934.985 [Default:GPS:D] Stopped
2014-04-20T09:58:54.990Z,1397987934.990 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T09:58:54.990Z,1397987934.990 [Default:GPS] Stopped
2014-04-20T09:58:54.990Z,1397987934.990 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T09:58:54.990Z,1397987934.990 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T09:58:54.990Z,1397987934.990 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T09:59:15.605Z,1397987955.605 [NAL9602](INFO): Powering down
2014-04-20T10:03:55.599Z,1397988235.599 [Default:CallIridium] Running Loop=1
2014-04-20T10:03:55.599Z,1397988235.599 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:03:55.599Z,1397988235.599 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:03:55.599Z,1397988235.599 [Default:CallIridium:A] Stopped
2014-04-20T10:03:55.599Z,1397988235.599 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:03:55.600Z,1397988235.600 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium] Running Loop=1
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:04:00.581Z,1397988240.581 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:04:00.582Z,1397988240.582 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:04:00.582Z,1397988240.582 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:04:00.582Z,1397988240.582 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS] Running Loop=1
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:04:00.583Z,1397988240.583 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:04:00.584Z,1397988240.584 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:04:00.584Z,1397988240.584 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:04:00.584Z,1397988240.584 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:04:01.659Z,1397988241.659 [NAL9602](INFO): Powering up
2014-04-20T10:04:12.328Z,1397988252.328 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode:+CIEV:1,1
AT-MSSTM
2014-04-20T10:04:12.328Z,1397988252.328 [NAL9602] Communications Fault, FailCount= 2
2014-04-20T10:04:12.328Z,1397988252.328 [NAL9602](ERROR): Communications Fault
2014-04-20T10:04:12.362Z,1397988252.362 [CBIT](ERROR): Communications Fault in component: NAL9602
2014-04-20T10:04:12.362Z,1397988252.362 [CBIT](CRITICAL): Communications Fault in component: NAL9602
2014-04-20T10:04:12.740Z,1397988252.740 [NAL9602](INFO): Powering down
2014-04-20T10:06:12.373Z,1397988372.373 [CBIT](INFO): Clearing failed count for component NAL9602
2014-04-20T10:06:12.373Z,1397988372.373 [NAL9602] No Fault, FailCount= 2
2014-04-20T10:06:12.814Z,1397988372.814 [NAL9602](INFO): Powering up NAL9602
2014-04-20T10:06:23.593Z,1397988383.593 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:06:41.866Z,1397988401.866 [NAL9602](INFO): SBD MO Status=1, MOMSN=27553, MT Status=0, MTMSN=0
2014-04-20T10:06:41.922Z,1397988401.922 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0020.lzma
2014-04-20T10:06:41.922Z,1397988401.922 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:06:41.924Z,1397988401.924 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0020.lzma.parts/0000.sbd
2014-04-20T10:06:41.924Z,1397988401.924 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0020.lzma
2014-04-20T10:06:51.893Z,1397988411.893 [NAL9602](INFO): SBD MO Status=1, MOMSN=27554, MT Status=0, MTMSN=0
2014-04-20T10:06:51.941Z,1397988411.941 [NAL9602](INFO): Sent 116 bytes from file Logs/20140420T092729/Express0021.lzma
2014-04-20T10:06:51.941Z,1397988411.941 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:06:51.944Z,1397988411.944 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0021.lzma.parts/0000.sbd
2014-04-20T10:06:51.944Z,1397988411.944 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0021.lzma
2014-04-20T10:06:59.621Z,1397988419.621 [NAL9602](INFO): SBD MO Status=0, MOMSN=27555, MT Status=0, MTMSN=0
2014-04-20T10:06:59.732Z,1397988419.732 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:06:59.732Z,1397988419.732 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:06:59.732Z,1397988419.732 [Default:Iridium] Stopped
2014-04-20T10:06:59.732Z,1397988419.732 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:06:59.732Z,1397988419.732 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:06:59.737Z,1397988419.737 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium:B] Stopped
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium] Stopped
2014-04-20T10:07:00.231Z,1397988420.231 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:07:01.029Z,1397988421.029 [NAL9602](IMPORTANT): GPS fix at: 1397988407.00
2014-04-20T10:07:01.049Z,1397988421.049 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:07:01.049Z,1397988421.049 [Default:GPS:D] Running Loop=1
2014-04-20T10:07:01.550Z,1397988421.550 [Default:GPS:D] Stopped
2014-04-20T10:07:01.550Z,1397988421.550 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:07:01.550Z,1397988421.550 [Default:GPS] Stopped
2014-04-20T10:07:01.550Z,1397988421.550 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:07:01.551Z,1397988421.551 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:07:01.551Z,1397988421.551 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:07:22.050Z,1397988442.050 [NAL9602](INFO): Powering down
2014-04-20T10:12:02.107Z,1397988722.107 [Default:CallIridium] Running Loop=1
2014-04-20T10:12:02.108Z,1397988722.108 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:12:02.108Z,1397988722.108 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:12:02.108Z,1397988722.108 [Default:CallIridium:A] Stopped
2014-04-20T10:12:02.108Z,1397988722.108 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:12:02.108Z,1397988722.108 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium] Running Loop=1
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:12:07.152Z,1397988727.152 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:12:07.153Z,1397988727.153 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:12:07.153Z,1397988727.153 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:12:07.153Z,1397988727.153 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS] Running Loop=1
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:12:07.154Z,1397988727.154 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:12:07.155Z,1397988727.155 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:12:07.155Z,1397988727.155 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:12:07.155Z,1397988727.155 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:12:08.158Z,1397988728.158 [NAL9602](INFO): Powering up
2014-04-20T10:12:18.896Z,1397988738.896 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:12:41.246Z,1397988761.246 [NAL9602](INFO): SBD MO Status=1, MOMSN=27556, MT Status=0, MTMSN=0
2014-04-20T10:12:41.295Z,1397988761.295 [NAL9602](INFO): Sent 127 bytes from file Logs/20140420T092729/Courier0024.lzma
2014-04-20T10:12:41.295Z,1397988761.295 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:12:41.296Z,1397988761.296 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0024.lzma.parts/0000.sbd
2014-04-20T10:12:41.297Z,1397988761.297 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0024.lzma
2014-04-20T10:12:48.465Z,1397988768.465 [NAL9602](INFO): SBD MO Status=1, MOMSN=27557, MT Status=0, MTMSN=0
2014-04-20T10:12:48.534Z,1397988768.534 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0025.lzma
2014-04-20T10:12:48.534Z,1397988768.534 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:12:48.536Z,1397988768.536 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0025.lzma.parts/0000.sbd
2014-04-20T10:12:48.536Z,1397988768.536 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0025.lzma
2014-04-20T10:12:54.571Z,1397988774.571 [NAL9602](INFO): SBD MO Status=0, MOMSN=27558, MT Status=0, MTMSN=0
2014-04-20T10:12:54.656Z,1397988774.656 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:12:54.656Z,1397988774.656 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:12:54.656Z,1397988774.656 [Default:Iridium] Stopped
2014-04-20T10:12:54.657Z,1397988774.657 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:12:54.657Z,1397988774.657 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:12:54.657Z,1397988774.657 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:12:55.073Z,1397988775.073 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:12:55.073Z,1397988775.073 [Default:CallIridium:B] Stopped
2014-04-20T10:12:55.073Z,1397988775.073 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:12:55.073Z,1397988775.073 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:12:55.074Z,1397988775.074 [Default:CallIridium] Stopped
2014-04-20T10:12:55.074Z,1397988775.074 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:12:55.929Z,1397988775.929 [NAL9602](IMPORTANT): GPS fix at: 1397988762.00
2014-04-20T10:12:55.947Z,1397988775.947 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:12:55.947Z,1397988775.947 [Default:GPS:D] Running Loop=1
2014-04-20T10:12:56.381Z,1397988776.381 [Default:GPS:D] Stopped
2014-04-20T10:12:56.382Z,1397988776.382 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:12:56.382Z,1397988776.382 [Default:GPS] Stopped
2014-04-20T10:12:56.382Z,1397988776.382 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:12:56.382Z,1397988776.382 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:12:56.382Z,1397988776.382 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:13:16.925Z,1397988796.925 [NAL9602](INFO): Powering down
2014-04-20T10:17:56.943Z,1397989076.943 [Default:CallIridium] Running Loop=1
2014-04-20T10:17:56.943Z,1397989076.943 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:17:56.943Z,1397989076.943 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:17:56.944Z,1397989076.944 [Default:CallIridium:A] Stopped
2014-04-20T10:17:56.944Z,1397989076.944 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:17:56.944Z,1397989076.944 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:18:01.906Z,1397989081.906 [Default:Iridium] Running Loop=1
2014-04-20T10:18:01.906Z,1397989081.906 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:18:01.906Z,1397989081.906 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:18:01.906Z,1397989081.906 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:18:01.906Z,1397989081.906 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:18:01.907Z,1397989081.907 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:18:01.907Z,1397989081.907 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:18:01.907Z,1397989081.907 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:18:01.908Z,1397989081.908 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS] Running Loop=1
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:18:01.908Z,1397989081.908 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:18:01.909Z,1397989081.909 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:18:01.909Z,1397989081.909 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:18:01.909Z,1397989081.909 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:18:03.000Z,1397989083.000 [NAL9602](INFO): Powering up
2014-04-20T10:18:13.790Z,1397989093.790 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:18:31.986Z,1397989111.986 [NAL9602](INFO): SBD MO Status=1, MOMSN=27559, MT Status=0, MTMSN=0
2014-04-20T10:18:32.047Z,1397989112.047 [NAL9602](INFO): Sent 77 bytes from file Logs/20140420T092729/Courier0028.lzma
2014-04-20T10:18:32.047Z,1397989112.047 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:18:32.048Z,1397989112.048 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0028.lzma.parts/0000.sbd
2014-04-20T10:18:32.049Z,1397989112.049 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0028.lzma
2014-04-20T10:18:40.958Z,1397989120.958 [NAL9602](INFO): SBD MO Status=1, MOMSN=27560, MT Status=0, MTMSN=0
2014-04-20T10:18:41.012Z,1397989121.012 [NAL9602](INFO): Sent 105 bytes from file Logs/20140420T092729/Express0029.lzma
2014-04-20T10:18:41.013Z,1397989121.013 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:18:41.014Z,1397989121.014 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0029.lzma.parts/0000.sbd
2014-04-20T10:18:41.014Z,1397989121.014 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0029.lzma
2014-04-20T10:18:50.013Z,1397989130.013 [NAL9602](INFO): SBD MO Status=0, MOMSN=27561, MT Status=0, MTMSN=0
2014-04-20T10:18:50.093Z,1397989130.093 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:18:50.093Z,1397989130.093 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:18:50.093Z,1397989130.093 [Default:Iridium] Stopped
2014-04-20T10:18:50.094Z,1397989130.094 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:18:50.094Z,1397989130.094 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:18:50.094Z,1397989130.094 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:18:50.543Z,1397989130.543 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:18:50.544Z,1397989130.544 [Default:CallIridium:B] Stopped
2014-04-20T10:18:50.544Z,1397989130.544 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:18:50.544Z,1397989130.544 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:18:50.544Z,1397989130.544 [Default:CallIridium] Stopped
2014-04-20T10:18:50.544Z,1397989130.544 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:18:51.410Z,1397989131.410 [NAL9602](IMPORTANT): GPS fix at: 1397989118.00
2014-04-20T10:18:51.456Z,1397989131.456 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:18:51.456Z,1397989131.456 [Default:GPS:D] Running Loop=1
2014-04-20T10:18:51.885Z,1397989131.885 [Default:GPS:D] Stopped
2014-04-20T10:18:51.886Z,1397989131.886 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:18:51.886Z,1397989131.886 [Default:GPS] Stopped
2014-04-20T10:18:51.886Z,1397989131.886 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:18:51.886Z,1397989131.886 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:18:51.886Z,1397989131.886 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:19:12.412Z,1397989152.412 [NAL9602](INFO): Powering down
2014-04-20T10:23:52.431Z,1397989432.431 [Default:CallIridium] Running Loop=1
2014-04-20T10:23:52.431Z,1397989432.431 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:23:52.431Z,1397989432.431 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:23:52.432Z,1397989432.432 [Default:CallIridium:A] Stopped
2014-04-20T10:23:52.432Z,1397989432.432 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:23:52.432Z,1397989432.432 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:23:57.444Z,1397989437.444 [Default:Iridium] Running Loop=1
2014-04-20T10:23:57.444Z,1397989437.444 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:23:57.444Z,1397989437.444 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:23:57.444Z,1397989437.444 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:23:57.445Z,1397989437.445 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:23:57.445Z,1397989437.445 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:23:57.445Z,1397989437.445 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:23:57.446Z,1397989437.446 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:23:57.446Z,1397989437.446 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:23:57.446Z,1397989437.446 [Default:GPS] Running Loop=1
2014-04-20T10:23:57.446Z,1397989437.446 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:23:57.446Z,1397989437.446 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:23:57.446Z,1397989437.446 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:23:57.447Z,1397989437.447 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:23:57.447Z,1397989437.447 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:23:57.447Z,1397989437.447 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:23:57.447Z,1397989437.447 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:23:57.448Z,1397989437.448 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:23:58.470Z,1397989438.470 [NAL9602](INFO): Powering up
2014-04-20T10:24:09.305Z,1397989449.305 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:24:24.088Z,1397989464.088 [NAL9602](INFO): SBD MO Status=1, MOMSN=27562, MT Status=0, MTMSN=0
2014-04-20T10:24:24.144Z,1397989464.144 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0032.lzma
2014-04-20T10:24:24.145Z,1397989464.145 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:24:24.146Z,1397989464.146 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0032.lzma.parts/0000.sbd
2014-04-20T10:24:24.147Z,1397989464.147 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0032.lzma
2014-04-20T10:24:32.809Z,1397989472.809 [NAL9602](INFO): SBD MO Status=1, MOMSN=27563, MT Status=0, MTMSN=0
2014-04-20T10:24:32.862Z,1397989472.862 [NAL9602](INFO): Sent 116 bytes from file Logs/20140420T092729/Express0033.lzma
2014-04-20T10:24:32.862Z,1397989472.862 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:24:32.864Z,1397989472.864 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0033.lzma.parts/0000.sbd
2014-04-20T10:24:32.864Z,1397989472.864 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0033.lzma
2014-04-20T10:24:41.118Z,1397989481.118 [NAL9602](INFO): SBD MO Status=0, MOMSN=27564, MT Status=0, MTMSN=0
2014-04-20T10:24:41.268Z,1397989481.268 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:24:41.268Z,1397989481.268 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:24:41.269Z,1397989481.269 [Default:Iridium] Stopped
2014-04-20T10:24:41.269Z,1397989481.269 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:24:41.269Z,1397989481.269 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:24:41.269Z,1397989481.269 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium:B] Stopped
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium] Stopped
2014-04-20T10:24:41.754Z,1397989481.754 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:25:16.841Z,1397989516.841 [NAL9602](IMPORTANT): GPS fix at: 1397989503.00
2014-04-20T10:25:16.860Z,1397989516.860 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:25:16.860Z,1397989516.860 [Default:GPS:D] Running Loop=1
2014-04-20T10:25:17.354Z,1397989517.354 [Default:GPS:D] Stopped
2014-04-20T10:25:17.359Z,1397989517.359 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:25:17.359Z,1397989517.359 [Default:GPS] Stopped
2014-04-20T10:25:17.359Z,1397989517.359 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:25:17.359Z,1397989517.359 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:25:17.359Z,1397989517.359 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:25:37.934Z,1397989537.934 [NAL9602](INFO): Powering down
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium] Running Loop=1
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium:A] Stopped
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:29:43.023Z,1397989783.023 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium] Running Loop=1
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:29:47.961Z,1397989787.961 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:29:47.962Z,1397989787.962 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:29:47.962Z,1397989787.962 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:29:47.962Z,1397989787.962 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS] Running Loop=1
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:29:47.963Z,1397989787.963 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:29:47.964Z,1397989787.964 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:29:47.964Z,1397989787.964 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:29:47.964Z,1397989787.964 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:29:48.966Z,1397989788.966 [NAL9602](INFO): Powering up
2014-04-20T10:29:59.526Z,1397989799.526 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode:+CIEV:0,5

2014-04-20T10:29:59.526Z,1397989799.526 [NAL9602] Communications Fault, FailCount= 1
2014-04-20T10:29:59.526Z,1397989799.526 [NAL9602](ERROR): Communications Fault
2014-04-20T10:29:59.561Z,1397989799.561 [CBIT](ERROR): Communications Fault in component: NAL9602
2014-04-20T10:29:59.943Z,1397989799.943 [NAL9602](INFO): Powering down
2014-04-20T10:30:00.867Z,1397989800.867 [CBIT](INFO): Clearing failed state for component NAL9602
2014-04-20T10:30:00.867Z,1397989800.867 [NAL9602] No Fault, FailCount= 1
2014-04-20T10:30:05.063Z,1397989805.063 [NAL9602](INFO): Powering up NAL9602
2014-04-20T10:30:15.842Z,1397989815.842 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:30:30.671Z,1397989830.671 [NAL9602](INFO): SBD MO Status=1, MOMSN=27565, MT Status=0, MTMSN=0
2014-04-20T10:30:30.725Z,1397989830.725 [NAL9602](INFO): Sent 78 bytes from file Logs/20140420T092729/Courier0036.lzma
2014-04-20T10:30:30.725Z,1397989830.725 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:30:30.727Z,1397989830.727 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0036.lzma.parts/0000.sbd
2014-04-20T10:30:30.727Z,1397989830.727 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0036.lzma
2014-04-20T10:30:39.406Z,1397989839.406 [NAL9602](INFO): SBD MO Status=1, MOMSN=27566, MT Status=0, MTMSN=0
2014-04-20T10:30:39.458Z,1397989839.458 [NAL9602](INFO): Sent 105 bytes from file Logs/20140420T092729/Express0037.lzma
2014-04-20T10:30:39.459Z,1397989839.459 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:30:39.460Z,1397989839.460 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0037.lzma.parts/0000.sbd
2014-04-20T10:30:39.461Z,1397989839.461 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0037.lzma
2014-04-20T10:30:48.122Z,1397989848.122 [NAL9602](INFO): SBD MO Status=0, MOMSN=27567, MT Status=0, MTMSN=0
2014-04-20T10:30:48.206Z,1397989848.206 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:30:48.207Z,1397989848.207 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:30:48.207Z,1397989848.207 [Default:Iridium] Stopped
2014-04-20T10:30:48.207Z,1397989848.207 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:30:48.207Z,1397989848.207 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:30:48.207Z,1397989848.207 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:30:48.620Z,1397989848.620 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:30:48.621Z,1397989848.621 [Default:CallIridium:B] Stopped
2014-04-20T10:30:48.622Z,1397989848.622 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:30:48.623Z,1397989848.623 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:30:48.623Z,1397989848.623 [Default:CallIridium] Stopped
2014-04-20T10:30:48.624Z,1397989848.624 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:30:49.572Z,1397989849.572 [NAL9602](IMPORTANT): GPS fix at: 1397989836.00
2014-04-20T10:30:49.616Z,1397989849.616 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:30:49.616Z,1397989849.616 [Default:GPS:D] Running Loop=1
2014-04-20T10:30:50.024Z,1397989850.024 [Default:GPS:D] Stopped
2014-04-20T10:30:50.025Z,1397989850.025 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:30:50.025Z,1397989850.025 [Default:GPS] Stopped
2014-04-20T10:30:50.025Z,1397989850.025 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:30:50.025Z,1397989850.025 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:30:50.025Z,1397989850.025 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:31:10.614Z,1397989870.614 [NAL9602](INFO): Powering down
2014-04-20T10:35:50.661Z,1397990150.661 [Default:CallIridium] Running Loop=1
2014-04-20T10:35:50.661Z,1397990150.661 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:35:50.661Z,1397990150.661 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:35:50.661Z,1397990150.661 [Default:CallIridium:A] Stopped
2014-04-20T10:35:50.662Z,1397990150.662 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:35:50.662Z,1397990150.662 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:35:55.623Z,1397990155.623 [Default:Iridium] Running Loop=1
2014-04-20T10:35:55.624Z,1397990155.624 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:35:55.624Z,1397990155.624 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:35:55.624Z,1397990155.624 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:35:55.624Z,1397990155.624 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:35:55.625Z,1397990155.625 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:35:55.625Z,1397990155.625 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:35:55.625Z,1397990155.625 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:35:55.626Z,1397990155.626 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:35:55.626Z,1397990155.626 [Default:GPS] Running Loop=1
2014-04-20T10:35:55.626Z,1397990155.626 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:35:55.626Z,1397990155.626 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:35:55.626Z,1397990155.626 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:35:55.627Z,1397990155.627 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:35:55.627Z,1397990155.627 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:35:55.628Z,1397990155.628 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:35:55.628Z,1397990155.628 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:35:55.628Z,1397990155.628 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:35:56.671Z,1397990156.671 [NAL9602](INFO): Powering up
2014-04-20T10:36:07.483Z,1397990167.483 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:36:26.300Z,1397990186.300 [NAL9602](INFO): SBD MO Status=1, MOMSN=27568, MT Status=0, MTMSN=0
2014-04-20T10:36:26.348Z,1397990186.348 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0040.lzma
2014-04-20T10:36:26.348Z,1397990186.348 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:36:26.350Z,1397990186.350 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0040.lzma.parts/0000.sbd
2014-04-20T10:36:26.350Z,1397990186.350 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0040.lzma
2014-04-20T10:36:35.229Z,1397990195.229 [NAL9602](INFO): SBD MO Status=1, MOMSN=27569, MT Status=0, MTMSN=0
2014-04-20T10:36:35.286Z,1397990195.286 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0041.lzma
2014-04-20T10:36:35.286Z,1397990195.286 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:36:35.288Z,1397990195.288 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0041.lzma.parts/0000.sbd
2014-04-20T10:36:35.288Z,1397990195.288 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0041.lzma
2014-04-20T10:36:42.990Z,1397990202.990 [NAL9602](INFO): SBD MO Status=0, MOMSN=27570, MT Status=0, MTMSN=0
2014-04-20T10:36:43.104Z,1397990203.104 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:36:43.104Z,1397990203.104 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:36:43.105Z,1397990203.105 [Default:Iridium] Stopped
2014-04-20T10:36:43.105Z,1397990203.105 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:36:43.105Z,1397990203.105 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:36:43.105Z,1397990203.105 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium:B] Stopped
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium] Stopped
2014-04-20T10:36:43.548Z,1397990203.548 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:36:47.516Z,1397990207.516 [NAL9602](IMPORTANT): GPS fix at: 1397990194.00
2014-04-20T10:36:47.535Z,1397990207.535 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:36:47.535Z,1397990207.535 [Default:GPS:D] Running Loop=1
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS:D] Stopped
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS] Stopped
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:36:48.007Z,1397990208.007 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:37:08.556Z,1397990228.556 [NAL9602](INFO): Powering down
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium] Running Loop=1
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium:A] Stopped
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:41:43.581Z,1397990503.581 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium] Running Loop=1
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:41:48.580Z,1397990508.580 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:41:48.581Z,1397990508.581 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:41:48.581Z,1397990508.581 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:41:48.581Z,1397990508.581 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS] Running Loop=1
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:41:48.582Z,1397990508.582 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:41:48.583Z,1397990508.583 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:41:48.583Z,1397990508.583 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:41:48.583Z,1397990508.583 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:41:49.586Z,1397990509.586 [NAL9602](INFO): Powering up
2014-04-20T10:42:00.330Z,1397990520.330 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:42:18.770Z,1397990538.770 [NAL9602](INFO): SBD MO Status=1, MOMSN=27571, MT Status=0, MTMSN=0
2014-04-20T10:42:18.827Z,1397990538.827 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0044.lzma
2014-04-20T10:42:18.827Z,1397990538.827 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:42:18.828Z,1397990538.828 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0044.lzma.parts/0000.sbd
2014-04-20T10:42:18.829Z,1397990538.829 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0044.lzma
2014-04-20T10:42:28.526Z,1397990548.526 [NAL9602](INFO): SBD MO Status=1, MOMSN=27572, MT Status=0, MTMSN=0
2014-04-20T10:42:28.586Z,1397990548.586 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0045.lzma
2014-04-20T10:42:28.586Z,1397990548.586 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:42:28.588Z,1397990548.588 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0045.lzma.parts/0000.sbd
2014-04-20T10:42:28.588Z,1397990548.588 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0045.lzma
2014-04-20T10:42:35.828Z,1397990555.828 [NAL9602](INFO): SBD MO Status=0, MOMSN=27573, MT Status=0, MTMSN=0
2014-04-20T10:42:35.929Z,1397990555.929 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:42:35.930Z,1397990555.930 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:42:35.930Z,1397990555.930 [Default:Iridium] Stopped
2014-04-20T10:42:35.930Z,1397990555.930 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:42:35.930Z,1397990555.930 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:42:35.930Z,1397990555.930 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:42:36.391Z,1397990556.391 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:42:36.391Z,1397990556.391 [Default:CallIridium:B] Stopped
2014-04-20T10:42:36.391Z,1397990556.391 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:42:36.392Z,1397990556.392 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:42:36.392Z,1397990556.392 [Default:CallIridium] Stopped
2014-04-20T10:42:36.392Z,1397990556.392 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:42:37.225Z,1397990557.225 [NAL9602](IMPORTANT): GPS fix at: 1397990543.00
2014-04-20T10:42:37.243Z,1397990557.243 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:42:37.244Z,1397990557.244 [Default:GPS:D] Running Loop=1
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS:D] Stopped
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS] Stopped
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:42:37.741Z,1397990557.741 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:42:53.252Z,1397990573.252 [NAL9602](INFO): Powering down
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium] Running Loop=1
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium:A] Stopped
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:47:38.307Z,1397990858.307 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:47:43.307Z,1397990863.307 [Default:Iridium] Running Loop=1
2014-04-20T10:47:43.307Z,1397990863.307 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:47:43.307Z,1397990863.307 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:47:43.308Z,1397990863.308 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:47:43.308Z,1397990863.308 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:47:43.308Z,1397990863.308 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:47:43.309Z,1397990863.309 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:47:43.309Z,1397990863.309 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:47:43.309Z,1397990863.309 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:47:43.309Z,1397990863.309 [Default:GPS] Running Loop=1
2014-04-20T10:47:43.310Z,1397990863.310 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:47:43.310Z,1397990863.310 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:47:43.310Z,1397990863.310 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:47:43.310Z,1397990863.310 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:47:43.310Z,1397990863.310 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:47:43.311Z,1397990863.311 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:47:43.311Z,1397990863.311 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:47:43.311Z,1397990863.311 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:47:44.306Z,1397990864.306 [NAL9602](INFO): Powering up
2014-04-20T10:47:55.024Z,1397990875.024 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:48:12.583Z,1397990892.583 [NAL9602](INFO): SBD MO Status=1, MOMSN=27574, MT Status=0, MTMSN=0
2014-04-20T10:48:12.631Z,1397990892.631 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0048.lzma
2014-04-20T10:48:12.631Z,1397990892.631 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:48:12.633Z,1397990892.633 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0048.lzma.parts/0000.sbd
2014-04-20T10:48:12.633Z,1397990892.633 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0048.lzma
2014-04-20T10:48:23.969Z,1397990903.969 [NAL9602](INFO): SBD MO Status=1, MOMSN=27575, MT Status=0, MTMSN=0
2014-04-20T10:48:24.025Z,1397990904.025 [NAL9602](INFO): Sent 117 bytes from file Logs/20140420T092729/Express0049.lzma
2014-04-20T10:48:24.025Z,1397990904.025 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:48:24.027Z,1397990904.027 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0049.lzma.parts/0000.sbd
2014-04-20T10:48:24.027Z,1397990904.027 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0049.lzma
2014-04-20T10:48:31.781Z,1397990911.781 [NAL9602](INFO): SBD MO Status=0, MOMSN=27576, MT Status=0, MTMSN=0
2014-04-20T10:48:31.863Z,1397990911.863 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:48:31.864Z,1397990911.864 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:48:31.864Z,1397990911.864 [Default:Iridium] Stopped
2014-04-20T10:48:31.864Z,1397990911.864 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:48:31.864Z,1397990911.864 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:48:31.864Z,1397990911.864 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:48:32.302Z,1397990912.302 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:48:32.302Z,1397990912.302 [Default:CallIridium:B] Stopped
2014-04-20T10:48:32.302Z,1397990912.302 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:48:32.302Z,1397990912.302 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:48:32.303Z,1397990912.303 [Default:CallIridium] Stopped
2014-04-20T10:48:32.303Z,1397990912.303 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:48:33.209Z,1397990913.209 [NAL9602](IMPORTANT): GPS fix at: 1397990899.00
2014-04-20T10:48:33.245Z,1397990913.245 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:48:33.245Z,1397990913.245 [Default:GPS:D] Running Loop=1
2014-04-20T10:48:33.767Z,1397990913.767 [Default:GPS:D] Stopped
2014-04-20T10:48:33.772Z,1397990913.772 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:48:33.772Z,1397990913.772 [Default:GPS] Stopped
2014-04-20T10:48:33.772Z,1397990913.772 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:48:33.772Z,1397990913.772 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:48:33.772Z,1397990913.772 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:48:49.356Z,1397990929.356 [NAL9602](INFO): Powering down
2014-04-20T10:50:04.302Z,1397991004.302 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:50:09.329Z,1397991009.329 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:50:19.321Z,1397991019.321 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:50:24.328Z,1397991024.328 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:50:29.312Z,1397991029.312 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:50:34.309Z,1397991034.309 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2014-04-20T10:53:34.356Z,1397991214.356 [Default:CallIridium] Running Loop=1
2014-04-20T10:53:34.356Z,1397991214.356 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:53:34.356Z,1397991214.356 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:53:34.356Z,1397991214.356 [Default:CallIridium:A] Stopped
2014-04-20T10:53:34.356Z,1397991214.356 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:53:34.357Z,1397991214.357 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:53:39.350Z,1397991219.350 [Default:Iridium] Running Loop=1
2014-04-20T10:53:39.350Z,1397991219.350 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:53:39.350Z,1397991219.350 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:53:39.351Z,1397991219.351 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:53:39.351Z,1397991219.351 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:53:39.351Z,1397991219.351 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:53:39.351Z,1397991219.351 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:53:39.352Z,1397991219.352 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:53:39.352Z,1397991219.352 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:53:39.352Z,1397991219.352 [Default:GPS] Running Loop=1
2014-04-20T10:53:39.352Z,1397991219.352 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:53:39.352Z,1397991219.352 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:53:39.352Z,1397991219.352 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:53:39.353Z,1397991219.353 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:53:39.353Z,1397991219.353 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:53:39.354Z,1397991219.354 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:53:39.354Z,1397991219.354 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:53:39.354Z,1397991219.354 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:53:40.361Z,1397991220.361 [NAL9602](INFO): Powering up
2014-04-20T10:53:51.148Z,1397991231.148 [NAL9602](INFO): NAL9602 initialized
2014-04-20T10:54:06.504Z,1397991246.504 [NAL9602](INFO): SBD MO Status=1, MOMSN=27577, MT Status=0, MTMSN=0
2014-04-20T10:54:06.552Z,1397991246.552 [NAL9602](INFO): Sent 78 bytes from file Logs/20140420T092729/Courier0052.lzma
2014-04-20T10:54:06.552Z,1397991246.552 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:54:06.554Z,1397991246.554 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0052.lzma.parts/0000.sbd
2014-04-20T10:54:06.554Z,1397991246.554 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0052.lzma
2014-04-20T10:54:17.933Z,1397991257.933 [NAL9602](INFO): SBD MO Status=1, MOMSN=27578, MT Status=0, MTMSN=0
2014-04-20T10:54:17.990Z,1397991257.990 [NAL9602](INFO): Sent 104 bytes from file Logs/20140420T092729/Express0053.lzma
2014-04-20T10:54:17.990Z,1397991257.990 [NAL9602](INFO): Packets left to send: 0
2014-04-20T10:54:17.992Z,1397991257.992 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0053.lzma.parts/0000.sbd
2014-04-20T10:54:17.992Z,1397991257.992 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0053.lzma
2014-04-20T10:54:25.845Z,1397991265.845 [NAL9602](INFO): SBD MO Status=0, MOMSN=27579, MT Status=0, MTMSN=0
2014-04-20T10:54:25.949Z,1397991265.949 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T10:54:25.949Z,1397991265.949 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T10:54:25.950Z,1397991265.950 [Default:Iridium] Stopped
2014-04-20T10:54:25.950Z,1397991265.950 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T10:54:25.950Z,1397991265.950 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T10:54:25.950Z,1397991265.950 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:54:26.361Z,1397991266.361 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T10:54:26.361Z,1397991266.361 [Default:CallIridium:B] Stopped
2014-04-20T10:54:26.361Z,1397991266.361 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T10:54:26.361Z,1397991266.361 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T10:54:26.361Z,1397991266.361 [Default:CallIridium] Stopped
2014-04-20T10:54:26.362Z,1397991266.362 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T10:54:27.169Z,1397991267.169 [NAL9602](IMPORTANT): GPS fix at: 1397991253.00
2014-04-20T10:54:27.209Z,1397991267.209 [Default:GPS:Read_GPS] Stopped
2014-04-20T10:54:27.209Z,1397991267.209 [Default:GPS:D] Running Loop=1
2014-04-20T10:54:27.682Z,1397991267.682 [Default:GPS:D] Stopped
2014-04-20T10:54:27.683Z,1397991267.683 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T10:54:27.683Z,1397991267.683 [Default:GPS] Stopped
2014-04-20T10:54:27.683Z,1397991267.683 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T10:54:27.683Z,1397991267.683 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T10:54:27.683Z,1397991267.683 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T10:54:43.175Z,1397991283.175 [NAL9602](INFO): Powering down
2014-04-20T10:59:28.259Z,1397991568.259 [Default:CallIridium] Running Loop=1
2014-04-20T10:59:28.259Z,1397991568.259 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T10:59:28.259Z,1397991568.259 [Default:CallIridium:A] Running Loop=1
2014-04-20T10:59:28.259Z,1397991568.259 [Default:CallIridium:A] Stopped
2014-04-20T10:59:28.259Z,1397991568.259 [Default:CallIridium:B] Running Loop=1
2014-04-20T10:59:28.260Z,1397991568.260 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T10:59:33.295Z,1397991573.295 [Default:Iridium] Running Loop=1
2014-04-20T10:59:33.295Z,1397991573.295 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T10:59:33.295Z,1397991573.295 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T10:59:33.295Z,1397991573.295 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:59:33.296Z,1397991573.296 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T10:59:33.296Z,1397991573.296 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:59:33.296Z,1397991573.296 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T10:59:33.297Z,1397991573.297 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:59:33.297Z,1397991573.297 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T10:59:33.297Z,1397991573.297 [Default:GPS] Running Loop=1
2014-04-20T10:59:33.297Z,1397991573.297 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T10:59:33.297Z,1397991573.297 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T10:59:33.297Z,1397991573.297 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T10:59:33.297Z,1397991573.297 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T10:59:33.298Z,1397991573.298 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T10:59:33.302Z,1397991573.302 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T10:59:33.303Z,1397991573.303 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T10:59:33.303Z,1397991573.303 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T10:59:34.356Z,1397991574.356 [NAL9602](INFO): Powering up
2014-04-20T10:59:45.229Z,1397991585.229 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:00:05.232Z,1397991605.232 [NAL9602](INFO): SBD MO Status=1, MOMSN=27580, MT Status=0, MTMSN=0
2014-04-20T11:00:05.296Z,1397991605.296 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0056.lzma
2014-04-20T11:00:05.296Z,1397991605.296 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:00:05.298Z,1397991605.298 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0056.lzma.parts/0000.sbd
2014-04-20T11:00:05.298Z,1397991605.298 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0056.lzma
2014-04-20T11:00:29.477Z,1397991629.477 [NAL9602](INFO): SBD MO Status=2, MOMSN=27581, MT Status=2, MTMSN=0
2014-04-20T11:00:29.477Z,1397991629.477 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T11:00:49.471Z,1397991649.471 [NAL9602](INFO): SBD MO Status=1, MOMSN=27581, MT Status=0, MTMSN=0
2014-04-20T11:00:49.533Z,1397991649.533 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0057.lzma
2014-04-20T11:00:49.533Z,1397991649.533 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:00:49.535Z,1397991649.535 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0057.lzma.parts/0000.sbd
2014-04-20T11:00:49.535Z,1397991649.535 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0057.lzma
2014-04-20T11:01:02.941Z,1397991662.941 [NAL9602](INFO): SBD MO Status=0, MOMSN=27582, MT Status=0, MTMSN=0
2014-04-20T11:01:03.039Z,1397991663.039 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:01:03.040Z,1397991663.040 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:01:03.040Z,1397991663.040 [Default:Iridium] Stopped
2014-04-20T11:01:03.040Z,1397991663.040 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:01:03.040Z,1397991663.040 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:01:03.040Z,1397991663.040 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium:B] Stopped
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium] Stopped
2014-04-20T11:01:03.419Z,1397991663.419 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:01:04.313Z,1397991664.313 [NAL9602](IMPORTANT): GPS fix at: 1397991651.00
2014-04-20T11:01:04.352Z,1397991664.352 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:01:04.352Z,1397991664.352 [Default:GPS:D] Running Loop=1
2014-04-20T11:01:04.858Z,1397991664.858 [Default:GPS:D] Stopped
2014-04-20T11:01:04.859Z,1397991664.859 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:01:04.859Z,1397991664.859 [Default:GPS] Stopped
2014-04-20T11:01:04.859Z,1397991664.859 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:01:04.859Z,1397991664.859 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:01:04.859Z,1397991664.859 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:01:25.399Z,1397991685.399 [NAL9602](INFO): Powering down
2014-04-20T11:06:05.423Z,1397991965.423 [Default:CallIridium] Running Loop=1
2014-04-20T11:06:05.423Z,1397991965.423 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:06:05.423Z,1397991965.423 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:06:05.423Z,1397991965.423 [Default:CallIridium:A] Stopped
2014-04-20T11:06:05.423Z,1397991965.423 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:06:05.424Z,1397991965.424 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:06:10.442Z,1397991970.442 [Default:Iridium] Running Loop=1
2014-04-20T11:06:10.442Z,1397991970.442 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:06:10.442Z,1397991970.442 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:06:10.442Z,1397991970.442 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:06:10.443Z,1397991970.443 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:06:10.443Z,1397991970.443 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:06:10.443Z,1397991970.443 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:06:10.443Z,1397991970.443 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:06:10.444Z,1397991970.444 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS] Running Loop=1
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:06:10.444Z,1397991970.444 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:06:10.445Z,1397991970.445 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:06:10.445Z,1397991970.445 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:06:10.445Z,1397991970.445 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:06:11.475Z,1397991971.475 [NAL9602](INFO): Powering up
2014-04-20T11:06:22.216Z,1397991982.216 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:06:48.290Z,1397992008.290 [NAL9602](INFO): SBD MO Status=1, MOMSN=27583, MT Status=0, MTMSN=0
2014-04-20T11:06:48.341Z,1397992008.341 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0060.lzma
2014-04-20T11:06:48.341Z,1397992008.341 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:06:48.343Z,1397992008.343 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0060.lzma.parts/0000.sbd
2014-04-20T11:06:48.343Z,1397992008.343 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0060.lzma
2014-04-20T11:06:56.533Z,1397992016.533 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 40 of 46
2014-04-20T11:06:56.533Z,1397992016.533 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 48.7 50.2 53.7 52.1 -211.9 -333.0 -263.5 -165.6 68.9 -223.4 -262.7 1 38.6 230.1 -263.1 1 137 -224 -254 2 25 261 -254 2 3.61 -8.50 142.9 48.7 15.4 0.005 35.0 1489 73
2014-04-20T11:06:56.966Z,1397992016.966 [NAL9602](INFO): SBD MO Status=1, MOMSN=27584, MT Status=0, MTMSN=0
2014-04-20T11:06:57.014Z,1397992017.014 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0061.lzma
2014-04-20T11:06:57.015Z,1397992017.015 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:06:57.016Z,1397992017.016 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0061.lzma.parts/0000.sbd
2014-04-20T11:06:57.017Z,1397992017.017 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0061.lzma
2014-04-20T11:07:06.976Z,1397992026.976 [NAL9602](INFO): SBD MO Status=0, MOMSN=27585, MT Status=0, MTMSN=0
2014-04-20T11:07:07.061Z,1397992027.061 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:07:07.061Z,1397992027.061 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:07:07.061Z,1397992027.061 [Default:Iridium] Stopped
2014-04-20T11:07:07.062Z,1397992027.062 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:07:07.062Z,1397992027.062 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:07:07.062Z,1397992027.062 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:07:07.514Z,1397992027.514 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:07:07.514Z,1397992027.514 [Default:CallIridium:B] Stopped
2014-04-20T11:07:07.514Z,1397992027.514 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:07:07.515Z,1397992027.515 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:07:07.515Z,1397992027.515 [Default:CallIridium] Stopped
2014-04-20T11:07:07.515Z,1397992027.515 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:07:08.349Z,1397992028.349 [NAL9602](IMPORTANT): GPS fix at: 1397992014.00
2014-04-20T11:07:08.369Z,1397992028.369 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:07:08.369Z,1397992028.369 [Default:GPS:D] Running Loop=1
2014-04-20T11:07:08.828Z,1397992028.828 [Default:GPS:D] Stopped
2014-04-20T11:07:08.828Z,1397992028.828 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:07:08.828Z,1397992028.828 [Default:GPS] Stopped
2014-04-20T11:07:08.829Z,1397992028.829 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:07:08.829Z,1397992028.829 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:07:08.829Z,1397992028.829 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:07:29.375Z,1397992049.375 [NAL9602](INFO): Powering down
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium] Running Loop=1
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium:A] Stopped
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:12:09.382Z,1397992329.382 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:12:14.435Z,1397992334.435 [Default:Iridium] Running Loop=1
2014-04-20T11:12:14.435Z,1397992334.435 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:12:14.435Z,1397992334.435 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:12:14.435Z,1397992334.435 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:12:14.436Z,1397992334.436 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:12:14.436Z,1397992334.436 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:12:14.436Z,1397992334.436 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:12:14.436Z,1397992334.436 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:12:14.437Z,1397992334.437 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS] Running Loop=1
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:12:14.437Z,1397992334.437 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:12:14.438Z,1397992334.438 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:12:14.439Z,1397992334.439 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:12:14.439Z,1397992334.439 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:12:15.466Z,1397992335.466 [NAL9602](INFO): Powering up
2014-04-20T11:12:26.309Z,1397992346.309 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:12:59.787Z,1397992379.787 [NAL9602](INFO): SBD MO Status=1, MOMSN=27586, MT Status=0, MTMSN=0
2014-04-20T11:12:59.845Z,1397992379.845 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0064.lzma
2014-04-20T11:12:59.845Z,1397992379.845 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:12:59.847Z,1397992379.847 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0064.lzma.parts/0000.sbd
2014-04-20T11:12:59.847Z,1397992379.847 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0064.lzma
2014-04-20T11:13:11.055Z,1397992391.055 [NAL9602](INFO): SBD MO Status=1, MOMSN=27587, MT Status=0, MTMSN=0
2014-04-20T11:13:11.102Z,1397992391.102 [NAL9602](INFO): Sent 115 bytes from file Logs/20140420T092729/Express0065.lzma
2014-04-20T11:13:11.103Z,1397992391.103 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:13:11.104Z,1397992391.104 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0065.lzma.parts/0000.sbd
2014-04-20T11:13:11.105Z,1397992391.105 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0065.lzma
2014-04-20T11:13:22.276Z,1397992402.276 [NAL9602](INFO): SBD MO Status=0, MOMSN=27588, MT Status=0, MTMSN=0
2014-04-20T11:13:22.371Z,1397992402.371 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:13:22.371Z,1397992402.371 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:13:22.372Z,1397992402.372 [Default:Iridium] Stopped
2014-04-20T11:13:22.372Z,1397992402.372 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:13:22.372Z,1397992402.372 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:13:22.372Z,1397992402.372 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:13:22.806Z,1397992402.806 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:13:22.806Z,1397992402.806 [Default:CallIridium:B] Stopped
2014-04-20T11:13:22.806Z,1397992402.806 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:13:22.807Z,1397992402.807 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:13:22.807Z,1397992402.807 [Default:CallIridium] Stopped
2014-04-20T11:13:22.807Z,1397992402.807 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:13:23.628Z,1397992403.628 [NAL9602](IMPORTANT): GPS fix at: 1397992390.00
2014-04-20T11:13:23.671Z,1397992403.671 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:13:23.671Z,1397992403.671 [Default:GPS:D] Running Loop=1
2014-04-20T11:13:24.134Z,1397992404.134 [Default:GPS:D] Stopped
2014-04-20T11:13:24.143Z,1397992404.143 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:13:24.143Z,1397992404.143 [Default:GPS] Stopped
2014-04-20T11:13:24.143Z,1397992404.143 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:13:24.143Z,1397992404.143 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:13:24.143Z,1397992404.143 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:13:44.741Z,1397992424.741 [NAL9602](INFO): Powering down
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium] Running Loop=1
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium:A] Stopped
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:18:24.754Z,1397992704.754 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:18:29.734Z,1397992709.734 [Default:Iridium] Running Loop=1
2014-04-20T11:18:29.734Z,1397992709.734 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:18:29.735Z,1397992709.735 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:18:29.735Z,1397992709.735 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:18:29.735Z,1397992709.735 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:18:29.735Z,1397992709.735 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:18:29.736Z,1397992709.736 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:18:29.736Z,1397992709.736 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:18:29.736Z,1397992709.736 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:18:29.736Z,1397992709.736 [Default:GPS] Running Loop=1
2014-04-20T11:18:29.737Z,1397992709.737 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:18:29.737Z,1397992709.737 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:18:29.737Z,1397992709.737 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:18:29.737Z,1397992709.737 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:18:29.737Z,1397992709.737 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:18:29.738Z,1397992709.738 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:18:29.738Z,1397992709.738 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:18:29.738Z,1397992709.738 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:18:30.778Z,1397992710.778 [NAL9602](INFO): Powering up
2014-04-20T11:18:41.647Z,1397992721.647 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:19:16.513Z,1397992756.513 [NAL9602](INFO): SBD MO Status=2, MOMSN=27589, MT Status=2, MTMSN=0
2014-04-20T11:19:16.513Z,1397992756.513 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T11:19:17.788Z,1397992757.788 [NAL9602](IMPORTANT): GPS fix at: 1397992744.00
2014-04-20T11:19:17.835Z,1397992757.835 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:19:17.835Z,1397992757.835 [Default:GPS:D] Running Loop=1
2014-04-20T11:19:18.230Z,1397992758.230 [Default:GPS:D] Stopped
2014-04-20T11:19:18.230Z,1397992758.230 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:19:18.230Z,1397992758.230 [Default:GPS] Stopped
2014-04-20T11:19:18.230Z,1397992758.230 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:19:18.230Z,1397992758.230 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:19:18.231Z,1397992758.231 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:19:40.330Z,1397992780.330 [NAL9602](INFO): SBD MO Status=1, MOMSN=27589, MT Status=0, MTMSN=0
2014-04-20T11:19:40.382Z,1397992780.382 [NAL9602](INFO): Sent 78 bytes from file Logs/20140420T092729/Courier0068.lzma
2014-04-20T11:19:40.382Z,1397992780.382 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:19:40.384Z,1397992780.384 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0068.lzma.parts/0000.sbd
2014-04-20T11:19:40.384Z,1397992780.384 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0068.lzma
2014-04-20T11:19:48.807Z,1397992788.807 [NAL9602](INFO): SBD MO Status=1, MOMSN=27590, MT Status=0, MTMSN=0
2014-04-20T11:19:48.855Z,1397992788.855 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0069.lzma
2014-04-20T11:19:48.855Z,1397992788.855 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:19:48.857Z,1397992788.857 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0069.lzma.parts/0000.sbd
2014-04-20T11:19:48.857Z,1397992788.857 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0069.lzma
2014-04-20T11:19:56.712Z,1397992796.712 [NAL9602](INFO): SBD MO Status=0, MOMSN=27591, MT Status=0, MTMSN=0
2014-04-20T11:19:56.810Z,1397992796.810 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:19:56.811Z,1397992796.811 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:19:56.811Z,1397992796.811 [Default:Iridium] Stopped
2014-04-20T11:19:56.811Z,1397992796.811 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:19:56.811Z,1397992796.811 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:19:56.811Z,1397992796.811 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:19:57.212Z,1397992797.212 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:19:57.212Z,1397992797.212 [Default:CallIridium:B] Stopped
2014-04-20T11:19:57.212Z,1397992797.212 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:19:57.213Z,1397992797.213 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:19:57.213Z,1397992797.213 [Default:CallIridium] Stopped
2014-04-20T11:19:57.213Z,1397992797.213 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:20:07.351Z,1397992807.351 [NAL9602](INFO): Powering down
2014-04-20T11:24:57.391Z,1397993097.391 [Default:CallIridium] Running Loop=1
2014-04-20T11:24:57.391Z,1397993097.391 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:24:57.391Z,1397993097.391 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:24:57.391Z,1397993097.391 [Default:CallIridium:A] Stopped
2014-04-20T11:24:57.391Z,1397993097.391 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:24:57.392Z,1397993097.392 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:25:02.385Z,1397993102.385 [Default:Iridium] Running Loop=1
2014-04-20T11:25:02.386Z,1397993102.386 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:25:02.386Z,1397993102.386 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:25:02.386Z,1397993102.386 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:25:02.386Z,1397993102.386 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:25:02.386Z,1397993102.386 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:25:02.387Z,1397993102.387 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:25:02.387Z,1397993102.387 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:25:02.387Z,1397993102.387 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:25:02.387Z,1397993102.387 [Default:GPS] Running Loop=1
2014-04-20T11:25:02.387Z,1397993102.387 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:25:02.388Z,1397993102.388 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:25:02.388Z,1397993102.388 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:25:02.388Z,1397993102.388 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:25:02.388Z,1397993102.388 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:25:02.389Z,1397993102.389 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:25:02.389Z,1397993102.389 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:25:02.389Z,1397993102.389 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:25:03.397Z,1397993103.397 [NAL9602](INFO): Powering up
2014-04-20T11:25:14.340Z,1397993114.340 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:25:31.750Z,1397993131.750 [NAL9602](INFO): SBD MO Status=1, MOMSN=27592, MT Status=0, MTMSN=0
2014-04-20T11:25:31.803Z,1397993131.803 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0072.lzma
2014-04-20T11:25:31.803Z,1397993131.803 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:25:31.805Z,1397993131.805 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0072.lzma.parts/0000.sbd
2014-04-20T11:25:31.805Z,1397993131.805 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0072.lzma
2014-04-20T11:25:38.451Z,1397993138.451 [NAL9602](INFO): SBD MO Status=1, MOMSN=27593, MT Status=0, MTMSN=0
2014-04-20T11:25:38.509Z,1397993138.509 [NAL9602](INFO): Sent 107 bytes from file Logs/20140420T092729/Express0073.lzma
2014-04-20T11:25:38.509Z,1397993138.509 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:25:38.511Z,1397993138.511 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0073.lzma.parts/0000.sbd
2014-04-20T11:25:38.511Z,1397993138.511 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0073.lzma
2014-04-20T11:25:47.594Z,1397993147.594 [NAL9602](INFO): SBD MO Status=0, MOMSN=27594, MT Status=0, MTMSN=0
2014-04-20T11:25:47.686Z,1397993147.686 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:25:47.686Z,1397993147.686 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:25:47.686Z,1397993147.686 [Default:Iridium] Stopped
2014-04-20T11:25:47.687Z,1397993147.687 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:25:47.687Z,1397993147.687 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:25:47.687Z,1397993147.687 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:25:48.130Z,1397993148.130 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:25:48.130Z,1397993148.130 [Default:CallIridium:B] Stopped
2014-04-20T11:25:48.130Z,1397993148.130 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:25:48.130Z,1397993148.130 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:25:48.130Z,1397993148.130 [Default:CallIridium] Stopped
2014-04-20T11:25:48.131Z,1397993148.131 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:25:48.939Z,1397993148.939 [NAL9602](IMPORTANT): GPS fix at: 1397993135.00
2014-04-20T11:25:48.957Z,1397993148.957 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:25:48.957Z,1397993148.957 [Default:GPS:D] Running Loop=1
2014-04-20T11:25:49.428Z,1397993149.428 [Default:GPS:D] Stopped
2014-04-20T11:25:49.428Z,1397993149.428 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:25:49.428Z,1397993149.428 [Default:GPS] Stopped
2014-04-20T11:25:49.429Z,1397993149.429 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:25:49.429Z,1397993149.429 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:25:49.429Z,1397993149.429 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:26:09.999Z,1397993169.999 [NAL9602](INFO): Powering down
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium] Running Loop=1
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium:A] Stopped
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:30:50.001Z,1397993450.001 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:30:55.056Z,1397993455.056 [Default:Iridium] Running Loop=1
2014-04-20T11:30:55.057Z,1397993455.057 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:30:55.057Z,1397993455.057 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:30:55.057Z,1397993455.057 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:30:55.057Z,1397993455.057 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:30:55.057Z,1397993455.057 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:30:55.058Z,1397993455.058 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:30:55.058Z,1397993455.058 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:30:55.058Z,1397993455.058 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:30:55.058Z,1397993455.058 [Default:GPS] Running Loop=1
2014-04-20T11:30:55.058Z,1397993455.058 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:30:55.059Z,1397993455.059 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:30:55.059Z,1397993455.059 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:30:55.059Z,1397993455.059 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:30:55.059Z,1397993455.059 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:30:55.060Z,1397993455.060 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:30:55.060Z,1397993455.060 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:30:55.061Z,1397993455.061 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:30:56.080Z,1397993456.080 [NAL9602](INFO): Powering up
2014-04-20T11:31:06.995Z,1397993466.995 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:31:32.525Z,1397993492.525 [NAL9602](INFO): SBD MO Status=1, MOMSN=27595, MT Status=0, MTMSN=0
2014-04-20T11:31:32.578Z,1397993492.578 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0076.lzma
2014-04-20T11:31:32.578Z,1397993492.578 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:31:32.580Z,1397993492.580 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0076.lzma.parts/0000.sbd
2014-04-20T11:31:32.580Z,1397993492.580 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0076.lzma
2014-04-20T11:31:36.340Z,1397993496.340 [DVL_micro](ERROR): NQ1 string checksum mismatch. Reported:108 Calculated:125
2014-04-20T11:31:36.341Z,1397993496.341 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 46.5 46.8 4 -3.5 -40.5 -91.6 -64.4 -10 -158 -121 -34 12 12 13 13 117.6 31.9 -54.0 1 -113.7 51.2 -47.3 1 148 -165 -87 2 -7 222 -87 2 2.13 -2.67 140.0 46.5 15.4 0.005 35.0 1489 108
2014-04-20T11:31:41.492Z,1397993501.492 [NAL9602](INFO): SBD MO Status=1, MOMSN=27596, MT Status=0, MTMSN=0
2014-04-20T11:31:41.540Z,1397993501.540 [NAL9602](INFO): Sent 116 bytes from file Logs/20140420T092729/Express0077.lzma
2014-04-20T11:31:41.540Z,1397993501.540 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:31:41.543Z,1397993501.543 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0077.lzma.parts/0000.sbd
2014-04-20T11:31:41.543Z,1397993501.543 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0077.lzma
2014-04-20T11:31:49.357Z,1397993509.357 [NAL9602](INFO): SBD MO Status=0, MOMSN=27597, MT Status=0, MTMSN=0
2014-04-20T11:31:49.443Z,1397993509.443 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:31:49.464Z,1397993509.464 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:31:49.464Z,1397993509.464 [Default:Iridium] Stopped
2014-04-20T11:31:49.464Z,1397993509.464 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:31:49.464Z,1397993509.464 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:31:49.464Z,1397993509.464 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:31:49.881Z,1397993509.881 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:31:49.881Z,1397993509.881 [Default:CallIridium:B] Stopped
2014-04-20T11:31:49.881Z,1397993509.881 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:31:49.881Z,1397993509.881 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:31:49.881Z,1397993509.881 [Default:CallIridium] Stopped
2014-04-20T11:31:49.882Z,1397993509.882 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:31:50.740Z,1397993510.740 [NAL9602](IMPORTANT): GPS fix at: 1397993497.00
2014-04-20T11:31:50.786Z,1397993510.786 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:31:50.786Z,1397993510.786 [Default:GPS:D] Running Loop=1
2014-04-20T11:31:51.253Z,1397993511.253 [Default:GPS:D] Stopped
2014-04-20T11:31:51.253Z,1397993511.253 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:31:51.254Z,1397993511.254 [Default:GPS] Stopped
2014-04-20T11:31:51.254Z,1397993511.254 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:31:51.254Z,1397993511.254 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:31:51.254Z,1397993511.254 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:32:11.761Z,1397993531.761 [NAL9602](INFO): Powering down
2014-04-20T11:36:51.872Z,1397993811.872 [Default:CallIridium] Running Loop=1
2014-04-20T11:36:51.872Z,1397993811.872 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:36:51.873Z,1397993811.873 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:36:51.873Z,1397993811.873 [Default:CallIridium:A] Stopped
2014-04-20T11:36:51.873Z,1397993811.873 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:36:51.873Z,1397993811.873 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium] Running Loop=1
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:36:56.811Z,1397993816.811 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:36:56.812Z,1397993816.812 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:36:56.812Z,1397993816.812 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:36:56.812Z,1397993816.812 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS] Running Loop=1
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:36:56.813Z,1397993816.813 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:36:56.814Z,1397993816.814 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:36:56.814Z,1397993816.814 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:36:56.814Z,1397993816.814 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:36:57.873Z,1397993817.873 [NAL9602](INFO): Powering up
2014-04-20T11:37:08.635Z,1397993828.635 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:37:12.123Z,1397993832.123 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 43 of 46
2014-04-20T11:37:12.123Z,1397993832.123 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 43.2 47.2 52.7 47.4 -10.8 -33.6 -1 -159 11 13 14 13 133.7 77.7 -66.7 1 -150.4 67.7 -34.1 1 214 12 -142 2 -140 163 -142 2 0.77 -12.91 127.4 43.2 15.4 0.005 35.0 1489 115
2014-04-20T11:37:29.524Z,1397993849.524 [NAL9602](INFO): SBD MO Status=1, MOMSN=27598, MT Status=0, MTMSN=0
2014-04-20T11:37:29.572Z,1397993849.572 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0080.lzma
2014-04-20T11:37:29.572Z,1397993849.572 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:37:29.574Z,1397993849.574 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0080.lzma.parts/0000.sbd
2014-04-20T11:37:29.574Z,1397993849.574 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0080.lzma
2014-04-20T11:37:54.382Z,1397993874.382 [NAL9602](INFO): SBD MO Status=2, MOMSN=27599, MT Status=2, MTMSN=0
2014-04-20T11:37:54.382Z,1397993874.382 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-20T11:37:55.675Z,1397993875.675 [NAL9602](IMPORTANT): GPS fix at: 1397993862.00
2014-04-20T11:37:55.694Z,1397993875.694 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:37:55.694Z,1397993875.694 [Default:GPS:D] Running Loop=1
2014-04-20T11:37:56.241Z,1397993876.241 [Default:GPS:D] Stopped
2014-04-20T11:37:56.242Z,1397993876.242 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:37:56.242Z,1397993876.242 [Default:GPS] Stopped
2014-04-20T11:37:56.242Z,1397993876.242 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:37:56.242Z,1397993876.242 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:37:56.242Z,1397993876.242 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:38:11.537Z,1397993891.537 [NAL9602](INFO): SBD MO Status=1, MOMSN=27599, MT Status=0, MTMSN=0
2014-04-20T11:38:11.597Z,1397993891.597 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0081.lzma
2014-04-20T11:38:11.597Z,1397993891.597 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:38:11.599Z,1397993891.599 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0081.lzma.parts/0000.sbd
2014-04-20T11:38:11.599Z,1397993891.599 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0081.lzma
2014-04-20T11:38:21.095Z,1397993901.095 [NAL9602](INFO): SBD MO Status=0, MOMSN=27600, MT Status=0, MTMSN=0
2014-04-20T11:38:21.183Z,1397993901.183 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:38:21.184Z,1397993901.184 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:38:21.184Z,1397993901.184 [Default:Iridium] Stopped
2014-04-20T11:38:21.184Z,1397993901.184 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:38:21.184Z,1397993901.184 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:38:21.184Z,1397993901.184 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:38:21.599Z,1397993901.599 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:38:21.599Z,1397993901.599 [Default:CallIridium:B] Stopped
2014-04-20T11:38:21.600Z,1397993901.600 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:38:21.600Z,1397993901.600 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:38:21.600Z,1397993901.600 [Default:CallIridium] Stopped
2014-04-20T11:38:21.600Z,1397993901.600 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:38:31.693Z,1397993911.693 [NAL9602](INFO): Powering down
2014-04-20T11:43:21.768Z,1397994201.768 [Default:CallIridium] Running Loop=1
2014-04-20T11:43:21.768Z,1397994201.768 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:43:21.768Z,1397994201.768 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:43:21.768Z,1397994201.768 [Default:CallIridium:A] Stopped
2014-04-20T11:43:21.769Z,1397994201.769 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:43:21.769Z,1397994201.769 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium] Running Loop=1
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:43:26.717Z,1397994206.717 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:43:26.718Z,1397994206.718 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:43:26.718Z,1397994206.718 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:43:26.718Z,1397994206.718 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS] Running Loop=1
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:43:26.719Z,1397994206.719 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:43:26.720Z,1397994206.720 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:43:26.720Z,1397994206.720 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:43:26.720Z,1397994206.720 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:43:27.751Z,1397994207.751 [NAL9602](INFO): Powering up
2014-04-20T11:43:38.472Z,1397994218.472 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:43:53.779Z,1397994233.779 [NAL9602](INFO): SBD MO Status=1, MOMSN=27601, MT Status=0, MTMSN=0
2014-04-20T11:43:53.831Z,1397994233.831 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0084.lzma
2014-04-20T11:43:53.832Z,1397994233.832 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:43:53.833Z,1397994233.833 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0084.lzma.parts/0000.sbd
2014-04-20T11:43:53.834Z,1397994233.834 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0084.lzma
2014-04-20T11:44:04.410Z,1397994244.410 [NAL9602](INFO): SBD MO Status=1, MOMSN=27602, MT Status=0, MTMSN=0
2014-04-20T11:44:04.468Z,1397994244.468 [NAL9602](INFO): Sent 106 bytes from file Logs/20140420T092729/Express0085.lzma
2014-04-20T11:44:04.468Z,1397994244.468 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:44:04.470Z,1397994244.470 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Express0085.lzma.parts/0000.sbd
2014-04-20T11:44:04.470Z,1397994244.470 [NAL9602](INFO): Completed sending Logs/20140420T092729/Express0085.lzma
2014-04-20T11:44:12.300Z,1397994252.300 [NAL9602](INFO): SBD MO Status=0, MOMSN=27603, MT Status=0, MTMSN=0
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium] Stopped
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:44:12.383Z,1397994252.383 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:44:12.825Z,1397994252.825 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-20T11:44:12.825Z,1397994252.825 [Default:CallIridium:B] Stopped
2014-04-20T11:44:12.825Z,1397994252.825 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:44:12.826Z,1397994252.826 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-20T11:44:12.826Z,1397994252.826 [Default:CallIridium] Stopped
2014-04-20T11:44:12.826Z,1397994252.826 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:44:13.660Z,1397994253.660 [NAL9602](IMPORTANT): GPS fix at: 1397994240.00
2014-04-20T11:44:13.679Z,1397994253.679 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:44:13.679Z,1397994253.679 [Default:GPS:D] Running Loop=1
2014-04-20T11:44:14.222Z,1397994254.222 [Default:GPS:D] Stopped
2014-04-20T11:44:14.223Z,1397994254.223 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:44:14.223Z,1397994254.223 [Default:GPS] Stopped
2014-04-20T11:44:14.223Z,1397994254.223 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:44:14.223Z,1397994254.223 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:44:14.223Z,1397994254.223 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:44:34.737Z,1397994274.737 [NAL9602](INFO): Powering down
2014-04-20T11:49:14.789Z,1397994554.789 [Default:CallIridium] Running Loop=1
2014-04-20T11:49:14.790Z,1397994554.790 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-20T11:49:14.790Z,1397994554.790 [Default:CallIridium:A] Running Loop=1
2014-04-20T11:49:14.790Z,1397994554.790 [Default:CallIridium:A] Stopped
2014-04-20T11:49:14.790Z,1397994554.790 [Default:CallIridium:B] Running Loop=1
2014-04-20T11:49:14.790Z,1397994554.790 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-20T11:49:19.791Z,1397994559.791 [Default:Iridium] Running Loop=1
2014-04-20T11:49:19.791Z,1397994559.791 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-20T11:49:19.792Z,1397994559.792 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-20T11:49:19.792Z,1397994559.792 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:49:19.792Z,1397994559.792 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-20T11:49:19.792Z,1397994559.792 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:49:19.793Z,1397994559.793 [Default:Iridium:B.GoToSurface] Stopped
2014-04-20T11:49:19.793Z,1397994559.793 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:49:19.793Z,1397994559.793 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS] Running Loop=1
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-20T11:49:19.794Z,1397994559.794 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-20T11:49:19.795Z,1397994559.795 [Default:GPS:B.GoToSurface] Stopped
2014-04-20T11:49:19.795Z,1397994559.795 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:49:19.795Z,1397994559.795 [Default:GPS:Read_GPS] Running Loop=1
2014-04-20T11:49:20.786Z,1397994560.786 [NAL9602](INFO): Powering up
2014-04-20T11:49:31.523Z,1397994571.523 [NAL9602](INFO): NAL9602 initialized
2014-04-20T11:49:51.565Z,1397994591.565 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=27604, MT Status=1, MTMSN=1812
2014-04-20T11:49:51.614Z,1397994591.614 [NAL9602](INFO): Sent 76 bytes from file Logs/20140420T092729/Courier0088.lzma
2014-04-20T11:49:51.614Z,1397994591.614 [NAL9602](INFO): Packets left to send: 0
2014-04-20T11:49:51.616Z,1397994591.616 [NAL9602](INFO): Stored copy of sent data in Logs/20140420T092729/Courier0088.lzma.parts/0000.sbd
2014-04-20T11:49:51.616Z,1397994591.616 [NAL9602](INFO): Completed sending Logs/20140420T092729/Courier0088.lzma
2014-04-20T11:49:52.224Z,1397994592.224 [NAL9602](INFO): Received command:restart system
2014-04-20T11:49:52.264Z,1397994592.264 [CommandLine](IMPORTANT): got command restart system
2014-04-20T11:49:53.517Z,1397994593.517 [NAL9602](IMPORTANT): GPS fix at: 1397994580.00
2014-04-20T11:49:53.559Z,1397994593.559 [Default:GPS:Read_GPS] Stopped
2014-04-20T11:49:53.559Z,1397994593.559 [Default:GPS:D] Running Loop=1
2014-04-20T11:49:53.998Z,1397994593.998 [Default:GPS:D] Stopped
2014-04-20T11:49:53.999Z,1397994593.999 [Default:GPS](INFO): Completed Default:GPS
2014-04-20T11:49:53.999Z,1397994593.999 [Default:GPS] Stopped
2014-04-20T11:49:53.999Z,1397994593.999 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-20T11:49:53.999Z,1397994593.999 [Default:GPS:A.SetSpeed] Stopped
2014-04-20T11:49:53.999Z,1397994593.999 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:49:54.490Z,1397994594.490 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-04-20T11:49:54.511Z,1397994594.511 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-04-20T11:49:54.903Z,1397994594.903 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-04-20T11:49:54.915Z,1397994594.915 [WetLabsBB2FL](INFO): Powering down
2014-04-20T11:49:54.919Z,1397994594.919 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-04-20T11:49:54.999Z,1397994594.999 [CTD_NeilBrown](INFO): Powering down
2014-04-20T11:49:55.011Z,1397994595.011 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2014-04-20T11:49:55.111Z,1397994595.111 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2014-04-20T11:49:55.113Z,1397994595.113 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-04-20T11:49:55.132Z,1397994595.132 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-04-20T11:49:55.132Z,1397994595.132 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-04-20T11:49:55.376Z,1397994595.376 [controlThread](DEBUG): Uninitializing ControlThread
2014-04-20T11:49:55.377Z,1397994595.377 [AHRS_sp3003D](INFO): Powering down
2014-04-20T11:49:55.378Z,1397994595.378 [DVL_micro](INFO): uninitialize:Powering down
2014-04-20T11:49:55.379Z,1397994595.379 [NAL9602](INFO): Powering down
2014-04-20T11:49:55.392Z,1397994595.392 [Radio_Freewave](INFO): Powering down
2014-04-20T11:49:55.396Z,1397994595.396 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-04-20T11:49:55.398Z,1397994595.398 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-04-20T11:49:55.398Z,1397994595.398 [Default] Stopped
2014-04-20T11:49:55.398Z,1397994595.398 [Default](INFO): Aggregate::uninitialize Default
2014-04-20T11:49:55.398Z,1397994595.398 [Default:Iridium] Stopped
2014-04-20T11:49:55.398Z,1397994595.398 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-20T11:49:55.398Z,1397994595.398 [Default:Iridium:A.SetSpeed] Stopped
2014-04-20T11:49:55.399Z,1397994595.399 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:49:55.399Z,1397994595.399 [Default:Iridium:Read_Iridium] Stopped
2014-04-20T11:49:55.399Z,1397994595.399 [Default:CallIridium] Stopped
2014-04-20T11:49:55.399Z,1397994595.399 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-20T11:49:55.399Z,1397994595.399 [Default:CallIridium:B] Stopped
2014-04-20T11:49:55.399Z,1397994595.399 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface] Stopped
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Stopped
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface:B.GoToSurface] Stopped
2014-04-20T11:49:55.400Z,1397994595.400 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-20T11:49:55.411Z,1397994595.411 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-04-20T11:49:55.411Z,1397994595.411 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-04-20T11:49:55.416Z,1397994595.416 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-04-20T11:49:55.416Z,1397994595.416 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-04-20T11:49:55.417Z,1397994595.417 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-04-20T11:49:55.417Z,1397994595.417 [BuoyancyServo](INFO): Powering down
2014-04-20T11:49:55.432Z,1397994595.432 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-04-20T11:49:55.432Z,1397994595.432 [ElevatorServo](INFO): Powering down
2014-04-20T11:49:55.433Z,1397994595.433 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-04-20T11:49:55.434Z,1397994595.434 [MassServo](INFO): Powering down
2014-04-20T11:49:55.435Z,1397994595.435 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-04-20T11:49:55.435Z,1397994595.435 [RudderServo](INFO): Powering down
2014-04-20T11:49:55.436Z,1397994595.436 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-04-20T11:49:55.436Z,1397994595.436 [ThrusterServo](INFO): Powering down
2014-04-20T11:49:55.437Z,1397994595.437 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-04-20T11:49:55.437Z,1397994595.437 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-04-20T11:49:55.438Z,1397994595.438 [CBIT](DEBUG): Uninitialize CBIT Component.