2012-05-03T17:41:02.531Z,1336066862.531 [Supervisor](DEBUG): Initializing supervisor.
2012-05-03T17:41:02.533Z,1336066862.533 [SyncHandler](DEBUG): Created PCaller Thread at 1077138656
2012-05-03T17:41:02.534Z,1336066862.534 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-05-03T17:41:02.535Z,1336066862.535 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077335264
2012-05-03T17:41:02.536Z,1336066862.536 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-05-03T17:41:02.546Z,1336066862.546 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-05-03T17:41:02.547Z,1336066862.547 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077531872
2012-05-03T17:41:02.548Z,1336066862.548 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-05-03T17:41:02.549Z,1336066862.549 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-05-03T17:41:02.550Z,1336066862.550 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-05-03T17:41:02.821Z,1336066862.821 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-05-03T17:41:02.822Z,1336066862.822 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-05-03T17:41:02.000Z,1336066863.000 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-05-03T17:41:03.000Z,1336066863.000 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-05-03T17:41:03.084Z,1336066863.085 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-05-03T17:41:03.085Z,1336066863.085 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-05-03T17:41:03.270Z,1336066863.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-05-03T17:41:03.271Z,1336066863.271 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-05-03T17:41:03.400Z,1336066863.400 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-05-03T17:41:03.400Z,1336066863.400 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-05-03T17:41:03.616Z,1336066863.616 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-05-03T17:41:03.616Z,1336066863.616 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-05-03T17:41:03.763Z,1336066863.763 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-05-03T17:41:03.764Z,1336066863.764 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-05-03T17:41:03.967Z,1336066863.967 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-05-03T17:41:03.967Z,1336066863.967 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-05-03T17:41:04.066Z,1336066864.066 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-05-03T17:41:04.067Z,1336066864.067 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-05-03T17:41:04.456Z,1336066864.456 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-05-03T17:41:04.456Z,1336066864.456 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-05-03T17:41:04.567Z,1336066864.567 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-05-03T17:41:04.568Z,1336066864.568 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-05-03T17:41:04.655Z,1336066864.655 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-05-03T17:41:04.656Z,1336066864.656 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-05-03T17:41:04.757Z,1336066864.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-05-03T17:41:04.890Z,1336066864.890 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-05-03T17:41:04.989Z,1336066864.989 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-05-03T17:41:05.086Z,1336066865.086 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-05-03T17:41:05.195Z,1336066865.195 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-05-03T17:41:05.285Z,1336066865.284 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-05-03T17:41:05.373Z,1336066865.372 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-05-03T17:41:05.485Z,1336066865.485 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-05-03T17:41:05.615Z,1336066865.615 [InternalSim] Loaded
2012-05-03T17:41:05.616Z,1336066865.616 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-05-03T17:41:05.616Z,1336066865.616 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-05-03T17:41:05.617Z,1336066865.617 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-05-03T17:41:05.659Z,1336066865.659 [SBIT](DEBUG): Construct Startup Built In Test.
2012-05-03T17:41:05.670Z,1336066865.670 [SBIT] Loaded
2012-05-03T17:41:05.671Z,1336066865.671 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-05-03T17:41:05.671Z,1336066865.671 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-05-03T17:41:05.695Z,1336066865.695 [IBIT] Loaded
2012-05-03T17:41:05.696Z,1336066865.696 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-05-03T17:41:05.703Z,1336066865.703 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-05-03T17:41:05.811Z,1336066865.811 [CBIT] Loaded
2012-05-03T17:41:05.811Z,1336066865.811 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-05-03T17:41:05.812Z,1336066865.812 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-05-03T17:41:05.812Z,1336066865.812 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-05-03T17:41:05.945Z,1336066865.945 [BuoyancyServo] Loaded
2012-05-03T17:41:05.945Z,1336066865.945 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-05-03T17:41:05.952Z,1336066865.952 [ElevatorServo] Loaded
2012-05-03T17:41:05.952Z,1336066865.952 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-05-03T17:41:05.959Z,1336066865.959 [MassServo] Loaded
2012-05-03T17:41:05.959Z,1336066865.959 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-05-03T17:41:05.966Z,1336066865.966 [RudderServo] Loaded
2012-05-03T17:41:05.966Z,1336066865.966 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-05-03T17:41:05.973Z,1336066865.973 [ThrusterServo] Loaded
2012-05-03T17:41:05.973Z,1336066865.973 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-05-03T17:41:05.974Z,1336066865.974 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-05-03T17:41:05.974Z,1336066865.974 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-05-03T17:41:05.989Z,1336066865.989 [DepthRateCalculator] Loaded
2012-05-03T17:41:05.989Z,1336066865.989 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-05-03T17:41:06.005Z,1336066866.005 [NavChart] Loaded
2012-05-03T17:41:06.005Z,1336066866.005 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-05-03T17:41:06.011Z,1336066866.011 [PitchRateCalculator] Loaded
2012-05-03T17:41:06.011Z,1336066866.011 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-05-03T17:41:06.017Z,1336066866.017 [SpeedCalculator] Loaded
2012-05-03T17:41:06.017Z,1336066866.017 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-05-03T17:41:06.032Z,1336066866.032 [TempGradientCalculator] Loaded
2012-05-03T17:41:06.032Z,1336066866.032 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-05-03T17:41:06.038Z,1336066866.038 [YawRateCalculator] Loaded
2012-05-03T17:41:06.038Z,1336066866.038 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-05-03T17:41:06.069Z,1336066866.069 [Navigation] Loaded
2012-05-03T17:41:06.069Z,1336066866.069 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-05-03T17:41:06.069Z,1336066866.069 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-05-03T17:41:06.070Z,1336066866.070 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-05-03T17:41:06.285Z,1336066866.285 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-05-03T17:41:06.285Z,1336066866.286 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-05-03T17:41:06.305Z,1336066866.305 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-05-03T17:41:06.306Z,1336066866.306 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-05-03T17:41:06.346Z,1336066866.346 [VerticalControl](DEBUG): Construct VerticalControl.
2012-05-03T17:41:06.389Z,1336066866.389 [VerticalControl] Loaded
2012-05-03T17:41:06.389Z,1336066866.389 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-05-03T17:41:06.391Z,1336066866.391 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-05-03T17:41:06.410Z,1336066866.410 [HorizontalControl] Loaded
2012-05-03T17:41:06.411Z,1336066866.411 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-05-03T17:41:06.412Z,1336066866.412 [SpeedControl](DEBUG): Construct SpeedControl.
2012-05-03T17:41:06.413Z,1336066866.413 [SpeedControl] Loaded
2012-05-03T17:41:06.414Z,1336066866.414 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-05-03T17:41:06.414Z,1336066866.414 [LoopControl](DEBUG): Construct LoopControl.
2012-05-03T17:41:06.415Z,1336066866.415 [LoopControl] Loaded
2012-05-03T17:41:06.415Z,1336066866.415 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-05-03T17:41:06.416Z,1336066866.416 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-05-03T17:41:06.416Z,1336066866.416 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-05-03T17:41:06.422Z,1336066866.422 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-05-03T17:41:06.426Z,1336066866.426 [AsyncPiEstimator] Loaded
2012-05-03T17:41:06.426Z,1336066866.427 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-05-03T17:41:06.428Z,1336066866.428 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1078994144
2012-05-03T17:41:06.428Z,1336066866.428 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-05-03T17:41:06.429Z,1336066866.429 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-05-03T17:41:06.522Z,1336066866.522 [AHRS_sp3003D] Loaded
2012-05-03T17:41:06.522Z,1336066866.522 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-05-03T17:41:06.775Z,1336066866.775 [Batt_Ocean_Server] Loaded
2012-05-03T17:41:06.775Z,1336066866.775 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-05-03T17:41:06.788Z,1336066866.788 [Depth_Keller] Loaded
2012-05-03T17:41:06.788Z,1336066866.788 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-05-03T17:41:06.793Z,1336066866.793 [DropWeight] Loaded
2012-05-03T17:41:06.793Z,1336066866.793 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-05-03T17:41:06.895Z,1336066866.895 [DVL_micro] Loaded
2012-05-03T17:41:06.896Z,1336066866.896 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2012-05-03T17:41:06.975Z,1336066866.975 [NAL9601] Loaded
2012-05-03T17:41:06.976Z,1336066866.976 [ComponentRegistry](DEBUG): SyncComponent "NAL9601" handled in the control thread.
2012-05-03T17:41:07.025Z,1336066867.025 [Onboard] Loaded
2012-05-03T17:41:07.026Z,1336066867.026 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-05-03T17:41:07.032Z,1336066867.032 [Radio_Freewave] Loaded
2012-05-03T17:41:07.032Z,1336066867.032 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-05-03T17:41:07.033Z,1336066867.033 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-05-03T17:41:07.033Z,1336066867.033 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-05-03T17:41:07.078Z,1336066867.078 [CTD_NeilBrown] Loaded
2012-05-03T17:41:07.078Z,1336066867.078 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-05-03T17:41:07.079Z,1336066867.079 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1079645408
2012-05-03T17:41:07.111Z,1336066867.111 [WetLabsBB2FL] Loaded
2012-05-03T17:41:07.111Z,1336066867.111 [ComponentRegistry](DEBUG): SyncComponent "WetLabsBB2FL" handled in the control thread.
2012-05-03T17:41:07.112Z,1336066867.112 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-05-03T17:41:07.114Z,1336066867.114 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-05-03T17:41:07.115Z,1336066867.115 [ComponentRegistry](DEBUG): SyncComponent "Maintainer" handled in the control thread.
2012-05-03T17:41:07.116Z,1336066867.115 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-05-03T17:41:07.121Z,1336066867.121 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-05-03T17:41:07.122Z,1336066867.122 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1079842016
2012-05-03T17:41:07.122Z,1336066867.122 [Supervisor](DEBUG): Running supervisor.
2012-05-03T17:41:07.125Z,1336066867.125 [controlThread](DEBUG): Initializing ControlThread
2012-05-03T17:41:07.126Z,1336066867.126 [InternalSim](DEBUG):  InternalSim initializing...
2012-05-03T17:41:07.161Z,1336066867.161 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-05-03T17:41:07.169Z,1336066867.169 [SBIT](INFO): Initialize SBIT Component.
2012-05-03T17:41:07.170Z,1336066867.170 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9626 $
2012-05-03T17:41:07.171Z,1336066867.171 [IBIT](INFO): Initialize IBIT Component.
2012-05-03T17:41:07.174Z,1336066867.174 [CBIT](DEBUG): Initialize CBIT Component.
2012-05-03T17:41:07.174Z,1336066867.174 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2012-05-03T17:41:07.175Z,1336066867.175 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-05-03T17:41:07.200Z,1336066867.200 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-05-03T17:41:07.200Z,1336066867.200 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-05-03T17:41:07.201Z,1336066867.201 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-05-03T17:41:07.201Z,1336066867.201 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-05-03T17:41:07.202Z,1336066867.202 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-05-03T17:41:07.205Z,1336066867.205 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-05-03T17:41:07.205Z,1336066867.205 [Navigation](DEBUG): Initializing Navigation.
2012-05-03T17:41:07.206Z,1336066867.205 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-05-03T17:41:07.208Z,1336066867.208 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-05-03T17:41:07.208Z,1336066867.208 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-05-03T17:41:07.209Z,1336066867.209 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-05-03T17:41:07.285Z,1336066867.285 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-05-03T17:41:07.290Z,1336066867.290 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-05-03T17:41:07.294Z,1336066867.294 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-05-03T17:41:07.298Z,1336066867.298 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-05-03T17:41:07.302Z,1336066867.302 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-05-03T17:41:07.303Z,1336066867.303 [NavChartDb](INFO): Creating index for Soundings
2012-05-03T17:41:07.306Z,1336066867.306 [NavChartDb](INFO): Creating index for Contour 0p0
2012-05-03T17:41:07.308Z,1336066867.308 [NavChartDb](INFO): Creating index for Contour 1p8
2012-05-03T17:41:07.310Z,1336066867.310 [NavChartDb](INFO): Creating index for Contour 3p6
2012-05-03T17:41:07.312Z,1336066867.312 [NavChartDb](INFO): Creating index for Contour 5p4
2012-05-03T17:41:07.314Z,1336066867.314 [NavChartDb](INFO): Creating index for Contour 9p1
2012-05-03T17:41:07.316Z,1336066867.316 [NavChartDb](INFO): Creating index for Contour 10p9
2012-05-03T17:41:07.318Z,1336066867.318 [NavChartDb](INFO): Creating index for Contour 18p2
2012-05-03T17:41:07.320Z,1336066867.320 [NavChartDb](INFO): Creating index for Contour 36p5
2012-05-03T17:41:07.322Z,1336066867.322 [NavChartDb](INFO): Creating index for Contour 54p8
2012-05-03T17:41:07.324Z,1336066867.324 [NavChartDb](INFO): Creating index for Contour 73p1
2012-05-03T17:41:07.326Z,1336066867.326 [NavChartDb](INFO): Creating index for Contour 91p4
2012-05-03T17:41:07.329Z,1336066867.329 [NavChartDb](INFO): Creating index for Contour 182p8
2012-05-03T17:41:07.331Z,1336066867.331 [NavChartDb](INFO): Creating index for Contour 365p7
2012-05-03T17:41:07.335Z,1336066867.335 [NavChartDb](INFO): Creating index for Contour 548p6
2012-05-03T17:41:07.336Z,1336066867.336 [NavChartDb](INFO): Creating index for Contour 731p5
2012-05-03T17:41:07.338Z,1336066867.339 [NavChartDb](INFO): Creating index for Contour 914p4
2012-05-03T17:41:07.340Z,1336066867.340 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-05-03T17:41:07.343Z,1336066867.343 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-05-03T17:41:07.345Z,1336066867.345 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-05-03T17:41:07.347Z,1336066867.347 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-05-03T17:41:07.349Z,1336066867.349 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-05-03T17:41:07.351Z,1336066867.351 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-05-03T17:41:07.353Z,1336066867.353 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-05-03T17:41:07.355Z,1336066867.355 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-05-03T17:41:07.357Z,1336066867.357 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-05-03T17:41:07.359Z,1336066867.359 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-05-03T17:41:07.361Z,1336066867.361 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-05-03T17:41:07.363Z,1336066867.363 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-05-03T17:41:07.365Z,1336066867.365 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-05-03T17:41:07.367Z,1336066867.367 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-05-03T17:41:07.369Z,1336066867.369 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-05-03T17:41:08.815Z,1336066868.815 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-05-03T17:41:08.820Z,1336066868.820 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-05-03T17:41:08.830Z,1336066868.830 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T17:41:08.842Z,1336066868.842 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

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

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

    </Aggregate>

</Mission>


2012-05-03T17:41:08.843Z,1336066868.843 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-05-03T17:41:08.870Z,1336066868.870 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-05-03T17:41:08.873Z,1336066868.873 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-05-03T17:41:08.876Z,1336066868.876 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T17:41:08.883Z,1336066868.883 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-05-03T17:41:08.886Z,1336066868.886 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T17:41:08.892Z,1336066868.892 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-05-03T17:41:08.901Z,1336066868.901 [Default:D.SetSpeed](DEBUG): Construct.
2012-05-03T17:41:08.904Z,1336066868.904 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-05-03T17:41:08.910Z,1336066868.910 [Default:F.Wait](DEBUG): Construct Wait.
2012-05-03T17:41:08.914Z,1336066868.914 [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 on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout><Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium" >

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

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

<!-- Run at low speed -->

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

    <Guidance:GoToSurface RunIn="Parallel"/>

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

</Mission>


2012-05-03T17:41:08.919Z,1336066868.919 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9601,Onboard,Radio_Freewave,WetLabsBB2FL,Depth_Keller,DepthRateCalculator,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintainer,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-05-03T17:41:08.938Z,1336066868.938 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-05-03T17:41:09.046Z,1336066869.046 [DVL_micro](DEBUG): Initializing DVL_micro.
2012-05-03T17:41:09.066Z,1336066869.066 [Radio_Freewave](INFO): Powering up
2012-05-03T17:41:09.071Z,1336066869.071 [WetLabsBB2FL](INFO): Powering down
2012-05-03T17:41:09.141Z,1336066869.141 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-05-03T17:41:09.142Z,1336066869.142 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-05-03T17:41:09.151Z,1336066869.151 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-05-03T17:41:09.152Z,1336066869.152 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-05-03T17:41:09.160Z,1336066869.160 [MassServo](DEBUG): Initializing EZServoServo.
2012-05-03T17:41:09.161Z,1336066869.161 [MassServo](DEBUG): Initializing MassServo.
2012-05-03T17:41:09.171Z,1336066869.171 [RudderServo](DEBUG): Initializing EZServoServo.
2012-05-03T17:41:09.172Z,1336066869.172 [RudderServo](DEBUG): Initializing RudderServo.
2012-05-03T17:41:09.180Z,1336066869.180 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-05-03T17:41:09.181Z,1336066869.181 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-05-03T17:41:12.061Z,1336066872.061 [NAL9601](INFO): Powering up NAL9601
2012-05-03T17:41:22.578Z,1336066882.578 [SBIT](IMPORTANT): Beginning Startup BIT
2012-05-03T17:41:22.580Z,1336066882.580 [CBIT](IMPORTANT): Beginning GF scan
2012-05-03T17:41:48.819Z,1336066908.819 [CBIT](IMPORTANT): No ground fault detected
2012-05-03T17:42:04.735Z,1336066924.735 [SBIT](IMPORTANT): SBIT PASSED
2012-05-03T17:42:05.165Z,1336066925.165 [MissionManager](IMPORTANT): Started mission Startup
2012-05-03T17:42:05.165Z,1336066925.165 [Startup] Running Loop=1
2012-05-03T17:42:05.165Z,1336066925.165 [Startup](INFO): Aggregate::initialize Startup
2012-05-03T17:42:05.165Z,1336066925.165 [Startup:A.GoToSurface] Running Loop=1
2012-05-03T17:42:05.165Z,1336066925.165 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:42:05.172Z,1336066925.172 [Startup:StartupSatComms] Running Loop=1
2012-05-03T17:42:05.172Z,1336066925.172 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-05-03T17:42:05.172Z,1336066925.172 [Startup:StartupSatComms:A] Running Loop=1
2012-05-03T17:42:05.528Z,1336066925.528 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T17:42:17.583Z,1336066937.583 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:42:18.721Z,1336066938.721 [NAL9601](IMPORTANT): GPS fix at: 1336066941.00
2012-05-03T17:42:18.734Z,1336066938.734 [Startup:StartupSatComms:A] Stopped
2012-05-03T17:42:18.734Z,1336066938.734 [Startup:StartupSatComms:B] Running Loop=1
2012-05-03T17:42:19.133Z,1336066939.133 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T17:42:36.244Z,1336066956.244 [NAL9601](INFO): SBD MO Status=1, MOMSN=5871, MT Status=0, MTMSN=0
2012-05-03T17:42:36.443Z,1336066956.443 [NAL9601](INFO): Sent 204 bytes from file Logs/20120503T152308/shore0015.lzma
2012-05-03T17:42:36.443Z,1336066956.443 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:42:36.444Z,1336066956.444 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000000
2012-05-03T17:42:43.964Z,1336066963.964 [NAL9601](INFO): SBD MO Status=1, MOMSN=5872, MT Status=0, MTMSN=0
2012-05-03T17:42:44.131Z,1336066964.131 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T174102/shore0000.lzma
2012-05-03T17:42:44.131Z,1336066964.131 [NAL9601](INFO): Packets left to send: 1
2012-05-03T17:42:44.132Z,1336066964.132 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000001
2012-05-03T17:42:53.658Z,1336066973.658 [NAL9601](INFO): SBD MO Status=1, MOMSN=5873, MT Status=0, MTMSN=0
2012-05-03T17:42:53.815Z,1336066973.815 [NAL9601](INFO): Sent 312 bytes from file Logs/20120503T174102/shore0000.lzma
2012-05-03T17:42:53.815Z,1336066973.815 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:42:53.816Z,1336066973.816 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000002
2012-05-03T17:43:00.900Z,1336066980.899 [NAL9601](INFO): SBD MO Status=0, MOMSN=5874, MT Status=0, MTMSN=0
2012-05-03T17:43:01.124Z,1336066981.124 [Startup:StartupSatComms:B] Stopped
2012-05-03T17:43:01.124Z,1336066981.124 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-05-03T17:43:01.124Z,1336066981.125 [Startup:StartupSatComms] Stopped
2012-05-03T17:43:01.125Z,1336066981.125 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-05-03T17:43:01.125Z,1336066981.125 [Startup](INFO): Completed Startup
2012-05-03T17:43:01.125Z,1336066981.125 [Startup] Stopped
2012-05-03T17:43:01.126Z,1336066981.126 [Startup](INFO): Aggregate::uninitialize Startup
2012-05-03T17:43:01.126Z,1336066981.126 [Startup:A.GoToSurface] Stopped
2012-05-03T17:43:01.126Z,1336066981.126 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:43:01.296Z,1336066981.296 [MissionManager](IMPORTANT): Started mission Default
2012-05-03T17:43:01.296Z,1336066981.296 [Default] Running Loop=1
2012-05-03T17:43:01.297Z,1336066981.297 [Default](INFO): Aggregate::initialize Default
2012-05-03T17:43:01.297Z,1336066981.297 [Default:D.SetSpeed] Running Loop=1
2012-05-03T17:43:01.297Z,1336066981.297 [Default:D.SetSpeed](DEBUG): Initialize.
2012-05-03T17:43:01.297Z,1336066981.297 [Default:E.GoToSurface] Running Loop=1
2012-05-03T17:43:01.297Z,1336066981.297 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium] Running Loop=1
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:43:01.298Z,1336066981.298 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:43:01.299Z,1336066981.299 [Default:E.GoToSurface] Running Loop=1
2012-05-03T17:43:01.305Z,1336066981.305 [Default:D.SetSpeed] Running Loop=1
2012-05-03T17:43:01.315Z,1336066981.315 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:43:01.315Z,1336066981.315 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:43:01.315Z,1336066981.316 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:43:01.316Z,1336066981.316 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:43:01.320Z,1336066981.320 [Default:GPS] Running Loop=1
2012-05-03T17:43:01.320Z,1336066981.320 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:43:01.321Z,1336066981.321 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:43:01.321Z,1336066981.321 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:43:01.321Z,1336066981.321 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:43:01.321Z,1336066981.321 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:43:01.326Z,1336066981.326 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:43:01.327Z,1336066981.327 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:43:01.327Z,1336066981.327 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:43:01.327Z,1336066981.327 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:43:01.687Z,1336066981.687 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-05-03T17:43:01.689Z,1336066981.689 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-05-03T17:43:03.271Z,1336066983.271 [NAL9601](IMPORTANT): GPS fix at: 1336066986.00
2012-05-03T17:43:03.342Z,1336066983.342 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:43:03.342Z,1336066983.342 [Default:GPS:D] Running Loop=1
2012-05-03T17:43:03.683Z,1336066983.683 [Default:GPS:D] Stopped
2012-05-03T17:43:03.683Z,1336066983.683 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:43:03.683Z,1336066983.683 [Default:GPS] Stopped
2012-05-03T17:43:03.683Z,1336066983.683 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:43:03.683Z,1336066983.684 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:43:03.684Z,1336066983.684 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:43:18.438Z,1336066998.438 [NAL9601](INFO): SBD MO Status=1, MOMSN=5875, MT Status=0, MTMSN=0
2012-05-03T17:43:18.575Z,1336066998.575 [NAL9601](INFO): Sent 164 bytes from file Logs/20120503T174102/shore0001.lzma
2012-05-03T17:43:18.575Z,1336066998.575 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:43:18.576Z,1336066998.576 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000003
2012-05-03T17:43:26.502Z,1336067006.502 [NAL9601](INFO): SBD MO Status=0, MOMSN=5876, MT Status=0, MTMSN=0
2012-05-03T17:43:26.676Z,1336067006.676 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:43:26.677Z,1336067006.677 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T17:43:26.677Z,1336067006.677 [Default:Iridium] Stopped
2012-05-03T17:43:26.677Z,1336067006.677 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:43:26.677Z,1336067006.677 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:43:26.677Z,1336067006.677 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:43:26.677Z,1336067006.677 [Default:F.Wait] Running Loop=1
2012-05-03T17:43:26.677Z,1336067006.677 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-05-03T17:43:37.116Z,1336067017.116 [NAL9601](INFO): Powering down
2012-05-03T17:48:27.180Z,1336067307.180 [Default:CallIridium] Running Loop=1
2012-05-03T17:48:27.181Z,1336067307.181 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T17:48:27.181Z,1336067307.181 [Default:CallIridium:A] Running Loop=1
2012-05-03T17:48:27.183Z,1336067307.183 [Default:CallIridium:A] Stopped
2012-05-03T17:48:27.184Z,1336067307.184 [Default:CallIridium:B] Running Loop=1
2012-05-03T17:48:27.184Z,1336067307.184 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T17:48:32.003Z,1336067312.003 [Default:Iridium] Running Loop=1
2012-05-03T17:48:32.004Z,1336067312.003 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:48:32.004Z,1336067312.004 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:48:32.004Z,1336067312.004 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:48:32.004Z,1336067312.004 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:48:32.004Z,1336067312.004 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:48:32.005Z,1336067312.005 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:48:32.005Z,1336067312.005 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:48:32.005Z,1336067312.005 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:48:32.005Z,1336067312.005 [Default:GPS] Running Loop=1
2012-05-03T17:48:32.006Z,1336067312.006 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:48:32.006Z,1336067312.006 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:48:32.006Z,1336067312.006 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:48:32.006Z,1336067312.006 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:48:32.006Z,1336067312.006 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:48:32.008Z,1336067312.008 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:48:32.008Z,1336067312.008 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:48:32.008Z,1336067312.008 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:48:32.640Z,1336067312.640 [NAL9601](INFO): Powering up
2012-05-03T17:49:38.067Z,1336067378.067 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:49:39.219Z,1336067379.219 [NAL9601](IMPORTANT): GPS fix at: 1336067383.00
2012-05-03T17:49:39.234Z,1336067379.234 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:49:39.234Z,1336067379.234 [Default:GPS:D] Running Loop=1
2012-05-03T17:49:39.631Z,1336067379.631 [Default:GPS:D] Stopped
2012-05-03T17:49:39.632Z,1336067379.632 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:49:39.632Z,1336067379.632 [Default:GPS] Stopped
2012-05-03T17:49:39.632Z,1336067379.632 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:49:39.632Z,1336067379.632 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:49:39.632Z,1336067379.632 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:50:05.628Z,1336067405.628 [NAL9601](INFO): SBD MO Status=1, MOMSN=5877, MT Status=0, MTMSN=0
2012-05-03T17:50:05.811Z,1336067405.811 [NAL9601](INFO): Sent 280 bytes from file Logs/20120503T174102/shore0002.lzma
2012-05-03T17:50:05.811Z,1336067405.811 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:50:05.812Z,1336067405.812 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000004
2012-05-03T17:50:16.430Z,1336067416.430 [NAL9601](INFO): SBD MO Status=0, MOMSN=5878, MT Status=0, MTMSN=0
2012-05-03T17:50:16.627Z,1336067416.627 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:50:16.628Z,1336067416.628 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T17:50:16.628Z,1336067416.628 [Default:Iridium] Stopped
2012-05-03T17:50:16.628Z,1336067416.628 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:50:16.628Z,1336067416.628 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:50:16.628Z,1336067416.628 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:50:16.866Z,1336067416.866 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T17:50:16.867Z,1336067416.866 [Default:CallIridium:B] Stopped
2012-05-03T17:50:16.867Z,1336067416.867 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T17:50:16.867Z,1336067416.867 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T17:50:16.867Z,1336067416.867 [Default:CallIridium] Stopped
2012-05-03T17:50:16.867Z,1336067416.867 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T17:50:26.968Z,1336067426.968 [NAL9601](INFO): Powering down
2012-05-03T17:55:16.974Z,1336067716.974 [Default:CallIridium] Running Loop=1
2012-05-03T17:55:16.990Z,1336067716.990 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T17:55:16.991Z,1336067716.991 [Default:CallIridium:A] Running Loop=1
2012-05-03T17:55:16.991Z,1336067716.991 [Default:CallIridium:A] Stopped
2012-05-03T17:55:16.991Z,1336067716.991 [Default:CallIridium:B] Running Loop=1
2012-05-03T17:55:16.991Z,1336067716.991 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium] Running Loop=1
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T17:55:22.010Z,1336067722.010 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:55:22.011Z,1336067722.011 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T17:55:22.011Z,1336067722.011 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:55:22.011Z,1336067722.011 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS] Running Loop=1
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T17:55:22.012Z,1336067722.012 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T17:55:22.013Z,1336067722.013 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T17:55:22.013Z,1336067722.013 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T17:55:22.013Z,1336067722.013 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T17:55:22.708Z,1336067722.708 [NAL9601](INFO): Powering up
2012-05-03T17:56:28.435Z,1336067788.435 [NAL9601](INFO): NAL9601 initialized
2012-05-03T17:56:29.577Z,1336067789.577 [NAL9601](IMPORTANT): GPS fix at: 1336067794.00
2012-05-03T17:56:29.593Z,1336067789.593 [Default:GPS:Read_GPS] Stopped
2012-05-03T17:56:29.593Z,1336067789.593 [Default:GPS:D] Running Loop=1
2012-05-03T17:56:29.928Z,1336067789.928 [Default:GPS:D] Stopped
2012-05-03T17:56:29.928Z,1336067789.928 [Default:GPS](INFO): Completed Default:GPS
2012-05-03T17:56:29.928Z,1336067789.928 [Default:GPS] Stopped
2012-05-03T17:56:29.929Z,1336067789.929 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T17:56:29.929Z,1336067789.929 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T17:56:29.929Z,1336067789.929 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:56:49.069Z,1336067809.069 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5879, MT Status=1, MTMSN=2576
2012-05-03T17:56:49.187Z,1336067809.187 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T174102/shore0003.lzma
2012-05-03T17:56:49.187Z,1336067809.187 [NAL9601](INFO): Packets left to send: 1
2012-05-03T17:56:49.188Z,1336067809.188 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000005
2012-05-03T17:56:49.743Z,1336067809.743 [NAL9601](IMPORTANT): Initialized file: Config/lrauv-daphne/Control.cfg
2012-05-03T17:56:49.744Z,1336067809.744 [NAL9601](IMPORTANT): More data left to go, at position 74
2012-05-03T17:57:03.018Z,1336067823.017 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5880, MT Status=1, MTMSN=2577
2012-05-03T17:57:03.171Z,1336067823.171 [NAL9601](INFO): Sent 2 bytes from file Logs/20120503T174102/shore0003.lzma
2012-05-03T17:57:03.171Z,1336067823.171 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:57:03.172Z,1336067823.172 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000006
2012-05-03T17:57:03.582Z,1336067823.582 [NAL9601](IMPORTANT): Added data to file: Config/lrauv-daphne/Control.cfg
2012-05-03T17:57:06.993Z,1336067826.993 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4FA2C2E5.part | gunzip -f -d | cat `cp Config/lrauv-daphne/.svn/text-base/Control.cfg.svn-base Config/lrauv-daphne/Control.cfg` | vim -e Config/lrauv-daphne/Control.cfg
2012-05-03T17:57:07.080Z,1336067827.080 [CommandLine](IMPORTANT): e3c2b59bfebc3821de9456b35ea38564  Config/lrauv-daphne/Control.cfg

2012-05-03T17:57:16.322Z,1336067836.322 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=5881, MT Status=1, MTMSN=2578
2012-05-03T17:57:16.999Z,1336067836.999 [NAL9601](IMPORTANT): Initialized file: Config/logger.cfg
2012-05-03T17:57:17.000Z,1336067837.000 [NAL9601](IMPORTANT): More data left to go, at position 90
2012-05-03T17:57:25.693Z,1336067845.693 [NAL9601](IMPORTANT): SBD MO Status=0, MOMSN=5882, MT Status=1, MTMSN=2579
2012-05-03T17:57:26.358Z,1336067846.358 [NAL9601](IMPORTANT): Added data to file: Config/logger.cfg
2012-05-03T17:57:29.391Z,1336067849.391 [NAL9601](IMPORTANT): Success executing cat Logs/latest/4FA2C573.part | gunzip -f -d | cat `cp Config/.svn/text-base/logger.cfg.svn-base Config/logger.cfg` | vim -e Config/logger.cfg
2012-05-03T17:57:29.451Z,1336067849.451 [CommandLine](IMPORTANT): 6f788bf31d8483c331d627f9387ac42e  Config/logger.cfg

2012-05-03T17:57:37.022Z,1336067857.022 [NAL9601](INFO): SBD MO Status=0, MOMSN=5883, MT Status=0, MTMSN=0
2012-05-03T17:57:50.179Z,1336067870.179 [NAL9601](INFO): SBD MO Status=1, MOMSN=5884, MT Status=0, MTMSN=0
2012-05-03T17:57:50.395Z,1336067870.395 [NAL9601](INFO): Sent 332 bytes from file Logs/20120503T174102/shore0004.lzma
2012-05-03T17:57:50.395Z,1336067870.395 [NAL9601](INFO): Packets left to send: 1
2012-05-03T17:57:50.396Z,1336067870.396 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000007
2012-05-03T17:57:57.857Z,1336067877.857 [NAL9601](INFO): SBD MO Status=1, MOMSN=5885, MT Status=0, MTMSN=0
2012-05-03T17:57:57.983Z,1336067877.983 [NAL9601](INFO): Sent 224 bytes from file Logs/20120503T174102/shore0004.lzma
2012-05-03T17:57:57.983Z,1336067877.983 [NAL9601](INFO): Packets left to send: 0
2012-05-03T17:57:57.984Z,1336067877.984 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000008
2012-05-03T17:58:05.985Z,1336067885.985 [NAL9601](INFO): SBD MO Status=0, MOMSN=5886, MT Status=0, MTMSN=0
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium](INFO): Completed Default:Iridium
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium] Stopped
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T17:58:06.191Z,1336067886.191 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T17:58:06.372Z,1336067886.372 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-05-03T17:58:06.373Z,1336067886.372 [Default:CallIridium:B] Stopped
2012-05-03T17:58:06.373Z,1336067886.373 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T17:58:06.373Z,1336067886.373 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-05-03T17:58:06.373Z,1336067886.373 [Default:CallIridium] Stopped
2012-05-03T17:58:06.373Z,1336067886.373 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T17:58:16.527Z,1336067896.527 [NAL9601](INFO): Powering down
2012-05-03T18:03:06.525Z,1336068186.525 [Default:CallIridium] Running Loop=1
2012-05-03T18:03:06.525Z,1336068186.525 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-05-03T18:03:06.525Z,1336068186.525 [Default:CallIridium:A] Running Loop=1
2012-05-03T18:03:06.526Z,1336068186.526 [Default:CallIridium:A] Stopped
2012-05-03T18:03:06.526Z,1336068186.526 [Default:CallIridium:B] Running Loop=1
2012-05-03T18:03:06.526Z,1336068186.526 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-05-03T18:03:11.491Z,1336068191.491 [Default:Iridium] Running Loop=1
2012-05-03T18:03:11.491Z,1336068191.491 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-05-03T18:03:11.491Z,1336068191.491 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-05-03T18:03:11.491Z,1336068191.491 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-05-03T18:03:11.492Z,1336068191.492 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-05-03T18:03:11.492Z,1336068191.492 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T18:03:11.493Z,1336068191.493 [Default:Iridium:B.GoToSurface] Stopped
2012-05-03T18:03:11.493Z,1336068191.493 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T18:03:11.493Z,1336068191.493 [Default:Iridium:Read_Iridium] Running Loop=1
2012-05-03T18:03:11.493Z,1336068191.493 [Default:GPS] Running Loop=1
2012-05-03T18:03:11.493Z,1336068191.493 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-05-03T18:03:11.493Z,1336068191.493 [Default:GPS:A.SetSpeed] Running Loop=1
2012-05-03T18:03:11.493Z,1336068191.493 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-05-03T18:03:11.494Z,1336068191.494 [Default:GPS:B.GoToSurface] Running Loop=1
2012-05-03T18:03:11.494Z,1336068191.494 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-05-03T18:03:11.497Z,1336068191.497 [Default:GPS:B.GoToSurface] Stopped
2012-05-03T18:03:11.497Z,1336068191.497 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T18:03:11.497Z,1336068191.497 [Default:GPS:Read_GPS] Running Loop=1
2012-05-03T18:03:12.158Z,1336068192.158 [NAL9601](INFO): Powering up
2012-05-03T18:04:17.783Z,1336068257.783 [NAL9601](INFO): NAL9601 initialized
2012-05-03T18:04:36.430Z,1336068276.430 [NAL9601](IMPORTANT): SBD MO Status=1, MOMSN=5887, MT Status=1, MTMSN=2580
2012-05-03T18:04:36.647Z,1336068276.647 [NAL9601](INFO): Sent 121 bytes from file Logs/20120503T174102/shore0005.lzma
2012-05-03T18:04:36.647Z,1336068276.647 [NAL9601](INFO): Packets left to send: 0
2012-05-03T18:04:36.648Z,1336068276.648 [NAL9601](INFO): Stored copy of sent data in Logs/latest/sent0000009
2012-05-03T18:04:36.960Z,1336068276.960 [NAL9601](INFO): Received command:restart application
2012-05-03T18:04:37.003Z,1336068277.003 [CommandLine](IMPORTANT): got command restart application
2012-05-03T18:04:37.102Z,1336068277.102 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2012-05-03T18:04:37.103Z,1336068277.103 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2012-05-03T18:04:37.708Z,1336068277.708 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2012-05-03T18:04:37.808Z,1336068277.807 [CTD_NeilBrown](INFO): Powering down
2012-05-03T18:04:37.808Z,1336068277.808 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2012-05-03T18:04:37.833Z,1336068277.833 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2012-05-03T18:04:37.833Z,1336068277.833 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2012-05-03T18:04:37.833Z,1336068277.833 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2012-05-03T18:04:38.082Z,1336068278.082 [controlThread](DEBUG): Uninitializing ControlThread
2012-05-03T18:04:38.082Z,1336068278.082 [AHRS_sp3003D](INFO): Powering down
2012-05-03T18:04:38.172Z,1336068278.172 [DVL_micro](INFO): Powering down
2012-05-03T18:04:38.172Z,1336068278.172 [NAL9601](INFO): Powering down
2012-05-03T18:04:38.173Z,1336068278.173 [WetLabsBB2FL](INFO): Powering down
2012-05-03T18:04:38.174Z,1336068278.174 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2012-05-03T18:04:38.175Z,1336068278.175 [Default] Stopped
2012-05-03T18:04:38.175Z,1336068278.175 [Default](INFO): Aggregate::uninitialize Default
2012-05-03T18:04:38.175Z,1336068278.175 [Default:GPS] Stopped
2012-05-03T18:04:38.175Z,1336068278.175 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-05-03T18:04:38.175Z,1336068278.175 [Default:GPS:A.SetSpeed] Stopped
2012-05-03T18:04:38.176Z,1336068278.175 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T18:04:38.176Z,1336068278.176 [Default:GPS:Read_GPS] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:Iridium] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-05-03T18:04:38.176Z,1336068278.176 [Default:Iridium:A.SetSpeed] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-05-03T18:04:38.176Z,1336068278.176 [Default:Iridium:Read_Iridium] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:CallIridium] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-05-03T18:04:38.176Z,1336068278.176 [Default:CallIridium:B] Stopped
2012-05-03T18:04:38.176Z,1336068278.176 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-05-03T18:04:38.176Z,1336068278.176 [Default:D.SetSpeed] Stopped
2012-05-03T18:04:38.176Z,1336068278.177 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-05-03T18:04:38.177Z,1336068278.177 [Default:E.GoToSurface] Stopped
2012-05-03T18:04:38.177Z,1336068278.177 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-05-03T18:04:38.177Z,1336068278.177 [Default:F.Wait] Stopped
2012-05-03T18:04:38.177Z,1336068278.177 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-05-03T18:04:38.181Z,1336068278.181 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2012-05-03T18:04:38.182Z,1336068278.182 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2012-05-03T18:04:38.182Z,1336068278.182 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2012-05-03T18:04:38.183Z,1336068278.182 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2012-05-03T18:04:38.183Z,1336068278.183 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2012-05-03T18:04:38.183Z,1336068278.183 [BuoyancyServo](INFO): Powering down
2012-05-03T18:04:38.184Z,1336068278.184 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2012-05-03T18:04:38.184Z,1336068278.184 [ElevatorServo](INFO): Powering down
2012-05-03T18:04:38.184Z,1336068278.184 [MassServo](DEBUG): Uninitialize Mass Servo.
2012-05-03T18:04:38.184Z,1336068278.184 [MassServo](INFO): Powering down
2012-05-03T18:04:38.185Z,1336068278.185 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2012-05-03T18:04:38.185Z,1336068278.185 [RudderServo](INFO): Powering down
2012-05-03T18:04:38.185Z,1336068278.185 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-05-03T18:04:38.185Z,1336068278.185 [ThrusterServo](INFO): Powering down
2012-05-03T18:04:38.186Z,1336068278.186 [SBIT](DEBUG): Uninitialize SBIT Component.
2012-05-03T18:04:38.186Z,1336068278.186 [IBIT](DEBUG): Uninitialize IBIT Component.
2012-05-03T18:04:38.186Z,1336068278.186 [CBIT](DEBUG): Uninitialize CBIT Component.