2014-04-28T22:18:21.574Z,1398723501.574 [Supervisor](DEBUG): Initializing supervisor.
2014-04-28T22:18:21.578Z,1398723501.578 [SyncHandler](DEBUG): Created PCaller Thread at 4033C4E0
2014-04-28T22:18:21.578Z,1398723501.578 [SyncHandler](INFO): Protected caller Thread ID is 777
2014-04-28T22:18:21.579Z,1398723501.579 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-04-28T22:18:21.581Z,1398723501.581 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036C4E0
2014-04-28T22:18:21.582Z,1398723501.582 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 778
2014-04-28T22:18:21.585Z,1398723501.585 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-04-28T22:18:21.596Z,1398723501.596 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-04-28T22:18:21.602Z,1398723501.602 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039C4E0
2014-04-28T22:18:21.602Z,1398723501.602 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 779
2014-04-28T22:18:21.603Z,1398723501.603 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-04-28T22:18:21.606Z,1398723501.606 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CC4E0
2014-04-28T22:18:21.606Z,1398723501.606 [logger ThreadHandler](INFO): Protected caller Thread ID is 780
2014-04-28T22:18:21.608Z,1398723501.608 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-04-28T22:18:21.609Z,1398723501.609 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-04-28T22:18:21.613Z,1398723501.613 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-04-28T22:18:22.027Z,1398723502.027 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-04-28T22:18:22.028Z,1398723502.028 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-04-28T22:18:22.340Z,1398723502.340 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-04-28T22:18:22.341Z,1398723502.341 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-04-28T22:18:22.438Z,1398723502.438 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-04-28T22:18:22.439Z,1398723502.439 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-04-28T22:18:22.668Z,1398723502.668 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-04-28T22:18:22.669Z,1398723502.669 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-04-28T22:18:22.856Z,1398723502.856 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-04-28T22:18:22.858Z,1398723502.858 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-04-28T22:18:23.209Z,1398723503.209 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-04-28T22:18:23.210Z,1398723503.210 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-04-28T22:18:23.413Z,1398723503.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-04-28T22:18:23.415Z,1398723503.415 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-04-28T22:18:23.812Z,1398723503.812 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-04-28T22:18:23.815Z,1398723503.815 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-04-28T22:18:23.942Z,1398723503.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-04-28T22:18:23.944Z,1398723503.944 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-04-28T22:18:24.541Z,1398723504.541 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-04-28T22:18:24.542Z,1398723504.542 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-04-28T22:18:24.666Z,1398723504.666 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-04-28T22:18:24.739Z,1398723504.739 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-04-28T22:18:24.852Z,1398723504.852 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-04-28T22:18:24.977Z,1398723504.977 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-04-28T22:18:24.978Z,1398723504.978 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-04-28T22:18:25.092Z,1398723505.092 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-04-28T22:18:25.093Z,1398723505.093 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-04-28T22:18:25.248Z,1398723505.248 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-04-28T22:18:25.250Z,1398723505.250 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-04-28T22:18:25.254Z,1398723505.254 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-04-28T22:18:25.375Z,1398723505.375 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-04-28T22:18:25.526Z,1398723505.526 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-04-28T22:18:25.633Z,1398723505.633 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-04-28T22:18:25.739Z,1398723505.739 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-04-28T22:18:25.918Z,1398723505.918 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-04-28T22:18:26.054Z,1398723506.054 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-04-28T22:18:26.152Z,1398723506.152 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-04-28T22:18:26.270Z,1398723506.270 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-04-28T22:18:26.382Z,1398723506.382 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-04-28T22:18:26.490Z,1398723506.490 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-04-28T22:18:26.590Z,1398723506.590 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-04-28T22:18:26.703Z,1398723506.703 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2014-04-28T22:18:26.706Z,1398723506.706 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-04-28T22:18:27.314Z,1398723507.314 [AHRS_sp3003D] Loaded
2014-04-28T22:18:27.314Z,1398723507.314 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-04-28T22:18:27.645Z,1398723507.645 [Batt_Ocean_Server] Loaded
2014-04-28T22:18:27.645Z,1398723507.645 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-04-28T22:18:27.844Z,1398723507.844 [DataOverHttps] Loaded
2014-04-28T22:18:27.844Z,1398723507.844 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2014-04-28T22:18:27.858Z,1398723507.858 [Depth_Keller] Loaded
2014-04-28T22:18:27.859Z,1398723507.859 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-04-28T22:18:27.864Z,1398723507.864 [DropWeight] Loaded
2014-04-28T22:18:27.864Z,1398723507.864 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-04-28T22:18:28.021Z,1398723508.021 [DVL_micro] Loaded
2014-04-28T22:18:28.021Z,1398723508.021 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-04-28T22:18:28.135Z,1398723508.135 [NAL9602] Loaded
2014-04-28T22:18:28.135Z,1398723508.135 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-04-28T22:18:28.191Z,1398723508.191 [Onboard] Loaded
2014-04-28T22:18:28.191Z,1398723508.191 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-04-28T22:18:28.203Z,1398723508.203 [Radio_Freewave] Loaded
2014-04-28T22:18:28.203Z,1398723508.203 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2014-04-28T22:18:28.210Z,1398723508.210 [SCPI] Loaded
2014-04-28T22:18:28.210Z,1398723508.210 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-04-28T22:18:28.211Z,1398723508.211 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-04-28T22:18:28.211Z,1398723508.211 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-04-28T22:18:28.537Z,1398723508.537 [ExternalSim] Loaded
2014-04-28T22:18:28.537Z,1398723508.537 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2014-04-28T22:18:28.596Z,1398723508.596 [InternalSim] Loaded
2014-04-28T22:18:28.596Z,1398723508.596 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-04-28T22:18:28.596Z,1398723508.596 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-04-28T22:18:28.597Z,1398723508.597 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-04-28T22:18:28.900Z,1398723508.900 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-04-28T22:18:28.900Z,1398723508.900 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-04-28T22:18:28.911Z,1398723508.911 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2014-04-28T22:18:28.916Z,1398723508.916 [AsyncPiEstimator] Loaded
2014-04-28T22:18:28.916Z,1398723508.916 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2014-04-28T22:18:28.921Z,1398723508.921 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A24E0
2014-04-28T22:18:28.921Z,1398723508.921 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 862
2014-04-28T22:18:28.922Z,1398723508.922 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-04-28T22:18:28.923Z,1398723508.923 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-04-28T22:18:29.027Z,1398723509.027 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-04-28T22:18:29.028Z,1398723509.028 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-04-28T22:18:29.049Z,1398723509.049 [NavChart] Loaded
2014-04-28T22:18:29.049Z,1398723509.049 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-04-28T22:18:29.053Z,1398723509.053 [UniversalFixResidualReporter] Loaded
2014-04-28T22:18:29.053Z,1398723509.053 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-04-28T22:18:29.054Z,1398723509.054 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-04-28T22:18:29.056Z,1398723509.056 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-04-28T22:18:29.130Z,1398723509.130 [VerticalControl](DEBUG): Construct VerticalControl.
2014-04-28T22:18:29.251Z,1398723509.251 [VerticalControl] Loaded
2014-04-28T22:18:29.251Z,1398723509.251 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-04-28T22:18:29.252Z,1398723509.252 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-04-28T22:18:29.328Z,1398723509.328 [HorizontalControl] Loaded
2014-04-28T22:18:29.329Z,1398723509.329 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-04-28T22:18:29.329Z,1398723509.329 [SpeedControl](DEBUG): Construct SpeedControl.
2014-04-28T22:18:29.331Z,1398723509.331 [SpeedControl] Loaded
2014-04-28T22:18:29.332Z,1398723509.332 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-04-28T22:18:29.332Z,1398723509.332 [LoopControl](DEBUG): Construct LoopControl.
2014-04-28T22:18:29.333Z,1398723509.333 [LoopControl] Loaded
2014-04-28T22:18:29.333Z,1398723509.333 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-04-28T22:18:29.334Z,1398723509.334 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-04-28T22:18:29.334Z,1398723509.334 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-04-28T22:18:29.371Z,1398723509.371 [DepthRateCalculator] Loaded
2014-04-28T22:18:29.371Z,1398723509.371 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-04-28T22:18:29.376Z,1398723509.376 [PitchRateCalculator] Loaded
2014-04-28T22:18:29.377Z,1398723509.377 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-04-28T22:18:29.385Z,1398723509.385 [SpeedCalculator] Loaded
2014-04-28T22:18:29.385Z,1398723509.385 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-04-28T22:18:29.402Z,1398723509.402 [TempGradientCalculator] Loaded
2014-04-28T22:18:29.402Z,1398723509.402 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-04-28T22:18:29.408Z,1398723509.408 [YawRateCalculator] Loaded
2014-04-28T22:18:29.408Z,1398723509.408 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-04-28T22:18:29.408Z,1398723509.408 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-04-28T22:18:29.409Z,1398723509.409 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-04-28T22:18:29.550Z,1398723509.550 [CTD_NeilBrown] Loaded
2014-04-28T22:18:29.550Z,1398723509.550 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-04-28T22:18:29.554Z,1398723509.554 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407444E0
2014-04-28T22:18:29.554Z,1398723509.554 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 863
2014-04-28T22:18:29.567Z,1398723509.567 [ISUS] Loaded
2014-04-28T22:18:29.568Z,1398723509.568 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-04-28T22:18:29.587Z,1398723509.587 [PAR_Licor] Loaded
2014-04-28T22:18:29.587Z,1398723509.587 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-04-28T22:18:29.627Z,1398723509.627 [WetLabsBB2FL] Loaded
2014-04-28T22:18:29.628Z,1398723509.628 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-04-28T22:18:29.630Z,1398723509.630 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407744E0
2014-04-28T22:18:29.630Z,1398723509.630 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 864
2014-04-28T22:18:29.631Z,1398723509.631 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-04-28T22:18:29.633Z,1398723509.633 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-04-28T22:18:29.888Z,1398723509.888 [SBIT](DEBUG): Construct Startup Built In Test.
2014-04-28T22:18:29.904Z,1398723509.904 [SBIT] Loaded
2014-04-28T22:18:29.904Z,1398723509.904 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-04-28T22:18:29.905Z,1398723509.905 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-04-28T22:18:29.919Z,1398723509.919 [IBIT] Loaded
2014-04-28T22:18:29.919Z,1398723509.919 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-04-28T22:18:29.921Z,1398723509.921 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-04-28T22:18:30.004Z,1398723510.004 [CBIT] Loaded
2014-04-28T22:18:30.005Z,1398723510.005 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-04-28T22:18:30.005Z,1398723510.005 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-04-28T22:18:30.006Z,1398723510.006 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-04-28T22:18:30.102Z,1398723510.102 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-04-28T22:18:30.103Z,1398723510.103 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-04-28T22:18:30.222Z,1398723510.222 [BuoyancyServo] Loaded
2014-04-28T22:18:30.223Z,1398723510.223 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-04-28T22:18:30.231Z,1398723510.231 [ElevatorServo] Loaded
2014-04-28T22:18:30.232Z,1398723510.232 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-04-28T22:18:30.240Z,1398723510.240 [MassServo] Loaded
2014-04-28T22:18:30.240Z,1398723510.240 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-04-28T22:18:30.249Z,1398723510.249 [RudderServo] Loaded
2014-04-28T22:18:30.249Z,1398723510.249 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-04-28T22:18:30.261Z,1398723510.261 [ThrusterServo] Loaded
2014-04-28T22:18:30.261Z,1398723510.261 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-04-28T22:18:30.262Z,1398723510.262 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-04-28T22:18:30.263Z,1398723510.263 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-04-28T22:18:30.301Z,1398723510.301 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-04-28T22:18:30.307Z,1398723510.307 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-04-28T22:18:30.308Z,1398723510.308 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-04-28T22:18:30.314Z,1398723510.314 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-04-28T22:18:30.319Z,1398723510.319 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408434E0
2014-04-28T22:18:30.320Z,1398723510.320 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 865
2014-04-28T22:18:30.324Z,1398723510.324 [Supervisor](INFO): Main Thread ID is 767
2014-04-28T22:18:30.325Z,1398723510.325 [Supervisor](DEBUG): Running supervisor.
2014-04-28T22:18:30.325Z,1398723510.325 [CommandLine ThreadHandler](INFO): Handler Thread ID is 866
2014-04-28T22:18:30.332Z,1398723510.332 [controlThread ThreadHandler](INFO): Handler Thread ID is 867
2014-04-28T22:18:30.332Z,1398723510.332 [controlThread](DEBUG): Initializing ControlThread
2014-04-28T22:18:30.336Z,1398723510.336 [logger ThreadHandler](INFO): Handler Thread ID is 868
2014-04-28T22:18:30.372Z,1398723510.372 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 869
2014-04-28T22:18:30.372Z,1398723510.372 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2014-04-28T22:18:30.396Z,1398723510.396 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 870
2014-04-28T22:18:30.396Z,1398723510.396 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-04-28T22:18:30.400Z,1398723510.400 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-04-28T22:18:30.412Z,1398723510.412 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 872
2014-04-28T22:18:30.413Z,1398723510.413 [WetLabsBB2FL](INFO): Powering down
2014-04-28T22:18:30.440Z,1398723510.440 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 873
2014-04-28T22:18:30.451Z,1398723510.451 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-04-28T22:18:30.453Z,1398723510.453 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-04-28T22:18:30.454Z,1398723510.454 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-04-28T22:18:30.454Z,1398723510.454 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-04-28T22:18:30.454Z,1398723510.454 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-04-28T22:18:30.454Z,1398723510.454 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-04-28T22:18:30.455Z,1398723510.455 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-04-28T22:18:30.455Z,1398723510.455 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-04-28T22:18:30.456Z,1398723510.456 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-04-28T22:18:32.072Z,1398723512.072 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-04-28T22:18:32.112Z,1398723512.112 [ExternalSim](INFO): ExternalSim initializing...
2014-04-28T22:18:32.436Z,1398723512.436 [ExternalSim](DEBUG): beaconLat = 36.81340
2014-04-28T22:18:32.436Z,1398723512.436 [ExternalSim](DEBUG): beaconLon = -121.82240
2014-04-28T22:18:32.437Z,1398723512.437 [ExternalSim](DEBUG): beaconDepth = 25.00
2014-04-28T22:18:32.587Z,1398723512.587 [ExternalSim](DEBUG): Simulator initialized
2014-04-28T22:18:32.803Z,1398723512.803 [InternalSim](DEBUG):  InternalSim initializing...
2014-04-28T22:18:32.903Z,1398723512.903 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-28T22:18:32.915Z,1398723512.915 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-04-28T22:18:32.916Z,1398723512.916 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-04-28T22:18:32.916Z,1398723512.916 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-04-28T22:18:32.918Z,1398723512.918 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-04-28T22:18:32.918Z,1398723512.918 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-04-28T22:18:32.919Z,1398723512.919 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-04-28T22:18:32.927Z,1398723512.927 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-04-28T22:18:32.928Z,1398723512.928 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-04-28T22:18:32.928Z,1398723512.928 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-04-28T22:18:32.928Z,1398723512.928 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-04-28T22:18:32.929Z,1398723512.929 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-04-28T22:18:32.939Z,1398723512.939 [SBIT](INFO): Initialize SBIT Component.
2014-04-28T22:18:32.940Z,1398723512.940 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11255
2014-04-28T22:18:32.940Z,1398723512.940 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-04-28T22:18:32.940Z,1398723512.940 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-04-28T22:18:32.941Z,1398723512.941 [IBIT](INFO): Initialize IBIT Component.
2014-04-28T22:18:32.942Z,1398723512.942 [CBIT](DEBUG): Initialize CBIT Component.
2014-04-28T22:18:32.942Z,1398723512.942 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2014-04-28T22:18:32.942Z,1398723512.942 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2014-04-28T22:18:32.972Z,1398723512.972 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-04-28T22:18:32.996Z,1398723512.996 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-28T22:18:33.032Z,1398723513.032 [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-28T22:18:33.033Z,1398723513.033 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-04-28T22:18:33.104Z,1398723513.104 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-04-28T22:18:33.106Z,1398723513.106 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-04-28T22:18:33.109Z,1398723513.109 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-28T22:18:33.130Z,1398723513.130 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-04-28T22:18:33.165Z,1398723513.165 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-28T22:18:33.184Z,1398723513.184 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-04-28T22:18:33.218Z,1398723513.218 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-04-28T22:18:33.221Z,1398723513.221 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-04-28T22:18:33.241Z,1398723513.241 [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-28T22:18:33.252Z,1398723513.252 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,DataOverHttps,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-28T22:18:33.345Z,1398723513.345 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-04-28T22:18:33.467Z,1398723513.467 [DVL_micro](INFO): Initializing
2014-04-28T22:18:33.855Z,1398723513.855 [Radio_Freewave](INFO): Powering up
2014-04-28T22:18:34.158Z,1398723514.158 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-04-28T22:18:34.169Z,1398723514.169 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-04-28T22:18:34.184Z,1398723514.184 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-04-28T22:18:34.189Z,1398723514.189 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-04-28T22:18:34.206Z,1398723514.206 [MassServo](DEBUG): Initializing EZServoServo.
2014-04-28T22:18:34.213Z,1398723514.213 [MassServo](DEBUG): Initializing MassServo.
2014-04-28T22:18:34.219Z,1398723514.219 [RudderServo](DEBUG): Initializing EZServoServo.
2014-04-28T22:18:34.225Z,1398723514.225 [RudderServo](DEBUG): Initializing RudderServo.
2014-04-28T22:18:34.231Z,1398723514.231 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-04-28T22:18:34.274Z,1398723514.274 [CommandLine](FAULT): Scheduling is paused
2014-04-28T22:18:36.673Z,1398723516.673 [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-28T22:18:40.121Z,1398723520.121 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003506
2014-04-28T22:18:42.511Z,1398723522.511 [NAL9602](IMPORTANT): GPS fix at: 1398723522.50
2014-04-28T22:18:44.074Z,1398723524.074 [NAL9602](INFO): No messages in MT queue
2014-04-28T22:18:48.851Z,1398723528.851 [SBIT](IMPORTANT): Beginning Startup BIT
2014-04-28T22:18:48.854Z,1398723528.854 [CBIT](IMPORTANT): Beginning GF scan
2014-04-28T22:18:49.851Z,1398723529.851 [NAL9602](INFO): Powering down
2014-04-28T22:19:15.238Z,1398723555.238 [CBIT](IMPORTANT): No ground fault detected
2014-04-28T22:19:33.067Z,1398723573.067 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 44 of 46
2014-04-28T22:19:33.067Z,1398723573.067 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -200 -282 -313 -223 3 3 3 3 150.8 -78.7 -274.5 2 -169.9 9.1 -274.5 2 150 -78 -274 2 -169  -4.73 -1.34 204.5 -3.0 23.4 0.005 35.0 1489 64
2014-04-28T22:19:43.499Z,1398723583.499 [SBIT](IMPORTANT): SBIT PASSED
2014-04-28T22:19:44.051Z,1398723584.051 [MissionManager](IMPORTANT): Started mission Startup
2014-04-28T22:19:44.051Z,1398723584.051 [Startup] Running Loop=1
2014-04-28T22:19:44.051Z,1398723584.051 [Startup](INFO): Aggregate::initialize Startup
2014-04-28T22:19:44.051Z,1398723584.051 [Startup:A.GoToSurface] Running Loop=1
2014-04-28T22:19:44.051Z,1398723584.051 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:19:44.061Z,1398723584.061 [Startup:StartupSatComms] Running Loop=1
2014-04-28T22:19:44.081Z,1398723584.081 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-04-28T22:19:44.081Z,1398723584.081 [Startup:StartupSatComms:A] Running Loop=1
2014-04-28T22:19:44.548Z,1398723584.548 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-28T22:19:44.992Z,1398723584.992 [NAL9602](INFO): Powering up
2014-04-28T22:19:50.662Z,1398723590.662 [NAL9602](IMPORTANT): GPS fix at: 1398723590.66
2014-04-28T22:19:50.705Z,1398723590.705 [Startup:StartupSatComms:A] Stopped
2014-04-28T22:19:50.706Z,1398723590.706 [Startup:StartupSatComms:B] Running Loop=1
2014-04-28T22:19:51.209Z,1398723591.209 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-28T22:19:53.122Z,1398723593.122 [NAL9602](INFO): No messages in MT queue
2014-04-28T22:19:55.241Z,1398723595.241 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20140428T210127/Courier0028.lzma
2014-04-28T22:19:56.226Z,1398723596.226 [DataOverHttps](INFO): Moved sent file to Logs/20140428T210127/Courier0028.lzma.bak
2014-04-28T22:19:56.226Z,1398723596.226 [DataOverHttps](INFO): SBD MOMSN=802795
2014-04-28T22:19:59.704Z,1398723599.704 [NAL9602](INFO): Powering down
2014-04-28T22:20:03.116Z,1398723603.116 [DataOverHttps](INFO): Sending 360 bytes from file Logs/20140428T221821/Courier0000.lzma
2014-04-28T22:20:04.110Z,1398723604.110 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Courier0000.lzma.bak
2014-04-28T22:20:04.111Z,1398723604.111 [DataOverHttps](INFO): SBD MOMSN=802797
2014-04-28T22:20:11.158Z,1398723611.158 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20140428T210127/Express0029.lzma
2014-04-28T22:20:12.135Z,1398723612.135 [DataOverHttps](INFO): Moved sent file to Logs/20140428T210127/Express0029.lzma.bak
2014-04-28T22:20:12.135Z,1398723612.135 [DataOverHttps](INFO): SBD MOMSN=802801
2014-04-28T22:20:19.249Z,1398723619.249 [DataOverHttps](INFO): Sending 680 bytes from file Logs/20140428T221821/Express0001.lzma
2014-04-28T22:20:20.190Z,1398723620.190 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Express0001.lzma.bak
2014-04-28T22:20:20.190Z,1398723620.190 [DataOverHttps](INFO): SBD MOMSN=802803
2014-04-28T22:20:20.701Z,1398723620.701 [Startup:StartupSatComms:B] Stopped
2014-04-28T22:20:20.701Z,1398723620.701 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-04-28T22:20:20.701Z,1398723620.701 [Startup:StartupSatComms] Stopped
2014-04-28T22:20:20.701Z,1398723620.701 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-04-28T22:20:20.709Z,1398723620.709 [Startup](INFO): Completed Startup
2014-04-28T22:20:20.709Z,1398723620.709 [Startup] Stopped
2014-04-28T22:20:20.709Z,1398723620.709 [Startup](INFO): Aggregate::uninitialize Startup
2014-04-28T22:20:20.709Z,1398723620.709 [Startup:A.GoToSurface] Stopped
2014-04-28T22:20:20.709Z,1398723620.709 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:20:21.161Z,1398723621.161 [MissionManager](IMPORTANT): Started mission Default
2014-04-28T22:20:21.161Z,1398723621.161 [Default] Running Loop=1
2014-04-28T22:20:21.161Z,1398723621.161 [Default](INFO): Aggregate::initialize Default
2014-04-28T22:20:21.161Z,1398723621.161 [Default:Iridium] Running Loop=1
2014-04-28T22:20:21.161Z,1398723621.161 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-28T22:20:21.161Z,1398723621.161 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-28T22:20:21.161Z,1398723621.161 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-28T22:20:21.162Z,1398723621.162 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-28T22:20:21.162Z,1398723621.162 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:20:21.177Z,1398723621.177 [Default:Iridium:B.GoToSurface] Stopped
2014-04-28T22:20:21.177Z,1398723621.177 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:20:21.177Z,1398723621.177 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-28T22:20:21.177Z,1398723621.177 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-28T22:20:21.187Z,1398723621.187 [Default:GPS] Running Loop=1
2014-04-28T22:20:21.191Z,1398723621.191 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-28T22:20:21.191Z,1398723621.191 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-28T22:20:21.191Z,1398723621.191 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-28T22:20:21.191Z,1398723621.191 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-28T22:20:21.191Z,1398723621.191 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:20:21.208Z,1398723621.208 [Default:GPS:B.GoToSurface] Stopped
2014-04-28T22:20:21.208Z,1398723621.208 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:20:21.208Z,1398723621.208 [Default:GPS:Read_GPS] Running Loop=1
2014-04-28T22:20:21.208Z,1398723621.208 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-28T22:20:22.854Z,1398723622.854 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-04-28T22:20:22.857Z,1398723622.857 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-04-28T22:20:23.769Z,1398723623.769 [NAL9602](INFO): Powering up
2014-04-28T22:20:27.968Z,1398723627.968 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20140428T221821/Courier0004.lzma
2014-04-28T22:20:28.939Z,1398723628.939 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Courier0004.lzma.bak
2014-04-28T22:20:28.939Z,1398723628.939 [DataOverHttps](INFO): SBD MOMSN=802816
2014-04-28T22:20:31.438Z,1398723631.438 [NAL9602](IMPORTANT): GPS fix at: 1398723631.43
2014-04-28T22:20:31.469Z,1398723631.469 [Default:GPS:Read_GPS] Stopped
2014-04-28T22:20:31.469Z,1398723631.469 [Default:GPS:D] Running Loop=1
2014-04-28T22:20:31.997Z,1398723631.997 [Default:GPS:D] Stopped
2014-04-28T22:20:31.998Z,1398723631.998 [Default:GPS](INFO): Completed Default:GPS
2014-04-28T22:20:31.998Z,1398723631.998 [Default:GPS] Stopped
2014-04-28T22:20:31.998Z,1398723631.998 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-28T22:20:31.998Z,1398723631.998 [Default:GPS:A.SetSpeed] Stopped
2014-04-28T22:20:31.998Z,1398723631.998 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-28T22:20:32.914Z,1398723632.914 [NAL9602](INFO): No messages in MT queue
2014-04-28T22:20:36.127Z,1398723636.127 [DataOverHttps](INFO): Sending 174 bytes from file Logs/20140428T221821/Express0005.lzma
2014-04-28T22:20:37.096Z,1398723637.096 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Express0005.lzma.bak
2014-04-28T22:20:37.096Z,1398723637.096 [DataOverHttps](INFO): SBD MOMSN=802818
2014-04-28T22:20:37.684Z,1398723637.684 [Default:Iridium:Read_Iridium] Stopped
2014-04-28T22:20:37.684Z,1398723637.684 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-28T22:20:37.693Z,1398723637.693 [Default:Iridium] Stopped
2014-04-28T22:20:37.693Z,1398723637.693 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-28T22:20:37.693Z,1398723637.693 [Default:Iridium:A.SetSpeed] Stopped
2014-04-28T22:20:37.693Z,1398723637.693 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface] Running Loop=1
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize.
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-28T22:20:37.693Z,1398723637.693 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:20:38.270Z,1398723638.270 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1
2014-04-28T22:20:38.275Z,1398723638.275 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1
2014-04-28T22:20:43.989Z,1398723643.989 [NAL9602](INFO): Powering down
2014-04-28T22:25:38.463Z,1398723938.463 [Default:CallIridium] Running Loop=1
2014-04-28T22:25:38.463Z,1398723938.463 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2014-04-28T22:25:38.463Z,1398723938.463 [Default:CallIridium:A] Running Loop=1
2014-04-28T22:25:38.476Z,1398723938.476 [Default:CallIridium:A] Stopped
2014-04-28T22:25:38.476Z,1398723938.476 [Default:CallIridium:B] Running Loop=1
2014-04-28T22:25:38.477Z,1398723938.477 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium] Running Loop=1
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-04-28T22:25:43.426Z,1398723943.426 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:25:43.431Z,1398723943.431 [Default:Iridium:B.GoToSurface] Stopped
2014-04-28T22:25:43.431Z,1398723943.431 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:25:43.432Z,1398723943.432 [Default:Iridium:Read_Iridium] Running Loop=1
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS] Running Loop=1
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS:A.SetSpeed] Running Loop=1
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS:B.GoToSurface] Running Loop=1
2014-04-28T22:25:43.432Z,1398723943.432 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-04-28T22:25:43.433Z,1398723943.433 [Default:GPS:B.GoToSurface] Stopped
2014-04-28T22:25:43.433Z,1398723943.433 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:25:43.433Z,1398723943.433 [Default:GPS:Read_GPS] Running Loop=1
2014-04-28T22:25:44.670Z,1398723944.670 [NAL9602](INFO): Powering up
2014-04-28T22:25:46.127Z,1398723946.127 [DataOverHttps](INFO): Sending 76 bytes from file Logs/20140428T221821/Courier0008.lzma
2014-04-28T22:25:47.028Z,1398723947.028 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Courier0008.lzma.bak
2014-04-28T22:25:47.028Z,1398723947.028 [DataOverHttps](INFO): SBD MOMSN=802831
2014-04-28T22:25:50.778Z,1398723950.778 [NAL9602](IMPORTANT): GPS fix at: 1398723950.77
2014-04-28T22:25:50.803Z,1398723950.803 [Default:GPS:Read_GPS] Stopped
2014-04-28T22:25:50.803Z,1398723950.803 [Default:GPS:D] Running Loop=1
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS:D] Stopped
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS](INFO): Completed Default:GPS
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS] Stopped
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS:A.SetSpeed] Stopped
2014-04-28T22:25:51.297Z,1398723951.297 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-04-28T22:25:52.738Z,1398723952.738 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20140428T221821/Express0009.lzma
2014-04-28T22:25:52.756Z,1398723952.756 [NAL9602](INFO): No messages in MT queue
2014-04-28T22:25:53.662Z,1398723953.662 [DataOverHttps](INFO): Moved sent file to Logs/20140428T221821/Express0009.lzma.bak
2014-04-28T22:25:53.663Z,1398723953.663 [DataOverHttps](INFO): SBD MOMSN=802833
2014-04-28T22:25:54.243Z,1398723954.243 [Default:Iridium:Read_Iridium] Stopped
2014-04-28T22:25:54.244Z,1398723954.244 [Default:Iridium](INFO): Completed Default:Iridium
2014-04-28T22:25:54.244Z,1398723954.244 [Default:Iridium] Stopped
2014-04-28T22:25:54.244Z,1398723954.244 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-04-28T22:25:54.244Z,1398723954.244 [Default:Iridium:A.SetSpeed] Stopped
2014-04-28T22:25:54.244Z,1398723954.244 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-04-28T22:25:54.724Z,1398723954.724 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2014-04-28T22:25:54.724Z,1398723954.724 [Default:CallIridium:B] Stopped
2014-04-28T22:25:54.724Z,1398723954.724 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2014-04-28T22:25:54.724Z,1398723954.724 [Default:CallIridium](INFO): Completed Default:CallIridium
2014-04-28T22:25:54.725Z,1398723954.725 [Default:CallIridium] Stopped
2014-04-28T22:25:54.725Z,1398723954.725 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2014-04-28T22:26:00.445Z,1398723960.445 [NAL9602](INFO): Powering down
2014-04-28T22:26:38.128Z,1398723998.128 [CommandLine](IMPORTANT): got command quit
2014-04-28T22:26:39.136Z,1398723999.136 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:39.136Z,1398723999.136 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.329Z,1398723999.329 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-04-28T22:26:39.329Z,1398723999.329 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.330Z,1398723999.330 [CommandLine](INFO): Join timeout helper Thread ID is 929
2014-04-28T22:26:39.337Z,1398723999.337 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-04-28T22:26:39.337Z,1398723999.337 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.338Z,1398723999.338 [NavChartDb](INFO): Join timeout helper Thread ID is 930
2014-04-28T22:26:39.365Z,1398723999.365 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:39.366Z,1398723999.366 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.376Z,1398723999.376 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-04-28T22:26:39.376Z,1398723999.376 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.376Z,1398723999.376 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 931
2014-04-28T22:26:39.558Z,1398723999.558 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:39.558Z,1398723999.558 [WetLabsBB2FL](INFO): Powering down
2014-04-28T22:26:39.559Z,1398723999.559 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.570Z,1398723999.570 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-04-28T22:26:39.570Z,1398723999.570 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.570Z,1398723999.570 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 932
2014-04-28T22:26:39.718Z,1398723999.718 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:39.718Z,1398723999.718 [CTD_NeilBrown](INFO): Powering down
2014-04-28T22:26:39.719Z,1398723999.719 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.722Z,1398723999.722 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2014-04-28T22:26:39.722Z,1398723999.722 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:39.723Z,1398723999.723 [AsyncPiEstimator](INFO): Join timeout helper Thread ID is 933
2014-04-28T22:26:40.043Z,1398724000.043 [AsyncPiEstimator ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:40.043Z,1398724000.043 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2014-04-28T22:26:40.043Z,1398724000.043 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:40.055Z,1398724000.055 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-04-28T22:26:40.056Z,1398724000.056 [logger ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:40.056Z,1398724000.056 [logger](INFO): Join timeout helper Thread ID is 934
2014-04-28T22:26:40.101Z,1398724000.101 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:40.102Z,1398724000.102 [logger ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:40.119Z,1398724000.119 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-04-28T22:26:40.119Z,1398724000.119 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:40.120Z,1398724000.120 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-04-28T22:26:40.120Z,1398724000.120 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:40.120Z,1398724000.120 [controlThread](INFO): Join timeout helper Thread ID is 935
2014-04-28T22:26:44.261Z,1398724004.261 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-04-28T22:26:44.261Z,1398724004.261 [controlThread](DEBUG): Uninitializing ControlThread
2014-04-28T22:26:44.262Z,1398724004.262 [AHRS_sp3003D](INFO): Powering down
2014-04-28T22:26:44.263Z,1398724004.263 [DVL_micro](INFO): uninitialize:Powering down
2014-04-28T22:26:44.264Z,1398724004.264 [NAL9602](INFO): Powering down
2014-04-28T22:26:44.353Z,1398724004.353 [Radio_Freewave](INFO): Powering down
2014-04-28T22:26:44.356Z,1398724004.356 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-04-28T22:26:44.357Z,1398724004.357 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-04-28T22:26:44.358Z,1398724004.358 [Default] Stopped
2014-04-28T22:26:44.358Z,1398724004.358 [Default](INFO): Aggregate::uninitialize Default
2014-04-28T22:26:44.358Z,1398724004.358 [Default:WaitAtTheSurface] Stopped
2014-04-28T22:26:44.359Z,1398724004.359 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2014-04-28T22:26:44.359Z,1398724004.359 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Stopped
2014-04-28T22:26:44.359Z,1398724004.359 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2014-04-28T22:26:44.359Z,1398724004.359 [Default:WaitAtTheSurface:B.GoToSurface] Stopped
2014-04-28T22:26:44.359Z,1398724004.359 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-04-28T22:26:44.365Z,1398724004.365 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-04-28T22:26:44.365Z,1398724004.365 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-04-28T22:26:44.366Z,1398724004.366 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-04-28T22:26:44.366Z,1398724004.366 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-04-28T22:26:44.367Z,1398724004.367 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-04-28T22:26:44.367Z,1398724004.367 [BuoyancyServo](INFO): Powering down
2014-04-28T22:26:44.381Z,1398724004.381 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-04-28T22:26:44.381Z,1398724004.381 [ElevatorServo](INFO): Powering down
2014-04-28T22:26:44.382Z,1398724004.382 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-04-28T22:26:44.383Z,1398724004.383 [MassServo](INFO): Powering down
2014-04-28T22:26:44.384Z,1398724004.384 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-04-28T22:26:44.384Z,1398724004.384 [RudderServo](INFO): Powering down
2014-04-28T22:26:44.385Z,1398724004.385 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-04-28T22:26:44.385Z,1398724004.385 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-04-28T22:26:44.385Z,1398724004.385 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-04-28T22:26:44.386Z,1398724004.386 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-04-28T22:26:44.429Z,1398724004.429 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:44.501Z,1398724004.501 [AsyncPiEstimator ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:44.524Z,1398724004.524 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:44.528Z,1398724004.528 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:44.559Z,1398724004.559 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-04-28T22:26:44.613Z,1398724004.613 [logger ThreadHandler](INFO): Thread cancelled.