2012-11-26T19:40:14.725Z,1353958814.725 [Supervisor](DEBUG): Initializing supervisor.
2012-11-26T19:40:14.729Z,1353958814.729 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2012-11-26T19:40:14.729Z,1353958814.729 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-11-26T19:40:14.734Z,1353958814.734 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2012-11-26T19:40:14.738Z,1353958814.738 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-11-26T19:40:14.748Z,1353958814.749 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-11-26T19:40:14.750Z,1353958814.750 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2012-11-26T19:40:14.751Z,1353958814.751 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2012-11-26T19:40:14.754Z,1353958814.754 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2012-11-26T19:40:14.755Z,1353958814.755 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-11-26T19:40:14.758Z,1353958814.758 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-11-26T19:40:15.071Z,1353958815.071 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-11-26T19:40:15.073Z,1353958815.073 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-11-26T19:40:15.287Z,1353958815.287 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-11-26T19:40:15.288Z,1353958815.288 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-11-26T19:40:15.382Z,1353958815.382 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-11-26T19:40:15.384Z,1353958815.384 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-11-26T19:40:15.604Z,1353958815.604 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-11-26T19:40:15.605Z,1353958815.605 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-11-26T19:40:15.755Z,1353958815.755 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-11-26T19:40:15.757Z,1353958815.757 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-11-26T19:40:16.010Z,1353958816.010 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-11-26T19:40:16.011Z,1353958816.011 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-11-26T19:40:16.199Z,1353958816.199 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-11-26T19:40:16.201Z,1353958816.201 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-11-26T19:40:16.478Z,1353958816.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-11-26T19:40:16.480Z,1353958816.480 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-11-26T19:40:16.590Z,1353958816.590 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-11-26T19:40:16.590Z,1353958816.591 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-11-26T19:40:17.038Z,1353958817.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-11-26T19:40:17.038Z,1353958817.039 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-11-26T19:40:17.167Z,1353958817.167 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-11-26T19:40:17.168Z,1353958817.168 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-11-26T19:40:17.264Z,1353958817.263 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-11-26T19:40:17.267Z,1353958817.267 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-11-26T19:40:17.379Z,1353958817.378 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-11-26T19:40:17.522Z,1353958817.522 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-11-26T19:40:17.618Z,1353958817.618 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-11-26T19:40:17.732Z,1353958817.732 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-11-26T19:40:17.842Z,1353958817.842 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-11-26T19:40:17.976Z,1353958817.976 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-11-26T19:40:18.081Z,1353958818.081 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-11-26T19:40:18.194Z,1353958818.194 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2012-11-26T19:40:18.273Z,1353958818.273 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-11-26T19:40:18.481Z,1353958818.481 [InternalSim] Loaded
2012-11-26T19:40:18.481Z,1353958818.481 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-11-26T19:40:18.482Z,1353958818.482 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-11-26T19:40:18.482Z,1353958818.483 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-11-26T19:40:18.563Z,1353958818.563 [SBIT](DEBUG): Construct Startup Built In Test.
2012-11-26T19:40:18.596Z,1353958818.596 [SBIT] Loaded
2012-11-26T19:40:18.596Z,1353958818.596 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-11-26T19:40:18.597Z,1353958818.597 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-11-26T19:40:18.630Z,1353958818.630 [IBIT] Loaded
2012-11-26T19:40:18.630Z,1353958818.630 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-11-26T19:40:18.633Z,1353958818.633 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-11-26T19:40:18.772Z,1353958818.772 [CBIT] Loaded
2012-11-26T19:40:18.772Z,1353958818.772 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-11-26T19:40:18.773Z,1353958818.773 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-11-26T19:40:18.773Z,1353958818.773 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-11-26T19:40:18.947Z,1353958818.947 [BuoyancyServo] Loaded
2012-11-26T19:40:18.947Z,1353958818.947 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-11-26T19:40:18.959Z,1353958818.959 [ElevatorServo] Loaded
2012-11-26T19:40:18.960Z,1353958818.960 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-11-26T19:40:18.975Z,1353958818.975 [MassServo] Loaded
2012-11-26T19:40:18.975Z,1353958818.975 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-11-26T19:40:18.988Z,1353958818.987 [RudderServo] Loaded
2012-11-26T19:40:18.988Z,1353958818.988 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-11-26T19:40:18.000Z,1353958819.000 [ThrusterServo] Loaded
2012-11-26T19:40:18.000Z,1353958819.000 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-11-26T19:40:19.000Z,1353958819.000 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-11-26T19:40:19.001Z,1353958819.001 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-11-26T19:40:19.037Z,1353958819.037 [DepthRateCalculator] Loaded
2012-11-26T19:40:19.038Z,1353958819.037 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-11-26T19:40:22.415Z,1353958822.415 [HFRadarModelCalc] Loaded
2012-11-26T19:40:22.415Z,1353958822.415 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-11-26T19:40:22.431Z,1353958822.431 [NavChart] Loaded
2012-11-26T19:40:22.431Z,1353958822.431 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-11-26T19:40:22.437Z,1353958822.437 [PitchRateCalculator] Loaded
2012-11-26T19:40:22.438Z,1353958822.438 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-11-26T19:40:22.444Z,1353958822.444 [SpeedCalculator] Loaded
2012-11-26T19:40:22.444Z,1353958822.444 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-11-26T19:40:22.463Z,1353958822.464 [TempGradientCalculator] Loaded
2012-11-26T19:40:22.464Z,1353958822.464 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-11-26T19:40:22.470Z,1353958822.470 [YawRateCalculator] Loaded
2012-11-26T19:40:22.470Z,1353958822.470 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-11-26T19:40:22.515Z,1353958822.515 [Navigation] Loaded
2012-11-26T19:40:22.515Z,1353958822.515 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-11-26T19:40:22.515Z,1353958822.515 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-11-26T19:40:22.516Z,1353958822.516 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-11-26T19:40:22.794Z,1353958822.794 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-11-26T19:40:22.794Z,1353958822.794 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-11-26T19:40:22.838Z,1353958822.838 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-11-26T19:40:22.839Z,1353958822.839 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-11-26T19:40:22.902Z,1353958822.902 [VerticalControl](DEBUG): Construct VerticalControl.
2012-11-26T19:40:23.008Z,1353958823.008 [VerticalControl] Loaded
2012-11-26T19:40:23.008Z,1353958823.008 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-11-26T19:40:23.009Z,1353958823.009 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-11-26T19:40:23.069Z,1353958823.069 [HorizontalControl] Loaded
2012-11-26T19:40:23.069Z,1353958823.069 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-11-26T19:40:23.070Z,1353958823.070 [SpeedControl](DEBUG): Construct SpeedControl.
2012-11-26T19:40:23.072Z,1353958823.072 [SpeedControl] Loaded
2012-11-26T19:40:23.072Z,1353958823.072 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-11-26T19:40:23.073Z,1353958823.073 [LoopControl](DEBUG): Construct LoopControl.
2012-11-26T19:40:23.074Z,1353958823.074 [LoopControl] Loaded
2012-11-26T19:40:23.074Z,1353958823.074 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-11-26T19:40:23.074Z,1353958823.074 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-11-26T19:40:23.075Z,1353958823.075 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-11-26T19:40:23.084Z,1353958823.084 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-11-26T19:40:23.089Z,1353958823.089 [AsyncPiEstimator] Loaded
2012-11-26T19:40:23.089Z,1353958823.089 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-11-26T19:40:23.090Z,1353958823.090 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A14E0
2012-11-26T19:40:23.091Z,1353958823.091 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-11-26T19:40:23.091Z,1353958823.091 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-11-26T19:40:23.278Z,1353958823.278 [AHRS_sp3003D] Loaded
2012-11-26T19:40:23.279Z,1353958823.279 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-11-26T19:40:23.579Z,1353958823.579 [Batt_Ocean_Server] Loaded
2012-11-26T19:40:23.580Z,1353958823.580 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-11-26T19:40:23.594Z,1353958823.594 [Depth_Keller] Loaded
2012-11-26T19:40:23.594Z,1353958823.594 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-11-26T19:40:23.600Z,1353958823.600 [DropWeight] Loaded
2012-11-26T19:40:23.600Z,1353958823.600 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-11-26T19:40:23.786Z,1353958823.786 [DVL_micro] Loaded
2012-11-26T19:40:23.786Z,1353958823.786 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-11-26T19:40:23.790Z,1353958823.790 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 407234E0
2012-11-26T19:40:23.885Z,1353958823.885 [NAL9602] Loaded
2012-11-26T19:40:23.885Z,1353958823.885 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-11-26T19:40:23.940Z,1353958823.940 [Onboard] Loaded
2012-11-26T19:40:23.941Z,1353958823.941 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-11-26T19:40:23.951Z,1353958823.951 [Radio_Freewave] Loaded
2012-11-26T19:40:23.952Z,1353958823.952 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-11-26T19:40:23.952Z,1353958823.952 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-11-26T19:40:23.953Z,1353958823.953 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-11-26T19:40:24.060Z,1353958824.060 [CTD_NeilBrown] Loaded
2012-11-26T19:40:24.060Z,1353958824.060 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-11-26T19:40:24.062Z,1353958824.062 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4077C4E0
2012-11-26T19:40:24.079Z,1353958824.079 [PAR_Licor] Loaded
2012-11-26T19:40:24.079Z,1353958824.079 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2012-11-26T19:40:24.140Z,1353958824.140 [Turbulence_NPS] Loaded
2012-11-26T19:40:24.140Z,1353958824.140 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-11-26T19:40:24.142Z,1353958824.142 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407AC4E0
2012-11-26T19:40:24.178Z,1353958824.178 [WetLabsBB2FL] Loaded
2012-11-26T19:40:24.178Z,1353958824.178 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-11-26T19:40:24.182Z,1353958824.182 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407DC4E0
2012-11-26T19:40:24.183Z,1353958824.183 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-11-26T19:40:24.185Z,1353958824.185 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-11-26T19:40:24.187Z,1353958824.187 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-11-26T19:40:24.197Z,1353958824.197 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-11-26T19:40:24.198Z,1353958824.198 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4080C4E0
2012-11-26T19:40:24.203Z,1353958824.203 [Supervisor](DEBUG): Running supervisor.
2012-11-26T19:40:24.204Z,1353958824.204 [CommandLine](INFO): Thread ID is 748
2012-11-26T19:40:24.207Z,1353958824.207 [controlThread](INFO): Thread ID is 747
2012-11-26T19:40:24.207Z,1353958824.207 [controlThread](DEBUG): Initializing ControlThread
2012-11-26T19:40:24.208Z,1353958824.208 [CycleStarter](INFO): Thread ID is 746
2012-11-26T19:40:24.208Z,1353958824.208 [InternalSim](DEBUG):  InternalSim initializing...
2012-11-26T19:40:24.317Z,1353958824.317 [logger](INFO): Thread ID is 749
2012-11-26T19:40:24.427Z,1353958824.427 [AsyncPiEstimator](INFO): Thread ID is 810
2012-11-26T19:40:24.427Z,1353958824.427 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-11-26T19:40:24.450Z,1353958824.450 [DVL_micro](INFO): Thread ID is 811
2012-11-26T19:40:24.543Z,1353958824.543 [CTD_NeilBrown](INFO): Thread ID is 812
2012-11-26T19:40:24.544Z,1353958824.544 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-11-26T19:40:24.555Z,1353958824.555 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2012-11-26T19:40:24.599Z,1353958824.599 [Turbulence_NPS](INFO): Thread ID is 813
2012-11-26T19:40:24.599Z,1353958824.599 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-11-26T19:40:24.600Z,1353958824.600 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1
2012-11-26T19:40:24.607Z,1353958824.607 [WetLabsBB2FL](INFO): Thread ID is 814
2012-11-26T19:40:24.608Z,1353958824.608 [WetLabsBB2FL](INFO): Powering down
2012-11-26T19:40:24.627Z,1353958824.628 [NavChartDb](INFO): Thread ID is 815
2012-11-26T19:40:24.629Z,1353958824.629 [DVL_micro](INFO): Initializing
2012-11-26T19:40:24.629Z,1353958824.629 [DVL_micro](INFO): start:Powering up
2012-11-26T19:40:24.634Z,1353958824.634 [SBIT](INFO): Initialize SBIT Component.
2012-11-26T19:40:24.635Z,1353958824.635 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 10092
2012-11-26T19:40:24.635Z,1353958824.635 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-11-26T19:40:24.637Z,1353958824.637 [DVL_micro](INFO): Cycling power to configure device.
2012-11-26T19:40:24.648Z,1353958824.648 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-11-26T19:40:24.649Z,1353958824.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-11-26T19:40:24.649Z,1353958824.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-11-26T19:40:24.649Z,1353958824.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-11-26T19:40:24.650Z,1353958824.649 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-11-26T19:40:24.672Z,1353958824.672 [IBIT](INFO): Initialize IBIT Component.
2012-11-26T19:40:24.673Z,1353958824.673 [CBIT](DEBUG): Initialize CBIT Component.
2012-11-26T19:40:24.673Z,1353958824.673 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-11-26T19:40:24.673Z,1353958824.673 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-11-26T19:40:24.704Z,1353958824.704 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-11-26T19:40:24.705Z,1353958824.705 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-11-26T19:40:24.705Z,1353958824.705 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-11-26T19:40:24.706Z,1353958824.706 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-11-26T19:40:24.706Z,1353958824.706 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-11-26T19:40:24.717Z,1353958824.717 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-11-26T19:40:24.717Z,1353958824.717 [Navigation](DEBUG): Initializing Navigation.
2012-11-26T19:40:24.718Z,1353958824.718 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-11-26T19:40:24.731Z,1353958824.731 [Turbulence_NPS](INFO): Pause powering down
2012-11-26T19:40:24.752Z,1353958824.752 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-11-26T19:40:24.752Z,1353958824.752 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-11-26T19:40:24.753Z,1353958824.753 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-11-26T19:40:26.386Z,1353958826.385 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-11-26T19:40:26.427Z,1353958826.427 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-11-26T19:40:26.485Z,1353958826.485 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-11-26T19:40:26.505Z,1353958826.505 [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-11-26T19:40:26.506Z,1353958826.506 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-11-26T19:40:26.606Z,1353958826.606 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-11-26T19:40:26.620Z,1353958826.620 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-11-26T19:40:26.635Z,1353958826.635 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-11-26T19:40:26.667Z,1353958826.667 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-11-26T19:40:26.670Z,1353958826.670 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-11-26T19:40:26.693Z,1353958826.693 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-11-26T19:40:26.724Z,1353958826.724 [Default:D.SetSpeed](DEBUG): Construct.
2012-11-26T19:40:26.727Z,1353958826.727 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-11-26T19:40:26.732Z,1353958826.732 [Default:F.Wait](DEBUG): Construct Wait.
2012-11-26T19:40:26.766Z,1353958826.766 [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-11-26T19:40:26.786Z,1353958826.786 [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-11-26T19:40:26.795Z,1353958826.795 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2012-11-26T19:40:26.795Z,1353958826.795 [DVL_micro](INFO): Querying output modes
2012-11-26T19:40:26.796Z,1353958826.796 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-11-26T19:40:26.807Z,1353958826.806 [DVL_micro](DEBUG): cmdResponse: 01
2012-11-26T19:40:26.807Z,1353958826.807 [DVL_micro](INFO): NQ1 output enabled
2012-11-26T19:40:26.807Z,1353958826.807 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-11-26T19:40:26.819Z,1353958826.819 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-11-26T19:40:26.824Z,1353958826.824 [DVL_micro](INFO): pause:Powering down
2012-11-26T19:40:26.855Z,1353958826.855 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-11-26T19:40:27.070Z,1353958827.070 [Radio_Freewave](INFO): Powering up
2012-11-26T19:40:27.415Z,1353958827.415 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-11-26T19:40:27.423Z,1353958827.423 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-11-26T19:40:27.430Z,1353958827.430 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-11-26T19:40:27.459Z,1353958827.459 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-11-26T19:40:27.465Z,1353958827.465 [MassServo](DEBUG): Initializing EZServoServo.
2012-11-26T19:40:27.471Z,1353958827.471 [MassServo](DEBUG): Initializing MassServo.
2012-11-26T19:40:27.477Z,1353958827.477 [RudderServo](DEBUG): Initializing EZServoServo.
2012-11-26T19:40:27.483Z,1353958827.483 [RudderServo](DEBUG): Initializing RudderServo.
2012-11-26T19:40:27.500Z,1353958827.500 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-11-26T19:40:27.507Z,1353958827.507 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-11-26T19:40:29.070Z,1353958829.070 [NAL9602](INFO): Powering up NAL9602
2012-11-26T19:40:39.795Z,1353958839.795 [NAL9602](INFO): NAL9602 initialized
2012-11-26T19:40:40.137Z,1353958840.137 [SBIT](IMPORTANT): Beginning Startup BIT
2012-11-26T19:40:40.156Z,1353958840.156 [CBIT](IMPORTANT): Beginning GF scan
2012-11-26T19:41:06.823Z,1353958866.823 [CBIT](IMPORTANT): No ground fault detected
2012-11-26T19:41:34.152Z,1353958894.152 [SBIT](IMPORTANT): SBIT PASSED
2012-11-26T19:41:34.552Z,1353958894.552 [MissionManager](IMPORTANT): Started mission Startup
2012-11-26T19:41:34.552Z,1353958894.552 [Startup] Running Loop=1
2012-11-26T19:41:34.552Z,1353958894.552 [Startup](INFO): Aggregate::initialize Startup
2012-11-26T19:41:34.552Z,1353958894.552 [Startup:A.GoToSurface] Running Loop=1
2012-11-26T19:41:34.552Z,1353958894.552 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:41:34.558Z,1353958894.558 [Startup:StartupSatComms] Running Loop=1
2012-11-26T19:41:34.558Z,1353958894.558 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-11-26T19:41:34.559Z,1353958894.559 [Startup:StartupSatComms:A] Running Loop=1
2012-11-26T19:41:34.966Z,1353958894.966 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-11-26T19:42:34.962Z,1353958954.962 [Startup:StartupSatComms:A](INFO): Timed out from 2012-11-26T19:41:34.6Z
2012-11-26T19:42:34.962Z,1353958954.962 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2012-11-26T19:42:34.962Z,1353958954.962 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2012-11-26T19:42:34.963Z,1353958954.963 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2012-11-26T19:42:34.963Z,1353958954.963 [Startup:StartupSatComms:A] Stopped
2012-11-26T19:42:34.963Z,1353958954.963 [Startup:StartupSatComms:B] Running Loop=1
2012-11-26T19:42:35.354Z,1353958955.354 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms:B](INFO): Timed out from 2012-11-26T19:42:34.0Z
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms:B] Stopped
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-11-26T19:43:35.291Z,1353959015.291 [Startup:StartupSatComms] Stopped
2012-11-26T19:43:35.292Z,1353959015.292 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-11-26T19:43:35.292Z,1353959015.292 [Startup](INFO): Completed Startup
2012-11-26T19:43:35.292Z,1353959015.293 [Startup] Stopped
2012-11-26T19:43:35.293Z,1353959015.293 [Startup](INFO): Aggregate::uninitialize Startup
2012-11-26T19:43:35.293Z,1353959015.293 [Startup:A.GoToSurface] Stopped
2012-11-26T19:43:35.293Z,1353959015.293 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T19:43:35.673Z,1353959015.673 [MissionManager](IMPORTANT): Started mission Default
2012-11-26T19:43:35.674Z,1353959015.674 [Default] Running Loop=1
2012-11-26T19:43:35.674Z,1353959015.674 [Default](INFO): Aggregate::initialize Default
2012-11-26T19:43:35.674Z,1353959015.674 [Default:D.SetSpeed] Running Loop=1
2012-11-26T19:43:35.674Z,1353959015.674 [Default:D.SetSpeed](DEBUG): Initialize.
2012-11-26T19:43:35.674Z,1353959015.674 [Default:E.GoToSurface] Running Loop=1
2012-11-26T19:43:35.674Z,1353959015.674 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:43:35.674Z,1353959015.674 [Default:Iridium] Running Loop=1
2012-11-26T19:43:35.674Z,1353959015.674 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T19:43:35.674Z,1353959015.674 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T19:43:35.675Z,1353959015.675 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T19:43:35.675Z,1353959015.675 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T19:43:35.675Z,1353959015.675 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:43:35.675Z,1353959015.675 [Default:E.GoToSurface] Running Loop=1
2012-11-26T19:43:35.680Z,1353959015.681 [Default:D.SetSpeed] Running Loop=1
2012-11-26T19:43:35.685Z,1353959015.685 [Default:CallIridium] Running Loop=1
2012-11-26T19:43:35.685Z,1353959015.685 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T19:43:35.686Z,1353959015.686 [Default:CallIridium:A] Running Loop=1
2012-11-26T19:43:35.688Z,1353959015.688 [Default:CallIridium:A] Stopped
2012-11-26T19:43:35.688Z,1353959015.688 [Default:CallIridium:B] Running Loop=1
2012-11-26T19:43:35.688Z,1353959015.688 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T19:43:35.693Z,1353959015.693 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T19:43:35.693Z,1353959015.694 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T19:43:35.694Z,1353959015.694 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T19:43:35.694Z,1353959015.694 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T19:43:35.699Z,1353959015.699 [Default:GPS] Running Loop=1
2012-11-26T19:43:35.699Z,1353959015.699 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T19:43:35.699Z,1353959015.699 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T19:43:35.700Z,1353959015.700 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T19:43:35.700Z,1353959015.700 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T19:43:35.700Z,1353959015.700 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:43:35.705Z,1353959015.705 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T19:43:35.705Z,1353959015.705 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T19:43:35.705Z,1353959015.705 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T19:43:35.705Z,1353959015.705 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T19:43:36.076Z,1353959016.076 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-11-26T19:43:36.078Z,1353959016.078 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-11-26T19:45:55.843Z,1353959155.843 [CommandLine](IMPORTANT): got command failComponent
2012-11-26T19:45:55.844Z,1353959155.844 [CommandLine](IMPORTANT): Failed components:
2012-11-26T19:45:55.844Z,1353959155.844 [CommandLine](IMPORTANT): No failed Components.
2012-11-26T19:46:24.250Z,1353959184.250 [NAL9602](INFO): SBD MO Status=2, MOMSN=5127, MT Status=2, MTMSN=0
2012-11-26T19:46:24.250Z,1353959184.250 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:47:07.538Z,1353959227.538 [NAL9602](INFO): SBD MO Status=2, MOMSN=5127, MT Status=2, MTMSN=0
2012-11-26T19:47:07.538Z,1353959227.538 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:47:37.197Z,1353959257.197 [NAL9602](INFO): SBD MO Status=2, MOMSN=5127, MT Status=2, MTMSN=0
2012-11-26T19:47:37.198Z,1353959257.197 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:50:42.352Z,1353959442.352 [NAL9602](FAULT): GPS failed to acquire within timeout.
2012-11-26T19:50:42.352Z,1353959442.352 [NAL9602] Data Fault, FailCount= 1
2012-11-26T19:50:42.352Z,1353959442.352 [NAL9602](ERROR): Data Fault
2012-11-26T19:50:42.376Z,1353959442.376 [CBIT](ERROR): Data Fault in component: NAL9602
2012-11-26T19:50:42.752Z,1353959442.752 [NAL9602](INFO): Powering down
2012-11-26T19:50:42.780Z,1353959442.780 [CBIT](INFO): Clearing failed state for component NAL9602
2012-11-26T19:50:42.780Z,1353959442.780 [NAL9602] No Fault, FailCount= 1
2012-11-26T19:50:47.953Z,1353959447.953 [NAL9602](INFO): Powering up NAL9602
2012-11-26T19:50:58.787Z,1353959458.787 [NAL9602](INFO): NAL9602 initialized
2012-11-26T19:51:50.898Z,1353959510.898 [NAL9602](INFO): SBD MO Status=1, MOMSN=5127, MT Status=0, MTMSN=0
2012-11-26T19:51:50.947Z,1353959510.947 [NAL9602](INFO): Sent 332 bytes from file Logs/20121126T193604/shore0000.lzma
2012-11-26T19:51:50.947Z,1353959510.947 [NAL9602](INFO): Packets left to send: 1
2012-11-26T19:51:50.949Z,1353959510.949 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T193604/shore0000.lzma.parts/0001.sbd
2012-11-26T19:51:59.573Z,1353959519.573 [NAL9602](INFO): SBD MO Status=2, MOMSN=5128, MT Status=2, MTMSN=0
2012-11-26T19:51:59.574Z,1353959519.574 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:52:00.780Z,1353959520.780 [NAL9602](IMPORTANT): GPS fix at: 1353959519.00
2012-11-26T19:52:00.796Z,1353959520.796 [Default:GPS:Read_GPS] Stopped
2012-11-26T19:52:00.796Z,1353959520.796 [Default:GPS:D] Running Loop=1
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS:D] Stopped
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS] Stopped
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T19:52:01.208Z,1353959521.208 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T19:52:08.225Z,1353959528.225 [NAL9602](INFO): SBD MO Status=2, MOMSN=5128, MT Status=2, MTMSN=0
2012-11-26T19:52:08.225Z,1353959528.225 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:52:20.771Z,1353959540.770 [NAL9602](INFO): SBD MO Status=1, MOMSN=5128, MT Status=0, MTMSN=0
2012-11-26T19:52:20.819Z,1353959540.819 [NAL9602](INFO): Sent 300 bytes from file Logs/20121126T193604/shore0000.lzma
2012-11-26T19:52:20.819Z,1353959540.819 [NAL9602](INFO): Packets left to send: 0
2012-11-26T19:52:20.820Z,1353959540.820 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T193604/shore0000.lzma.parts/0000.sbd
2012-11-26T19:52:26.243Z,1353959546.243 [NAL9602](INFO): SBD MO Status=2, MOMSN=5129, MT Status=2, MTMSN=0
2012-11-26T19:52:26.244Z,1353959546.244 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:52:38.044Z,1353959558.044 [NAL9602](INFO): SBD MO Status=1, MOMSN=5129, MT Status=0, MTMSN=0
2012-11-26T19:52:38.099Z,1353959558.099 [NAL9602](INFO): Sent 151 bytes from file Logs/20121126T193604/shore0001.lzma
2012-11-26T19:52:38.099Z,1353959558.099 [NAL9602](INFO): Packets left to send: 0
2012-11-26T19:52:38.104Z,1353959558.104 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T193604/shore0001.lzma.parts/0000.sbd
2012-11-26T19:52:48.726Z,1353959568.726 [NAL9602](INFO): SBD MO Status=1, MOMSN=5130, MT Status=0, MTMSN=0
2012-11-26T19:52:48.787Z,1353959568.787 [NAL9602](INFO): Sent 332 bytes from file Logs/20121126T194014/shore0000.lzma
2012-11-26T19:52:48.787Z,1353959568.787 [NAL9602](INFO): Packets left to send: 1
2012-11-26T19:52:48.788Z,1353959568.788 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0000.lzma.parts/0001.sbd
2012-11-26T19:52:56.913Z,1353959576.913 [NAL9602](INFO): SBD MO Status=1, MOMSN=5131, MT Status=0, MTMSN=0
2012-11-26T19:52:56.963Z,1353959576.963 [NAL9602](INFO): Sent 170 bytes from file Logs/20121126T194014/shore0000.lzma
2012-11-26T19:52:56.963Z,1353959576.963 [NAL9602](INFO): Packets left to send: 0
2012-11-26T19:52:56.964Z,1353959576.964 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0000.lzma.parts/0000.sbd
2012-11-26T19:53:04.513Z,1353959584.513 [NAL9602](INFO): SBD MO Status=0, MOMSN=5132, MT Status=0, MTMSN=0
2012-11-26T19:53:04.597Z,1353959584.597 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T19:53:04.597Z,1353959584.597 [Default:Iridium](INFO): Completed Default:Iridium
2012-11-26T19:53:04.597Z,1353959584.597 [Default:Iridium] Stopped
2012-11-26T19:53:04.598Z,1353959584.598 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T19:53:04.598Z,1353959584.598 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T19:53:04.598Z,1353959584.598 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T19:53:04.598Z,1353959584.598 [Default:F.Wait] Running Loop=1
2012-11-26T19:53:04.598Z,1353959584.598 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-11-26T19:53:04.966Z,1353959584.966 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-11-26T19:53:04.966Z,1353959584.966 [Default:CallIridium:B] Stopped
2012-11-26T19:53:04.966Z,1353959584.966 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T19:53:04.966Z,1353959584.966 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-11-26T19:53:04.966Z,1353959584.967 [Default:CallIridium] Stopped
2012-11-26T19:53:04.967Z,1353959584.967 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T19:53:15.101Z,1353959595.101 [NAL9602](INFO): Powering down
2012-11-26T19:58:05.084Z,1353959885.084 [Default:CallIridium] Running Loop=1
2012-11-26T19:58:05.084Z,1353959885.084 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T19:58:05.084Z,1353959885.084 [Default:CallIridium:A] Running Loop=1
2012-11-26T19:58:05.084Z,1353959885.085 [Default:CallIridium:A] Stopped
2012-11-26T19:58:05.085Z,1353959885.085 [Default:CallIridium:B] Running Loop=1
2012-11-26T19:58:05.085Z,1353959885.085 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium] Running Loop=1
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T19:58:10.116Z,1353959890.116 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:58:10.117Z,1353959890.117 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T19:58:10.117Z,1353959890.117 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T19:58:10.117Z,1353959890.117 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T19:58:10.117Z,1353959890.118 [Default:GPS] Running Loop=1
2012-11-26T19:58:10.118Z,1353959890.118 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T19:58:10.118Z,1353959890.118 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T19:58:10.118Z,1353959890.118 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T19:58:10.118Z,1353959890.118 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T19:58:10.118Z,1353959890.118 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T19:58:10.119Z,1353959890.119 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T19:58:10.119Z,1353959890.119 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T19:58:10.119Z,1353959890.119 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T19:58:10.712Z,1353959890.712 [NAL9602](INFO): Powering up
2012-11-26T19:58:21.551Z,1353959901.551 [NAL9602](INFO): NAL9602 initialized
2012-11-26T19:58:38.921Z,1353959918.921 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=5133, MT Status=1, MTMSN=397
2012-11-26T19:58:38.975Z,1353959918.975 [NAL9602](INFO): Sent 332 bytes from file Logs/20121126T194014/shore0001.lzma
2012-11-26T19:58:38.975Z,1353959918.975 [NAL9602](INFO): Packets left to send: 1
2012-11-26T19:58:38.976Z,1353959918.976 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0001.lzma.parts/0001.sbd
2012-11-26T19:58:39.435Z,1353959919.435 [NAL9602](INFO): Received command:ibit
2012-11-26T19:58:39.523Z,1353959919.523 [CommandLine](IMPORTANT): got command ibit
2012-11-26T19:58:39.711Z,1353959919.711 [IBIT](IMPORTANT): Beginning Initiated BIT
2012-11-26T19:58:39.711Z,1353959919.711 [IBIT](IMPORTANT): Beginning control surface checks.

2012-11-26T19:58:39.712Z,1353959919.712 [CBIT](IMPORTANT): Beginning GF scan
2012-11-26T19:58:40.483Z,1353959920.483 [NAL9602](IMPORTANT): GPS fix at: 1353959919.00
2012-11-26T19:58:40.489Z,1353959920.489 [Radio_Freewave](INFO): Powering down
2012-11-26T19:58:41.289Z,1353959921.289 [Radio_Freewave](INFO): Powering up
2012-11-26T19:58:57.417Z,1353959937.417 [NAL9602](INFO): SBD MO Status=1, MOMSN=5134, MT Status=0, MTMSN=0
2012-11-26T19:58:57.471Z,1353959937.471 [NAL9602](INFO): Sent 289 bytes from file Logs/20121126T194014/shore0001.lzma
2012-11-26T19:58:57.471Z,1353959937.471 [NAL9602](INFO): Packets left to send: 0
2012-11-26T19:58:57.472Z,1353959937.472 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0001.lzma.parts/0000.sbd
2012-11-26T19:59:07.855Z,1353959947.855 [CBIT](IMPORTANT): No ground fault detected
2012-11-26T19:59:18.353Z,1353959958.353 [NAL9602](INFO): SBD MO Status=2, MOMSN=5135, MT Status=2, MTMSN=0
2012-11-26T19:59:18.354Z,1353959958.354 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T19:59:19.515Z,1353959959.515 [NAL9602](IMPORTANT): GPS fix at: 1353959958.00
2012-11-26T19:59:25.606Z,1353959965.606 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 36.804226 Longitude: -121.786491
2012-11-26T19:59:25.977Z,1353959965.977 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 236.980011
Voltage: 16.312000
2012-11-26T19:59:25.978Z,1353959965.978 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah
2012-11-26T19:59:25.978Z,1353959965.978 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V
2012-11-26T19:59:26.389Z,1353959966.389 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2012-11-26T19:59:26.389Z,1353959966.389 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2012-11-26T19:59:26.390Z,1353959966.390 [IBIT](IMPORTANT): Pressure:18.168247 PSI
2012-11-26T19:59:26.390Z,1353959966.390 [IBIT](IMPORTANT): Humidity:23.593349 %
2012-11-26T19:59:26.793Z,1353959966.793 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2012-11-26T19:59:26.793Z,1353959966.793 [IBIT](IMPORTANT): buoyancyNeutral: 498.000000 cc
2012-11-26T19:59:26.794Z,1353959966.793 [IBIT](IMPORTANT): massDefault: 1.090000 cm
2012-11-26T19:59:26.794Z,1353959966.794 [IBIT](IMPORTANT): stopDepth: 125.000000 m
2012-11-26T19:59:26.794Z,1353959966.794 [IBIT](IMPORTANT): abortDepth: 150.000000 m
2012-11-26T19:59:26.794Z,1353959966.794 [IBIT](IMPORTANT): IBIT PASSED
2012-11-26T19:59:27.102Z,1353959967.102 [Default:GPS:Read_GPS] Stopped
2012-11-26T19:59:27.102Z,1353959967.102 [Default:GPS:D] Running Loop=1
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS:D] Stopped
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS] Stopped
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T19:59:27.509Z,1353959967.509 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T19:59:29.089Z,1353959969.089 [NAL9602](INFO): SBD MO Status=0, MOMSN=5135, MT Status=0, MTMSN=0
2012-11-26T19:59:41.857Z,1353959981.857 [NAL9602](INFO): SBD MO Status=1, MOMSN=5136, MT Status=0, MTMSN=0
2012-11-26T19:59:41.907Z,1353959981.907 [NAL9602](INFO): Sent 332 bytes from file Logs/20121126T194014/shore0002.lzma
2012-11-26T19:59:41.907Z,1353959981.907 [NAL9602](INFO): Packets left to send: 2
2012-11-26T19:59:41.908Z,1353959981.908 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0002.lzma.parts/0002.sbd
2012-11-26T20:00:02.173Z,1353960002.173 [NAL9602](INFO): SBD MO Status=1, MOMSN=5137, MT Status=0, MTMSN=0
2012-11-26T20:00:02.227Z,1353960002.227 [NAL9602](INFO): Sent 332 bytes from file Logs/20121126T194014/shore0002.lzma
2012-11-26T20:00:02.227Z,1353960002.227 [NAL9602](INFO): Packets left to send: 1
2012-11-26T20:00:02.228Z,1353960002.228 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0002.lzma.parts/0001.sbd
2012-11-26T20:00:14.165Z,1353960014.165 [NAL9602](INFO): SBD MO Status=1, MOMSN=5138, MT Status=0, MTMSN=0
2012-11-26T20:00:14.219Z,1353960014.219 [NAL9602](INFO): Sent 52 bytes from file Logs/20121126T194014/shore0002.lzma
2012-11-26T20:00:14.219Z,1353960014.219 [NAL9602](INFO): Packets left to send: 0
2012-11-26T20:00:14.220Z,1353960014.220 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0002.lzma.parts/0000.sbd
2012-11-26T20:00:24.169Z,1353960024.169 [NAL9602](INFO): SBD MO Status=0, MOMSN=5139, MT Status=0, MTMSN=0
2012-11-26T20:00:24.265Z,1353960024.265 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T20:00:24.265Z,1353960024.265 [Default:Iridium](INFO): Completed Default:Iridium
2012-11-26T20:00:24.266Z,1353960024.266 [Default:Iridium] Stopped
2012-11-26T20:00:24.266Z,1353960024.266 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T20:00:24.266Z,1353960024.266 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T20:00:24.266Z,1353960024.266 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:00:24.590Z,1353960024.590 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-11-26T20:00:24.590Z,1353960024.590 [Default:CallIridium:B] Stopped
2012-11-26T20:00:24.590Z,1353960024.590 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T20:00:24.591Z,1353960024.591 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-11-26T20:00:24.591Z,1353960024.591 [Default:CallIridium] Stopped
2012-11-26T20:00:24.591Z,1353960024.591 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T20:00:34.751Z,1353960034.751 [NAL9602](INFO): Powering down
2012-11-26T20:05:24.767Z,1353960324.767 [Default:CallIridium] Running Loop=1
2012-11-26T20:05:24.767Z,1353960324.767 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T20:05:24.767Z,1353960324.767 [Default:CallIridium:A] Running Loop=1
2012-11-26T20:05:24.767Z,1353960324.767 [Default:CallIridium:A] Stopped
2012-11-26T20:05:24.767Z,1353960324.767 [Default:CallIridium:B] Running Loop=1
2012-11-26T20:05:24.768Z,1353960324.768 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium] Running Loop=1
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T20:05:29.757Z,1353960329.757 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:05:29.758Z,1353960329.758 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T20:05:29.758Z,1353960329.758 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:05:29.758Z,1353960329.758 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS] Running Loop=1
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T20:05:29.759Z,1353960329.759 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:05:29.760Z,1353960329.760 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T20:05:29.760Z,1353960329.760 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:05:29.760Z,1353960329.760 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T20:05:30.372Z,1353960330.372 [NAL9602](INFO): Powering up
2012-11-26T20:05:41.259Z,1353960341.259 [NAL9602](INFO): NAL9602 initialized
2012-11-26T20:06:02.953Z,1353960362.953 [NAL9602](INFO): SBD MO Status=1, MOMSN=5140, MT Status=0, MTMSN=0
2012-11-26T20:06:03.003Z,1353960363.003 [NAL9602](INFO): Sent 114 bytes from file Logs/20121126T194014/shore0003.lzma
2012-11-26T20:06:03.003Z,1353960363.003 [NAL9602](INFO): Packets left to send: 0
2012-11-26T20:06:03.004Z,1353960363.004 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0003.lzma.parts/0000.sbd
2012-11-26T20:06:14.544Z,1353960374.544 [NAL9602](INFO): SBD MO Status=0, MOMSN=5141, MT Status=0, MTMSN=0
2012-11-26T20:06:14.619Z,1353960374.619 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T20:06:14.620Z,1353960374.620 [Default:Iridium](INFO): Completed Default:Iridium
2012-11-26T20:06:14.620Z,1353960374.620 [Default:Iridium] Stopped
2012-11-26T20:06:14.620Z,1353960374.620 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T20:06:14.620Z,1353960374.620 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T20:06:14.620Z,1353960374.620 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:06:14.962Z,1353960374.962 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-11-26T20:06:14.962Z,1353960374.962 [Default:CallIridium:B] Stopped
2012-11-26T20:06:14.962Z,1353960374.962 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T20:06:14.962Z,1353960374.963 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-11-26T20:06:14.963Z,1353960374.963 [Default:CallIridium] Stopped
2012-11-26T20:06:14.963Z,1353960374.963 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T20:06:15.789Z,1353960375.789 [NAL9602](IMPORTANT): GPS fix at: 1353960376.00
2012-11-26T20:06:15.806Z,1353960375.806 [Default:GPS:Read_GPS] Stopped
2012-11-26T20:06:15.806Z,1353960375.806 [Default:GPS:D] Running Loop=1
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS:D] Stopped
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS] Stopped
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T20:06:16.181Z,1353960376.181 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:06:36.704Z,1353960396.704 [NAL9602](INFO): Powering down
2012-11-26T20:11:16.672Z,1353960676.671 [Default:CallIridium] Running Loop=1
2012-11-26T20:11:16.672Z,1353960676.672 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T20:11:16.672Z,1353960676.672 [Default:CallIridium:A] Running Loop=1
2012-11-26T20:11:16.672Z,1353960676.672 [Default:CallIridium:A] Stopped
2012-11-26T20:11:16.672Z,1353960676.672 [Default:CallIridium:B] Running Loop=1
2012-11-26T20:11:16.673Z,1353960676.672 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium] Running Loop=1
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T20:11:21.787Z,1353960681.787 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:11:21.788Z,1353960681.788 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T20:11:21.788Z,1353960681.788 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:11:21.788Z,1353960681.788 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS] Running Loop=1
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T20:11:21.789Z,1353960681.789 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:11:21.790Z,1353960681.790 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T20:11:21.790Z,1353960681.790 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:11:21.790Z,1353960681.790 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T20:11:22.384Z,1353960682.384 [NAL9602](INFO): Powering up
2012-11-26T20:11:33.219Z,1353960693.219 [NAL9602](INFO): NAL9602 initialized
2012-11-26T20:11:51.361Z,1353960711.361 [NAL9602](INFO): SBD MO Status=1, MOMSN=5142, MT Status=0, MTMSN=0
2012-11-26T20:11:51.411Z,1353960711.411 [NAL9602](INFO): Sent 162 bytes from file Logs/20121126T194014/shore0004.lzma
2012-11-26T20:11:51.411Z,1353960711.411 [NAL9602](INFO): Packets left to send: 0
2012-11-26T20:11:51.412Z,1353960711.412 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0004.lzma.parts/0000.sbd
2012-11-26T20:11:59.761Z,1353960719.761 [NAL9602](INFO): SBD MO Status=0, MOMSN=5143, MT Status=0, MTMSN=0
2012-11-26T20:11:59.856Z,1353960719.856 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T20:11:59.857Z,1353960719.856 [Default:Iridium](INFO): Completed Default:Iridium
2012-11-26T20:11:59.857Z,1353960719.856 [Default:Iridium] Stopped
2012-11-26T20:11:59.857Z,1353960719.857 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T20:11:59.857Z,1353960719.857 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T20:11:59.857Z,1353960719.857 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:12:00.208Z,1353960720.208 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-11-26T20:12:00.208Z,1353960720.208 [Default:CallIridium:B] Stopped
2012-11-26T20:12:00.208Z,1353960720.208 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T20:12:00.209Z,1353960720.209 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-11-26T20:12:00.209Z,1353960720.209 [Default:CallIridium] Stopped
2012-11-26T20:12:00.209Z,1353960720.209 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T20:12:26.595Z,1353960746.595 [NAL9602](IMPORTANT): GPS fix at: 1353960747.00
2012-11-26T20:12:26.612Z,1353960746.612 [Default:GPS:Read_GPS] Stopped
2012-11-26T20:12:26.612Z,1353960746.612 [Default:GPS:D] Running Loop=1
2012-11-26T20:12:27.004Z,1353960747.004 [Default:GPS:D] Stopped
2012-11-26T20:12:27.005Z,1353960747.005 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T20:12:27.005Z,1353960747.005 [Default:GPS] Stopped
2012-11-26T20:12:27.005Z,1353960747.005 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T20:12:27.005Z,1353960747.005 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T20:12:27.005Z,1353960747.005 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:12:47.524Z,1353960767.524 [NAL9602](INFO): Powering down
2012-11-26T20:17:02.554Z,1353961022.554 [Default:CallIridium] Running Loop=1
2012-11-26T20:17:02.554Z,1353961022.554 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T20:17:02.554Z,1353961022.554 [Default:CallIridium:A] Running Loop=1
2012-11-26T20:17:02.555Z,1353961022.555 [Default:CallIridium:A] Stopped
2012-11-26T20:17:02.555Z,1353961022.555 [Default:CallIridium:B] Running Loop=1
2012-11-26T20:17:02.555Z,1353961022.556 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T20:17:07.532Z,1353961027.532 [Default:Iridium] Running Loop=1
2012-11-26T20:17:07.532Z,1353961027.532 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T20:17:07.532Z,1353961027.532 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T20:17:07.532Z,1353961027.532 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:17:07.532Z,1353961027.532 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T20:17:07.533Z,1353961027.533 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:17:07.533Z,1353961027.533 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T20:17:07.533Z,1353961027.533 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:17:07.533Z,1353961027.533 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS] Running Loop=1
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T20:17:07.534Z,1353961027.534 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:17:07.535Z,1353961027.535 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T20:17:07.535Z,1353961027.535 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:17:07.535Z,1353961027.535 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T20:17:08.188Z,1353961028.188 [NAL9602](INFO): Powering up
2012-11-26T20:17:18.631Z,1353961038.631 [NAL9602](INFO): NAL9602 initialized
2012-11-26T20:17:56.349Z,1353961076.349 [NAL9602](INFO): SBD MO Status=2, MOMSN=5144, MT Status=2, MTMSN=0
2012-11-26T20:17:56.349Z,1353961076.349 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:18:20.589Z,1353961100.589 [NAL9602](INFO): SBD MO Status=2, MOMSN=5144, MT Status=2, MTMSN=0
2012-11-26T20:18:20.590Z,1353961100.589 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:18:49.947Z,1353961129.947 [NAL9602](INFO): SBD MO Status=1, MOMSN=5144, MT Status=0, MTMSN=0
2012-11-26T20:18:49.995Z,1353961129.995 [NAL9602](INFO): Sent 175 bytes from file Logs/20121126T194014/shore0005.lzma
2012-11-26T20:18:49.995Z,1353961129.995 [NAL9602](INFO): Packets left to send: 0
2012-11-26T20:18:49.997Z,1353961129.997 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0005.lzma.parts/0000.sbd
2012-11-26T20:19:03.953Z,1353961143.954 [NAL9602](INFO): SBD MO Status=0, MOMSN=5145, MT Status=0, MTMSN=0
2012-11-26T20:19:04.037Z,1353961144.037 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T20:19:04.037Z,1353961144.037 [Default:Iridium](INFO): Completed Default:Iridium
2012-11-26T20:19:04.037Z,1353961144.037 [Default:Iridium] Stopped
2012-11-26T20:19:04.037Z,1353961144.037 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T20:19:04.038Z,1353961144.037 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T20:19:04.038Z,1353961144.038 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:19:04.363Z,1353961144.363 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-11-26T20:19:04.363Z,1353961144.363 [Default:CallIridium:B] Stopped
2012-11-26T20:19:04.363Z,1353961144.363 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T20:19:04.364Z,1353961144.364 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-11-26T20:19:04.364Z,1353961144.364 [Default:CallIridium] Stopped
2012-11-26T20:19:04.364Z,1353961144.364 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T20:19:19.149Z,1353961159.149 [NAL9602](IMPORTANT): GPS fix at: 1353961160.00
2012-11-26T20:19:19.167Z,1353961159.167 [Default:GPS:Read_GPS] Stopped
2012-11-26T20:19:19.167Z,1353961159.167 [Default:GPS:D] Running Loop=1
2012-11-26T20:19:19.581Z,1353961159.581 [Default:GPS:D] Stopped
2012-11-26T20:19:19.582Z,1353961159.582 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T20:19:19.582Z,1353961159.582 [Default:GPS] Stopped
2012-11-26T20:19:19.582Z,1353961159.582 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T20:19:19.582Z,1353961159.582 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T20:19:19.582Z,1353961159.582 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:19:40.152Z,1353961180.152 [NAL9602](INFO): Powering down
2012-11-26T20:24:05.120Z,1353961445.120 [Default:CallIridium] Running Loop=1
2012-11-26T20:24:05.120Z,1353961445.120 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-11-26T20:24:05.120Z,1353961445.120 [Default:CallIridium:A] Running Loop=1
2012-11-26T20:24:05.121Z,1353961445.121 [Default:CallIridium:A] Stopped
2012-11-26T20:24:05.121Z,1353961445.121 [Default:CallIridium:B] Running Loop=1
2012-11-26T20:24:05.121Z,1353961445.121 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-11-26T20:24:10.165Z,1353961450.165 [Default:Iridium] Running Loop=1
2012-11-26T20:24:10.166Z,1353961450.165 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-11-26T20:24:10.166Z,1353961450.166 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-11-26T20:24:10.166Z,1353961450.166 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:24:10.166Z,1353961450.166 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-11-26T20:24:10.166Z,1353961450.166 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:24:10.167Z,1353961450.167 [Default:Iridium:B.GoToSurface] Stopped
2012-11-26T20:24:10.167Z,1353961450.167 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:24:10.167Z,1353961450.167 [Default:Iridium:Read_Iridium] Running Loop=1
2012-11-26T20:24:10.167Z,1353961450.167 [Default:GPS] Running Loop=1
2012-11-26T20:24:10.168Z,1353961450.168 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-11-26T20:24:10.168Z,1353961450.168 [Default:GPS:A.SetSpeed] Running Loop=1
2012-11-26T20:24:10.168Z,1353961450.168 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-11-26T20:24:10.168Z,1353961450.168 [Default:GPS:B.GoToSurface] Running Loop=1
2012-11-26T20:24:10.168Z,1353961450.168 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-11-26T20:24:10.169Z,1353961450.169 [Default:GPS:B.GoToSurface] Stopped
2012-11-26T20:24:10.169Z,1353961450.169 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:24:10.169Z,1353961450.169 [Default:GPS:Read_GPS] Running Loop=1
2012-11-26T20:24:10.772Z,1353961450.772 [NAL9602](INFO): Powering up
2012-11-26T20:24:21.603Z,1353961461.603 [NAL9602](INFO): NAL9602 initialized
2012-11-26T20:24:42.949Z,1353961482.949 [NAL9602](INFO): SBD MO Status=2, MOMSN=5146, MT Status=2, MTMSN=0
2012-11-26T20:24:42.949Z,1353961482.949 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:25:07.109Z,1353961507.109 [NAL9602](INFO): SBD MO Status=2, MOMSN=5146, MT Status=2, MTMSN=0
2012-11-26T20:25:07.109Z,1353961507.109 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:25:30.517Z,1353961530.517 [NAL9602](INFO): SBD MO Status=2, MOMSN=5146, MT Status=2, MTMSN=0
2012-11-26T20:25:30.517Z,1353961530.517 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:25:55.109Z,1353961555.109 [NAL9602](INFO): SBD MO Status=2, MOMSN=5146, MT Status=2, MTMSN=0
2012-11-26T20:25:55.110Z,1353961555.110 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:25:56.275Z,1353961556.275 [NAL9602](IMPORTANT): GPS fix at: 1353961558.00
2012-11-26T20:25:56.292Z,1353961556.292 [Default:GPS:Read_GPS] Stopped
2012-11-26T20:25:56.292Z,1353961556.292 [Default:GPS:D] Running Loop=1
2012-11-26T20:25:56.771Z,1353961556.771 [Default:GPS:D] Stopped
2012-11-26T20:25:56.771Z,1353961556.772 [Default:GPS](INFO): Completed Default:GPS
2012-11-26T20:25:56.772Z,1353961556.772 [Default:GPS] Stopped
2012-11-26T20:25:56.772Z,1353961556.772 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-11-26T20:25:56.772Z,1353961556.772 [Default:GPS:A.SetSpeed] Stopped
2012-11-26T20:25:56.772Z,1353961556.772 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:26:13.625Z,1353961573.625 [NAL9602](INFO): SBD MO Status=2, MOMSN=5146, MT Status=2, MTMSN=0
2012-11-26T20:26:13.626Z,1353961573.625 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:26:50.621Z,1353961610.621 [NAL9602](INFO): SBD MO Status=1, MOMSN=5146, MT Status=0, MTMSN=0
2012-11-26T20:26:50.671Z,1353961610.671 [NAL9602](INFO): Sent 177 bytes from file Logs/20121126T194014/shore0006.lzma
2012-11-26T20:26:50.671Z,1353961610.671 [NAL9602](INFO): Packets left to send: 0
2012-11-26T20:26:50.673Z,1353961610.672 [NAL9602](INFO): Stored copy of sent data in Logs/20121126T194014/shore0006.lzma.parts/0000.sbd
2012-11-26T20:27:06.617Z,1353961626.617 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:27:06.617Z,1353961626.617 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:27:24.144Z,1353961644.144 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:27:24.144Z,1353961644.144 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:27:39.725Z,1353961659.725 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:27:39.726Z,1353961659.726 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:27:54.144Z,1353961674.144 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:27:54.144Z,1353961674.144 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:28:03.265Z,1353961683.265 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:28:03.266Z,1353961683.266 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:28:10.797Z,1353961690.797 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:28:10.797Z,1353961690.797 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:29:21.108Z,1353961761.108 [NAL9602](ERROR): Verify xmit timeout failure.
2012-11-26T20:29:22.323Z,1353961762.323 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:24.723Z,1353961764.723 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:27.123Z,1353961767.123 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:29.528Z,1353961769.528 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:29.909Z,1353961769.909 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:29:29.910Z,1353961769.909 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:29:31.927Z,1353961771.927 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:34.323Z,1353961774.323 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:36.691Z,1353961776.691 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:39.087Z,1353961779.088 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:39.113Z,1353961779.113 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:29:39.113Z,1353961779.113 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:29:41.491Z,1353961781.491 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:44.215Z,1353961784.215 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:46.616Z,1353961786.616 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:47.801Z,1353961787.801 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:29:47.801Z,1353961787.801 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:29:49.011Z,1353961789.011 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:51.415Z,1353961791.415 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:53.727Z,1353961793.727 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:56.181Z,1353961796.181 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:29:56.202Z,1353961796.202 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:29:56.203Z,1353961796.203 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:29:58.526Z,1353961798.526 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:01.308Z,1353961801.308 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:03.256Z,1353961803.256 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:04.840Z,1353961804.840 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:30:04.840Z,1353961804.840 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:30:05.657Z,1353961805.657 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:08.458Z,1353961808.458 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:10.787Z,1353961810.787 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:13.187Z,1353961813.187 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:15.592Z,1353961815.592 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:17.987Z,1353961817.987 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:20.387Z,1353961820.387 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:22.787Z,1353961822.787 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:25.187Z,1353961825.187 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:27.587Z,1353961827.587 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:30.003Z,1353961830.003 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:32.387Z,1353961832.387 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:34.787Z,1353961834.787 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:37.187Z,1353961837.187 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:39.587Z,1353961839.587 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:30:42.049Z,1353961842.049 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-11-26T20:31:15.172Z,1353961875.172 [NAL9602](ERROR): Verify xmit timeout failure.
2012-11-26T20:31:17.629Z,1353961877.629 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:31:17.629Z,1353961877.629 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:31:26.292Z,1353961886.292 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:31:26.292Z,1353961886.292 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:31:35.025Z,1353961895.025 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:31:35.025Z,1353961895.025 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:31:51.748Z,1353961911.748 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:31:51.748Z,1353961911.748 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:31:57.701Z,1353961917.701 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:31:57.701Z,1353961917.701 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:06.377Z,1353961926.377 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:06.377Z,1353961926.377 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:14.701Z,1353961934.701 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:14.701Z,1353961934.701 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:23.485Z,1353961943.485 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:23.486Z,1353961943.486 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:32.140Z,1353961952.140 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:32.140Z,1353961952.140 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:40.881Z,1353961960.881 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:40.882Z,1353961960.882 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:49.217Z,1353961969.217 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:49.217Z,1353961969.217 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:32:57.997Z,1353961977.997 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:32:57.998Z,1353961977.997 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:06.747Z,1353961986.747 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:33:06.747Z,1353961986.747 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:15.048Z,1353961995.048 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:33:15.048Z,1353961995.048 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:23.825Z,1353962003.825 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:33:23.826Z,1353962003.826 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:32.554Z,1353962012.554 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:33:32.554Z,1353962012.554 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:41.277Z,1353962021.277 [NAL9602](INFO): SBD MO Status=2, MOMSN=5147, MT Status=2, MTMSN=0
2012-11-26T20:33:41.277Z,1353962021.277 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-11-26T20:33:54.797Z,1353962034.797 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=5147, MT Status=1, MTMSN=398
2012-11-26T20:33:55.351Z,1353962035.351 [NAL9602](INFO): Received command:Restart app
2012-11-26T20:33:55.355Z,1353962035.355 [CommandLine](IMPORTANT): got command restart application
2012-11-26T20:33:56.430Z,1353962036.430 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-11-26T20:33:56.431Z,1353962036.431 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-11-26T20:33:56.598Z,1353962036.598 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2012-11-26T20:33:56.791Z,1353962036.791 [WetLabsBB2FL](INFO): Powering down
2012-11-26T20:33:56.792Z,1353962036.792 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler
2012-11-26T20:33:56.987Z,1353962036.987 [Turbulence_NPS](INFO): Uninitialize Powering down
2012-11-26T20:33:56.998Z,1353962036.998 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-11-26T20:33:57.107Z,1353962037.107 [CTD_NeilBrown](INFO): Powering down
2012-11-26T20:33:57.110Z,1353962037.110 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2012-11-26T20:33:57.159Z,1353962037.159 [DVL_micro](INFO): uninitialize:Powering down
2012-11-26T20:33:57.171Z,1353962037.171 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-11-26T20:33:57.427Z,1353962037.427 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-11-26T20:33:57.435Z,1353962037.435 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2012-11-26T20:33:57.455Z,1353962037.455 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-11-26T20:33:57.457Z,1353962037.457 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-11-26T20:33:57.616Z,1353962037.616 [controlThread](DEBUG): Uninitializing ControlThread
2012-11-26T20:33:57.616Z,1353962037.616 [AHRS_sp3003D](INFO): Powering down
2012-11-26T20:33:57.703Z,1353962037.704 [NAL9602](INFO): Powering down
2012-11-26T20:33:57.705Z,1353962037.705 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-11-26T20:33:57.706Z,1353962037.706 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-11-26T20:33:57.707Z,1353962037.707 [Default] Stopped
2012-11-26T20:33:57.707Z,1353962037.707 [Default](INFO): Aggregate::uninitialize Default
2012-11-26T20:33:57.707Z,1353962037.707 [Default:Iridium] Stopped
2012-11-26T20:33:57.707Z,1353962037.707 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-11-26T20:33:57.707Z,1353962037.707 [Default:Iridium:A.SetSpeed] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:33:57.708Z,1353962037.708 [Default:Iridium:Read_Iridium] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:CallIridium] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-11-26T20:33:57.708Z,1353962037.708 [Default:CallIridium:B] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-11-26T20:33:57.708Z,1353962037.708 [Default:D.SetSpeed] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-11-26T20:33:57.708Z,1353962037.708 [Default:E.GoToSurface] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-11-26T20:33:57.708Z,1353962037.708 [Default:F.Wait] Stopped
2012-11-26T20:33:57.708Z,1353962037.708 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-11-26T20:33:57.713Z,1353962037.713 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-11-26T20:33:57.713Z,1353962037.713 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-11-26T20:33:57.713Z,1353962037.713 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-11-26T20:33:57.714Z,1353962037.714 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-11-26T20:33:57.714Z,1353962037.714 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-11-26T20:33:57.714Z,1353962037.714 [BuoyancyServo](INFO): Powering down
2012-11-26T20:33:57.726Z,1353962037.727 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-11-26T20:33:57.727Z,1353962037.727 [ElevatorServo](INFO): Powering down
2012-11-26T20:33:57.728Z,1353962037.727 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-11-26T20:33:57.728Z,1353962037.728 [MassServo](INFO): Powering down
2012-11-26T20:33:57.728Z,1353962037.728 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-11-26T20:33:57.729Z,1353962037.728 [RudderServo](INFO): Powering down
2012-11-26T20:33:57.729Z,1353962037.729 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-11-26T20:33:57.729Z,1353962037.729 [ThrusterServo](INFO): Powering down
2012-11-26T20:33:57.730Z,1353962037.730 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-11-26T20:33:57.731Z,1353962037.731 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-11-26T20:33:57.731Z,1353962037.731 [CBIT](DEBUG): Uninitialize CBIT Component.