2013-11-05T19:14:51.103Z,1383678891.103 [Supervisor](DEBUG): Initializing supervisor.
2013-11-05T19:14:51.106Z,1383678891.106 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-11-05T19:14:51.107Z,1383678891.107 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-11-05T19:14:51.108Z,1383678891.108 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-11-05T19:14:51.112Z,1383678891.112 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-11-05T19:14:51.124Z,1383678891.124 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-11-05T19:14:51.126Z,1383678891.126 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-11-05T19:14:51.127Z,1383678891.127 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-11-05T19:14:51.128Z,1383678891.128 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-11-05T19:14:51.130Z,1383678891.130 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2013-11-05T19:14:51.131Z,1383678891.131 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-11-05T19:14:51.132Z,1383678891.132 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-11-05T19:14:51.411Z,1383678891.411 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-11-05T19:14:51.412Z,1383678891.412 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-11-05T19:14:51.610Z,1383678891.610 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-11-05T19:14:51.611Z,1383678891.611 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-11-05T19:14:51.696Z,1383678891.696 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-11-05T19:14:51.697Z,1383678891.697 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-11-05T19:14:51.814Z,1383678891.814 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-11-05T19:14:51.814Z,1383678891.814 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-11-05T19:14:51.953Z,1383678891.953 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-11-05T19:14:51.954Z,1383678891.954 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-11-05T19:14:52.195Z,1383678892.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-11-05T19:14:52.195Z,1383678892.195 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-11-05T19:14:52.364Z,1383678892.364 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-11-05T19:14:52.364Z,1383678892.364 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-11-05T19:14:52.630Z,1383678892.630 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-11-05T19:14:52.631Z,1383678892.631 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-11-05T19:14:52.731Z,1383678892.731 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-11-05T19:14:52.732Z,1383678892.732 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-11-05T19:14:53.166Z,1383678893.166 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-11-05T19:14:53.167Z,1383678893.167 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-11-05T19:14:53.278Z,1383678893.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-11-05T19:14:53.279Z,1383678893.279 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-11-05T19:14:53.364Z,1383678893.364 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2013-11-05T19:14:53.464Z,1383678893.464 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2013-11-05T19:14:53.466Z,1383678893.466 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-11-05T19:14:53.467Z,1383678893.467 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-11-05T19:14:53.562Z,1383678893.562 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-11-05T19:14:53.690Z,1383678893.690 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-11-05T19:14:53.790Z,1383678893.790 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-11-05T19:14:53.893Z,1383678893.893 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-11-05T19:14:53.995Z,1383678893.995 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-11-05T19:14:54.124Z,1383678894.124 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-11-05T19:14:54.219Z,1383678894.219 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-11-05T19:14:54.305Z,1383678894.305 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2013-11-05T19:14:54.397Z,1383678894.397 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-11-05T19:14:54.398Z,1383678894.398 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-11-05T19:14:54.400Z,1383678894.400 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-11-05T19:14:54.573Z,1383678894.573 [InternalSim] Loaded
2013-11-05T19:14:54.573Z,1383678894.573 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-11-05T19:14:54.574Z,1383678894.574 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-11-05T19:14:54.574Z,1383678894.574 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-11-05T19:14:54.666Z,1383678894.666 [SBIT](DEBUG): Construct Startup Built In Test.
2013-11-05T19:14:54.697Z,1383678894.697 [SBIT] Loaded
2013-11-05T19:14:54.697Z,1383678894.697 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-11-05T19:14:54.698Z,1383678894.698 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-11-05T19:14:54.727Z,1383678894.727 [IBIT] Loaded
2013-11-05T19:14:54.727Z,1383678894.727 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-11-05T19:14:54.730Z,1383678894.730 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-11-05T19:14:54.848Z,1383678894.848 [CBIT] Loaded
2013-11-05T19:14:54.848Z,1383678894.848 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-11-05T19:14:54.848Z,1383678894.848 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-11-05T19:14:54.849Z,1383678894.849 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-11-05T19:14:55.021Z,1383678895.021 [BuoyancyServo] Loaded
2013-11-05T19:14:55.022Z,1383678895.022 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-11-05T19:14:55.034Z,1383678895.034 [ElevatorServo] Loaded
2013-11-05T19:14:55.034Z,1383678895.034 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-11-05T19:14:55.046Z,1383678895.046 [MassServo] Loaded
2013-11-05T19:14:55.046Z,1383678895.046 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-11-05T19:14:55.058Z,1383678895.058 [RudderServo] Loaded
2013-11-05T19:14:55.058Z,1383678895.058 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-11-05T19:14:55.069Z,1383678895.069 [ThrusterServo] Loaded
2013-11-05T19:14:55.070Z,1383678895.070 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-11-05T19:14:55.070Z,1383678895.070 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-11-05T19:14:55.071Z,1383678895.071 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-11-05T19:14:55.108Z,1383678895.108 [DepthRateCalculator] Loaded
2013-11-05T19:14:55.108Z,1383678895.108 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-11-05T19:14:57.953Z,1383678897.953 [HFRadarModelCalc] Loaded
2013-11-05T19:14:57.953Z,1383678897.953 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-11-05T19:14:57.969Z,1383678897.969 [NavChart] Loaded
2013-11-05T19:14:57.970Z,1383678897.970 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-11-05T19:14:57.976Z,1383678897.976 [PitchRateCalculator] Loaded
2013-11-05T19:14:57.976Z,1383678897.976 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-11-05T19:14:57.987Z,1383678897.987 [SpeedCalculator] Loaded
2013-11-05T19:14:57.987Z,1383678897.987 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-11-05T19:14:58.004Z,1383678898.004 [TempGradientCalculator] Loaded
2013-11-05T19:14:58.004Z,1383678898.004 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-11-05T19:14:58.010Z,1383678898.010 [YawRateCalculator] Loaded
2013-11-05T19:14:58.010Z,1383678898.010 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-11-05T19:14:58.058Z,1383678898.058 [Navigation] Loaded
2013-11-05T19:14:58.058Z,1383678898.058 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-11-05T19:14:58.059Z,1383678898.059 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-11-05T19:14:58.059Z,1383678898.059 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-11-05T19:14:58.309Z,1383678898.309 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-11-05T19:14:58.309Z,1383678898.309 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-11-05T19:14:58.334Z,1383678898.334 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-11-05T19:14:58.335Z,1383678898.335 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-11-05T19:14:58.386Z,1383678898.386 [VerticalControl](DEBUG): Construct VerticalControl.
2013-11-05T19:14:58.483Z,1383678898.483 [VerticalControl] Loaded
2013-11-05T19:14:58.484Z,1383678898.484 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-11-05T19:14:58.484Z,1383678898.484 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-11-05T19:14:58.543Z,1383678898.543 [HorizontalControl] Loaded
2013-11-05T19:14:58.544Z,1383678898.544 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-11-05T19:14:58.544Z,1383678898.544 [SpeedControl](DEBUG): Construct SpeedControl.
2013-11-05T19:14:58.546Z,1383678898.546 [SpeedControl] Loaded
2013-11-05T19:14:58.547Z,1383678898.547 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-11-05T19:14:58.547Z,1383678898.547 [LoopControl](DEBUG): Construct LoopControl.
2013-11-05T19:14:58.548Z,1383678898.548 [LoopControl] Loaded
2013-11-05T19:14:58.548Z,1383678898.548 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-11-05T19:14:58.549Z,1383678898.549 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-11-05T19:14:58.549Z,1383678898.549 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-11-05T19:14:58.555Z,1383678898.555 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-11-05T19:14:58.560Z,1383678898.560 [AsyncPiEstimator] Loaded
2013-11-05T19:14:58.560Z,1383678898.560 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-11-05T19:14:58.562Z,1383678898.562 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0
2013-11-05T19:14:58.562Z,1383678898.562 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-11-05T19:14:58.563Z,1383678898.563 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-11-05T19:14:58.790Z,1383678898.790 [AHRS_sp3003D] Loaded
2013-11-05T19:14:58.791Z,1383678898.791 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-11-05T19:14:58.861Z,1383678898.861 [DataOverHttps] Loaded
2013-11-05T19:14:58.862Z,1383678898.862 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2013-11-05T19:14:58.875Z,1383678898.875 [Depth_Keller] Loaded
2013-11-05T19:14:58.876Z,1383678898.876 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-11-05T19:14:59.064Z,1383678899.064 [DVL_micro] Loaded
2013-11-05T19:14:59.064Z,1383678899.064 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-11-05T19:14:59.065Z,1383678899.065 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 4085C4E0
2013-11-05T19:14:59.159Z,1383678899.159 [NAL9602] Loaded
2013-11-05T19:14:59.159Z,1383678899.159 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-11-05T19:14:59.202Z,1383678899.202 [Onboard] Loaded
2013-11-05T19:14:59.202Z,1383678899.202 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-11-05T19:14:59.209Z,1383678899.209 [Radio_Freewave] Loaded
2013-11-05T19:14:59.209Z,1383678899.209 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-11-05T19:14:59.358Z,1383678899.358 [DAT] Loaded
2013-11-05T19:14:59.359Z,1383678899.359 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-11-05T19:14:59.359Z,1383678899.359 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-11-05T19:14:59.360Z,1383678899.360 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-11-05T19:14:59.463Z,1383678899.463 [CTD_NeilBrown] Loaded
2013-11-05T19:14:59.464Z,1383678899.464 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-11-05T19:14:59.465Z,1383678899.465 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408B94E0
2013-11-05T19:14:59.498Z,1383678899.498 [WetLabsBB2FL] Loaded
2013-11-05T19:14:59.498Z,1383678899.498 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-11-05T19:14:59.499Z,1383678899.499 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408E94E0
2013-11-05T19:14:59.500Z,1383678899.500 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-11-05T19:14:59.503Z,1383678899.503 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-11-05T19:14:59.504Z,1383678899.504 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-11-05T19:14:59.511Z,1383678899.511 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-11-05T19:14:59.512Z,1383678899.512 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 409194E0
2013-11-05T19:14:59.517Z,1383678899.517 [Supervisor](DEBUG): Running supervisor.
2013-11-05T19:14:59.519Z,1383678899.519 [CommandLine](INFO): Thread ID is 2256
2013-11-05T19:14:59.521Z,1383678899.521 [controlThread](INFO): Thread ID is 2255
2013-11-05T19:14:59.521Z,1383678899.521 [controlThread](DEBUG): Initializing ControlThread
2013-11-05T19:14:59.522Z,1383678899.522 [CycleStarter](INFO): Thread ID is 2254
2013-11-05T19:14:59.522Z,1383678899.522 [InternalSim](DEBUG):  InternalSim initializing...
2013-11-05T19:14:59.556Z,1383678899.556 [logger](INFO): Thread ID is 2257
2013-11-05T19:14:59.582Z,1383678899.582 [SBIT](INFO): Initialize SBIT Component.
2013-11-05T19:14:59.583Z,1383678899.583 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:10713
2013-11-05T19:14:59.583Z,1383678899.583 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-11-05T19:14:59.583Z,1383678899.583 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-11-05T19:14:59.584Z,1383678899.584 [IBIT](INFO): Initialize IBIT Component.
2013-11-05T19:14:59.585Z,1383678899.585 [CBIT](DEBUG): Initialize CBIT Component.
2013-11-05T19:14:59.585Z,1383678899.585 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-11-05T19:14:59.596Z,1383678899.596 [AsyncPiEstimator](INFO): Thread ID is 2324
2013-11-05T19:14:59.596Z,1383678899.596 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-11-05T19:14:59.609Z,1383678899.609 [DVL_micro](INFO): Thread ID is 2325
2013-11-05T19:14:59.616Z,1383678899.616 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-11-05T19:14:59.617Z,1383678899.617 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-11-05T19:14:59.617Z,1383678899.617 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-11-05T19:14:59.618Z,1383678899.618 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-11-05T19:14:59.618Z,1383678899.618 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-11-05T19:14:59.619Z,1383678899.619 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-11-05T19:14:59.619Z,1383678899.619 [Navigation](DEBUG): Initializing Navigation.
2013-11-05T19:14:59.620Z,1383678899.620 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-11-05T19:14:59.621Z,1383678899.621 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-11-05T19:14:59.622Z,1383678899.622 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-11-05T19:14:59.622Z,1383678899.622 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-11-05T19:14:59.626Z,1383678899.626 [DVL_micro](INFO): Initializing
2013-11-05T19:14:59.627Z,1383678899.627 [DVL_micro](INFO): start:Powering up
2013-11-05T19:14:59.628Z,1383678899.628 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-11-05T19:14:59.631Z,1383678899.631 [DVL_micro](INFO): Cycling power to configure device.
2013-11-05T19:14:59.638Z,1383678899.638 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-11-05T19:14:59.648Z,1383678899.648 [CTD_NeilBrown](INFO): Thread ID is 2326
2013-11-05T19:14:59.648Z,1383678899.648 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-11-05T19:14:59.656Z,1383678899.656 [WetLabsBB2FL](INFO): Thread ID is 2327
2013-11-05T19:14:59.656Z,1383678899.656 [WetLabsBB2FL](INFO): Powering down
2013-11-05T19:14:59.684Z,1383678899.684 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-11-05T19:14:59.697Z,1383678899.697 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-11-05T19:14:59.701Z,1383678899.701 [NavChartDb](INFO): Thread ID is 2328
2013-11-05T19:14:59.704Z,1383678899.704 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-11-05T19:14:59.705Z,1383678899.705 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-11-05T19:14:59.705Z,1383678899.705 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-11-05T19:14:59.705Z,1383678899.705 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-11-05T19:14:59.706Z,1383678899.706 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-11-05T19:14:59.706Z,1383678899.706 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-11-05T19:14:59.706Z,1383678899.706 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-11-05T19:14:59.706Z,1383678899.706 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-11-05T19:14:59.707Z,1383678899.707 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-11-05T19:14:59.746Z,1383678899.746 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2013-11-05T19:14:59.747Z,1383678899.747 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-11-05T19:14:59.832Z,1383678899.832 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-11-05T19:14:59.834Z,1383678899.834 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-11-05T19:14:59.837Z,1383678899.837 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-11-05T19:14:59.857Z,1383678899.857 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-11-05T19:14:59.896Z,1383678899.896 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-11-05T19:14:59.905Z,1383678899.905 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-11-05T19:14:59.926Z,1383678899.926 [Default:D.SetSpeed](DEBUG): Construct.
2013-11-05T19:14:59.929Z,1383678899.929 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-11-05T19:14:59.946Z,1383678899.946 [Default:F.Wait](DEBUG): Construct Wait.
2013-11-05T19:14:59.950Z,1383678899.950 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS" >

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

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

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2013-11-05T19:14:59.954Z,1383678899.954 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,DataOverHttps,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2013-11-05T19:15:00.030Z,1383678900.030 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-11-05T19:15:00.280Z,1383678900.280 [Radio_Freewave](INFO): Powering up
2013-11-05T19:15:00.299Z,1383678900.299 [DAT](INFO): Powering up
2013-11-05T19:15:00.299Z,1383678900.299 [DAT](DEBUG): Initializing DAT.
2013-11-05T19:15:00.551Z,1383678900.551 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-11-05T19:15:00.573Z,1383678900.573 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-11-05T19:15:00.582Z,1383678900.582 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-11-05T19:15:00.589Z,1383678900.589 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-11-05T19:15:00.595Z,1383678900.595 [MassServo](DEBUG): Initializing EZServoServo.
2013-11-05T19:15:00.601Z,1383678900.601 [MassServo](DEBUG): Initializing MassServo.
2013-11-05T19:15:00.612Z,1383678900.612 [RudderServo](DEBUG): Initializing EZServoServo.
2013-11-05T19:15:00.621Z,1383678900.621 [RudderServo](DEBUG): Initializing RudderServo.
2013-11-05T19:15:00.627Z,1383678900.627 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-11-05T19:15:00.633Z,1383678900.633 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-11-05T19:15:01.743Z,1383678901.743 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-11-05T19:15:01.743Z,1383678901.743 [DVL_micro](INFO): Querying output modes
2013-11-05T19:15:01.743Z,1383678901.743 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-11-05T19:15:01.754Z,1383678901.754 [DVL_micro](DEBUG): cmdResponse: 01
2013-11-05T19:15:01.755Z,1383678901.755 [DVL_micro](INFO): NQ1 output enabled
2013-11-05T19:15:01.755Z,1383678901.755 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-11-05T19:15:01.767Z,1383678901.767 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-11-05T19:15:01.772Z,1383678901.772 [DVL_micro](INFO): pause:Powering down
2013-11-05T19:15:04.497Z,1383678904.497 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003507
2013-11-05T19:15:04.500Z,1383678904.500 [NAL9602](INFO): Powering up NAL9602
2013-11-05T19:15:15.103Z,1383678915.103 [NAL9602](INFO): NAL9602 initialized
2013-11-05T19:15:15.177Z,1383678915.177 [SBIT](IMPORTANT): Beginning Startup BIT
2013-11-05T19:15:15.180Z,1383678915.180 [CBIT](IMPORTANT): Beginning GF scan
2013-11-05T19:15:20.446Z,1383678920.446 [DAT](INFO): Powering down
2013-11-05T19:15:34.137Z,1383678934.137 [DataOverHttps](INFO): Received command:ibit
2013-11-05T19:15:34.138Z,1383678934.138 [DataOverHttps](IMPORTANT): SBD MTMSN=20131105T191556
2013-11-05T19:15:34.177Z,1383678934.177 [CommandLine](IMPORTANT): got command ibit
2013-11-05T19:15:34.371Z,1383678934.371 [IBIT](FAULT): Cannot run IBIT while SBIT is in progress.
2013-11-05T19:15:34.877Z,1383678934.877 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-11-05T19:15:34.877Z,1383678934.877 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2013-11-05T19:15:34.877Z,1383678934.877 [IBIT](IMPORTANT): massDefault: 0.800000 cm
2013-11-05T19:15:34.878Z,1383678934.878 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-11-05T19:15:34.878Z,1383678934.878 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-11-05T19:15:34.879Z,1383678934.879 [IBIT](IMPORTANT): IBIT FAILED
2013-11-05T19:15:41.925Z,1383678941.925 [CBIT](IMPORTANT): No ground fault detected
2013-11-05T19:16:09.289Z,1383678969.289 [SBIT](IMPORTANT): SBIT PASSED
2013-11-05T19:16:09.680Z,1383678969.680 [MissionManager](IMPORTANT): Started mission Startup
2013-11-05T19:16:09.680Z,1383678969.680 [Startup] Running Loop=1
2013-11-05T19:16:09.680Z,1383678969.680 [Startup](INFO): Aggregate::initialize Startup
2013-11-05T19:16:09.681Z,1383678969.681 [Startup:A.GoToSurface] Running Loop=1
2013-11-05T19:16:09.681Z,1383678969.681 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-11-05T19:16:09.687Z,1383678969.687 [Startup:StartupSatComms] Running Loop=1
2013-11-05T19:16:09.687Z,1383678969.687 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-11-05T19:16:09.687Z,1383678969.687 [Startup:StartupSatComms:A] Running Loop=1
2013-11-05T19:16:10.085Z,1383678970.085 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-11-05T19:16:32.937Z,1383678992.937 [DataOverHttps](INFO): Received command:ibit
2013-11-05T19:16:32.938Z,1383678992.938 [DataOverHttps](IMPORTANT): SBD MTMSN=20131105T191655
2013-11-05T19:16:32.980Z,1383678992.980 [CommandLine](IMPORTANT): got command ibit
2013-11-05T19:16:32.984Z,1383678992.984 [IBIT](IMPORTANT): Beginning Initiated BIT
2013-11-05T19:16:32.985Z,1383678992.985 [IBIT](IMPORTANT): Beginning control surface checks.

2013-11-05T19:16:32.986Z,1383678992.986 [CBIT](IMPORTANT): Beginning GF scan
2013-11-05T19:16:33.384Z,1383678993.384 [IBIT](IMPORTANT): Beginning Initiated BIT
2013-11-05T19:16:33.384Z,1383678993.384 [IBIT](IMPORTANT): Beginning control surface checks.

2013-11-05T19:16:33.784Z,1383678993.784 [Radio_Freewave](INFO): Powering down
2013-11-05T19:16:34.572Z,1383678994.572 [Radio_Freewave](INFO): Powering up
2013-11-05T19:16:59.238Z,1383679019.238 [CBIT](IMPORTANT): No ground fault detected
2013-11-05T19:17:20.021Z,1383679040.021 [CommandLine](IMPORTANT): got command show variable quality
2013-11-05T19:17:20.043Z,1383679040.043 [CommandLine](INFO): NAL9602.sigQuality (count)
2013-11-05T19:17:26.299Z,1383679046.299 [CommandLine](IMPORTANT): got command report mod NAL9602.sigQuality
2013-11-05T19:17:26.337Z,1383679046.337 [Reporter](INFO): NAL9602.sigQuality no_value
2013-11-05T19:17:33.577Z,1383679053.577 [DataOverHttps](INFO): Received command:ibit
2013-11-05T19:17:33.577Z,1383679053.577 [DataOverHttps](IMPORTANT): SBD MTMSN=20131105T191756
2013-11-05T19:17:33.602Z,1383679053.602 [CommandLine](IMPORTANT): got command ibit
2013-11-05T19:18:10.441Z,1383679090.441 [NAL9602](IMPORTANT): GPS fix at: 1383679112.00
2013-11-05T19:18:13.251Z,1383679093.251 [NAL9602](IMPORTANT): GPS fix at: 1383679114.00
2013-11-05T19:18:16.613Z,1383679096.613 [NAL9602](IMPORTANT): GPS fix at: 1383679118.00
2013-11-05T19:18:19.468Z,1383679099.468 [NAL9602](IMPORTANT): GPS fix at: 1383679121.00
2013-11-05T19:18:22.270Z,1383679102.270 [NAL9602](IMPORTANT): GPS fix at: 1383679124.00
2013-11-05T19:18:23.893Z,1383679103.893 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2013-11-05T19:18:24.290Z,1383679104.290 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2013-11-05T19:18:24.703Z,1383679104.703 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2013-11-05T19:18:24.704Z,1383679104.704 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2013-11-05T19:18:24.704Z,1383679104.704 [IBIT](IMPORTANT): Pressure:11.265132 PSI
2013-11-05T19:18:24.705Z,1383679104.705 [IBIT](IMPORTANT): Humidity:18.314013 %
2013-11-05T19:18:25.120Z,1383679105.120 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-11-05T19:18:25.120Z,1383679105.120 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2013-11-05T19:18:25.121Z,1383679105.121 [IBIT](IMPORTANT): massDefault: 0.800000 cm
2013-11-05T19:18:25.121Z,1383679105.121 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-11-05T19:18:25.121Z,1383679105.121 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-11-05T19:18:25.122Z,1383679105.122 [IBIT](IMPORTANT): IBIT FAILED
2013-11-05T19:18:25.474Z,1383679105.474 [NAL9602](IMPORTANT): GPS fix at: 1383679127.00
2013-11-05T19:18:25.489Z,1383679105.489 [Startup:StartupSatComms:A](INFO): Timed out from 2013-11-05T19:16:09.7Z
2013-11-05T19:18:25.489Z,1383679105.489 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1
2013-11-05T19:18:25.490Z,1383679105.490 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout
2013-11-05T19:18:25.490Z,1383679105.490 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout
2013-11-05T19:18:25.490Z,1383679105.490 [Startup:StartupSatComms:A] Stopped
2013-11-05T19:18:25.490Z,1383679105.490 [Startup:StartupSatComms:B] Running Loop=1
2013-11-05T19:18:25.927Z,1383679105.927 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-11-05T19:18:28.813Z,1383679108.813 [DataOverHttps](INFO): Sending 60 bytes from file Logs/20131105T190737/Courier0008.lzma
2013-11-05T19:18:30.012Z,1383679110.012 [DataOverHttps](INFO): Moved sent file to Logs/20131105T190737/Courier0008.lzma.bak
2013-11-05T19:18:30.013Z,1383679110.013 [DataOverHttps](INFO): Received command:ibit
2013-11-05T19:18:30.014Z,1383679110.014 [DataOverHttps](IMPORTANT): SBD MOMSN=222085, MTMSN=20131105T191852
2013-11-05T19:18:30.082Z,1383679110.082 [CommandLine](IMPORTANT): got command ibit
2013-11-05T19:18:30.886Z,1383679110.886 [IBIT](IMPORTANT): Beginning Initiated BIT
2013-11-05T19:18:30.886Z,1383679110.886 [IBIT](IMPORTANT): Beginning control surface checks.

2013-11-05T19:18:30.888Z,1383679110.888 [CBIT](IMPORTANT): Beginning GF scan
2013-11-05T19:18:32.500Z,1383679112.500 [Radio_Freewave](INFO): Powering down
2013-11-05T19:18:32.887Z,1383679112.887 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20131105T191451/Courier0000.lzma
2013-11-05T19:18:33.341Z,1383679113.341 [NAL9602](IMPORTANT): GPS fix at: 1383679135.00
2013-11-05T19:18:33.347Z,1383679113.347 [Radio_Freewave](INFO): Powering up
2013-11-05T19:18:36.534Z,1383679116.534 [DataOverHttps](INFO): Moved sent file to Logs/20131105T191451/Courier0000.lzma.bak
2013-11-05T19:18:36.534Z,1383679116.534 [DataOverHttps](INFO): SBD MOMSN=222087
2013-11-05T19:18:36.547Z,1383679116.547 [NAL9602](IMPORTANT): GPS fix at: 1383679138.00
2013-11-05T19:18:39.289Z,1383679119.289 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20131105T191451/Courier0004.lzma
2013-11-05T19:18:39.720Z,1383679119.720 [NAL9602](IMPORTANT): GPS fix at: 1383679141.00
2013-11-05T19:18:40.520Z,1383679120.520 [DataOverHttps](INFO): Moved sent file to Logs/20131105T191451/Courier0004.lzma.bak
2013-11-05T19:18:40.521Z,1383679120.521 [DataOverHttps](INFO): SBD MOMSN=222091
2013-11-05T19:18:42.941Z,1383679122.941 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20131105T191451/Courier0008.lzma
2013-11-05T19:18:42.970Z,1383679122.970 [NAL9602](IMPORTANT): GPS fix at: 1383679144.00
2013-11-05T19:18:43.741Z,1383679123.741 [DataOverHttps](INFO): Moved sent file to Logs/20131105T191451/Courier0008.lzma.bak
2013-11-05T19:18:43.742Z,1383679123.742 [DataOverHttps](INFO): SBD MOMSN=222093
2013-11-05T19:18:46.385Z,1383679126.385 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:18:46.416Z,1383679126.416 [NAL9602](IMPORTANT): GPS fix at: 1383679148.00
2013-11-05T19:18:49.536Z,1383679129.536 [NAL9602](IMPORTANT): GPS fix at: 1383679151.00
2013-11-05T19:18:52.712Z,1383679132.712 [NAL9602](IMPORTANT): GPS fix at: 1383679154.00
2013-11-05T19:18:55.613Z,1383679135.613 [NAL9602](IMPORTANT): GPS fix at: 1383679157.00
2013-11-05T19:18:57.294Z,1383679137.294 [CBIT](IMPORTANT): No ground fault detected
2013-11-05T19:18:58.468Z,1383679138.468 [NAL9602](IMPORTANT): GPS fix at: 1383679160.00
2013-11-05T19:19:01.384Z,1383679141.384 [NAL9602](IMPORTANT): GPS fix at: 1383679163.00
2013-11-05T19:19:04.849Z,1383679144.849 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:19:04.872Z,1383679144.872 [NAL9602](IMPORTANT): GPS fix at: 1383679166.00
2013-11-05T19:19:07.416Z,1383679147.416 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:19:08.239Z,1383679148.239 [NAL9602](IMPORTANT): GPS fix at: 1383679169.00
2013-11-05T19:19:11.466Z,1383679151.466 [NAL9602](IMPORTANT): GPS fix at: 1383679173.00
2013-11-05T19:19:14.271Z,1383679154.271 [NAL9602](IMPORTANT): GPS fix at: 1383679175.00
2013-11-05T19:19:17.451Z,1383679157.451 [NAL9602](IMPORTANT): GPS fix at: 1383679179.00
2013-11-05T19:19:20.272Z,1383679160.272 [NAL9602](IMPORTANT): GPS fix at: 1383679182.00
2013-11-05T19:19:23.468Z,1383679163.468 [NAL9602](IMPORTANT): GPS fix at: 1383679185.00
2013-11-05T19:19:25.453Z,1383679165.453 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:19:26.276Z,1383679166.276 [NAL9602](IMPORTANT): GPS fix at: 1383679188.00
2013-11-05T19:19:27.557Z,1383679167.557 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:19:29.584Z,1383679169.584 [NAL9602](IMPORTANT): GPS fix at: 1383679191.00
2013-11-05T19:19:32.374Z,1383679172.374 [NAL9602](IMPORTANT): GPS fix at: 1383679194.00
2013-11-05T19:19:35.570Z,1383679175.570 [NAL9602](IMPORTANT): GPS fix at: 1383679197.00
2013-11-05T19:19:38.391Z,1383679178.391 [NAL9602](IMPORTANT): GPS fix at: 1383679200.00
2013-11-05T19:19:41.352Z,1383679181.352 [NAL9602](IMPORTANT): GPS fix at: 1383679203.00
2013-11-05T19:19:44.192Z,1383679184.192 [NAL9602](IMPORTANT): GPS fix at: 1383679205.00
2013-11-05T19:19:46.177Z,1383679186.177 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:19:47.834Z,1383679187.834 [NAL9602](IMPORTANT): GPS fix at: 1383679209.00
2013-11-05T19:19:48.272Z,1383679188.272 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:19:50.286Z,1383679190.286 [NAL9602](IMPORTANT): GPS fix at: 1383679212.00
2013-11-05T19:19:53.491Z,1383679193.491 [NAL9602](IMPORTANT): GPS fix at: 1383679215.00
2013-11-05T19:19:56.291Z,1383679196.291 [NAL9602](IMPORTANT): GPS fix at: 1383679218.00
2013-11-05T19:19:59.508Z,1383679199.508 [NAL9602](IMPORTANT): GPS fix at: 1383679221.00
2013-11-05T19:20:02.345Z,1383679202.345 [NAL9602](IMPORTANT): GPS fix at: 1383679224.00
2013-11-05T19:20:05.568Z,1383679205.568 [NAL9602](IMPORTANT): GPS fix at: 1383679227.00
2013-11-05T19:20:06.773Z,1383679206.773 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:20:08.884Z,1383679208.884 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:20:08.911Z,1383679208.911 [NAL9602](IMPORTANT): GPS fix at: 1383679230.00
2013-11-05T19:20:11.345Z,1383679211.345 [NAL9602](IMPORTANT): GPS fix at: 1383679233.00
2013-11-05T19:20:13.765Z,1383679213.765 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=90.024376
2013-11-05T19:20:14.571Z,1383679214.571 [NAL9602](IMPORTANT): GPS fix at: 1383679236.00
2013-11-05T19:20:21.476Z,1383679221.476 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2013-11-05T19:20:21.889Z,1383679221.889 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2013-11-05T19:20:22.274Z,1383679222.274 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2013-11-05T19:20:22.274Z,1383679222.274 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2013-11-05T19:20:22.275Z,1383679222.275 [IBIT](IMPORTANT): Pressure:10.203115 PSI
2013-11-05T19:20:22.275Z,1383679222.275 [IBIT](IMPORTANT): Humidity:18.770906 %
2013-11-05T19:20:22.698Z,1383679222.698 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m
2013-11-05T19:20:22.699Z,1383679222.699 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2013-11-05T19:20:22.699Z,1383679222.699 [IBIT](IMPORTANT): massDefault: 0.800000 cm
2013-11-05T19:20:22.699Z,1383679222.699 [IBIT](IMPORTANT): stopDepth: 112.000000 m
2013-11-05T19:20:22.700Z,1383679222.700 [IBIT](IMPORTANT): abortDepth: 130.000000 m
2013-11-05T19:20:22.700Z,1383679222.700 [IBIT](IMPORTANT): IBIT FAILED
2013-11-05T19:20:23.078Z,1383679223.078 [Startup:StartupSatComms:B](INFO): Timed out from 2013-11-05T19:18:25.5Z
2013-11-05T19:20:23.078Z,1383679223.078 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1
2013-11-05T19:20:23.078Z,1383679223.078 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout
2013-11-05T19:20:23.078Z,1383679223.078 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout
2013-11-05T19:20:23.079Z,1383679223.079 [Startup:StartupSatComms:B] Stopped
2013-11-05T19:20:23.079Z,1383679223.079 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-11-05T19:20:23.079Z,1383679223.079 [Startup:StartupSatComms] Stopped
2013-11-05T19:20:23.079Z,1383679223.079 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-11-05T19:20:23.080Z,1383679223.080 [Startup](INFO): Completed Startup
2013-11-05T19:20:23.080Z,1383679223.080 [Startup] Stopped
2013-11-05T19:20:23.080Z,1383679223.080 [Startup](INFO): Aggregate::uninitialize Startup
2013-11-05T19:20:23.080Z,1383679223.080 [Startup:A.GoToSurface] Stopped
2013-11-05T19:20:23.080Z,1383679223.080 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-11-05T19:20:23.997Z,1383679223.997 [MissionManager](IMPORTANT): Started mission Default
2013-11-05T19:20:23.997Z,1383679223.997 [Default] Running Loop=1
2013-11-05T19:20:23.998Z,1383679223.998 [Default](INFO): Aggregate::initialize Default
2013-11-05T19:20:23.998Z,1383679223.998 [Default:D.SetSpeed] Running Loop=1
2013-11-05T19:20:23.998Z,1383679223.998 [Default:D.SetSpeed](DEBUG): Initialize.
2013-11-05T19:20:23.998Z,1383679223.998 [Default:E.GoToSurface] Running Loop=1
2013-11-05T19:20:23.998Z,1383679223.998 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium] Running Loop=1
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-11-05T19:20:23.999Z,1383679223.999 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-11-05T19:20:23.999Z,1383679223.999 [Default:E.GoToSurface] Running Loop=1
2013-11-05T19:20:24.005Z,1383679224.005 [Default:D.SetSpeed] Running Loop=1
2013-11-05T19:20:24.010Z,1383679224.010 [Default:CallIridium] Running Loop=1
2013-11-05T19:20:24.010Z,1383679224.010 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-11-05T19:20:24.011Z,1383679224.011 [Default:CallIridium:A] Running Loop=1
2013-11-05T19:20:24.013Z,1383679224.013 [Default:CallIridium:A] Stopped
2013-11-05T19:20:24.013Z,1383679224.013 [Default:CallIridium:B] Running Loop=1
2013-11-05T19:20:24.013Z,1383679224.013 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-11-05T19:20:24.018Z,1383679224.018 [Default:Iridium:B.GoToSurface] Stopped
2013-11-05T19:20:24.018Z,1383679224.018 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-11-05T19:20:24.019Z,1383679224.019 [Default:Iridium:Read_Iridium] Running Loop=1
2013-11-05T19:20:24.019Z,1383679224.019 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS] Running Loop=1
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS:A.SetSpeed] Running Loop=1
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS:B.GoToSurface] Running Loop=1
2013-11-05T19:20:24.024Z,1383679224.024 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-11-05T19:20:24.030Z,1383679224.030 [Default:GPS:B.GoToSurface] Stopped
2013-11-05T19:20:24.030Z,1383679224.030 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-11-05T19:20:24.030Z,1383679224.030 [Default:GPS:Read_GPS] Running Loop=1
2013-11-05T19:20:24.030Z,1383679224.030 [Default:GPS:A.SetSpeed] Running Loop=1
2013-11-05T19:20:24.045Z,1383679224.045 [Reporter](INFO): NAL9602.sigQuality 0 count
2013-11-05T19:20:24.982Z,1383679224.982 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-11-05T19:20:24.985Z,1383679224.985 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-11-05T19:20:26.478Z,1383679226.478 [NAL9602](IMPORTANT): GPS fix at: 1383679248.00
2013-11-05T19:20:26.494Z,1383679226.494 [Default:GPS:Read_GPS] Stopped
2013-11-05T19:20:26.494Z,1383679226.494 [Default:GPS:D] Running Loop=1
2013-11-05T19:20:26.905Z,1383679226.905 [Default:GPS:D] Stopped
2013-11-05T19:20:26.906Z,1383679226.906 [Default:GPS](INFO): Completed Default:GPS
2013-11-05T19:20:26.906Z,1383679226.906 [Default:GPS] Stopped
2013-11-05T19:20:26.906Z,1383679226.906 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-11-05T19:20:26.907Z,1383679226.907 [Default:GPS:A.SetSpeed] Stopped
2013-11-05T19:20:26.907Z,1383679226.907 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-11-05T19:20:27.268Z,1383679227.268 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:20:30.148Z,1383679230.148 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002306
2013-11-05T19:20:33.011Z,1383679233.011 [DataOverHttps](INFO): Sending 60 bytes from file Logs/20131105T191451/Courier0012.lzma
2013-11-05T19:20:36.640Z,1383679236.640 [DataOverHttps](INFO): Moved sent file to Logs/20131105T191451/Courier0012.lzma.bak
2013-11-05T19:20:36.641Z,1383679236.641 [DataOverHttps](INFO): SBD MOMSN=222095
2013-11-05T19:20:37.909Z,1383679237.909 [NAL9602](INFO): Powering down
2013-11-05T19:20:39.213Z,1383679239.213 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:20:57.752Z,1383679257.752 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:20:59.891Z,1383679259.891 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:21:18.462Z,1383679278.462 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:21:20.573Z,1383679280.573 [DataOverHttps](INFO): Sending 8865 bytes from file Logs/20131104T165741/Express0005.lzma
2013-11-05T19:21:38.025Z,1383679298.025 [CommandLine](IMPORTANT): got command quit
2013-11-05T19:21:39.000Z,1383679299.000 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2013-11-05T19:21:39.226Z,1383679299.226 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-11-05T19:21:39.227Z,1383679299.227 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-11-05T19:21:39.587Z,1383679299.587 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-11-05T19:21:39.808Z,1383679299.808 [WetLabsBB2FL](INFO): Powering down
2013-11-05T19:21:39.811Z,1383679299.811 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-11-05T19:21:39.825Z,1383679299.825 [CTD_NeilBrown](INFO): Powering down
2013-11-05T19:21:39.836Z,1383679299.836 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-11-05T19:21:40.092Z,1383679300.092 [DVL_micro](INFO): uninitialize:Powering down
2013-11-05T19:21:40.108Z,1383679300.108 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-11-05T19:21:40.264Z,1383679300.264 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-11-05T19:21:40.269Z,1383679300.269 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-11-05T19:21:40.361Z,1383679300.361 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-11-05T19:21:40.373Z,1383679300.373 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-11-05T19:21:40.697Z,1383679300.697 [controlThread](DEBUG): Uninitializing ControlThread
2013-11-05T19:21:40.698Z,1383679300.698 [AHRS_sp3003D](INFO): Powering down
2013-11-05T19:21:40.788Z,1383679300.788 [NAL9602](INFO): Powering down
2013-11-05T19:21:40.789Z,1383679300.789 [DAT](INFO): Powering down
2013-11-05T19:21:40.790Z,1383679300.790 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-11-05T19:21:40.791Z,1383679300.791 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-11-05T19:21:40.792Z,1383679300.792 [Default] Stopped
2013-11-05T19:21:40.792Z,1383679300.792 [Default](INFO): Aggregate::uninitialize Default
2013-11-05T19:21:40.792Z,1383679300.792 [Default:Iridium] Stopped
2013-11-05T19:21:40.792Z,1383679300.792 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-11-05T19:21:40.792Z,1383679300.792 [Default:Iridium:A.SetSpeed] Stopped
2013-11-05T19:21:40.792Z,1383679300.792 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-11-05T19:21:40.793Z,1383679300.793 [Default:Iridium:Read_Iridium] Stopped
2013-11-05T19:21:40.793Z,1383679300.793 [Default:CallIridium] Stopped
2013-11-05T19:21:40.793Z,1383679300.793 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-11-05T19:21:40.793Z,1383679300.793 [Default:CallIridium:B] Stopped
2013-11-05T19:21:40.793Z,1383679300.793 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-11-05T19:21:40.793Z,1383679300.793 [Default:D.SetSpeed] Stopped
2013-11-05T19:21:40.793Z,1383679300.793 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-11-05T19:21:40.793Z,1383679300.793 [Default:E.GoToSurface] Stopped
2013-11-05T19:21:40.793Z,1383679300.793 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-11-05T19:21:40.798Z,1383679300.798 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-11-05T19:21:40.798Z,1383679300.798 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-11-05T19:21:40.798Z,1383679300.798 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-11-05T19:21:40.799Z,1383679300.799 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-11-05T19:21:40.799Z,1383679300.799 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-11-05T19:21:40.799Z,1383679300.799 [BuoyancyServo](INFO): Powering down
2013-11-05T19:21:40.813Z,1383679300.813 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-11-05T19:21:40.813Z,1383679300.813 [ElevatorServo](INFO): Powering down
2013-11-05T19:21:40.814Z,1383679300.814 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-11-05T19:21:40.814Z,1383679300.814 [MassServo](INFO): Powering down
2013-11-05T19:21:40.815Z,1383679300.815 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-11-05T19:21:40.815Z,1383679300.815 [RudderServo](INFO): Powering down
2013-11-05T19:21:40.816Z,1383679300.816 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-11-05T19:21:40.816Z,1383679300.816 [ThrusterServo](INFO): Powering down
2013-11-05T19:21:40.817Z,1383679300.817 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-11-05T19:21:40.817Z,1383679300.817 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-11-05T19:21:40.818Z,1383679300.818 [CBIT](DEBUG): Uninitialize CBIT Component.