2014-04-21T19:11:23.678Z,1398107483.678 [Supervisor](DEBUG): Initializing supervisor.
2014-04-21T19:11:23.682Z,1398107483.682 [SyncHandler](DEBUG): Created PCaller Thread at 4033C4E0
2014-04-21T19:11:23.682Z,1398107483.682 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-04-21T19:11:23.684Z,1398107483.684 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036C4E0
2014-04-21T19:11:23.687Z,1398107483.687 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-04-21T19:11:23.699Z,1398107483.699 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-04-21T19:11:23.704Z,1398107483.704 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039C4E0
2014-04-21T19:11:23.705Z,1398107483.705 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-04-21T19:11:23.708Z,1398107483.708 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CC4E0
2014-04-21T19:11:23.710Z,1398107483.710 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-04-21T19:11:23.710Z,1398107483.710 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-04-21T19:11:23.715Z,1398107483.715 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-04-21T19:11:24.102Z,1398107484.102 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-04-21T19:11:24.102Z,1398107484.102 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-04-21T19:11:24.390Z,1398107484.390 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-04-21T19:11:24.391Z,1398107484.391 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-04-21T19:11:24.488Z,1398107484.488 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-04-21T19:11:24.491Z,1398107484.491 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-04-21T19:11:24.698Z,1398107484.698 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-04-21T19:11:24.699Z,1398107484.699 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-04-21T19:11:24.874Z,1398107484.874 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-04-21T19:11:24.877Z,1398107484.877 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-04-21T19:11:25.203Z,1398107485.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-04-21T19:11:25.204Z,1398107485.204 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-04-21T19:11:25.403Z,1398107485.403 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-04-21T19:11:25.405Z,1398107485.405 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-04-21T19:11:25.776Z,1398107485.776 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-04-21T19:11:25.779Z,1398107485.779 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-04-21T19:11:25.904Z,1398107485.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-04-21T19:11:25.905Z,1398107485.905 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-04-21T19:11:27.470Z,1398107487.470 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-04-21T19:11:27.471Z,1398107487.471 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-04-21T19:11:28.276Z,1398107488.276 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-04-21T19:11:28.276Z,1398107488.276 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-04-21T19:11:28.375Z,1398107488.375 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-04-21T19:11:28.488Z,1398107488.488 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-04-21T19:11:28.490Z,1398107488.490 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-04-21T19:11:28.609Z,1398107488.609 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-04-21T19:11:28.610Z,1398107488.610 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-04-21T19:11:28.760Z,1398107488.760 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-04-21T19:11:28.762Z,1398107488.762 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-04-21T19:11:28.766Z,1398107488.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-04-21T19:11:28.885Z,1398107488.885 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-04-21T19:11:29.029Z,1398107489.029 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-04-21T19:11:29.138Z,1398107489.138 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-04-21T19:11:29.242Z,1398107489.242 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-04-21T19:11:29.414Z,1398107489.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-04-21T19:11:29.547Z,1398107489.547 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-04-21T19:11:29.642Z,1398107489.642 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-04-21T19:11:29.746Z,1398107489.746 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-04-21T19:11:29.848Z,1398107489.848 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-04-21T19:11:29.946Z,1398107489.946 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-04-21T19:11:30.036Z,1398107490.036 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-04-21T19:11:30.134Z,1398107490.134 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2014-04-21T19:11:30.137Z,1398107490.137 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-04-21T19:11:30.835Z,1398107490.835 [AHRS_sp3003D] Loaded
2014-04-21T19:11:30.836Z,1398107490.836 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-04-21T19:11:31.134Z,1398107491.134 [Batt_Ocean_Server] Loaded
2014-04-21T19:11:31.134Z,1398107491.134 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-04-21T19:11:31.148Z,1398107491.148 [Depth_Keller] Loaded
2014-04-21T19:11:31.148Z,1398107491.148 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-04-21T19:11:31.153Z,1398107491.153 [DropWeight] Loaded
2014-04-21T19:11:31.154Z,1398107491.154 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-04-21T19:11:31.296Z,1398107491.296 [DVL_micro] Loaded
2014-04-21T19:11:31.297Z,1398107491.297 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-04-21T19:11:31.399Z,1398107491.399 [NAL9602] Loaded
2014-04-21T19:11:31.400Z,1398107491.400 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-04-21T19:11:31.453Z,1398107491.453 [Onboard] Loaded
2014-04-21T19:11:31.453Z,1398107491.453 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-04-21T19:11:31.460Z,1398107491.460 [Radio_Freewave] Loaded
2014-04-21T19:11:31.461Z,1398107491.461 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2014-04-21T19:11:31.467Z,1398107491.467 [SCPI] Loaded
2014-04-21T19:11:31.468Z,1398107491.468 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-04-21T19:11:31.468Z,1398107491.468 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-04-21T19:11:31.469Z,1398107491.469 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-04-21T19:11:31.767Z,1398107491.767 [InternalSim] Loaded
2014-04-21T19:11:31.768Z,1398107491.768 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-04-21T19:11:31.768Z,1398107491.768 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-04-21T19:11:31.769Z,1398107491.769 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-04-21T19:11:32.063Z,1398107492.063 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-04-21T19:11:32.064Z,1398107492.064 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-04-21T19:11:32.073Z,1398107492.073 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-04-21T19:11:32.078Z,1398107492.078 [AsyncPiEstimator] Loaded
2014-04-21T19:11:32.078Z,1398107492.078 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-04-21T19:11:32.079Z,1398107492.079 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A24E0
2014-04-21T19:11:32.080Z,1398107492.080 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-04-21T19:11:32.081Z,1398107492.081 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-04-21T19:11:32.179Z,1398107492.179 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-04-21T19:11:32.179Z,1398107492.179 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-04-21T19:11:32.197Z,1398107492.197 [NavChart] Loaded
2014-04-21T19:11:32.197Z,1398107492.197 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-04-21T19:11:32.201Z,1398107492.201 [UniversalFixResidualReporter] Loaded
2014-04-21T19:11:32.202Z,1398107492.202 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-04-21T19:11:32.202Z,1398107492.202 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-04-21T19:11:32.203Z,1398107492.203 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-04-21T19:11:32.271Z,1398107492.271 [VerticalControl](DEBUG): Construct VerticalControl.
2014-04-21T19:11:32.384Z,1398107492.384 [VerticalControl] Loaded
2014-04-21T19:11:32.384Z,1398107492.384 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-04-21T19:11:32.385Z,1398107492.385 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-04-21T19:11:32.454Z,1398107492.454 [HorizontalControl] Loaded
2014-04-21T19:11:32.454Z,1398107492.454 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-04-21T19:11:32.455Z,1398107492.455 [SpeedControl](DEBUG): Construct SpeedControl.
2014-04-21T19:11:32.457Z,1398107492.457 [SpeedControl] Loaded
2014-04-21T19:11:32.457Z,1398107492.457 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-04-21T19:11:32.458Z,1398107492.458 [LoopControl](DEBUG): Construct LoopControl.
2014-04-21T19:11:32.458Z,1398107492.458 [LoopControl] Loaded
2014-04-21T19:11:32.459Z,1398107492.459 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-04-21T19:11:32.459Z,1398107492.459 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-04-21T19:11:32.460Z,1398107492.460 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-04-21T19:11:32.489Z,1398107492.489 [DepthRateCalculator] Loaded
2014-04-21T19:11:32.489Z,1398107492.489 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-04-21T19:11:32.495Z,1398107492.495 [PitchRateCalculator] Loaded
2014-04-21T19:11:32.495Z,1398107492.495 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-04-21T19:11:32.503Z,1398107492.503 [SpeedCalculator] Loaded
2014-04-21T19:11:32.503Z,1398107492.503 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-04-21T19:11:32.520Z,1398107492.520 [TempGradientCalculator] Loaded
2014-04-21T19:11:32.520Z,1398107492.520 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-04-21T19:11:32.525Z,1398107492.525 [YawRateCalculator] Loaded
2014-04-21T19:11:32.526Z,1398107492.526 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-04-21T19:11:32.526Z,1398107492.526 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-04-21T19:11:32.527Z,1398107492.527 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-04-21T19:11:32.656Z,1398107492.656 [CTD_NeilBrown] Loaded
2014-04-21T19:11:32.657Z,1398107492.657 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-04-21T19:11:32.658Z,1398107492.658 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407444E0
2014-04-21T19:11:32.671Z,1398107492.671 [ISUS] Loaded
2014-04-21T19:11:32.671Z,1398107492.671 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-04-21T19:11:32.686Z,1398107492.686 [PAR_Licor] Loaded
2014-04-21T19:11:32.687Z,1398107492.687 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-04-21T19:11:32.724Z,1398107492.724 [WetLabsBB2FL] Loaded
2014-04-21T19:11:32.724Z,1398107492.724 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-04-21T19:11:32.725Z,1398107492.725 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407744E0
2014-04-21T19:11:32.726Z,1398107492.726 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-04-21T19:11:32.728Z,1398107492.728 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-04-21T19:11:32.848Z,1398107492.848 [SBIT](DEBUG): Construct Startup Built In Test.
2014-04-21T19:11:32.859Z,1398107492.859 [SBIT] Loaded
2014-04-21T19:11:32.860Z,1398107492.860 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-04-21T19:11:32.860Z,1398107492.860 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-04-21T19:11:32.873Z,1398107492.873 [IBIT] Loaded
2014-04-21T19:11:32.873Z,1398107492.873 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-04-21T19:11:32.875Z,1398107492.875 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-04-21T19:11:32.946Z,1398107492.946 [CBIT] Loaded
2014-04-21T19:11:32.947Z,1398107492.947 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-04-21T19:11:32.947Z,1398107492.947 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-04-21T19:11:32.949Z,1398107492.949 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-04-21T19:11:33.019Z,1398107493.019 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-04-21T19:11:33.020Z,1398107493.020 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-04-21T19:11:33.145Z,1398107493.145 [BuoyancyServo] Loaded
2014-04-21T19:11:33.145Z,1398107493.145 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-04-21T19:11:33.158Z,1398107493.158 [ElevatorServo] Loaded
2014-04-21T19:11:33.158Z,1398107493.158 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-04-21T19:11:33.170Z,1398107493.170 [MassServo] Loaded
2014-04-21T19:11:33.170Z,1398107493.170 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-04-21T19:11:33.182Z,1398107493.182 [RudderServo] Loaded
2014-04-21T19:11:33.183Z,1398107493.183 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-04-21T19:11:33.194Z,1398107493.194 [ThrusterServo] Loaded
2014-04-21T19:11:33.194Z,1398107493.194 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-04-21T19:11:33.195Z,1398107493.195 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-04-21T19:11:33.195Z,1398107493.195 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-04-21T19:11:33.235Z,1398107493.235 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-04-21T19:11:33.237Z,1398107493.237 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-04-21T19:11:33.238Z,1398107493.238 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-04-21T19:11:33.244Z,1398107493.244 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-04-21T19:11:33.245Z,1398107493.245 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408424E0
2014-04-21T19:11:33.250Z,1398107493.250 [Supervisor](DEBUG): Running supervisor.
2014-04-21T19:11:33.251Z,1398107493.251 [CommandLine](INFO): Thread ID is 773
2014-04-21T19:11:33.254Z,1398107493.254 [controlThread](INFO): Thread ID is 772
2014-04-21T19:11:33.254Z,1398107493.254 [controlThread](DEBUG): Initializing ControlThread
2014-04-21T19:11:33.255Z,1398107493.255 [CycleStarter](INFO): Thread ID is 771
2014-04-21T19:11:33.258Z,1398107493.258 [logger](INFO): Thread ID is 774
2014-04-21T19:11:33.284Z,1398107493.284 [AsyncPiEstimator](INFO): Thread ID is 856
2014-04-21T19:11:33.284Z,1398107493.284 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-04-21T19:11:33.307Z,1398107493.307 [CTD_NeilBrown](INFO): Thread ID is 857
2014-04-21T19:11:33.308Z,1398107493.308 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-04-21T19:11:33.311Z,1398107493.311 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-04-21T19:11:33.317Z,1398107493.317 [WetLabsBB2FL](INFO): Thread ID is 858
2014-04-21T19:11:33.319Z,1398107493.319 [WetLabsBB2FL](INFO): Powering down
2014-04-21T19:11:33.347Z,1398107493.347 [NavChartDb](INFO): Thread ID is 859
2014-04-21T19:11:33.356Z,1398107493.356 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-04-21T19:11:33.359Z,1398107493.359 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-04-21T19:11:33.359Z,1398107493.359 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-04-21T19:11:33.360Z,1398107493.360 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-04-21T19:11:33.360Z,1398107493.360 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-04-21T19:11:33.360Z,1398107493.360 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-04-21T19:11:33.360Z,1398107493.360 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-04-21T19:11:33.361Z,1398107493.361 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-04-21T19:11:33.361Z,1398107493.361 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-04-21T19:11:35.341Z,1398107495.341 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-04-21T19:11:35.373Z,1398107495.373 [InternalSim](DEBUG):  InternalSim initializing...
2014-04-21T19:11:35.674Z,1398107495.674 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-21T19:11:35.675Z,1398107495.675 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-04-21T19:11:35.675Z,1398107495.675 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-21T19:11:35.676Z,1398107495.676 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-04-21T19:11:35.677Z,1398107495.677 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-04-21T19:11:35.678Z,1398107495.678 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-04-21T19:11:35.679Z,1398107495.679 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-04-21T19:11:35.679Z,1398107495.679 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-04-21T19:11:35.679Z,1398107495.679 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-04-21T19:11:35.680Z,1398107495.680 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-04-21T19:11:35.680Z,1398107495.680 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-04-21T19:11:35.681Z,1398107495.681 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-04-21T19:11:35.694Z,1398107495.694 [SBIT](INFO): Initialize SBIT Component.
2014-04-21T19:11:35.695Z,1398107495.695 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11231
2014-04-21T19:11:35.695Z,1398107495.695 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-04-21T19:11:35.696Z,1398107495.696 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-04-21T19:11:35.696Z,1398107495.696 [IBIT](INFO): Initialize IBIT Component.
2014-04-21T19:11:35.697Z,1398107495.697 [CBIT](DEBUG): Initialize CBIT Component.
2014-04-21T19:11:35.697Z,1398107495.697 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2014-04-21T19:11:35.697Z,1398107495.697 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2014-04-21T19:11:35.724Z,1398107495.724 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-04-21T19:11:35.759Z,1398107495.759 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-21T19:11:35.768Z,1398107495.768 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2014-04-21T19:11:35.769Z,1398107495.769 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-04-21T19:11:35.845Z,1398107495.845 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-04-21T19:11:35.863Z,1398107495.863 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-04-21T19:11:35.867Z,1398107495.867 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-21T19:11:35.895Z,1398107495.895 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-04-21T19:11:35.898Z,1398107495.898 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-21T19:11:35.921Z,1398107495.921 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-04-21T19:11:35.963Z,1398107495.963 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-04-21T19:11:35.966Z,1398107495.966 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-21T19:11:35.989Z,1398107495.989 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS">

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

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

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

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

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium">

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2014-04-21T19:11:35.995Z,1398107495.995 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,Radio_Freewave,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-04-21T19:11:36.079Z,1398107496.079 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-04-21T19:11:36.252Z,1398107496.252 [DVL_micro](INFO): Initializing
2014-04-21T19:11:36.439Z,1398107496.439 [Radio_Freewave](INFO): Powering up
2014-04-21T19:11:36.849Z,1398107496.849 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-04-21T19:11:36.856Z,1398107496.856 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-04-21T19:11:36.889Z,1398107496.889 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-04-21T19:11:36.897Z,1398107496.897 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-04-21T19:11:36.924Z,1398107496.924 [MassServo](DEBUG): Initializing EZServoServo.
2014-04-21T19:11:36.932Z,1398107496.932 [MassServo](DEBUG): Initializing MassServo.
2014-04-21T19:11:36.957Z,1398107496.957 [RudderServo](DEBUG): Initializing EZServoServo.
2014-04-21T19:11:36.964Z,1398107496.964 [RudderServo](DEBUG): Initializing RudderServo.
2014-04-21T19:11:36.970Z,1398107496.970 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-04-21T19:11:36.976Z,1398107496.976 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-04-21T19:11:37.004Z,1398107497.004 [CommandLine](FAULT): Scheduling is paused
2014-04-21T19:11:37.179Z,1398107497.179 [NAL9602](INFO): Powering up NAL9602
2014-04-21T19:11:37.803Z,1398107497.803 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-04-21T19:11:48.222Z,1398107508.222 [NAL9602](INFO): NAL9602 initialized
2014-04-21T19:11:51.677Z,1398107511.677 [SBIT](IMPORTANT): Beginning Startup BIT
2014-04-21T19:11:51.680Z,1398107511.680 [CBIT](IMPORTANT): Beginning GF scan
2014-04-21T19:12:17.967Z,1398107537.967 [NAL9602](INFO): SBD MO Status=2, MOMSN=28221, MT Status=2, MTMSN=0
2014-04-21T19:12:17.967Z,1398107537.967 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2014-04-21T19:12:18.740Z,1398107538.740 [CBIT](FAULT): Chan 1 High side GF detected
mA:
CHAN 5 (24V): 0.096417
CHAN 4 (Batt): 0.055861
CHAN 2 (12V): 0.042565
CHAN 1 (5V): 0.017504
CHAN 0 (3.3V): 0.011861
OPEN: 0.000574
Full Scale Calc: 0.392
2014-04-21T19:12:22.731Z,1398107542.731 [DVL_micro](ERROR): NQ1 string checksum mismatch. Reported:75 Calculated:84
2014-04-21T19:12:22.735Z,1398107542.735 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 2.2 2.3 2.4 2.3 -68.1 271.0 19. 0 0 0 0 0 0 0 -117.2 334.5 65.5 1 -243.8 262.4 40.8 1 0 0 0 0 0 0 0 0 -2.42 -5.02 23.0 2.2 19.8 0.005 35.0 1489 75
2014-04-21T19:12:27.002Z,1398107547.002 [NAL9602](INFO): SBD MO Status=0, MOMSN=28221, MT Status=0, MTMSN=0
2014-04-21T19:12:27.003Z,1398107547.003 [NAL9602](INFO): No messages in MT queue
2014-04-21T19:12:28.485Z,1398107548.485 [NAL9602](IMPORTANT): GPS fix at: 1398107523.00
2014-04-21T19:12:36.066Z,1398107556.066 [NAL9602](INFO): Powering down
2014-04-21T19:12:45.765Z,1398107565.765 [SBIT](IMPORTANT): SBIT PASSED
2014-04-21T19:12:46.228Z,1398107566.228 [MissionManager](IMPORTANT): Started mission Startup
2014-04-21T19:12:46.229Z,1398107566.229 [Startup] Running Loop=1
2014-04-21T19:12:46.229Z,1398107566.229 [Startup](INFO): Aggregate::initialize Startup
2014-04-21T19:12:46.229Z,1398107566.229 [Startup:A.GoToSurface] Running Loop=1
2014-04-21T19:12:46.229Z,1398107566.229 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:12:46.239Z,1398107566.239 [Startup:StartupSatComms] Running Loop=1
2014-04-21T19:12:46.239Z,1398107566.239 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-04-21T19:12:46.239Z,1398107566.239 [Startup:StartupSatComms:A] Running Loop=1
2014-04-21T19:12:46.672Z,1398107566.672 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-21T19:12:47.088Z,1398107567.088 [NAL9602](INFO): Powering up
2014-04-21T19:12:57.910Z,1398107577.910 [NAL9602](INFO): NAL9602 initialized
2014-04-21T19:13:14.267Z,1398107594.267 [NAL9602](INFO): SBD MO Status=0, MOMSN=28222, MT Status=0, MTMSN=0
2014-04-21T19:13:14.267Z,1398107594.267 [NAL9602](INFO): No messages in MT queue
2014-04-21T19:13:21.615Z,1398107601.615 [NAL9602](IMPORTANT): GPS fix at: 1398107577.00
2014-04-21T19:13:21.668Z,1398107601.668 [Startup:StartupSatComms:A] Stopped
2014-04-21T19:13:21.668Z,1398107601.668 [Startup:StartupSatComms:B] Running Loop=1
2014-04-21T19:13:22.097Z,1398107602.097 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-21T19:13:44.344Z,1398107624.344 [NAL9602](INFO): SBD MO Status=1, MOMSN=28223, MT Status=0, MTMSN=0
2014-04-21T19:13:44.394Z,1398107624.394 [NAL9602](INFO): Sent 77 bytes from file Logs/20140421T175838/Courier0036.lzma
2014-04-21T19:13:44.394Z,1398107624.394 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:13:44.396Z,1398107624.396 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0036.lzma.parts/0000.sbd
2014-04-21T19:13:44.396Z,1398107624.396 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0036.lzma
2014-04-21T19:13:51.933Z,1398107631.933 [NAL9602](INFO): SBD MO Status=1, MOMSN=28224, MT Status=0, MTMSN=0
2014-04-21T19:13:51.982Z,1398107631.982 [NAL9602](INFO): Sent 25 bytes from file Logs/20140421T175838/Courier0040.lzma
2014-04-21T19:13:51.982Z,1398107631.982 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:13:51.984Z,1398107631.984 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Courier0040.lzma.parts/0000.sbd
2014-04-21T19:13:51.984Z,1398107631.984 [NAL9602](INFO): Completed sending Logs/20140421T175838/Courier0040.lzma
2014-04-21T19:14:01.127Z,1398107641.127 [NAL9602](INFO): SBD MO Status=1, MOMSN=28225, MT Status=0, MTMSN=0
2014-04-21T19:14:01.176Z,1398107641.176 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T191123/Courier0000.lzma
2014-04-21T19:14:01.176Z,1398107641.176 [NAL9602](INFO): Packets left to send: 1
2014-04-21T19:14:01.178Z,1398107641.178 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Courier0000.lzma.parts/0001.sbd
2014-04-21T19:14:11.203Z,1398107651.203 [NAL9602](INFO): SBD MO Status=1, MOMSN=28226, MT Status=0, MTMSN=0
2014-04-21T19:14:11.264Z,1398107651.264 [NAL9602](INFO): Sent 26 bytes from file Logs/20140421T191123/Courier0000.lzma
2014-04-21T19:14:11.264Z,1398107651.264 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:14:11.265Z,1398107651.265 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Courier0000.lzma.parts/0000.sbd
2014-04-21T19:14:11.265Z,1398107651.265 [NAL9602](INFO): Completed sending Logs/20140421T191123/Courier0000.lzma
2014-04-21T19:14:19.346Z,1398107659.346 [NAL9602](INFO): SBD MO Status=1, MOMSN=28227, MT Status=0, MTMSN=0
2014-04-21T19:14:19.396Z,1398107659.396 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T175838/Express0037.lzma
2014-04-21T19:14:19.397Z,1398107659.397 [NAL9602](INFO): Packets left to send: 1
2014-04-21T19:14:19.398Z,1398107659.398 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0037.lzma.parts/0001.sbd
2014-04-21T19:14:22.747Z,1398107662.747 [Startup:StartupSatComms:B](INFO): Timed out from 2014-04-21T19:13:21.7Z
2014-04-21T19:14:22.747Z,1398107662.747 [Startup:StartupSatComms:B] Stopped
2014-04-21T19:14:22.747Z,1398107662.747 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-04-21T19:14:22.747Z,1398107662.747 [Startup:StartupSatComms] Stopped
2014-04-21T19:14:22.747Z,1398107662.747 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-04-21T19:14:22.748Z,1398107662.748 [Startup](INFO): Completed Startup
2014-04-21T19:14:22.748Z,1398107662.748 [Startup] Stopped
2014-04-21T19:14:22.749Z,1398107662.749 [Startup](INFO): Aggregate::uninitialize Startup
2014-04-21T19:14:22.749Z,1398107662.749 [Startup:A.GoToSurface] Stopped
2014-04-21T19:14:22.749Z,1398107662.749 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T19:14:23.229Z,1398107663.229 [MissionManager](IMPORTANT): Started mission Default
2014-04-21T19:14:23.229Z,1398107663.229 [Default] Running Loop=1
2014-04-21T19:14:23.229Z,1398107663.229 [Default](INFO): Aggregate::initialize Default
2014-04-21T19:14:23.229Z,1398107663.229 [Default:Iridium] Running Loop=1
2014-04-21T19:14:23.229Z,1398107663.229 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-21T19:14:23.230Z,1398107663.230 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T19:14:23.230Z,1398107663.230 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-21T19:14:23.230Z,1398107663.230 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-21T19:14:23.230Z,1398107663.230 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:14:23.231Z,1398107663.231 [Default:CallIridium] Running Loop=1
2014-04-21T19:14:23.231Z,1398107663.231 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-21T19:14:23.231Z,1398107663.231 [Default:CallIridium:A] Running Loop=1
2014-04-21T19:14:23.233Z,1398107663.233 [Default:CallIridium:A] Stopped
2014-04-21T19:14:23.233Z,1398107663.233 [Default:CallIridium:B] Running Loop=1
2014-04-21T19:14:23.233Z,1398107663.233 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-21T19:14:23.264Z,1398107663.264 [Default:Iridium:B.GoToSurface] Stopped
2014-04-21T19:14:23.264Z,1398107663.264 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T19:14:23.264Z,1398107663.264 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-21T19:14:23.264Z,1398107663.264 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-21T19:14:23.270Z,1398107663.270 [Default:GPS] Running Loop=1
2014-04-21T19:14:23.282Z,1398107663.282 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-21T19:14:23.282Z,1398107663.282 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T19:14:23.282Z,1398107663.282 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-21T19:14:23.282Z,1398107663.282 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-21T19:14:23.282Z,1398107663.282 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:14:23.292Z,1398107663.292 [Default:GPS:B.GoToSurface] Stopped
2014-04-21T19:14:23.292Z,1398107663.292 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-21T19:14:23.292Z,1398107663.292 [Default:GPS:Read_GPS] Running Loop=1
2014-04-21T19:14:23.292Z,1398107663.292 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-21T19:14:23.757Z,1398107663.757 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-21T19:14:23.760Z,1398107663.760 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-21T19:14:25.687Z,1398107665.687 [NAL9602](INFO): SBD MO Status=1, MOMSN=28228, MT Status=0, MTMSN=0
2014-04-21T19:14:25.747Z,1398107665.747 [NAL9602](INFO): Sent 35 bytes from file Logs/20140421T175838/Express0037.lzma
2014-04-21T19:14:25.747Z,1398107665.747 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:14:25.748Z,1398107665.748 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0037.lzma.parts/0000.sbd
2014-04-21T19:14:25.749Z,1398107665.749 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0037.lzma
2014-04-21T19:14:32.729Z,1398107672.729 [NAL9602](INFO): SBD MO Status=1, MOMSN=28229, MT Status=0, MTMSN=0
2014-04-21T19:14:32.777Z,1398107672.777 [NAL9602](INFO): Sent 45 bytes from file Logs/20140421T191123/Courier0004.lzma
2014-04-21T19:14:32.777Z,1398107672.777 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:14:32.779Z,1398107672.779 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Courier0004.lzma.parts/0000.sbd
2014-04-21T19:14:32.779Z,1398107672.779 [NAL9602](INFO): Completed sending Logs/20140421T191123/Courier0004.lzma
2014-04-21T19:14:43.342Z,1398107683.342 [NAL9602](INFO): SBD MO Status=1, MOMSN=28230, MT Status=0, MTMSN=0
2014-04-21T19:14:43.402Z,1398107683.402 [NAL9602](INFO): Sent 25 bytes from file Logs/20140421T175838/Express0041.lzma
2014-04-21T19:14:43.402Z,1398107683.402 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:14:43.403Z,1398107683.403 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T175838/Express0041.lzma.parts/0000.sbd
2014-04-21T19:14:43.404Z,1398107683.404 [NAL9602](INFO): Completed sending Logs/20140421T175838/Express0041.lzma
2014-04-21T19:14:51.451Z,1398107691.451 [NAL9602](INFO): SBD MO Status=1, MOMSN=28231, MT Status=0, MTMSN=0
2014-04-21T19:14:51.502Z,1398107691.502 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T191123/Express0001.lzma
2014-04-21T19:14:51.502Z,1398107691.502 [NAL9602](INFO): Packets left to send: 2
2014-04-21T19:14:51.504Z,1398107691.504 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Express0001.lzma.parts/0002.sbd
2014-04-21T19:15:01.950Z,1398107701.950 [NAL9602](INFO): SBD MO Status=1, MOMSN=28232, MT Status=0, MTMSN=0
2014-04-21T19:15:02.003Z,1398107702.003 [NAL9602](INFO): Sent 332 bytes from file Logs/20140421T191123/Express0001.lzma
2014-04-21T19:15:02.003Z,1398107702.003 [NAL9602](INFO): Packets left to send: 1
2014-04-21T19:15:02.004Z,1398107702.004 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Express0001.lzma.parts/0001.sbd
2014-04-21T19:15:18.654Z,1398107718.654 [NAL9602](INFO): SBD MO Status=1, MOMSN=28233, MT Status=0, MTMSN=0
2014-04-21T19:15:18.704Z,1398107718.704 [NAL9602](INFO): Sent 236 bytes from file Logs/20140421T191123/Express0001.lzma
2014-04-21T19:15:18.705Z,1398107718.705 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:15:18.706Z,1398107718.706 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Express0001.lzma.parts/0000.sbd
2014-04-21T19:15:18.707Z,1398107718.707 [NAL9602](INFO): Completed sending Logs/20140421T191123/Express0001.lzma
2014-04-21T19:15:25.855Z,1398107725.855 [NAL9602](INFO): SBD MO Status=1, MOMSN=28234, MT Status=0, MTMSN=0
2014-04-21T19:15:25.908Z,1398107725.908 [NAL9602](INFO): Sent 103 bytes from file Logs/20140421T191123/Express0005.lzma
2014-04-21T19:15:25.909Z,1398107725.909 [NAL9602](INFO): Packets left to send: 0
2014-04-21T19:15:25.910Z,1398107725.910 [NAL9602](INFO): Stored copy of sent data in Logs/20140421T191123/Express0005.lzma.parts/0000.sbd
2014-04-21T19:15:25.910Z,1398107725.910 [NAL9602](INFO): Completed sending Logs/20140421T191123/Express0005.lzma
2014-04-21T19:15:37.729Z,1398107737.729 [NAL9602](INFO): SBD MO Status=0, MOMSN=28235, MT Status=0, MTMSN=0
2014-04-21T19:15:37.819Z,1398107737.819 [Default:Iridium:Read_Iridium] Stopped
2014-04-21T19:15:37.819Z,1398107737.819 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-21T19:15:37.819Z,1398107737.819 [Default:Iridium] Stopped
2014-04-21T19:15:37.819Z,1398107737.819 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-21T19:15:37.820Z,1398107737.820 [Default:Iridium:A.SetSpeed] Stopped
2014-04-21T19:15:37.820Z,1398107737.820 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface] Running Loop=1
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-21T19:15:37.820Z,1398107737.820 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-21T19:15:38.241Z,1398107738.241 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-21T19:15:38.248Z,1398107738.248 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-21T19:15:38.253Z,1398107738.253 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-21T19:15:38.253Z,1398107738.253 [Default:CallIridium:B] Stopped
2014-04-21T19:15:38.253Z,1398107738.253 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-21T19:15:38.253Z,1398107738.253 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-21T19:15:38.254Z,1398107738.254 [Default:CallIridium] Stopped
2014-04-21T19:15:38.254Z,1398107738.254 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-21T19:15:39.107Z,1398107739.107 [NAL9602](IMPORTANT): GPS fix at: 1398107714.00
2014-04-21T19:15:39.155Z,1398107739.155 [Default:GPS:Read_GPS] Stopped
2014-04-21T19:15:39.155Z,1398107739.155 [Default:GPS:D] Running Loop=1
2014-04-21T19:15:39.612Z,1398107739.612 [Default:GPS:D] Stopped
2014-04-21T19:15:39.612Z,1398107739.612 [Default:GPS](INFO): Completed Default:GPS
2014-04-21T19:15:39.612Z,1398107739.612 [Default:GPS] Stopped
2014-04-21T19:15:39.612Z,1398107739.612 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-21T19:15:39.613Z,1398107739.613 [Default:GPS:A.SetSpeed] Stopped
2014-04-21T19:15:39.613Z,1398107739.613 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-21T19:15:50.186Z,1398107750.186 [Depth_Keller](ERROR): Pressure reading out of range: 1830.877441 decibar
2014-04-21T19:16:00.203Z,1398107760.203 [NAL9602](INFO): Powering down
2014-04-21T19:16:10.220Z,1398107770.220 [Radio_Freewave](INFO): Powering down