2012-12-03T17:59:47.917Z,1354557587.917 [Supervisor](DEBUG): Initializing supervisor.
2012-12-03T17:59:47.919Z,1354557587.920 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-12-03T17:59:47.920Z,1354557587.920 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-12-03T17:59:47.921Z,1354557587.921 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-12-03T17:59:47.925Z,1354557587.925 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-12-03T17:59:47.936Z,1354557587.936 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-12-03T17:59:47.937Z,1354557587.937 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-12-03T17:59:47.938Z,1354557587.938 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2012-12-03T17:59:47.939Z,1354557587.939 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2012-12-03T17:59:47.940Z,1354557587.940 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-12-03T17:59:47.943Z,1354557587.943 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-12-03T17:59:48.423Z,1354557588.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-12-03T17:59:48.423Z,1354557588.423 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-12-03T17:59:48.623Z,1354557588.623 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-12-03T17:59:48.624Z,1354557588.624 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-12-03T17:59:48.712Z,1354557588.712 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-12-03T17:59:48.712Z,1354557588.712 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-12-03T17:59:48.927Z,1354557588.927 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-12-03T17:59:48.927Z,1354557588.927 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-12-03T17:59:49.310Z,1354557589.310 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-12-03T17:59:49.311Z,1354557589.311 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-12-03T17:59:49.560Z,1354557589.560 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-12-03T17:59:49.561Z,1354557589.561 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-12-03T17:59:49.739Z,1354557589.739 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-12-03T17:59:49.740Z,1354557589.740 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-12-03T17:59:50.013Z,1354557590.013 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-12-03T17:59:50.013Z,1354557590.013 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-12-03T17:59:50.117Z,1354557590.117 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-12-03T17:59:50.118Z,1354557590.118 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-12-03T17:59:50.543Z,1354557590.543 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-12-03T17:59:50.543Z,1354557590.543 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-12-03T17:59:50.663Z,1354557590.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-12-03T17:59:50.663Z,1354557590.663 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-12-03T17:59:50.751Z,1354557590.751 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-12-03T17:59:50.755Z,1354557590.755 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-12-03T17:59:50.860Z,1354557590.860 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-12-03T17:59:50.997Z,1354557590.997 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-12-03T17:59:51.086Z,1354557591.086 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-12-03T17:59:51.191Z,1354557591.191 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-12-03T17:59:51.296Z,1354557591.296 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-12-03T17:59:51.421Z,1354557591.421 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-12-03T17:59:51.517Z,1354557591.517 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-12-03T17:59:51.607Z,1354557591.606 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2012-12-03T17:59:51.644Z,1354557591.644 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-12-03T17:59:51.838Z,1354557591.838 [InternalSim] Loaded
2012-12-03T17:59:51.839Z,1354557591.839 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-12-03T17:59:51.839Z,1354557591.839 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-12-03T17:59:51.840Z,1354557591.840 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-12-03T17:59:51.920Z,1354557591.920 [SBIT](DEBUG): Construct Startup Built In Test.
2012-12-03T17:59:51.950Z,1354557591.950 [SBIT] Loaded
2012-12-03T17:59:51.950Z,1354557591.950 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-12-03T17:59:51.951Z,1354557591.951 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-12-03T17:59:51.981Z,1354557591.981 [IBIT] Loaded
2012-12-03T17:59:51.982Z,1354557591.981 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-12-03T17:59:51.985Z,1354557591.985 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-12-03T17:59:52.113Z,1354557592.113 [CBIT] Loaded
2012-12-03T17:59:52.114Z,1354557592.114 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-12-03T17:59:52.114Z,1354557592.114 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-12-03T17:59:52.115Z,1354557592.115 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-12-03T17:59:52.283Z,1354557592.283 [BuoyancyServo] Loaded
2012-12-03T17:59:52.283Z,1354557592.283 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-12-03T17:59:52.296Z,1354557592.296 [ElevatorServo] Loaded
2012-12-03T17:59:52.296Z,1354557592.296 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-12-03T17:59:52.309Z,1354557592.309 [MassServo] Loaded
2012-12-03T17:59:52.309Z,1354557592.309 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-12-03T17:59:52.322Z,1354557592.322 [RudderServo] Loaded
2012-12-03T17:59:52.322Z,1354557592.322 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-12-03T17:59:52.334Z,1354557592.334 [ThrusterServo] Loaded
2012-12-03T17:59:52.335Z,1354557592.335 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-12-03T17:59:52.335Z,1354557592.335 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-12-03T17:59:52.336Z,1354557592.336 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-12-03T17:59:52.364Z,1354557592.365 [DepthRateCalculator] Loaded
2012-12-03T17:59:52.365Z,1354557592.365 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-12-03T17:59:57.089Z,1354557597.089 [HFRadarModelCalc] Loaded
2012-12-03T17:59:57.089Z,1354557597.089 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-12-03T17:59:57.106Z,1354557597.106 [NavChart] Loaded
2012-12-03T17:59:57.106Z,1354557597.106 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-12-03T17:59:57.113Z,1354557597.113 [PitchRateCalculator] Loaded
2012-12-03T17:59:57.113Z,1354557597.113 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-12-03T17:59:57.120Z,1354557597.120 [SpeedCalculator] Loaded
2012-12-03T17:59:57.120Z,1354557597.120 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-12-03T17:59:57.136Z,1354557597.136 [TempGradientCalculator] Loaded
2012-12-03T17:59:57.136Z,1354557597.136 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-12-03T17:59:57.143Z,1354557597.143 [YawRateCalculator] Loaded
2012-12-03T17:59:57.143Z,1354557597.143 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-12-03T17:59:57.186Z,1354557597.186 [Navigation] Loaded
2012-12-03T17:59:57.186Z,1354557597.186 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-12-03T17:59:57.187Z,1354557597.187 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-12-03T17:59:57.187Z,1354557597.187 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-12-03T17:59:57.461Z,1354557597.461 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-12-03T17:59:57.461Z,1354557597.461 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-12-03T17:59:57.498Z,1354557597.498 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-12-03T17:59:57.498Z,1354557597.499 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-12-03T17:59:57.555Z,1354557597.555 [VerticalControl](DEBUG): Construct VerticalControl.
2012-12-03T17:59:57.655Z,1354557597.655 [VerticalControl] Loaded
2012-12-03T17:59:57.655Z,1354557597.655 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-12-03T17:59:57.656Z,1354557597.656 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-12-03T17:59:57.717Z,1354557597.717 [HorizontalControl] Loaded
2012-12-03T17:59:57.717Z,1354557597.717 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-12-03T17:59:57.718Z,1354557597.718 [SpeedControl](DEBUG): Construct SpeedControl.
2012-12-03T17:59:57.720Z,1354557597.720 [SpeedControl] Loaded
2012-12-03T17:59:57.720Z,1354557597.720 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-12-03T17:59:57.721Z,1354557597.721 [LoopControl](DEBUG): Construct LoopControl.
2012-12-03T17:59:57.722Z,1354557597.722 [LoopControl] Loaded
2012-12-03T17:59:57.722Z,1354557597.722 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-12-03T17:59:57.723Z,1354557597.723 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-12-03T17:59:57.723Z,1354557597.723 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-12-03T17:59:57.735Z,1354557597.735 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-12-03T17:59:57.741Z,1354557597.741 [AsyncPiEstimator] Loaded
2012-12-03T17:59:57.741Z,1354557597.741 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-12-03T17:59:57.742Z,1354557597.742 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A14E0
2012-12-03T17:59:57.743Z,1354557597.743 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-12-03T17:59:57.744Z,1354557597.744 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-12-03T17:59:57.913Z,1354557597.912 [AHRS_sp3003D] Loaded
2012-12-03T17:59:57.913Z,1354557597.913 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-12-03T17:59:58.187Z,1354557598.187 [Batt_Ocean_Server] Loaded
2012-12-03T17:59:58.188Z,1354557598.188 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-12-03T17:59:58.202Z,1354557598.202 [Depth_Keller] Loaded
2012-12-03T17:59:58.202Z,1354557598.202 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-12-03T17:59:58.208Z,1354557598.208 [DropWeight] Loaded
2012-12-03T17:59:58.209Z,1354557598.209 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-12-03T17:59:58.383Z,1354557598.383 [DVL_micro] Loaded
2012-12-03T17:59:58.384Z,1354557598.384 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-12-03T17:59:58.385Z,1354557598.385 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 407234E0
2012-12-03T17:59:58.473Z,1354557598.473 [NAL9602] Loaded
2012-12-03T17:59:58.474Z,1354557598.474 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-12-03T17:59:58.528Z,1354557598.528 [Onboard] Loaded
2012-12-03T17:59:58.529Z,1354557598.529 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-12-03T17:59:58.535Z,1354557598.536 [Radio_Freewave] Loaded
2012-12-03T17:59:58.536Z,1354557598.536 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-12-03T17:59:58.537Z,1354557598.537 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-12-03T17:59:58.537Z,1354557598.537 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-12-03T17:59:58.635Z,1354557598.635 [CTD_NeilBrown] Loaded
2012-12-03T17:59:58.635Z,1354557598.635 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-12-03T17:59:58.636Z,1354557598.636 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4077C4E0
2012-12-03T17:59:58.655Z,1354557598.655 [PAR_Licor] Loaded
2012-12-03T17:59:58.655Z,1354557598.655 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-12-03T17:59:58.712Z,1354557598.712 [Turbulence_NPS] Loaded
2012-12-03T17:59:58.712Z,1354557598.712 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-12-03T17:59:58.713Z,1354557598.713 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407AC4E0
2012-12-03T17:59:58.746Z,1354557598.746 [WetLabsBB2FL] Loaded
2012-12-03T17:59:58.747Z,1354557598.747 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-12-03T17:59:58.748Z,1354557598.748 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407DC4E0
2012-12-03T17:59:58.748Z,1354557598.748 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-12-03T17:59:58.751Z,1354557598.751 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-12-03T17:59:58.752Z,1354557598.752 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-12-03T17:59:58.759Z,1354557598.759 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-12-03T17:59:58.760Z,1354557598.760 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4080C4E0
2012-12-03T17:59:58.765Z,1354557598.764 [Supervisor](DEBUG): Running supervisor.
2012-12-03T17:59:58.766Z,1354557598.766 [CommandLine](INFO): Thread ID is 7058
2012-12-03T17:59:58.768Z,1354557598.768 [controlThread](INFO): Thread ID is 7057
2012-12-03T17:59:58.768Z,1354557598.768 [controlThread](DEBUG): Initializing ControlThread
2012-12-03T17:59:58.769Z,1354557598.769 [CycleStarter](INFO): Thread ID is 7056
2012-12-03T17:59:58.769Z,1354557598.769 [InternalSim](DEBUG):  InternalSim initializing...
2012-12-03T17:59:58.803Z,1354557598.803 [logger](INFO): Thread ID is 7059
2012-12-03T17:59:58.826Z,1354557598.826 [SBIT](INFO): Initialize SBIT Component.
2012-12-03T17:59:58.827Z,1354557598.827 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 10092
2012-12-03T17:59:58.835Z,1354557598.835 [IBIT](INFO): Initialize IBIT Component.
2012-12-03T17:59:58.836Z,1354557598.836 [CBIT](DEBUG): Initialize CBIT Component.
2012-12-03T17:59:58.836Z,1354557598.836 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-12-03T17:59:58.837Z,1354557598.837 [AsyncPiEstimator](INFO): Thread ID is 7120
2012-12-03T17:59:58.837Z,1354557598.837 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-12-03T17:59:58.858Z,1354557598.858 [DVL_micro](INFO): Thread ID is 7121
2012-12-03T17:59:58.868Z,1354557598.868 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-12-03T17:59:58.868Z,1354557598.868 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-12-03T17:59:58.869Z,1354557598.869 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-12-03T17:59:58.869Z,1354557598.869 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-12-03T17:59:58.869Z,1354557598.869 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-12-03T17:59:58.871Z,1354557598.871 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-12-03T17:59:58.871Z,1354557598.871 [Navigation](DEBUG): Initializing Navigation.
2012-12-03T17:59:58.872Z,1354557598.872 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-12-03T17:59:58.873Z,1354557598.874 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-12-03T17:59:58.874Z,1354557598.874 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-12-03T17:59:58.876Z,1354557598.876 [DVL_micro](INFO): Initializing
2012-12-03T17:59:58.876Z,1354557598.876 [DVL_micro](INFO): start:Powering up
2012-12-03T17:59:58.877Z,1354557598.877 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-12-03T17:59:58.877Z,1354557598.877 [DVL_micro](INFO): Cycling power to configure device.
2012-12-03T17:59:58.879Z,1354557598.879 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-12-03T17:59:58.895Z,1354557598.895 [CTD_NeilBrown](INFO): Thread ID is 7122
2012-12-03T17:59:58.896Z,1354557598.896 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-12-03T17:59:58.899Z,1354557598.899 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-12-03T17:59:58.919Z,1354557598.919 [Turbulence_NPS](INFO): Thread ID is 7123
2012-12-03T17:59:58.920Z,1354557598.920 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-12-03T17:59:58.920Z,1354557598.920 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-12-03T17:59:58.935Z,1354557598.935 [WetLabsBB2FL](INFO): Thread ID is 7124
2012-12-03T17:59:58.936Z,1354557598.936 [WetLabsBB2FL](INFO): Powering down
2012-12-03T17:59:58.962Z,1354557598.962 [NavChartDb](INFO): Thread ID is 7125
2012-12-03T17:59:58.969Z,1354557598.969 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-12-03T17:59:58.970Z,1354557598.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-12-03T17:59:58.970Z,1354557598.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-12-03T17:59:58.970Z,1354557598.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-12-03T17:59:58.971Z,1354557598.971 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-12-03T17:59:58.987Z,1354557598.987 [Turbulence_NPS](INFO): Pause powering down
2012-12-03T18:00:00.516Z,1354557600.516 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-12-03T18:00:00.561Z,1354557600.561 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-12-03T18:00:00.586Z,1354557600.586 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-12-03T18:00:00.604Z,1354557600.604 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-12-03T18:00:00.605Z,1354557600.605 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-12-03T18:00:00.696Z,1354557600.696 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-12-03T18:00:00.698Z,1354557600.698 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-12-03T18:00:00.701Z,1354557600.701 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-12-03T18:00:00.741Z,1354557600.741 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-12-03T18:00:00.744Z,1354557600.744 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-12-03T18:00:00.762Z,1354557600.762 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-12-03T18:00:00.774Z,1354557600.774 [Default:D.SetSpeed](DEBUG): Construct.
2012-12-03T18:00:00.788Z,1354557600.788 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-12-03T18:00:00.792Z,1354557600.792 [Default:F.Wait](DEBUG): Construct Wait.
2012-12-03T18:00:00.796Z,1354557600.796 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2012-12-03T18:00:00.800Z,1354557600.800 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2012-12-03T18:00:00.879Z,1354557600.879 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-12-03T18:00:00.935Z,1354557600.935 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-12-03T18:00:00.935Z,1354557600.935 [DVL_micro](INFO): Querying output modes
2012-12-03T18:00:00.936Z,1354557600.935 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-12-03T18:00:00.947Z,1354557600.947 [DVL_micro](DEBUG): cmdResponse: 01
2012-12-03T18:00:00.947Z,1354557600.947 [DVL_micro](INFO): NQ1 output enabled
2012-12-03T18:00:00.947Z,1354557600.947 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-12-03T18:00:00.959Z,1354557600.959 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-12-03T18:00:00.964Z,1354557600.964 [DVL_micro](INFO): pause:Powering down
2012-12-03T18:00:01.079Z,1354557601.079 [Radio_Freewave](INFO): Powering up
2012-12-03T18:00:01.355Z,1354557601.355 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-12-03T18:00:01.360Z,1354557601.360 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-12-03T18:00:01.379Z,1354557601.379 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-12-03T18:00:01.387Z,1354557601.387 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-12-03T18:00:01.393Z,1354557601.392 [MassServo](DEBUG): Initializing EZServoServo.
2012-12-03T18:00:01.399Z,1354557601.399 [MassServo](DEBUG): Initializing MassServo.
2012-12-03T18:00:01.404Z,1354557601.404 [RudderServo](DEBUG): Initializing EZServoServo.
2012-12-03T18:00:01.435Z,1354557601.435 [RudderServo](DEBUG): Initializing RudderServo.
2012-12-03T18:00:01.448Z,1354557601.448 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-12-03T18:00:01.455Z,1354557601.455 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-12-03T18:00:03.885Z,1354557603.885 [NAL9602](INFO): Powering up NAL9602
2012-12-03T18:00:14.539Z,1354557614.539 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:00:14.620Z,1354557614.620 [SBIT](IMPORTANT): Beginning Startup BIT
2012-12-03T18:00:14.623Z,1354557614.623 [CBIT](IMPORTANT): Beginning GF scan
2012-12-03T18:00:41.295Z,1354557641.295 [CBIT](IMPORTANT): No ground fault detected
2012-12-03T18:01:08.626Z,1354557668.626 [SBIT](IMPORTANT): SBIT PASSED
2012-12-03T18:01:09.053Z,1354557669.053 [MissionManager](IMPORTANT): Started mission Startup
2012-12-03T18:01:09.053Z,1354557669.053 [Startup] Running Loop=1
2012-12-03T18:01:09.053Z,1354557669.053 [Startup](INFO): Aggregate::initialize Startup
2012-12-03T18:01:09.054Z,1354557669.053 [Startup:A.GoToSurface] Running Loop=1
2012-12-03T18:01:09.054Z,1354557669.054 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:01:09.060Z,1354557669.059 [Startup:StartupSatComms] Running Loop=1
2012-12-03T18:01:09.060Z,1354557669.060 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-12-03T18:01:09.060Z,1354557669.060 [Startup:StartupSatComms:A] Running Loop=1
2012-12-03T18:01:09.419Z,1354557669.419 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-12-03T18:02:09.406Z,1354557729.406 [Startup:StartupSatComms:A](INFO): Timed out from 2012-12-03T18:01:09.1Z
2012-12-03T18:02:09.406Z,1354557729.406 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2012-12-03T18:02:09.406Z,1354557729.406 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2012-12-03T18:02:09.423Z,1354557729.422 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2012-12-03T18:02:09.423Z,1354557729.423 [Startup:StartupSatComms:A] Stopped
2012-12-03T18:02:09.423Z,1354557729.423 [Startup:StartupSatComms:B] Running Loop=1
2012-12-03T18:02:09.819Z,1354557729.819 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-12-03T18:02:31.558Z,1354557751.558 [NAL9602](INFO): SBD MO Status=1, MOMSN=5974, MT Status=0, MTMSN=0
2012-12-03T18:02:31.607Z,1354557751.607 [NAL9602](INFO): Sent 201 bytes from file Logs/20121129T220932/shore0041.lzma
2012-12-03T18:02:31.607Z,1354557751.607 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:02:31.609Z,1354557751.609 [NAL9602](INFO): Stored copy of sent data in Logs/20121129T220932/shore0041.lzma.parts/0000.sbd
2012-12-03T18:02:45.772Z,1354557765.772 [NAL9602](INFO): SBD MO Status=1, MOMSN=5975, MT Status=0, MTMSN=0
2012-12-03T18:02:45.827Z,1354557765.827 [NAL9602](INFO): Sent 332 bytes from file Logs/20121203T175947/shore0000.lzma
2012-12-03T18:02:45.827Z,1354557765.827 [NAL9602](INFO): Packets left to send: 1
2012-12-03T18:02:45.828Z,1354557765.829 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0000.lzma.parts/0001.sbd
2012-12-03T18:02:54.810Z,1354557774.810 [NAL9602](INFO): SBD MO Status=1, MOMSN=5976, MT Status=0, MTMSN=0
2012-12-03T18:02:54.859Z,1354557774.859 [NAL9602](INFO): Sent 133 bytes from file Logs/20121203T175947/shore0000.lzma
2012-12-03T18:02:54.859Z,1354557774.859 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:02:54.860Z,1354557774.860 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0000.lzma.parts/0000.sbd
2012-12-03T18:03:02.012Z,1354557782.012 [NAL9602](INFO): SBD MO Status=0, MOMSN=5977, MT Status=0, MTMSN=0
2012-12-03T18:03:02.091Z,1354557782.091 [Startup:StartupSatComms:B] Stopped
2012-12-03T18:03:02.091Z,1354557782.091 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-12-03T18:03:02.091Z,1354557782.091 [Startup:StartupSatComms] Stopped
2012-12-03T18:03:02.091Z,1354557782.091 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-12-03T18:03:02.092Z,1354557782.092 [Startup](INFO): Completed Startup
2012-12-03T18:03:02.092Z,1354557782.092 [Startup] Stopped
2012-12-03T18:03:02.092Z,1354557782.092 [Startup](INFO): Aggregate::uninitialize Startup
2012-12-03T18:03:02.092Z,1354557782.092 [Startup:A.GoToSurface] Stopped
2012-12-03T18:03:02.092Z,1354557782.092 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:03:02.424Z,1354557782.424 [MissionManager](IMPORTANT): Started mission Default
2012-12-03T18:03:02.424Z,1354557782.424 [Default] Running Loop=1
2012-12-03T18:03:02.424Z,1354557782.424 [Default](INFO): Aggregate::initialize Default
2012-12-03T18:03:02.424Z,1354557782.424 [Default:D.SetSpeed] Running Loop=1
2012-12-03T18:03:02.424Z,1354557782.424 [Default:D.SetSpeed](DEBUG): Initialize.
2012-12-03T18:03:02.424Z,1354557782.424 [Default:E.GoToSurface] Running Loop=1
2012-12-03T18:03:02.424Z,1354557782.424 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium] Running Loop=1
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:03:02.425Z,1354557782.425 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:03:02.426Z,1354557782.426 [Default:E.GoToSurface] Running Loop=1
2012-12-03T18:03:02.431Z,1354557782.431 [Default:D.SetSpeed] Running Loop=1
2012-12-03T18:03:02.441Z,1354557782.441 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:03:02.441Z,1354557782.441 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:03:02.441Z,1354557782.441 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:03:02.442Z,1354557782.441 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:03:02.446Z,1354557782.446 [Default:GPS] Running Loop=1
2012-12-03T18:03:02.446Z,1354557782.446 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:03:02.447Z,1354557782.447 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:03:02.447Z,1354557782.447 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:03:02.447Z,1354557782.447 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:03:02.447Z,1354557782.447 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:03:02.452Z,1354557782.452 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:03:02.452Z,1354557782.452 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:03:02.452Z,1354557782.452 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:03:02.452Z,1354557782.453 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:03:02.854Z,1354557782.854 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-12-03T18:03:02.857Z,1354557782.857 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-12-03T18:03:03.249Z,1354557783.249 [NAL9602](IMPORTANT): GPS fix at: 1354558721.00
2012-12-03T18:03:03.266Z,1354557783.266 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:03:03.266Z,1354557783.266 [Default:GPS:D] Running Loop=1
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS:D] Stopped
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS] Stopped
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:03:03.648Z,1354557783.648 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:03:21.404Z,1354557801.404 [NAL9602](INFO): SBD MO Status=1, MOMSN=5978, MT Status=0, MTMSN=0
2012-12-03T18:03:21.455Z,1354557801.455 [NAL9602](INFO): Sent 332 bytes from file Logs/20121203T175947/shore0001.lzma
2012-12-03T18:03:21.455Z,1354557801.455 [NAL9602](INFO): Packets left to send: 1
2012-12-03T18:03:21.457Z,1354557801.457 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0001.lzma.parts/0001.sbd
2012-12-03T18:03:28.441Z,1354557808.441 [NAL9602](INFO): SBD MO Status=1, MOMSN=5979, MT Status=0, MTMSN=0
2012-12-03T18:03:28.491Z,1354557808.491 [NAL9602](INFO): Sent 38 bytes from file Logs/20121203T175947/shore0001.lzma
2012-12-03T18:03:28.491Z,1354557808.491 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:03:28.492Z,1354557808.492 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0001.lzma.parts/0000.sbd
2012-12-03T18:03:39.674Z,1354557819.674 [NAL9602](INFO): SBD MO Status=0, MOMSN=5980, MT Status=0, MTMSN=0
2012-12-03T18:03:39.760Z,1354557819.760 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:03:39.760Z,1354557819.760 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:03:39.760Z,1354557819.760 [Default:Iridium] Stopped
2012-12-03T18:03:39.761Z,1354557819.760 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:03:39.761Z,1354557819.761 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:03:39.761Z,1354557819.761 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:03:39.761Z,1354557819.761 [Default:F.Wait] Running Loop=1
2012-12-03T18:03:39.761Z,1354557819.761 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-12-03T18:03:50.219Z,1354557830.219 [NAL9602](INFO): Powering down
2012-12-03T18:08:40.229Z,1354558120.229 [Default:CallIridium] Running Loop=1
2012-12-03T18:08:40.229Z,1354558120.229 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:08:40.229Z,1354558120.229 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:08:40.235Z,1354558120.235 [Default:CallIridium:A] Stopped
2012-12-03T18:08:40.235Z,1354558120.236 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:08:40.236Z,1354558120.236 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium] Running Loop=1
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:08:45.248Z,1354558125.248 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:08:45.249Z,1354558125.249 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:08:45.249Z,1354558125.249 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:08:45.249Z,1354558125.249 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS] Running Loop=1
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:08:45.250Z,1354558125.250 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:08:45.251Z,1354558125.251 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:08:45.251Z,1354558125.251 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:08:45.251Z,1354558125.251 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:08:45.842Z,1354558125.842 [NAL9602](INFO): Powering up
2012-12-03T18:08:56.683Z,1354558136.683 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:09:17.212Z,1354558157.212 [NAL9602](INFO): SBD MO Status=1, MOMSN=5981, MT Status=0, MTMSN=0
2012-12-03T18:09:17.259Z,1354558157.259 [NAL9602](INFO): Sent 95 bytes from file Logs/20121203T175947/shore0002.lzma
2012-12-03T18:09:17.259Z,1354558157.259 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:09:17.261Z,1354558157.261 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0002.lzma.parts/0000.sbd
2012-12-03T18:09:30.016Z,1354558170.016 [NAL9602](INFO): SBD MO Status=0, MOMSN=5982, MT Status=0, MTMSN=0
2012-12-03T18:09:30.101Z,1354558170.101 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:09:30.101Z,1354558170.101 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:09:30.101Z,1354558170.101 [Default:Iridium] Stopped
2012-12-03T18:09:30.101Z,1354558170.102 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:09:30.102Z,1354558170.102 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:09:30.102Z,1354558170.102 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:09:30.425Z,1354558170.425 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:09:30.425Z,1354558170.425 [Default:CallIridium:B] Stopped
2012-12-03T18:09:30.426Z,1354558170.425 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:09:30.426Z,1354558170.426 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:09:30.426Z,1354558170.426 [Default:CallIridium] Stopped
2012-12-03T18:09:30.426Z,1354558170.426 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:09:55.213Z,1354558195.214 [NAL9602](IMPORTANT): GPS fix at: 1354559134.00
2012-12-03T18:09:55.229Z,1354558195.229 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:09:55.230Z,1354558195.230 [Default:GPS:D] Running Loop=1
2012-12-03T18:09:55.676Z,1354558195.676 [Default:GPS:D] Stopped
2012-12-03T18:09:55.677Z,1354558195.677 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:09:55.677Z,1354558195.677 [Default:GPS] Stopped
2012-12-03T18:09:55.677Z,1354558195.677 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:09:55.677Z,1354558195.677 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:09:55.677Z,1354558195.677 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:10:16.193Z,1354558216.193 [NAL9602](INFO): Powering down
2012-12-03T18:14:31.183Z,1354558471.183 [Default:CallIridium] Running Loop=1
2012-12-03T18:14:31.183Z,1354558471.183 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:14:31.183Z,1354558471.183 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:14:31.184Z,1354558471.184 [Default:CallIridium:A] Stopped
2012-12-03T18:14:31.184Z,1354558471.184 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:14:31.184Z,1354558471.184 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:14:36.204Z,1354558476.204 [Default:Iridium] Running Loop=1
2012-12-03T18:14:36.204Z,1354558476.204 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:14:36.204Z,1354558476.204 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:14:36.204Z,1354558476.204 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:14:36.205Z,1354558476.205 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:14:36.205Z,1354558476.205 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:14:36.205Z,1354558476.205 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:14:36.206Z,1354558476.205 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:14:36.206Z,1354558476.206 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:14:36.206Z,1354558476.206 [Default:GPS] Running Loop=1
2012-12-03T18:14:36.206Z,1354558476.206 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:14:36.238Z,1354558476.238 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:14:36.238Z,1354558476.238 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:14:36.239Z,1354558476.239 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:14:36.239Z,1354558476.239 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:14:36.240Z,1354558476.240 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:14:36.240Z,1354558476.240 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:14:36.240Z,1354558476.240 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:14:36.852Z,1354558476.852 [NAL9602](INFO): Powering up
2012-12-03T18:14:47.687Z,1354558487.687 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:15:15.416Z,1354558515.416 [NAL9602](INFO): SBD MO Status=1, MOMSN=5983, MT Status=0, MTMSN=0
2012-12-03T18:15:15.463Z,1354558515.463 [NAL9602](INFO): Sent 277 bytes from file Logs/20121203T175947/shore0003.lzma
2012-12-03T18:15:15.463Z,1354558515.463 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:15:15.466Z,1354558515.466 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0003.lzma.parts/0000.sbd
2012-12-03T18:15:31.845Z,1354558531.845 [NAL9602](INFO): SBD MO Status=2, MOMSN=5984, MT Status=2, MTMSN=0
2012-12-03T18:15:31.845Z,1354558531.845 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T18:15:33.016Z,1354558533.016 [NAL9602](IMPORTANT): GPS fix at: 1354559472.00
2012-12-03T18:15:33.032Z,1354558533.032 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:15:33.032Z,1354558533.032 [Default:GPS:D] Running Loop=1
2012-12-03T18:15:33.449Z,1354558533.448 [Default:GPS:D] Stopped
2012-12-03T18:15:33.449Z,1354558533.449 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:15:33.449Z,1354558533.449 [Default:GPS] Stopped
2012-12-03T18:15:33.449Z,1354558533.449 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:15:33.449Z,1354558533.449 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:15:33.449Z,1354558533.449 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:15:48.989Z,1354558548.989 [NAL9602](INFO): SBD MO Status=0, MOMSN=5984, MT Status=0, MTMSN=0
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium] Stopped
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:15:49.073Z,1354558549.073 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:15:49.400Z,1354558549.400 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:15:49.400Z,1354558549.400 [Default:CallIridium:B] Stopped
2012-12-03T18:15:49.400Z,1354558549.400 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:15:49.400Z,1354558549.400 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:15:49.400Z,1354558549.400 [Default:CallIridium] Stopped
2012-12-03T18:15:49.400Z,1354558549.401 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:15:59.544Z,1354558559.545 [NAL9602](INFO): Powering down
2012-12-03T18:20:49.556Z,1354558849.556 [Default:CallIridium] Running Loop=1
2012-12-03T18:20:49.557Z,1354558849.556 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:20:49.557Z,1354558849.557 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:20:49.557Z,1354558849.557 [Default:CallIridium:A] Stopped
2012-12-03T18:20:49.557Z,1354558849.557 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:20:49.557Z,1354558849.557 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:20:54.584Z,1354558854.584 [Default:Iridium] Running Loop=1
2012-12-03T18:20:54.584Z,1354558854.584 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:20:54.584Z,1354558854.584 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:20:54.584Z,1354558854.584 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:20:54.585Z,1354558854.585 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:20:54.585Z,1354558854.585 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:20:54.585Z,1354558854.585 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:20:54.585Z,1354558854.585 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:20:54.586Z,1354558854.586 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS] Running Loop=1
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:20:54.586Z,1354558854.586 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:20:54.587Z,1354558854.587 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:20:54.587Z,1354558854.587 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:20:54.587Z,1354558854.587 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:20:55.188Z,1354558855.188 [NAL9602](INFO): Powering up
2012-12-03T18:21:06.019Z,1354558866.019 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:21:21.353Z,1354558881.353 [NAL9602](INFO): SBD MO Status=1, MOMSN=5985, MT Status=0, MTMSN=0
2012-12-03T18:21:21.403Z,1354558881.403 [NAL9602](INFO): Sent 160 bytes from file Logs/20121203T175947/shore0004.lzma
2012-12-03T18:21:21.403Z,1354558881.403 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:21:21.405Z,1354558881.405 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0004.lzma.parts/0000.sbd
2012-12-03T18:21:31.353Z,1354558891.353 [NAL9602](INFO): SBD MO Status=0, MOMSN=5986, MT Status=0, MTMSN=0
2012-12-03T18:21:31.437Z,1354558891.437 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:21:31.438Z,1354558891.438 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:21:31.438Z,1354558891.438 [Default:Iridium] Stopped
2012-12-03T18:21:31.438Z,1354558891.438 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:21:31.438Z,1354558891.438 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:21:31.438Z,1354558891.438 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:21:31.763Z,1354558891.763 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:21:31.763Z,1354558891.763 [Default:CallIridium:B] Stopped
2012-12-03T18:21:31.763Z,1354558891.763 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:21:31.764Z,1354558891.764 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:21:31.764Z,1354558891.764 [Default:CallIridium] Stopped
2012-12-03T18:21:31.764Z,1354558891.764 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:21:52.984Z,1354558912.984 [NAL9602](IMPORTANT): GPS fix at: 1354559853.00
2012-12-03T18:21:53.001Z,1354558913.000 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:21:53.001Z,1354558913.001 [Default:GPS:D] Running Loop=1
2012-12-03T18:21:53.378Z,1354558913.378 [Default:GPS:D] Stopped
2012-12-03T18:21:53.379Z,1354558913.379 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:21:53.379Z,1354558913.379 [Default:GPS] Stopped
2012-12-03T18:21:53.379Z,1354558913.379 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:21:53.379Z,1354558913.379 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:21:53.379Z,1354558913.379 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:22:13.904Z,1354558933.904 [NAL9602](INFO): Powering down
2012-12-03T18:26:33.953Z,1354559193.953 [Default:CallIridium] Running Loop=1
2012-12-03T18:26:33.953Z,1354559193.953 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:26:33.953Z,1354559193.953 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:26:33.954Z,1354559193.954 [Default:CallIridium:A] Stopped
2012-12-03T18:26:33.954Z,1354559193.954 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:26:33.954Z,1354559193.954 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium] Running Loop=1
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:26:38.925Z,1354559198.925 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:26:38.927Z,1354559198.927 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:26:38.927Z,1354559198.927 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:26:38.927Z,1354559198.927 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:26:38.927Z,1354559198.927 [Default:GPS] Running Loop=1
2012-12-03T18:26:38.927Z,1354559198.927 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:26:38.927Z,1354559198.927 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:26:38.927Z,1354559198.927 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:26:38.928Z,1354559198.928 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:26:38.928Z,1354559198.928 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:26:38.928Z,1354559198.928 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:26:38.928Z,1354559198.928 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:26:38.929Z,1354559198.929 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:26:39.548Z,1354559199.548 [NAL9602](INFO): Powering up
2012-12-03T18:26:50.383Z,1354559210.383 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:27:20.589Z,1354559240.589 [NAL9602](IMPORTANT): GPS fix at: 1354560181.00
2012-12-03T18:27:20.618Z,1354559240.618 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:27:20.619Z,1354559240.619 [Default:GPS:D] Running Loop=1
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS:D] Stopped
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS] Stopped
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:27:21.025Z,1354559241.025 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:27:41.176Z,1354559261.176 [NAL9602](INFO): SBD MO Status=2, MOMSN=5987, MT Status=2, MTMSN=0
2012-12-03T18:27:41.176Z,1354559261.176 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T18:28:09.257Z,1354559289.257 [NAL9602](INFO): SBD MO Status=1, MOMSN=5987, MT Status=0, MTMSN=0
2012-12-03T18:28:09.307Z,1354559289.307 [NAL9602](INFO): Sent 165 bytes from file Logs/20121203T175947/shore0005.lzma
2012-12-03T18:28:09.307Z,1354559289.307 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:28:09.309Z,1354559289.309 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0005.lzma.parts/0000.sbd
2012-12-03T18:28:23.250Z,1354559303.250 [NAL9602](INFO): SBD MO Status=0, MOMSN=5988, MT Status=0, MTMSN=0
2012-12-03T18:28:23.337Z,1354559303.337 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:28:23.338Z,1354559303.338 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:28:23.338Z,1354559303.338 [Default:Iridium] Stopped
2012-12-03T18:28:23.338Z,1354559303.338 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:28:23.338Z,1354559303.338 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:28:23.338Z,1354559303.338 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:28:23.696Z,1354559303.696 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:28:23.696Z,1354559303.696 [Default:CallIridium:B] Stopped
2012-12-03T18:28:23.696Z,1354559303.696 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:28:23.697Z,1354559303.697 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:28:23.697Z,1354559303.697 [Default:CallIridium] Stopped
2012-12-03T18:28:23.697Z,1354559303.697 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:28:33.843Z,1354559313.843 [NAL9602](INFO): Powering down
2012-12-03T18:28:48.820Z,1354559328.820 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:28:53.805Z,1354559333.805 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:28:58.805Z,1354559338.805 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:29:03.801Z,1354559343.801 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:29:08.805Z,1354559348.805 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:29:13.822Z,1354559353.822 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-12-03T18:33:23.856Z,1354559603.856 [Default:CallIridium] Running Loop=1
2012-12-03T18:33:23.856Z,1354559603.856 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:33:23.856Z,1354559603.856 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:33:23.857Z,1354559603.857 [Default:CallIridium:A] Stopped
2012-12-03T18:33:23.857Z,1354559603.857 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:33:23.857Z,1354559603.857 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium] Running Loop=1
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:33:28.834Z,1354559608.834 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:33:28.835Z,1354559608.835 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:33:28.835Z,1354559608.835 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:33:28.835Z,1354559608.835 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS] Running Loop=1
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:33:28.836Z,1354559608.836 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:33:28.837Z,1354559608.837 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:33:28.837Z,1354559608.837 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:33:28.837Z,1354559608.837 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:33:29.452Z,1354559609.452 [NAL9602](INFO): Powering up
2012-12-03T18:33:39.891Z,1354559619.891 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:34:00.517Z,1354559640.517 [NAL9602](INFO): SBD MO Status=1, MOMSN=5989, MT Status=0, MTMSN=0
2012-12-03T18:34:00.567Z,1354559640.567 [NAL9602](INFO): Sent 163 bytes from file Logs/20121203T175947/shore0006.lzma
2012-12-03T18:34:00.567Z,1354559640.567 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:34:00.568Z,1354559640.569 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0006.lzma.parts/0000.sbd
2012-12-03T18:34:10.521Z,1354559650.521 [NAL9602](INFO): SBD MO Status=0, MOMSN=5990, MT Status=0, MTMSN=0
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium] Stopped
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:34:10.605Z,1354559650.605 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:34:10.936Z,1354559650.936 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:34:10.936Z,1354559650.936 [Default:CallIridium:B] Stopped
2012-12-03T18:34:10.937Z,1354559650.937 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:34:10.937Z,1354559650.937 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:34:10.937Z,1354559650.937 [Default:CallIridium] Stopped
2012-12-03T18:34:10.937Z,1354559650.937 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:34:44.923Z,1354559684.923 [NAL9602](IMPORTANT): GPS fix at: 1354560626.00
2012-12-03T18:34:44.939Z,1354559684.939 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:34:44.939Z,1354559684.940 [Default:GPS:D] Running Loop=1
2012-12-03T18:34:45.349Z,1354559685.349 [Default:GPS:D] Stopped
2012-12-03T18:34:45.349Z,1354559685.349 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:34:45.349Z,1354559685.349 [Default:GPS] Stopped
2012-12-03T18:34:45.350Z,1354559685.349 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:34:45.350Z,1354559685.350 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:34:45.350Z,1354559685.350 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:35:05.868Z,1354559705.868 [NAL9602](INFO): Powering down
2012-12-03T18:39:10.884Z,1354559950.884 [Default:CallIridium] Running Loop=1
2012-12-03T18:39:10.885Z,1354559950.885 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:39:10.885Z,1354559950.885 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:39:10.885Z,1354559950.885 [Default:CallIridium:A] Stopped
2012-12-03T18:39:10.885Z,1354559950.885 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:39:10.885Z,1354559950.885 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:39:15.924Z,1354559955.924 [Default:Iridium] Running Loop=1
2012-12-03T18:39:15.925Z,1354559955.925 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:39:15.925Z,1354559955.925 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:39:15.925Z,1354559955.925 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:39:15.925Z,1354559955.925 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:39:15.925Z,1354559955.925 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:39:15.926Z,1354559955.926 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:39:15.926Z,1354559955.926 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:39:15.926Z,1354559955.926 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS] Running Loop=1
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:39:15.931Z,1354559955.931 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:39:15.932Z,1354559955.932 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:39:15.932Z,1354559955.932 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:39:15.932Z,1354559955.932 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:39:16.540Z,1354559956.540 [NAL9602](INFO): Powering up
2012-12-03T18:39:27.395Z,1354559967.395 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:39:40.813Z,1354559980.813 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#6 STATUS: 65535
2012-12-03T18:39:54.967Z,1354559994.967 [NAL9602](IMPORTANT): GPS fix at: 1354560936.00
2012-12-03T18:39:54.984Z,1354559994.984 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:39:54.984Z,1354559994.984 [Default:GPS:D] Running Loop=1
2012-12-03T18:39:55.419Z,1354559995.419 [Default:GPS:D] Stopped
2012-12-03T18:39:55.420Z,1354559995.420 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:39:55.420Z,1354559995.420 [Default:GPS] Stopped
2012-12-03T18:39:55.420Z,1354559995.420 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:39:55.420Z,1354559995.420 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:39:55.420Z,1354559995.420 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:40:59.541Z,1354560059.541 [NAL9602](INFO): SBD MO Status=1, MOMSN=5991, MT Status=0, MTMSN=0
2012-12-03T18:40:59.591Z,1354560059.591 [NAL9602](INFO): Sent 161 bytes from file Logs/20121203T175947/shore0007.lzma
2012-12-03T18:40:59.591Z,1354560059.591 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:40:59.593Z,1354560059.593 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0007.lzma.parts/0000.sbd
2012-12-03T18:41:10.741Z,1354560070.741 [NAL9602](INFO): SBD MO Status=0, MOMSN=5992, MT Status=0, MTMSN=0
2012-12-03T18:41:10.833Z,1354560070.833 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:41:10.833Z,1354560070.833 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:41:10.833Z,1354560070.833 [Default:Iridium] Stopped
2012-12-03T18:41:10.833Z,1354560070.833 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:41:10.833Z,1354560070.833 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:41:10.834Z,1354560070.833 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium:B] Stopped
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium] Stopped
2012-12-03T18:41:11.156Z,1354560071.156 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:41:21.292Z,1354560081.293 [NAL9602](INFO): Powering down
2012-12-03T18:46:11.340Z,1354560371.340 [Default:CallIridium] Running Loop=1
2012-12-03T18:46:11.340Z,1354560371.340 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:46:11.340Z,1354560371.340 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:46:11.340Z,1354560371.341 [Default:CallIridium:A] Stopped
2012-12-03T18:46:11.341Z,1354560371.341 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:46:11.341Z,1354560371.341 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:46:16.334Z,1354560376.334 [Default:Iridium] Running Loop=1
2012-12-03T18:46:16.334Z,1354560376.334 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:46:16.334Z,1354560376.334 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:46:16.334Z,1354560376.334 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:46:16.335Z,1354560376.335 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:46:16.335Z,1354560376.335 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:46:16.335Z,1354560376.335 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:46:16.335Z,1354560376.335 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:46:16.336Z,1354560376.336 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS] Running Loop=1
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:46:16.336Z,1354560376.336 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:46:16.337Z,1354560376.337 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:46:16.337Z,1354560376.337 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:46:16.337Z,1354560376.337 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:46:16.940Z,1354560376.940 [NAL9602](INFO): Powering up
2012-12-03T18:46:27.775Z,1354560387.775 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:46:48.693Z,1354560408.693 [NAL9602](INFO): SBD MO Status=1, MOMSN=5993, MT Status=0, MTMSN=0
2012-12-03T18:46:48.751Z,1354560408.751 [NAL9602](INFO): Sent 322 bytes from file Logs/20121203T175947/shore0008.lzma
2012-12-03T18:46:48.751Z,1354560408.751 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:46:48.753Z,1354560408.753 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0008.lzma.parts/0000.sbd
2012-12-03T18:46:55.089Z,1354560415.089 [NAL9602](INFO): SBD MO Status=0, MOMSN=5994, MT Status=0, MTMSN=0
2012-12-03T18:46:55.175Z,1354560415.175 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:46:55.175Z,1354560415.175 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:46:55.175Z,1354560415.175 [Default:Iridium] Stopped
2012-12-03T18:46:55.176Z,1354560415.176 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:46:55.176Z,1354560415.176 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:46:55.176Z,1354560415.176 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:46:55.552Z,1354560415.552 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:46:55.552Z,1354560415.552 [Default:CallIridium:B] Stopped
2012-12-03T18:46:55.553Z,1354560415.553 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:46:55.553Z,1354560415.553 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:46:55.553Z,1354560415.553 [Default:CallIridium] Stopped
2012-12-03T18:46:55.553Z,1354560415.553 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:47:22.743Z,1354560442.743 [NAL9602](IMPORTANT): GPS fix at: 1354561385.00
2012-12-03T18:47:22.760Z,1354560442.760 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:47:22.760Z,1354560442.760 [Default:GPS:D] Running Loop=1
2012-12-03T18:47:23.123Z,1354560443.123 [Default:GPS:D] Stopped
2012-12-03T18:47:23.123Z,1354560443.123 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:47:23.123Z,1354560443.123 [Default:GPS] Stopped
2012-12-03T18:47:23.123Z,1354560443.124 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:47:23.124Z,1354560443.124 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:47:23.124Z,1354560443.124 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:47:43.649Z,1354560463.648 [NAL9602](INFO): Powering down
2012-12-03T18:51:58.684Z,1354560718.684 [Default:CallIridium] Running Loop=1
2012-12-03T18:51:58.684Z,1354560718.684 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:51:58.684Z,1354560718.684 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:51:58.685Z,1354560718.685 [Default:CallIridium:A] Stopped
2012-12-03T18:51:58.685Z,1354560718.685 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:51:58.685Z,1354560718.685 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:52:03.680Z,1354560723.680 [Default:Iridium] Running Loop=1
2012-12-03T18:52:03.680Z,1354560723.680 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:52:03.680Z,1354560723.681 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:52:03.680Z,1354560723.681 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:52:03.681Z,1354560723.681 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:52:03.681Z,1354560723.681 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:52:03.682Z,1354560723.681 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:52:03.682Z,1354560723.682 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:52:03.682Z,1354560723.682 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:52:03.682Z,1354560723.682 [Default:GPS] Running Loop=1
2012-12-03T18:52:03.684Z,1354560723.684 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:52:03.684Z,1354560723.684 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:52:03.684Z,1354560723.684 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:52:03.684Z,1354560723.684 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:52:03.684Z,1354560723.684 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:52:03.685Z,1354560723.685 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:52:03.685Z,1354560723.685 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:52:03.686Z,1354560723.685 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:52:04.288Z,1354560724.288 [NAL9602](INFO): Powering up
2012-12-03T18:52:14.735Z,1354560734.735 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:52:30.450Z,1354560750.450 [NAL9602](INFO): SBD MO Status=1, MOMSN=5995, MT Status=0, MTMSN=0
2012-12-03T18:52:30.519Z,1354560750.519 [NAL9602](INFO): Sent 171 bytes from file Logs/20121203T175947/shore0009.lzma
2012-12-03T18:52:30.519Z,1354560750.519 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:52:30.521Z,1354560750.521 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0009.lzma.parts/0000.sbd
2012-12-03T18:52:40.049Z,1354560760.049 [NAL9602](INFO): SBD MO Status=0, MOMSN=5996, MT Status=0, MTMSN=0
2012-12-03T18:52:40.137Z,1354560760.137 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:52:40.137Z,1354560760.137 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:52:40.137Z,1354560760.137 [Default:Iridium] Stopped
2012-12-03T18:52:40.137Z,1354560760.137 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:52:40.138Z,1354560760.138 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:52:40.138Z,1354560760.138 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium:B] Stopped
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium] Stopped
2012-12-03T18:52:40.470Z,1354560760.470 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T18:52:44.055Z,1354560764.055 [NAL9602](IMPORTANT): GPS fix at: 1354561707.00
2012-12-03T18:52:44.074Z,1354560764.074 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:52:44.074Z,1354560764.074 [Default:GPS:D] Running Loop=1
2012-12-03T18:52:44.532Z,1354560764.532 [Default:GPS:D] Stopped
2012-12-03T18:52:44.533Z,1354560764.533 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:52:44.533Z,1354560764.533 [Default:GPS] Stopped
2012-12-03T18:52:44.533Z,1354560764.533 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:52:44.533Z,1354560764.533 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:52:44.533Z,1354560764.533 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:53:05.021Z,1354560785.020 [NAL9602](INFO): Powering down
2012-12-03T18:57:45.048Z,1354561065.048 [Default:CallIridium] Running Loop=1
2012-12-03T18:57:45.049Z,1354561065.049 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T18:57:45.049Z,1354561065.049 [Default:CallIridium:A] Running Loop=1
2012-12-03T18:57:45.049Z,1354561065.049 [Default:CallIridium:A] Stopped
2012-12-03T18:57:45.049Z,1354561065.049 [Default:CallIridium:B] Running Loop=1
2012-12-03T18:57:45.049Z,1354561065.049 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T18:57:50.032Z,1354561070.032 [Default:Iridium] Running Loop=1
2012-12-03T18:57:50.032Z,1354561070.032 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T18:57:50.032Z,1354561070.033 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T18:57:50.032Z,1354561070.033 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:57:50.033Z,1354561070.033 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T18:57:50.033Z,1354561070.033 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:57:50.034Z,1354561070.033 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T18:57:50.034Z,1354561070.034 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:57:50.034Z,1354561070.034 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T18:57:50.034Z,1354561070.034 [Default:GPS] Running Loop=1
2012-12-03T18:57:50.034Z,1354561070.034 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T18:57:50.034Z,1354561070.034 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T18:57:50.035Z,1354561070.035 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T18:57:50.035Z,1354561070.035 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T18:57:50.035Z,1354561070.035 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T18:57:50.036Z,1354561070.036 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T18:57:50.036Z,1354561070.036 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T18:57:50.036Z,1354561070.036 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T18:57:50.648Z,1354561070.648 [NAL9602](INFO): Powering up
2012-12-03T18:58:01.083Z,1354561081.083 [NAL9602](INFO): NAL9602 initialized
2012-12-03T18:58:18.156Z,1354561098.156 [NAL9602](IMPORTANT): GPS fix at: 1354562041.00
2012-12-03T18:58:18.175Z,1354561098.175 [Default:GPS:Read_GPS] Stopped
2012-12-03T18:58:18.175Z,1354561098.175 [Default:GPS:D] Running Loop=1
2012-12-03T18:58:18.584Z,1354561098.584 [Default:GPS:D] Stopped
2012-12-03T18:58:18.585Z,1354561098.585 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T18:58:18.585Z,1354561098.585 [Default:GPS] Stopped
2012-12-03T18:58:18.585Z,1354561098.585 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T18:58:18.585Z,1354561098.585 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T18:58:18.585Z,1354561098.585 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:58:47.546Z,1354561127.546 [NAL9602](INFO): SBD MO Status=2, MOMSN=5997, MT Status=2, MTMSN=0
2012-12-03T18:58:47.546Z,1354561127.546 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T18:59:05.326Z,1354561145.326 [NAL9602](INFO): SBD MO Status=2, MOMSN=5997, MT Status=2, MTMSN=0
2012-12-03T18:59:05.326Z,1354561145.326 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T18:59:29.885Z,1354561169.885 [NAL9602](INFO): SBD MO Status=2, MOMSN=5997, MT Status=2, MTMSN=0
2012-12-03T18:59:29.886Z,1354561169.886 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T18:59:43.274Z,1354561183.274 [NAL9602](INFO): SBD MO Status=1, MOMSN=5997, MT Status=0, MTMSN=0
2012-12-03T18:59:43.327Z,1354561183.327 [NAL9602](INFO): Sent 162 bytes from file Logs/20121203T175947/shore0010.lzma
2012-12-03T18:59:43.327Z,1354561183.327 [NAL9602](INFO): Packets left to send: 0
2012-12-03T18:59:43.329Z,1354561183.329 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0010.lzma.parts/0000.sbd
2012-12-03T18:59:53.681Z,1354561193.681 [NAL9602](INFO): SBD MO Status=0, MOMSN=5998, MT Status=0, MTMSN=0
2012-12-03T18:59:53.765Z,1354561193.765 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T18:59:53.765Z,1354561193.765 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T18:59:53.765Z,1354561193.765 [Default:Iridium] Stopped
2012-12-03T18:59:53.765Z,1354561193.765 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T18:59:53.765Z,1354561193.765 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T18:59:53.766Z,1354561193.766 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium:B] Stopped
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium] Stopped
2012-12-03T18:59:54.132Z,1354561194.132 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T19:00:04.233Z,1354561204.233 [NAL9602](INFO): Powering down
2012-12-03T19:04:54.243Z,1354561494.243 [Default:CallIridium] Running Loop=1
2012-12-03T19:04:54.244Z,1354561494.244 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T19:04:54.244Z,1354561494.244 [Default:CallIridium:A] Running Loop=1
2012-12-03T19:04:54.244Z,1354561494.244 [Default:CallIridium:A] Stopped
2012-12-03T19:04:54.244Z,1354561494.244 [Default:CallIridium:B] Running Loop=1
2012-12-03T19:04:54.244Z,1354561494.244 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T19:04:59.266Z,1354561499.266 [Default:Iridium] Running Loop=1
2012-12-03T19:04:59.268Z,1354561499.267 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T19:04:59.268Z,1354561499.268 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T19:04:59.268Z,1354561499.268 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T19:04:59.268Z,1354561499.268 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T19:04:59.268Z,1354561499.268 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T19:04:59.269Z,1354561499.269 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T19:04:59.269Z,1354561499.269 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T19:04:59.269Z,1354561499.269 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T19:04:59.269Z,1354561499.269 [Default:GPS] Running Loop=1
2012-12-03T19:04:59.269Z,1354561499.269 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T19:04:59.269Z,1354561499.269 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T19:04:59.269Z,1354561499.270 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T19:04:59.270Z,1354561499.270 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T19:04:59.270Z,1354561499.270 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T19:04:59.271Z,1354561499.271 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T19:04:59.271Z,1354561499.271 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T19:04:59.271Z,1354561499.271 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T19:04:59.872Z,1354561499.872 [NAL9602](INFO): Powering up
2012-12-03T19:05:10.707Z,1354561510.707 [NAL9602](INFO): NAL9602 initialized
2012-12-03T19:08:33.321Z,1354561713.321 [NAL9602](INFO): SBD MO Status=1, MOMSN=5999, MT Status=0, MTMSN=0
2012-12-03T19:08:33.371Z,1354561713.371 [NAL9602](INFO): Sent 150 bytes from file Logs/20121203T175947/shore0011.lzma
2012-12-03T19:08:33.371Z,1354561713.371 [NAL9602](INFO): Packets left to send: 0
2012-12-03T19:08:33.373Z,1354561713.372 [NAL9602](INFO): Stored copy of sent data in Logs/20121203T175947/shore0011.lzma.parts/0000.sbd
2012-12-03T19:08:52.089Z,1354561732.089 [NAL9602](INFO): SBD MO Status=2, MOMSN=6000, MT Status=2, MTMSN=0
2012-12-03T19:08:52.089Z,1354561732.089 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-12-03T19:09:07.253Z,1354561747.253 [NAL9602](INFO): SBD MO Status=0, MOMSN=6000, MT Status=0, MTMSN=0
2012-12-03T19:09:07.337Z,1354561747.337 [Default:Iridium:Read_Iridium] Stopped
2012-12-03T19:09:07.337Z,1354561747.337 [Default:Iridium](INFO): Completed Default:Iridium
2012-12-03T19:09:07.337Z,1354561747.337 [Default:Iridium] Stopped
2012-12-03T19:09:07.337Z,1354561747.337 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-12-03T19:09:07.338Z,1354561747.338 [Default:Iridium:A.SetSpeed] Stopped
2012-12-03T19:09:07.338Z,1354561747.338 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T19:09:07.733Z,1354561747.733 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-12-03T19:09:07.733Z,1354561747.733 [Default:CallIridium:B] Stopped
2012-12-03T19:09:07.733Z,1354561747.733 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-12-03T19:09:07.733Z,1354561747.733 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-12-03T19:09:07.734Z,1354561747.734 [Default:CallIridium] Stopped
2012-12-03T19:09:07.734Z,1354561747.734 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-12-03T19:13:50.091Z,1354562030.091 [NAL9602](IMPORTANT): GPS fix at: 1354562976.00
2012-12-03T19:13:50.124Z,1354562030.124 [Default:GPS:Read_GPS] Stopped
2012-12-03T19:13:50.124Z,1354562030.124 [Default:GPS:D] Running Loop=1
2012-12-03T19:13:50.488Z,1354562030.489 [Default:GPS:D] Stopped
2012-12-03T19:13:50.489Z,1354562030.489 [Default:GPS](INFO): Completed Default:GPS
2012-12-03T19:13:50.489Z,1354562030.489 [Default:GPS] Stopped
2012-12-03T19:13:50.489Z,1354562030.489 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-12-03T19:13:50.489Z,1354562030.489 [Default:GPS:A.SetSpeed] Stopped
2012-12-03T19:13:50.489Z,1354562030.489 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-12-03T19:14:10.980Z,1354562050.980 [NAL9602](INFO): Powering down
2012-12-03T19:14:10.999Z,1354562050.999 [Default:CallIridium] Running Loop=1
2012-12-03T19:14:10.999Z,1354562050.999 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-12-03T19:14:10.999Z,1354562050.999 [Default:CallIridium:A] Running Loop=1
2012-12-03T19:14:10.000Z,1354562051.000 [Default:CallIridium:A] Stopped
2012-12-03T19:14:10.000Z,1354562051.000 [Default:CallIridium:B] Running Loop=1
2012-12-03T19:14:10.000Z,1354562051.000 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium] Running Loop=1
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-12-03T19:14:16.032Z,1354562056.032 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T19:14:16.033Z,1354562056.033 [Default:Iridium:B.GoToSurface] Stopped
2012-12-03T19:14:16.033Z,1354562056.033 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T19:14:16.033Z,1354562056.033 [Default:Iridium:Read_Iridium] Running Loop=1
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS] Running Loop=1
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS:A.SetSpeed] Running Loop=1
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS:B.GoToSurface] Running Loop=1
2012-12-03T19:14:16.034Z,1354562056.034 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-12-03T19:14:16.035Z,1354562056.035 [Default:GPS:B.GoToSurface] Stopped
2012-12-03T19:14:16.035Z,1354562056.035 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-12-03T19:14:16.036Z,1354562056.036 [Default:GPS:Read_GPS] Running Loop=1
2012-12-03T19:14:16.688Z,1354562056.688 [NAL9602](INFO): Powering up
2012-12-03T19:14:27.483Z,1354562067.483 [NAL9602](INFO): NAL9602 initialized
2012-12-03T19:24:30.328Z,1354562670.328 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-12-03T19:24:30.328Z,1354562670.328 [NAL9602] Data Fault, FailCount= 1
2012-12-03T19:24:30.328Z,1354562670.328 [NAL9602](ERROR): Data Fault
2012-12-03T19:24:30.355Z,1354562670.355 [CBIT](ERROR): Data Fault in component: NAL9602
2012-12-03T19:24:30.724Z,1354562670.724 [NAL9602](INFO): Powering down
2012-12-03T19:24:30.749Z,1354562670.749 [CBIT](INFO): Clearing failed state for component NAL9602
2012-12-03T19:24:30.749Z,1354562670.750 [NAL9602] No Fault, FailCount= 1
2012-12-03T19:24:35.925Z,1354562675.925 [NAL9602](INFO): Powering up NAL9602
2012-12-03T19:24:46.363Z,1354562686.363 [NAL9602](INFO): NAL9602 initialized