2013-06-03T21:45:50.404Z,1370295950.404 [Supervisor](DEBUG): Initializing supervisor.
2013-06-03T21:45:50.408Z,1370295950.408 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0
2013-06-03T21:45:50.409Z,1370295950.409 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2013-06-03T21:45:50.410Z,1370295950.410 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0
2013-06-03T21:45:50.459Z,1370295950.459 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2013-06-03T21:45:50.486Z,1370295950.486 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2013-06-03T21:45:50.496Z,1370295950.496 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0
2013-06-03T21:45:50.497Z,1370295950.497 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2013-06-03T21:45:50.503Z,1370295950.503 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0
2013-06-03T21:45:50.503Z,1370295950.503 [Supervisor](INFO): Looking for Config files in directory: Config/
2013-06-03T21:45:50.538Z,1370295950.538 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2013-06-03T21:45:51.386Z,1370295951.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2013-06-03T21:45:51.387Z,1370295951.387 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2013-06-03T21:45:51.793Z,1370295951.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2013-06-03T21:45:51.794Z,1370295951.794 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2013-06-03T21:45:51.928Z,1370295951.928 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2013-06-03T21:45:51.945Z,1370295951.945 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2013-06-03T21:45:52.225Z,1370295952.225 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2013-06-03T21:45:52.226Z,1370295952.226 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2013-06-03T21:45:52.489Z,1370295952.489 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2013-06-03T21:45:52.491Z,1370295952.491 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2013-06-03T21:45:52.976Z,1370295952.977 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2013-06-03T21:45:52.977Z,1370295952.977 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2013-06-03T21:45:53.299Z,1370295953.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2013-06-03T21:45:53.303Z,1370295953.303 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2013-06-03T21:45:53.807Z,1370295953.807 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2013-06-03T21:45:53.807Z,1370295953.807 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2013-06-03T21:45:53.991Z,1370295953.991 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2013-06-03T21:45:53.992Z,1370295953.992 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2013-06-03T21:45:54.848Z,1370295954.848 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2013-06-03T21:45:54.849Z,1370295954.849 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2013-06-03T21:45:55.042Z,1370295955.042 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2013-06-03T21:45:55.043Z,1370295955.043 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2013-06-03T21:45:55.201Z,1370295955.201 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2013-06-03T21:45:55.211Z,1370295955.211 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2013-06-03T21:45:55.399Z,1370295955.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2013-06-03T21:45:55.665Z,1370295955.665 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2013-06-03T21:45:55.821Z,1370295955.821 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2013-06-03T21:45:56.015Z,1370295956.015 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2013-06-03T21:45:56.213Z,1370295956.213 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2013-06-03T21:45:56.447Z,1370295956.447 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2013-06-03T21:45:56.616Z,1370295956.616 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2013-06-03T21:45:56.777Z,1370295956.777 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2013-06-03T21:45:56.777Z,1370295956.777 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2013-06-03T21:45:56.786Z,1370295956.786 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2013-06-03T21:45:57.155Z,1370295957.155 [InternalSim] Loaded
2013-06-03T21:45:57.155Z,1370295957.155 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2013-06-03T21:45:57.156Z,1370295957.156 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2013-06-03T21:45:57.157Z,1370295957.157 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2013-06-03T21:45:57.317Z,1370295957.317 [SBIT](DEBUG): Construct Startup Built In Test.
2013-06-03T21:45:57.380Z,1370295957.380 [SBIT] Loaded
2013-06-03T21:45:57.380Z,1370295957.381 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2013-06-03T21:45:57.382Z,1370295957.382 [IBIT](DEBUG): Construct Initiated Built In Test.
2013-06-03T21:45:57.442Z,1370295957.442 [IBIT] Loaded
2013-06-03T21:45:57.442Z,1370295957.442 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2013-06-03T21:45:57.445Z,1370295957.445 [CBIT](DEBUG): Construct CBIT Built In Test.
2013-06-03T21:45:57.685Z,1370295957.685 [CBIT] Loaded
2013-06-03T21:45:57.685Z,1370295957.685 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2013-06-03T21:45:57.685Z,1370295957.685 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2013-06-03T21:45:57.686Z,1370295957.686 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2013-06-03T21:45:57.922Z,1370295957.921 [BuoyancyServo] Loaded
2013-06-03T21:45:57.922Z,1370295957.922 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2013-06-03T21:45:57.935Z,1370295957.935 [ElevatorServo] Loaded
2013-06-03T21:45:57.935Z,1370295957.935 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2013-06-03T21:45:57.978Z,1370295957.978 [MassServo] Loaded
2013-06-03T21:45:57.979Z,1370295957.978 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2013-06-03T21:45:58.003Z,1370295958.003 [RudderServo] Loaded
2013-06-03T21:45:58.003Z,1370295958.003 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2013-06-03T21:45:58.027Z,1370295958.027 [ThrusterServo] Loaded
2013-06-03T21:45:58.027Z,1370295958.027 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2013-06-03T21:45:58.027Z,1370295958.027 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2013-06-03T21:45:58.040Z,1370295958.040 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2013-06-03T21:45:58.093Z,1370295958.092 [DepthRateCalculator] Loaded
2013-06-03T21:45:58.093Z,1370295958.093 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2013-06-03T21:46:04.453Z,1370295964.453 [HFRadarModelCalc] Loaded
2013-06-03T21:46:04.454Z,1370295964.454 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2013-06-03T21:46:04.481Z,1370295964.481 [NavChart] Loaded
2013-06-03T21:46:04.481Z,1370295964.481 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2013-06-03T21:46:04.491Z,1370295964.491 [PitchRateCalculator] Loaded
2013-06-03T21:46:04.491Z,1370295964.491 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2013-06-03T21:46:04.522Z,1370295964.522 [SpeedCalculator] Loaded
2013-06-03T21:46:04.522Z,1370295964.522 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2013-06-03T21:46:04.549Z,1370295964.549 [TempGradientCalculator] Loaded
2013-06-03T21:46:04.549Z,1370295964.549 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2013-06-03T21:46:04.575Z,1370295964.575 [YawRateCalculator] Loaded
2013-06-03T21:46:04.575Z,1370295964.575 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2013-06-03T21:46:04.665Z,1370295964.665 [Navigation] Loaded
2013-06-03T21:46:04.666Z,1370295964.666 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2013-06-03T21:46:04.666Z,1370295964.666 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2013-06-03T21:46:04.667Z,1370295964.667 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2013-06-03T21:46:05.185Z,1370295965.185 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2013-06-03T21:46:05.187Z,1370295965.187 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2013-06-03T21:46:05.250Z,1370295965.250 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2013-06-03T21:46:05.251Z,1370295965.251 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2013-06-03T21:46:05.373Z,1370295965.373 [VerticalControl](DEBUG): Construct VerticalControl.
2013-06-03T21:46:05.621Z,1370295965.621 [VerticalControl] Loaded
2013-06-03T21:46:05.622Z,1370295965.622 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2013-06-03T21:46:05.623Z,1370295965.622 [HorizontalControl](DEBUG): Construct HorizontalControl.
2013-06-03T21:46:05.755Z,1370295965.755 [HorizontalControl] Loaded
2013-06-03T21:46:05.756Z,1370295965.756 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2013-06-03T21:46:05.762Z,1370295965.762 [SpeedControl](DEBUG): Construct SpeedControl.
2013-06-03T21:46:05.769Z,1370295965.769 [SpeedControl] Loaded
2013-06-03T21:46:05.770Z,1370295965.770 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2013-06-03T21:46:05.771Z,1370295965.770 [LoopControl](DEBUG): Construct LoopControl.
2013-06-03T21:46:05.771Z,1370295965.771 [LoopControl] Loaded
2013-06-03T21:46:05.771Z,1370295965.771 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2013-06-03T21:46:05.772Z,1370295965.772 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2013-06-03T21:46:05.772Z,1370295965.772 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2013-06-03T21:46:05.781Z,1370295965.781 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2013-06-03T21:46:05.792Z,1370295965.792 [AsyncPiEstimator] Loaded
2013-06-03T21:46:05.792Z,1370295965.792 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2013-06-03T21:46:05.800Z,1370295965.800 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 4063B4E0
2013-06-03T21:46:05.801Z,1370295965.801 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2013-06-03T21:46:05.808Z,1370295965.808 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2013-06-03T21:46:06.241Z,1370295966.241 [AHRS_sp3003D] Loaded
2013-06-03T21:46:06.241Z,1370295966.241 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2013-06-03T21:46:06.781Z,1370295966.782 [Batt_Ocean_Server] Loaded
2013-06-03T21:46:06.782Z,1370295966.782 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2013-06-03T21:46:06.799Z,1370295966.799 [Depth_Keller] Loaded
2013-06-03T21:46:06.799Z,1370295966.799 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2013-06-03T21:46:06.809Z,1370295966.809 [DropWeight] Loaded
2013-06-03T21:46:06.809Z,1370295966.809 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2013-06-03T21:46:07.213Z,1370295967.213 [DVL_micro] Loaded
2013-06-03T21:46:07.214Z,1370295967.214 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2013-06-03T21:46:07.228Z,1370295967.228 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406C34E0
2013-06-03T21:46:07.435Z,1370295967.435 [NAL9602] Loaded
2013-06-03T21:46:07.435Z,1370295967.435 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2013-06-03T21:46:07.545Z,1370295967.545 [Onboard] Loaded
2013-06-03T21:46:07.545Z,1370295967.545 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2013-06-03T21:46:07.561Z,1370295967.561 [Radio_Freewave] Loaded
2013-06-03T21:46:07.562Z,1370295967.562 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2013-06-03T21:46:07.883Z,1370295967.883 [DAT] Loaded
2013-06-03T21:46:07.883Z,1370295967.883 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2013-06-03T21:46:07.890Z,1370295967.890 [SCPI] Loaded
2013-06-03T21:46:07.890Z,1370295967.890 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2013-06-03T21:46:07.891Z,1370295967.891 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2013-06-03T21:46:07.891Z,1370295967.891 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2013-06-03T21:46:08.067Z,1370295968.067 [CTD_NeilBrown] Loaded
2013-06-03T21:46:08.068Z,1370295968.068 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2013-06-03T21:46:08.073Z,1370295968.073 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407154E0
2013-06-03T21:46:08.134Z,1370295968.134 [WetLabsBB2FL] Loaded
2013-06-03T21:46:08.134Z,1370295968.134 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2013-06-03T21:46:08.144Z,1370295968.144 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407454E0
2013-06-03T21:46:08.145Z,1370295968.145 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2013-06-03T21:46:08.147Z,1370295968.147 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2013-06-03T21:46:08.148Z,1370295968.148 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2013-06-03T21:46:08.154Z,1370295968.155 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2013-06-03T21:46:08.164Z,1370295968.164 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407754E0
2013-06-03T21:46:08.169Z,1370295968.169 [Supervisor](DEBUG): Running supervisor.
2013-06-03T21:46:08.170Z,1370295968.170 [CommandLine](INFO): Thread ID is 4954
2013-06-03T21:46:08.181Z,1370295968.181 [controlThread](INFO): Thread ID is 4953
2013-06-03T21:46:08.181Z,1370295968.181 [controlThread](DEBUG): Initializing ControlThread
2013-06-03T21:46:08.181Z,1370295968.181 [CycleStarter](INFO): Thread ID is 4952
2013-06-03T21:46:08.182Z,1370295968.182 [InternalSim](DEBUG):  InternalSim initializing...
2013-06-03T21:46:08.219Z,1370295968.219 [logger](INFO): Thread ID is 4955
2013-06-03T21:46:08.413Z,1370295968.413 [AsyncPiEstimator](INFO): Thread ID is 5016
2013-06-03T21:46:08.413Z,1370295968.413 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2013-06-03T21:46:08.572Z,1370295968.572 [DVL_micro](INFO): Thread ID is 5017
2013-06-03T21:46:08.737Z,1370295968.737 [CTD_NeilBrown](INFO): Thread ID is 5018
2013-06-03T21:46:08.737Z,1370295968.737 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2013-06-03T21:46:08.741Z,1370295968.741 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2013-06-03T21:46:08.789Z,1370295968.789 [WetLabsBB2FL](INFO): Thread ID is 5019
2013-06-03T21:46:08.790Z,1370295968.790 [WetLabsBB2FL](INFO): Powering down
2013-06-03T21:46:08.942Z,1370295968.941 [DVL_micro](INFO): Initializing
2013-06-03T21:46:08.942Z,1370295968.942 [DVL_micro](INFO): start:Powering up
2013-06-03T21:46:08.943Z,1370295968.943 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-06-03T21:46:08.948Z,1370295968.948 [DVL_micro](INFO): Cycling power to configure device.
2013-06-03T21:46:08.961Z,1370295968.961 [NavChartDb](INFO): Thread ID is 5020
2013-06-03T21:46:08.971Z,1370295968.971 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2013-06-03T21:46:08.972Z,1370295968.972 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2013-06-03T21:46:08.973Z,1370295968.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2013-06-03T21:46:08.973Z,1370295968.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2013-06-03T21:46:08.973Z,1370295968.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2013-06-03T21:46:08.973Z,1370295968.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2013-06-03T21:46:08.973Z,1370295968.973 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2013-06-03T21:46:08.974Z,1370295968.974 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2013-06-03T21:46:08.974Z,1370295968.974 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2013-06-03T21:46:09.007Z,1370295969.007 [SBIT](INFO): Initialize SBIT Component.
2013-06-03T21:46:09.007Z,1370295969.007 [SBIT](IMPORTANT): Tethys CM Info:
$Rev:10401
2013-06-03T21:46:09.024Z,1370295969.024 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2013-06-03T21:46:09.024Z,1370295969.024 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013
2013-06-03T21:46:09.025Z,1370295969.025 [IBIT](INFO): Initialize IBIT Component.
2013-06-03T21:46:09.026Z,1370295969.026 [CBIT](DEBUG): Initialize CBIT Component.
2013-06-03T21:46:09.026Z,1370295969.026 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2013-06-03T21:46:09.061Z,1370295969.061 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-06-03T21:46:09.062Z,1370295969.062 [NavChart](DEBUG): Initialize NavChart Derivation.
2013-06-03T21:46:09.062Z,1370295969.062 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2013-06-03T21:46:09.063Z,1370295969.063 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2013-06-03T21:46:09.063Z,1370295969.063 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2013-06-03T21:46:09.065Z,1370295969.065 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2013-06-03T21:46:09.065Z,1370295969.065 [Navigation](DEBUG): Initializing Navigation.
2013-06-03T21:46:09.066Z,1370295969.066 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2013-06-03T21:46:09.068Z,1370295969.068 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2013-06-03T21:46:09.084Z,1370295969.085 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2013-06-03T21:46:09.085Z,1370295969.085 [LoopControl](DEBUG): Initialize LoopControlComponent.
2013-06-03T21:46:10.405Z,1370295970.405 [Batt_Ocean_Server](ERROR): Batt_Ocean_Server A initialization uart error: serial timeout
2013-06-03T21:46:10.405Z,1370295970.405 [Batt_Ocean_Server](ERROR): Ocean Server Batteries failed to initialize. Re-initializing
2013-06-03T21:46:10.405Z,1370295970.405 [Batt_Ocean_Server] Communications Fault, FailCount= 1
2013-06-03T21:46:10.405Z,1370295970.405 [Batt_Ocean_Server](ERROR): Communications Fault
2013-06-03T21:46:10.411Z,1370295970.411 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2013-06-03T21:46:10.480Z,1370295970.480 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2013-06-03T21:46:10.533Z,1370295970.533 [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-06-03T21:46:10.534Z,1370295970.533 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2013-06-03T21:46:10.678Z,1370295970.678 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2013-06-03T21:46:10.687Z,1370295970.687 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2013-06-03T21:46:10.701Z,1370295970.701 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-06-03T21:46:10.725Z,1370295970.725 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2013-06-03T21:46:10.728Z,1370295970.728 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2013-06-03T21:46:10.763Z,1370295970.763 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2013-06-03T21:46:10.805Z,1370295970.805 [Default:D.SetSpeed](DEBUG): Construct.
2013-06-03T21:46:10.828Z,1370295970.828 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2013-06-03T21:46:10.833Z,1370295970.833 [Default:F.Wait](DEBUG): Construct Wait.
2013-06-03T21:46:10.860Z,1370295970.861 [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-06-03T21:46:10.865Z,1370295970.865 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,DAT,SCPI,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,
2013-06-03T21:46:11.029Z,1370295971.029 [DVL_micro](INFO): Opening uart, block timeout 10ths=20
2013-06-03T21:46:11.029Z,1370295971.029 [DVL_micro](INFO): Querying output modes
2013-06-03T21:46:11.029Z,1370295971.029 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2013-06-03T21:46:11.040Z,1370295971.040 [DVL_micro](DEBUG): cmdResponse: 01
2013-06-03T21:46:11.040Z,1370295971.040 [DVL_micro](INFO): NQ1 output enabled
2013-06-03T21:46:11.041Z,1370295971.041 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2013-06-03T21:46:11.052Z,1370295971.052 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2013-06-03T21:46:11.057Z,1370295971.057 [DVL_micro](INFO): pause:Powering down
2013-06-03T21:46:11.379Z,1370295971.379 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2013-06-03T21:46:11.643Z,1370295971.643 [Radio_Freewave](INFO): Powering up
2013-06-03T21:46:11.688Z,1370295971.688 [DAT](INFO): Powering up
2013-06-03T21:46:11.688Z,1370295971.688 [DAT](DEBUG): Initializing DAT.
2013-06-03T21:46:12.032Z,1370295972.032 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2013-06-03T21:46:12.041Z,1370295972.041 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2013-06-03T21:46:12.079Z,1370295972.079 [ElevatorServo](DEBUG): Initializing EZServoServo.
2013-06-03T21:46:12.084Z,1370295972.085 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2013-06-03T21:46:12.111Z,1370295972.111 [MassServo](DEBUG): Initializing EZServoServo.
2013-06-03T21:46:12.112Z,1370295972.112 [MassServo](DEBUG): Initializing MassServo.
2013-06-03T21:46:12.130Z,1370295972.130 [RudderServo](DEBUG): Initializing EZServoServo.
2013-06-03T21:46:12.132Z,1370295972.132 [RudderServo](DEBUG): Initializing RudderServo.
2013-06-03T21:46:12.166Z,1370295972.166 [ThrusterServo](DEBUG): Initializing EZServoServo.
2013-06-03T21:46:12.176Z,1370295972.176 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2013-06-03T21:46:12.231Z,1370295972.231 [CBIT](ERROR): Communications Fault in component: Batt_Ocean_Server
2013-06-03T21:46:12.231Z,1370295972.231 [CBIT](INFO): Clearing failed state for component Batt_Ocean_Server
2013-06-03T21:46:12.231Z,1370295972.231 [Batt_Ocean_Server] No Fault, FailCount= 1
2013-06-03T21:46:13.967Z,1370295973.967 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2013-06-03T21:46:14.019Z,1370295974.019 [NAL9602](INFO): Powering up NAL9602
2013-06-03T21:46:24.768Z,1370295984.768 [NAL9602](INFO): NAL9602 initialized
2013-06-03T21:46:24.943Z,1370295984.943 [SBIT](IMPORTANT): Beginning Startup BIT
2013-06-03T21:46:24.946Z,1370295984.946 [CBIT](IMPORTANT): Beginning GF scan
2013-06-03T21:46:31.716Z,1370295991.716 [DAT](INFO): Powering down
2013-06-03T21:46:38.841Z,1370295998.841 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-06-03T21:46:42.569Z,1370296002.569 [CommandLine](IMPORTANT): got command show stack
2013-06-03T21:46:42.569Z,1370296002.569 [CommandLine](INFO): Behavior Stack:

2013-06-03T21:46:42.569Z,1370296002.569 [MissionManager](INFO): Mission loaded, but not running.
2013-06-03T21:46:59.925Z,1370296019.925 [CBIT](IMPORTANT): No ground fault detected
2013-06-03T21:47:04.767Z,1370296024.767 [SBIT](FAULT): Mass: EXPECTED:-0.006000 ACTUAL:-0.004450
2013-06-03T21:47:04.768Z,1370296024.768 [SBIT](FAULT): Control surface position failure.
2013-06-03T21:47:19.103Z,1370296039.103 [SBIT](CRITICAL): SBIT FAILED
2013-06-03T21:47:19.468Z,1370296039.467 [MissionManager](IMPORTANT): Started mission Startup
2013-06-03T21:47:19.468Z,1370296039.468 [Startup] Running Loop=1
2013-06-03T21:47:19.476Z,1370296039.476 [Startup](INFO): Aggregate::initialize Startup
2013-06-03T21:47:19.476Z,1370296039.476 [Startup:A.GoToSurface] Running Loop=1
2013-06-03T21:47:19.477Z,1370296039.477 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-06-03T21:47:19.491Z,1370296039.491 [Startup:StartupSatComms] Running Loop=1
2013-06-03T21:47:19.491Z,1370296039.491 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2013-06-03T21:47:19.491Z,1370296039.491 [Startup:StartupSatComms:A] Running Loop=1
2013-06-03T21:47:19.800Z,1370296039.800 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-06-03T21:47:25.977Z,1370296045.977 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-06-03T21:47:44.617Z,1370296064.617 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-06-03T21:47:44.618Z,1370296064.618 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2013-06-03T21:47:44.619Z,1370296064.619 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.820000 degree
2013-06-03T21:47:51.215Z,1370296071.215 [Startup:StartupSatComms:A] Stopped
2013-06-03T21:47:51.215Z,1370296071.215 [Startup:StartupSatComms:B] Running Loop=1
2013-06-03T21:47:51.980Z,1370296071.980 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-06-03T21:47:55.071Z,1370296075.071 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:47:58.184Z,1370296078.184 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/SCPI_on.xml
2013-06-03T21:47:58.185Z,1370296078.185 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/SCPI_on.xml
2013-06-03T21:47:58.205Z,1370296078.205 [MissionManager](INFO): DefineArg SCPI_on.MassDefault = -0.006000 n/a
2013-06-03T21:47:58.207Z,1370296078.207 [SCPI_on:A.Pitch](DEBUG): Construct.
2013-06-03T21:47:58.217Z,1370296078.217 [SCPI_on:TestDrive:C.Wait](DEBUG): Construct Wait.
2013-06-03T21:47:58.220Z,1370296078.220 [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="SCPI_on">

    <DefineArg Name="MassDefault"><Control:VerticalControl.massDefault/></DefineArg>

    <Timeout Duration="P15M"/>

    <Guidance:Pitch RunIn="Parallel">
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Aggregate Id="TestDrive">

        <ReadData Strategy="MinError">
            <Sensor:SCPI.sampleSCPI/>
        </ReadData>

        <Aggregate Id="Data">

            <When><True/>
            </When>

            <SendData Service="Express"><Sensor:SCPI.sampleSCPI/><Units:bool/>
            </SendData>

            <Syslog Severity="None">Pause a cycle</Syslog>

        </Aggregate>

        <Guidance:Wait RunIn="Sequence">
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>2</Value></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2013-06-03T21:47:58.221Z,1370296078.221 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/SCPI_on.xml
2013-06-03T21:47:59.462Z,1370296079.462 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:01.903Z,1370296081.903 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:06.194Z,1370296086.194 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:08.611Z,1370296088.611 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:12.924Z,1370296092.924 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:13.533Z,1370296093.533 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2013-06-03T21:48:24.963Z,1370296104.963 [Startup:StartupSatComms:B] Stopped
2013-06-03T21:48:24.963Z,1370296104.963 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2013-06-03T21:48:24.963Z,1370296104.963 [Startup:StartupSatComms] Stopped
2013-06-03T21:48:24.964Z,1370296104.964 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2013-06-03T21:48:24.964Z,1370296104.964 [Startup](INFO): Completed Startup
2013-06-03T21:48:24.965Z,1370296104.964 [Startup] Stopped
2013-06-03T21:48:24.965Z,1370296104.965 [Startup](INFO): Aggregate::uninitialize Startup
2013-06-03T21:48:24.965Z,1370296104.965 [Startup:A.GoToSurface] Stopped
2013-06-03T21:48:24.965Z,1370296104.965 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-06-03T21:48:26.177Z,1370296106.177 [MissionManager](IMPORTANT): Started mission SCPI_on
2013-06-03T21:48:26.177Z,1370296106.177 [SCPI_on] Running Loop=1
2013-06-03T21:48:26.177Z,1370296106.177 [SCPI_on](INFO): Aggregate::initialize SCPI_on
2013-06-03T21:48:26.177Z,1370296106.178 [SCPI_on:A.Pitch] Running Loop=1
2013-06-03T21:48:26.178Z,1370296106.178 [SCPI_on:A.Pitch](DEBUG): Initialize.
2013-06-03T21:48:26.178Z,1370296106.178 [SCPI_on:TestDrive] Running Loop=1
2013-06-03T21:48:26.178Z,1370296106.178 [SCPI_on:TestDrive](INFO): Aggregate::initialize SCPI_on:TestDrive
2013-06-03T21:48:26.178Z,1370296106.178 [SCPI_on:TestDrive:A] Running Loop=1
2013-06-03T21:48:26.179Z,1370296106.179 [SCPI_on:TestDrive:C.Wait] Running Loop=1
2013-06-03T21:48:26.179Z,1370296106.179 [SCPI_on:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2013-06-03T21:48:26.209Z,1370296106.209 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:26.209Z,1370296106.209 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:26.209Z,1370296106.209 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:26.212Z,1370296106.212 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:26.212Z,1370296106.212 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:26.220Z,1370296106.220 [SCPI_on:TestDrive:A] Running Loop=1
2013-06-03T21:48:26.221Z,1370296106.221 [SCPI_on:TestDrive:A](DEBUG): Initialize ReadDataComponent to sense SCPI.sampleSCPI
2013-06-03T21:48:26.222Z,1370296106.222 [SCPI_on:A.Pitch] Running Loop=1
2013-06-03T21:48:27.248Z,1370296107.248 [SCPI](INFO): Powering up
2013-06-03T21:48:27.292Z,1370296107.292 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:27.292Z,1370296107.292 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:27.292Z,1370296107.292 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:27.307Z,1370296107.307 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:27.792Z,1370296107.792 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:27.877Z,1370296107.877 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:27.877Z,1370296107.877 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:27.877Z,1370296107.877 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:27.878Z,1370296107.878 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:27.878Z,1370296107.878 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:28.172Z,1370296108.172 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:28.173Z,1370296108.173 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:28.173Z,1370296108.173 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:28.173Z,1370296108.173 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:28.577Z,1370296108.577 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:28.577Z,1370296108.577 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:28.577Z,1370296108.577 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:28.578Z,1370296108.578 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:28.578Z,1370296108.578 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:28.946Z,1370296108.946 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:28.946Z,1370296108.946 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:28.946Z,1370296108.946 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:28.946Z,1370296108.946 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:29.399Z,1370296109.399 [SCPI](INFO): Init failed - response: ��H|��*��� may_23_2013 $"
2013-06-03T21:48:29.399Z,1370296109.399 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:48:29.400Z,1370296109.399 [SCPI] Communications Fault, FailCount= 1
2013-06-03T21:48:29.400Z,1370296109.400 [SCPI](ERROR): Communications Fault
2013-06-03T21:48:29.435Z,1370296109.435 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:29.436Z,1370296109.436 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:29.436Z,1370296109.436 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:29.436Z,1370296109.436 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:29.436Z,1370296109.436 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:29.493Z,1370296109.493 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:48:29.777Z,1370296109.777 [SCPI](INFO): Powering down
2013-06-03T21:48:29.971Z,1370296109.971 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:29.971Z,1370296109.971 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:29.971Z,1370296109.971 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:29.971Z,1370296109.971 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:30.319Z,1370296110.319 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:30.319Z,1370296110.319 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:30.319Z,1370296110.319 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:30.328Z,1370296110.328 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:30.329Z,1370296110.329 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:30.680Z,1370296110.680 [SCPI](INFO): Powering up
2013-06-03T21:48:30.710Z,1370296110.710 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:30.710Z,1370296110.710 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:30.710Z,1370296110.710 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:30.710Z,1370296110.710 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:30.727Z,1370296110.727 [CBIT](INFO): Clearing failed state for component SCPI
2013-06-03T21:48:30.727Z,1370296110.727 [SCPI] No Fault, FailCount= 1
2013-06-03T21:48:31.083Z,1370296111.083 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:31.083Z,1370296111.083 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:31.084Z,1370296111.084 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:31.084Z,1370296111.084 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:31.084Z,1370296111.084 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:31.487Z,1370296111.487 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:31.487Z,1370296111.487 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:31.487Z,1370296111.487 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:31.487Z,1370296111.487 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:31.901Z,1370296111.901 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:31.901Z,1370296111.901 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:31.901Z,1370296111.901 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:31.901Z,1370296111.901 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:31.902Z,1370296111.902 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:32.426Z,1370296112.426 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:32.426Z,1370296112.426 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:32.426Z,1370296112.426 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:32.426Z,1370296112.426 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:32.779Z,1370296112.779 [SCPI](INFO): Init failed - response: 6��Te�C�(�����"$Name: may_23_2013 $"
2013-06-03T21:48:32.779Z,1370296112.779 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:48:32.779Z,1370296112.779 [SCPI] Communications Fault, FailCount= 2
2013-06-03T21:48:32.779Z,1370296112.779 [SCPI](ERROR): Communications Fault
2013-06-03T21:48:32.813Z,1370296112.813 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:32.813Z,1370296112.813 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:32.814Z,1370296112.814 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:32.814Z,1370296112.814 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:32.814Z,1370296112.814 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:32.849Z,1370296112.849 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:48:33.186Z,1370296113.186 [NAL9602](INFO): Powering down
2013-06-03T21:48:33.216Z,1370296113.216 [SCPI](INFO): Powering down
2013-06-03T21:48:33.344Z,1370296113.344 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:33.344Z,1370296113.344 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:33.345Z,1370296113.345 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:33.345Z,1370296113.345 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:33.680Z,1370296113.680 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:33.680Z,1370296113.680 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:33.680Z,1370296113.680 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:33.681Z,1370296113.681 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:33.681Z,1370296113.681 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:34.036Z,1370296114.036 [SCPI](INFO): Powering up
2013-06-03T21:48:34.047Z,1370296114.047 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:34.048Z,1370296114.048 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:34.048Z,1370296114.048 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:34.048Z,1370296114.048 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:34.102Z,1370296114.102 [CBIT](INFO): Clearing failed state for component SCPI
2013-06-03T21:48:34.102Z,1370296114.102 [SCPI] No Fault, FailCount= 2
2013-06-03T21:48:34.577Z,1370296114.577 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:34.577Z,1370296114.577 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:34.577Z,1370296114.577 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:34.578Z,1370296114.578 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:34.578Z,1370296114.578 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:34.874Z,1370296114.874 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:34.874Z,1370296114.875 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:34.875Z,1370296114.875 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:34.875Z,1370296114.875 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:35.268Z,1370296115.268 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:35.269Z,1370296115.269 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:35.269Z,1370296115.269 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:35.269Z,1370296115.269 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:35.269Z,1370296115.269 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:35.711Z,1370296115.711 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:35.711Z,1370296115.711 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:35.711Z,1370296115.711 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:35.711Z,1370296115.711 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:36.034Z,1370296116.034 [SCPI](INFO): Init failed - response: ��We��YM�tag "$Name: may_23_2013 $"
2013-06-03T21:48:36.034Z,1370296116.034 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:48:36.034Z,1370296116.034 [SCPI] Communications Fault, FailCount= 3
2013-06-03T21:48:36.034Z,1370296116.034 [SCPI](ERROR): Communications Fault
2013-06-03T21:48:36.079Z,1370296116.079 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:36.079Z,1370296116.079 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:36.079Z,1370296116.079 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:36.079Z,1370296116.079 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:36.080Z,1370296116.080 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:36.122Z,1370296116.122 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:48:36.122Z,1370296116.122 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-06-03T21:48:36.570Z,1370296116.570 [SCPI](INFO): Powering down
2013-06-03T21:48:36.700Z,1370296116.700 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:36.700Z,1370296116.700 [SCPI_on:TestDrive:Data](INFO): Completed SCPI_on:TestDrive:Data
2013-06-03T21:48:36.700Z,1370296116.700 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:36.700Z,1370296116.700 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:37.196Z,1370296117.196 [SCPI_on:TestDrive:Data] Running Loop=1
2013-06-03T21:48:37.196Z,1370296117.196 [SCPI_on:TestDrive:Data](INFO): Aggregate::initialize SCPI_on:TestDrive:Data
2013-06-03T21:48:37.197Z,1370296117.197 [SCPI_on:TestDrive:Data:A] Running Loop=1
2013-06-03T21:48:37.197Z,1370296117.197 [SCPI_on:TestDrive:Data:A] Stopped
2013-06-03T21:48:37.197Z,1370296117.197 [SCPI_on:TestDrive:Data:B] Running Loop=1
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on] Stopped
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on](INFO): Aggregate::uninitialize SCPI_on
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on:A.Pitch] Stopped
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on:TestDrive] Stopped
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on:TestDrive](INFO): Aggregate::uninitialize SCPI_on:TestDrive
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on:TestDrive:A] Stopped
2013-06-03T21:48:37.198Z,1370296117.198 [SCPI_on:TestDrive:Data] Stopped
2013-06-03T21:48:37.199Z,1370296117.198 [SCPI_on:TestDrive:Data](INFO): Aggregate::uninitialize SCPI_on:TestDrive:Data
2013-06-03T21:48:37.199Z,1370296117.199 [SCPI_on:TestDrive:Data:B] Stopped
2013-06-03T21:48:37.199Z,1370296117.199 [SCPI_on:TestDrive:C.Wait] Stopped
2013-06-03T21:48:37.199Z,1370296117.199 [SCPI_on:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2013-06-03T21:48:37.548Z,1370296117.548 [MissionManager](IMPORTANT): Started mission Default
2013-06-03T21:48:37.549Z,1370296117.549 [Default] Running Loop=1
2013-06-03T21:48:37.550Z,1370296117.550 [Default](INFO): Aggregate::initialize Default
2013-06-03T21:48:37.550Z,1370296117.550 [Default:D.SetSpeed] Running Loop=1
2013-06-03T21:48:37.550Z,1370296117.550 [Default:D.SetSpeed](DEBUG): Initialize.
2013-06-03T21:48:37.550Z,1370296117.550 [Default:E.GoToSurface] Running Loop=1
2013-06-03T21:48:37.550Z,1370296117.550 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-06-03T21:48:37.550Z,1370296117.550 [Default:Iridium] Running Loop=1
2013-06-03T21:48:37.550Z,1370296117.550 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2013-06-03T21:48:37.550Z,1370296117.550 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-06-03T21:48:37.551Z,1370296117.551 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2013-06-03T21:48:37.551Z,1370296117.551 [Default:Iridium:B.GoToSurface] Running Loop=1
2013-06-03T21:48:37.551Z,1370296117.551 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-06-03T21:48:37.551Z,1370296117.551 [Default:E.GoToSurface] Running Loop=1
2013-06-03T21:48:37.579Z,1370296117.579 [Default:D.SetSpeed] Running Loop=1
2013-06-03T21:48:37.630Z,1370296117.630 [Default:Iridium:B.GoToSurface] Stopped
2013-06-03T21:48:37.630Z,1370296117.630 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-06-03T21:48:37.630Z,1370296117.630 [Default:Iridium:Read_Iridium] Running Loop=1
2013-06-03T21:48:37.630Z,1370296117.630 [Default:Iridium:A.SetSpeed] Running Loop=1
2013-06-03T21:48:37.635Z,1370296117.635 [Default:GPS] Running Loop=1
2013-06-03T21:48:37.635Z,1370296117.635 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2013-06-03T21:48:37.635Z,1370296117.635 [Default:GPS:A.SetSpeed] Running Loop=1
2013-06-03T21:48:37.635Z,1370296117.635 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2013-06-03T21:48:37.636Z,1370296117.636 [Default:GPS:B.GoToSurface] Running Loop=1
2013-06-03T21:48:37.636Z,1370296117.636 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2013-06-03T21:48:37.673Z,1370296117.673 [Default:GPS:B.GoToSurface] Stopped
2013-06-03T21:48:37.673Z,1370296117.673 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-06-03T21:48:37.673Z,1370296117.673 [Default:GPS:Read_GPS] Running Loop=1
2013-06-03T21:48:37.674Z,1370296117.674 [Default:GPS:A.SetSpeed] Running Loop=1
2013-06-03T21:48:38.098Z,1370296118.098 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2013-06-03T21:48:38.101Z,1370296118.101 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2013-06-03T21:48:38.374Z,1370296118.374 [NAL9602](INFO): Powering up
2013-06-03T21:48:49.085Z,1370296129.085 [NAL9602](INFO): NAL9602 initialized
2013-06-03T21:48:53.463Z,1370296133.463 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:57.293Z,1370296137.293 [CommandLine](IMPORTANT): got command failComponent none SCPI
2013-06-03T21:48:57.296Z,1370296137.296 [SCPI] No Fault, FailCount= 3
2013-06-03T21:48:57.297Z,1370296137.297 [CommandLine](IMPORTANT): SCPI failureMode is No Fault
2013-06-03T21:48:57.540Z,1370296137.540 [SCPI](INFO): Powering up
2013-06-03T21:48:58.112Z,1370296138.112 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:48:59.920Z,1370296139.920 [SCPI](INFO): Init failed - response: 
2013-06-03T21:48:59.920Z,1370296139.920 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:48:59.920Z,1370296139.920 [SCPI] Communications Fault, FailCount= 4
2013-06-03T21:48:59.920Z,1370296139.920 [SCPI](ERROR): Communications Fault
2013-06-03T21:48:59.945Z,1370296139.945 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:48:59.946Z,1370296139.945 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-06-03T21:49:00.181Z,1370296140.181 [SCPI](INFO): Powering down
2013-06-03T21:49:02.212Z,1370296142.212 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:06.988Z,1370296146.988 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:11.244Z,1370296151.244 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:15.836Z,1370296155.836 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:20.200Z,1370296160.200 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:24.672Z,1370296164.672 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:29.216Z,1370296169.216 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:34.090Z,1370296174.090 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:38.238Z,1370296178.238 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:38.977Z,1370296178.977 [CommandLine](IMPORTANT): got command failComponent none SCPI
2013-06-03T21:49:38.977Z,1370296178.977 [SCPI] No Fault, FailCount= 4
2013-06-03T21:49:38.977Z,1370296178.977 [CommandLine](IMPORTANT): SCPI failureMode is No Fault
2013-06-03T21:49:39.020Z,1370296179.020 [SCPI](INFO): Powering up
2013-06-03T21:49:41.712Z,1370296181.712 [SCPI](INFO): Init failed - response: 
2013-06-03T21:49:41.712Z,1370296181.712 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:49:41.712Z,1370296181.712 [SCPI] Communications Fault, FailCount= 5
2013-06-03T21:49:41.712Z,1370296181.712 [SCPI](ERROR): Communications Fault
2013-06-03T21:49:41.735Z,1370296181.735 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:49:41.736Z,1370296181.736 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-06-03T21:49:42.013Z,1370296182.013 [SCPI](INFO): Powering down
2013-06-03T21:49:43.275Z,1370296183.275 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:46.729Z,1370296186.729 [CommandLine](IMPORTANT): got command failComponent none SCPI
2013-06-03T21:49:46.729Z,1370296186.729 [SCPI] No Fault, FailCount= 5
2013-06-03T21:49:46.729Z,1370296186.729 [CommandLine](IMPORTANT): SCPI failureMode is No Fault
2013-06-03T21:49:46.856Z,1370296186.856 [SCPI](INFO): Powering up
2013-06-03T21:49:48.035Z,1370296188.035 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:48.884Z,1370296188.884 [SCPI](INFO): Init failed - response: ��UɤCVS tag "$Name: may_23_2013 $"
2013-06-03T21:49:48.884Z,1370296188.884 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:49:48.885Z,1370296188.885 [SCPI] Communications Fault, FailCount= 6
2013-06-03T21:49:48.885Z,1370296188.885 [SCPI](ERROR): Communications Fault
2013-06-03T21:49:48.929Z,1370296188.929 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:49:48.929Z,1370296188.929 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-06-03T21:49:49.204Z,1370296189.204 [SCPI](INFO): Powering down
2013-06-03T21:49:52.387Z,1370296192.387 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:49:56.792Z,1370296196.792 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:01.282Z,1370296201.282 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:05.609Z,1370296205.609 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:10.023Z,1370296210.023 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:14.175Z,1370296214.175 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:18.414Z,1370296218.414 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:22.819Z,1370296222.819 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:27.294Z,1370296227.295 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:31.724Z,1370296231.724 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:36.177Z,1370296236.177 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:41.009Z,1370296241.010 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:45.934Z,1370296245.934 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:49.994Z,1370296249.994 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:53.930Z,1370296253.931 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:50:58.294Z,1370296258.294 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:02.760Z,1370296262.760 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:06.784Z,1370296266.784 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:10.850Z,1370296270.850 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:15.210Z,1370296275.210 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:19.503Z,1370296279.503 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:23.906Z,1370296283.906 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:27.502Z,1370296287.502 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:32.074Z,1370296292.074 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:36.911Z,1370296296.911 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:41.526Z,1370296301.526 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:45.499Z,1370296305.499 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:49.946Z,1370296309.946 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:53.579Z,1370296313.579 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:54.933Z,1370296314.933 [CommandLine](IMPORTANT): got command failComponent none SCPI
2013-06-03T21:51:54.933Z,1370296314.933 [SCPI] No Fault, FailCount= 6
2013-06-03T21:51:54.933Z,1370296314.933 [CommandLine](IMPORTANT): SCPI failureMode is No Fault
2013-06-03T21:51:55.120Z,1370296315.120 [SCPI](INFO): Powering up
2013-06-03T21:51:57.928Z,1370296317.928 [SCPI](INFO): Init failed - response: 
2013-06-03T21:51:57.928Z,1370296317.928 [SCPI](FAULT): SCPI failed to initialize
2013-06-03T21:51:57.928Z,1370296317.928 [SCPI] Communications Fault, FailCount= 7
2013-06-03T21:51:57.928Z,1370296317.928 [SCPI](ERROR): Communications Fault
2013-06-03T21:51:57.988Z,1370296317.988 [CBIT](ERROR): Communications Fault in component: SCPI
2013-06-03T21:51:57.989Z,1370296317.989 [CBIT](CRITICAL): Communications Fault in component: SCPI
2013-06-03T21:51:58.232Z,1370296318.232 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:51:58.267Z,1370296318.267 [SCPI](INFO): Powering down
2013-06-03T21:52:02.744Z,1370296322.744 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:07.270Z,1370296327.270 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:11.646Z,1370296331.647 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:15.966Z,1370296335.966 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:20.700Z,1370296340.700 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:25.123Z,1370296345.123 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:29.550Z,1370296349.550 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:33.884Z,1370296353.884 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:38.706Z,1370296358.706 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:43.179Z,1370296363.179 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:47.575Z,1370296367.575 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:51.999Z,1370296371.999 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:52:56.360Z,1370296376.360 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:00.745Z,1370296380.745 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:05.168Z,1370296385.168 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:09.575Z,1370296389.575 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:13.773Z,1370296393.773 [Default:CallIridium] Running Loop=1
2013-06-03T21:53:13.773Z,1370296393.773 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2013-06-03T21:53:13.773Z,1370296393.773 [Default:CallIridium:A] Running Loop=1
2013-06-03T21:53:13.778Z,1370296393.778 [Default:CallIridium:A] Stopped
2013-06-03T21:53:13.778Z,1370296393.778 [Default:CallIridium:B] Running Loop=1
2013-06-03T21:53:13.778Z,1370296393.778 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2013-06-03T21:53:14.110Z,1370296394.110 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:18.500Z,1370296398.500 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:22.981Z,1370296402.981 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:27.672Z,1370296407.672 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:30.177Z,1370296410.177 [CommandLine](IMPORTANT): got command quit
2013-06-03T21:53:31.380Z,1370296411.380 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2013-06-03T21:53:31.380Z,1370296411.380 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2013-06-03T21:53:31.732Z,1370296411.732 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2013-06-03T21:53:31.881Z,1370296411.881 [WetLabsBB2FL](INFO): Powering down
2013-06-03T21:53:31.896Z,1370296411.896 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2013-06-03T21:53:32.108Z,1370296412.108 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2013-06-03T21:53:32.125Z,1370296412.125 [CTD_NeilBrown](INFO): Powering down
2013-06-03T21:53:32.132Z,1370296412.132 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler
2013-06-03T21:53:32.209Z,1370296412.209 [DVL_micro](INFO): uninitialize:Powering down
2013-06-03T21:53:32.228Z,1370296412.228 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler
2013-06-03T21:53:32.417Z,1370296412.417 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator.
2013-06-03T21:53:32.425Z,1370296412.425 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2013-06-03T21:53:32.469Z,1370296412.469 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2013-06-03T21:53:32.472Z,1370296412.472 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2013-06-03T21:53:32.529Z,1370296412.529 [controlThread](DEBUG): Uninitializing ControlThread
2013-06-03T21:53:32.529Z,1370296412.529 [AHRS_sp3003D](INFO): Powering down
2013-06-03T21:53:32.617Z,1370296412.617 [NAL9602](INFO): Powering down
2013-06-03T21:53:32.619Z,1370296412.619 [DAT](INFO): Powering down
2013-06-03T21:53:32.620Z,1370296412.620 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2013-06-03T21:53:32.620Z,1370296412.620 [NavChart](DEBUG): Uninitialize NavChart Derivation.
2013-06-03T21:53:32.621Z,1370296412.621 [Default] Stopped
2013-06-03T21:53:32.621Z,1370296412.621 [Default](INFO): Aggregate::uninitialize Default
2013-06-03T21:53:32.622Z,1370296412.622 [Default:GPS] Stopped
2013-06-03T21:53:32.622Z,1370296412.622 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2013-06-03T21:53:32.622Z,1370296412.622 [Default:GPS:A.SetSpeed] Stopped
2013-06-03T21:53:32.622Z,1370296412.622 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2013-06-03T21:53:32.623Z,1370296412.622 [Default:GPS:Read_GPS] Stopped
2013-06-03T21:53:32.623Z,1370296412.622 [Default:Iridium] Stopped
2013-06-03T21:53:32.623Z,1370296412.623 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2013-06-03T21:53:32.623Z,1370296412.623 [Default:Iridium:A.SetSpeed] Stopped
2013-06-03T21:53:32.623Z,1370296412.623 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2013-06-03T21:53:32.623Z,1370296412.623 [Default:Iridium:Read_Iridium] Stopped
2013-06-03T21:53:32.623Z,1370296412.623 [Default:CallIridium] Stopped
2013-06-03T21:53:32.623Z,1370296412.623 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2013-06-03T21:53:32.623Z,1370296412.623 [Default:CallIridium:B] Stopped
2013-06-03T21:53:32.623Z,1370296412.623 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2013-06-03T21:53:32.623Z,1370296412.623 [Default:D.SetSpeed] Stopped
2013-06-03T21:53:32.623Z,1370296412.624 [Default:D.SetSpeed](DEBUG): Uninitialize.
2013-06-03T21:53:32.624Z,1370296412.624 [Default:E.GoToSurface] Stopped
2013-06-03T21:53:32.624Z,1370296412.624 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2013-06-03T21:53:32.632Z,1370296412.632 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2013-06-03T21:53:32.633Z,1370296412.633 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2013-06-03T21:53:32.633Z,1370296412.633 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2013-06-03T21:53:32.633Z,1370296412.633 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2013-06-03T21:53:32.634Z,1370296412.634 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2013-06-03T21:53:32.634Z,1370296412.634 [BuoyancyServo](INFO): Powering down
2013-06-03T21:53:32.648Z,1370296412.648 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2013-06-03T21:53:32.649Z,1370296412.649 [ElevatorServo](INFO): Powering down
2013-06-03T21:53:32.650Z,1370296412.649 [MassServo](DEBUG): Uninitialize Mass Servo.
2013-06-03T21:53:32.650Z,1370296412.650 [MassServo](INFO): Powering down
2013-06-03T21:53:32.650Z,1370296412.650 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2013-06-03T21:53:32.651Z,1370296412.651 [RudderServo](INFO): Powering down
2013-06-03T21:53:32.651Z,1370296412.651 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2013-06-03T21:53:32.651Z,1370296412.651 [ThrusterServo](INFO): Powering down
2013-06-03T21:53:32.652Z,1370296412.652 [SBIT](DEBUG): Uninitialize SBIT Component.
2013-06-03T21:53:32.653Z,1370296412.653 [IBIT](DEBUG): Uninitialize IBIT Component.
2013-06-03T21:53:32.653Z,1370296412.653 [CBIT](DEBUG): Uninitialize CBIT Component.