2014-06-04T22:28:57.009Z,1401920937.009 [Supervisor](DEBUG): Initializing supervisor.
2014-06-04T22:28:57.011Z,1401920937.011 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2014-06-04T22:28:57.012Z,1401920937.012 [SyncHandler](INFO): Protected caller Thread ID is 8800
2014-06-04T22:28:57.012Z,1401920937.012 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2014-06-04T22:28:57.013Z,1401920937.013 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2014-06-04T22:28:57.014Z,1401920937.014 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 8801
2014-06-04T22:28:57.017Z,1401920937.017 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2014-06-04T22:28:57.039Z,1401920937.039 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2014-06-04T22:28:57.040Z,1401920937.040 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2014-06-04T22:28:57.041Z,1401920937.041 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 8802
2014-06-04T22:28:57.041Z,1401920937.041 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2014-06-04T22:28:57.042Z,1401920937.042 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2014-06-04T22:28:57.043Z,1401920937.043 [logger ThreadHandler](INFO): Protected caller Thread ID is 8803
2014-06-04T22:28:57.045Z,1401920937.045 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2014-06-04T22:28:57.045Z,1401920937.045 [Supervisor](INFO): Looking for Config files in directory: Config/
2014-06-04T22:28:57.047Z,1401920937.047 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2014-06-04T22:28:57.396Z,1401920937.396 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2014-06-04T22:28:57.397Z,1401920937.397 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2014-06-04T22:28:57.677Z,1401920937.677 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2014-06-04T22:28:57.678Z,1401920937.678 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2014-06-04T22:28:57.766Z,1401920937.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2014-06-04T22:28:57.767Z,1401920937.767 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2014-06-04T22:28:57.946Z,1401920937.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2014-06-04T22:28:57.946Z,1401920937.946 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2014-06-04T22:28:58.110Z,1401920938.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2014-06-04T22:28:58.111Z,1401920938.111 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2014-06-04T22:28:58.409Z,1401920938.409 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2014-06-04T22:28:58.410Z,1401920938.410 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2014-06-04T22:28:58.594Z,1401920938.594 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2014-06-04T22:28:58.594Z,1401920938.594 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2014-06-04T22:28:58.926Z,1401920938.926 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2014-06-04T22:28:58.926Z,1401920938.926 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2014-06-04T22:28:59.037Z,1401920939.037 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2014-06-04T22:28:59.038Z,1401920939.038 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2014-06-04T22:28:59.531Z,1401920939.531 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2014-06-04T22:28:59.531Z,1401920939.531 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2014-06-04T22:28:59.643Z,1401920939.643 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2014-06-04T22:28:59.644Z,1401920939.644 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2014-06-04T22:28:59.733Z,1401920939.733 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2014-06-04T22:28:59.860Z,1401920939.860 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2014-06-04T22:28:59.861Z,1401920939.861 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2014-06-04T22:28:59.967Z,1401920939.967 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2014-06-04T22:28:59.967Z,1401920939.967 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2014-06-04T22:29:00.108Z,1401920940.108 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2014-06-04T22:29:00.110Z,1401920940.110 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2014-06-04T22:29:00.111Z,1401920940.111 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2014-06-04T22:29:00.223Z,1401920940.223 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2014-06-04T22:29:00.353Z,1401920940.353 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2014-06-04T22:29:00.452Z,1401920940.452 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2014-06-04T22:29:00.547Z,1401920940.547 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2014-06-04T22:29:00.690Z,1401920940.690 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2014-06-04T22:29:00.807Z,1401920940.807 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2014-06-04T22:29:00.895Z,1401920940.895 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2014-06-04T22:29:00.000Z,1401920941.000 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2014-06-04T22:29:01.103Z,1401920941.103 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2014-06-04T22:29:01.202Z,1401920941.202 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2014-06-04T22:29:01.291Z,1401920941.291 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg
2014-06-04T22:29:01.392Z,1401920941.392 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/
2014-06-04T22:29:01.392Z,1401920941.392 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2014-06-04T22:29:01.394Z,1401920941.394 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2014-06-04T22:29:01.735Z,1401920941.735 [AHRS_sp3003D] Loaded
2014-06-04T22:29:01.735Z,1401920941.735 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2014-06-04T22:29:02.076Z,1401920942.076 [Batt_Ocean_Server] Loaded
2014-06-04T22:29:02.076Z,1401920942.076 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2014-06-04T22:29:02.090Z,1401920942.090 [Depth_Keller] Loaded
2014-06-04T22:29:02.090Z,1401920942.090 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2014-06-04T22:29:02.095Z,1401920942.095 [DropWeight] Loaded
2014-06-04T22:29:02.095Z,1401920942.095 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2014-06-04T22:29:02.236Z,1401920942.236 [DVL_micro] Loaded
2014-06-04T22:29:02.236Z,1401920942.236 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2014-06-04T22:29:02.337Z,1401920942.337 [NAL9602] Loaded
2014-06-04T22:29:02.337Z,1401920942.337 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2014-06-04T22:29:02.389Z,1401920942.389 [Onboard] Loaded
2014-06-04T22:29:02.389Z,1401920942.389 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2014-06-04T22:29:02.397Z,1401920942.397 [Radio_Freewave] Loaded
2014-06-04T22:29:02.397Z,1401920942.397 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread.
2014-06-04T22:29:02.398Z,1401920942.398 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 4060F4E0
2014-06-04T22:29:02.399Z,1401920942.399 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 8885
2014-06-04T22:29:02.406Z,1401920942.406 [SCPI] Loaded
2014-06-04T22:29:02.406Z,1401920942.406 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread.
2014-06-04T22:29:02.406Z,1401920942.406 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2014-06-04T22:29:02.407Z,1401920942.407 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2014-06-04T22:29:02.566Z,1401920942.566 [InternalSim] Loaded
2014-06-04T22:29:02.567Z,1401920942.567 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2014-06-04T22:29:02.567Z,1401920942.567 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2014-06-04T22:29:02.568Z,1401920942.568 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2014-06-04T22:29:02.812Z,1401920942.812 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2014-06-04T22:29:02.813Z,1401920942.813 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2014-06-04T22:29:02.818Z,1401920942.818 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2014-06-04T22:29:02.819Z,1401920942.819 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2014-06-04T22:29:02.899Z,1401920942.899 [DeadReckonUsingMultipleVelocitySources] Loaded
2014-06-04T22:29:02.900Z,1401920942.900 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2014-06-04T22:29:02.944Z,1401920942.944 [DeadReckonWithRespectToWater] Loaded
2014-06-04T22:29:02.945Z,1401920942.945 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2014-06-04T22:29:02.991Z,1401920942.991 [DeadReckonWithRespectToSeafloor] Loaded
2014-06-04T22:29:02.991Z,1401920942.991 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2014-06-04T22:29:03.038Z,1401920943.038 [DeadReckonUsingDVLWaterTrack] Loaded
2014-06-04T22:29:03.038Z,1401920943.038 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread.
2014-06-04T22:29:03.086Z,1401920943.086 [DeadReckonUsingCompactModelForecast] Loaded
2014-06-04T22:29:03.086Z,1401920943.086 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingCompactModelForecast" handled in the control thread.
2014-06-04T22:29:03.102Z,1401920943.102 [NavChart] Loaded
2014-06-04T22:29:03.102Z,1401920943.102 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2014-06-04T22:29:03.106Z,1401920943.106 [UniversalFixResidualReporter] Loaded
2014-06-04T22:29:03.106Z,1401920943.106 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2014-06-04T22:29:03.107Z,1401920943.107 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2014-06-04T22:29:03.108Z,1401920943.108 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2014-06-04T22:29:03.156Z,1401920943.156 [VerticalControl](DEBUG): Construct VerticalControl.
2014-06-04T22:29:03.269Z,1401920943.269 [VerticalControl] Loaded
2014-06-04T22:29:03.269Z,1401920943.269 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2014-06-04T22:29:03.270Z,1401920943.270 [HorizontalControl](DEBUG): Construct HorizontalControl.
2014-06-04T22:29:03.337Z,1401920943.337 [HorizontalControl] Loaded
2014-06-04T22:29:03.337Z,1401920943.337 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2014-06-04T22:29:03.338Z,1401920943.338 [SpeedControl](DEBUG): Construct SpeedControl.
2014-06-04T22:29:03.340Z,1401920943.340 [SpeedControl] Loaded
2014-06-04T22:29:03.340Z,1401920943.340 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2014-06-04T22:29:03.340Z,1401920943.340 [LoopControl](DEBUG): Construct LoopControl.
2014-06-04T22:29:03.341Z,1401920943.341 [LoopControl] Loaded
2014-06-04T22:29:03.341Z,1401920943.341 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2014-06-04T22:29:03.342Z,1401920943.342 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2014-06-04T22:29:03.342Z,1401920943.342 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2014-06-04T22:29:03.361Z,1401920943.361 [DepthRateCalculator] Loaded
2014-06-04T22:29:03.361Z,1401920943.361 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2014-06-04T22:29:03.366Z,1401920943.366 [PitchRateCalculator] Loaded
2014-06-04T22:29:03.367Z,1401920943.367 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2014-06-04T22:29:03.374Z,1401920943.374 [SpeedCalculator] Loaded
2014-06-04T22:29:03.374Z,1401920943.374 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2014-06-04T22:29:03.390Z,1401920943.390 [TempGradientCalculator] Loaded
2014-06-04T22:29:03.391Z,1401920943.391 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2014-06-04T22:29:03.396Z,1401920943.396 [YawRateCalculator] Loaded
2014-06-04T22:29:03.396Z,1401920943.396 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2014-06-04T22:29:03.397Z,1401920943.397 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2014-06-04T22:29:03.397Z,1401920943.397 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2014-06-04T22:29:03.503Z,1401920943.503 [CTD_NeilBrown] Loaded
2014-06-04T22:29:03.504Z,1401920943.504 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2014-06-04T22:29:03.505Z,1401920943.505 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4075E4E0
2014-06-04T22:29:03.505Z,1401920943.505 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 8886
2014-06-04T22:29:03.518Z,1401920943.518 [ISUS] Loaded
2014-06-04T22:29:03.518Z,1401920943.518 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread.
2014-06-04T22:29:03.533Z,1401920943.533 [PAR_Licor] Loaded
2014-06-04T22:29:03.533Z,1401920943.533 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2014-06-04T22:29:03.568Z,1401920943.568 [WetLabsBB2FL] Loaded
2014-06-04T22:29:03.568Z,1401920943.568 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2014-06-04T22:29:03.569Z,1401920943.569 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4078E4E0
2014-06-04T22:29:03.570Z,1401920943.570 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 8887
2014-06-04T22:29:03.570Z,1401920943.570 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2014-06-04T22:29:03.571Z,1401920943.571 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2014-06-04T22:29:03.664Z,1401920943.664 [SBIT](DEBUG): Construct Startup Built In Test.
2014-06-04T22:29:03.676Z,1401920943.676 [SBIT] Loaded
2014-06-04T22:29:03.676Z,1401920943.676 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2014-06-04T22:29:03.677Z,1401920943.677 [IBIT](DEBUG): Construct Initiated Built In Test.
2014-06-04T22:29:03.690Z,1401920943.690 [IBIT] Loaded
2014-06-04T22:29:03.690Z,1401920943.690 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2014-06-04T22:29:03.692Z,1401920943.692 [CBIT](DEBUG): Construct CBIT Built In Test.
2014-06-04T22:29:03.762Z,1401920943.762 [CBIT] Loaded
2014-06-04T22:29:03.762Z,1401920943.762 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2014-06-04T22:29:03.762Z,1401920943.762 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2014-06-04T22:29:03.763Z,1401920943.763 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2014-06-04T22:29:08.370Z,1401920948.370 [HFRadarModelCalc] Loaded
2014-06-04T22:29:08.370Z,1401920948.370 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2014-06-04T22:29:12.028Z,1401920952.028 [HFRadarCompactModelForecaster] Loaded
2014-06-04T22:29:12.028Z,1401920952.028 [ComponentRegistry](DEBUG): SyncComponent "HFRadarCompactModelForecaster" handled in the control thread.
2014-06-04T22:29:12.937Z,1401920952.937 [HFRCMSpaceInterpolator] Loaded
2014-06-04T22:29:12.937Z,1401920952.937 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSpaceInterpolator" handled in the control thread.
2014-06-04T22:29:12.939Z,1401920952.939 [HFRCMTimeInterpolator] Loaded
2014-06-04T22:29:12.939Z,1401920952.939 [ComponentRegistry](DEBUG): SyncComponent "HFRCMTimeInterpolator" handled in the control thread.
2014-06-04T22:29:13.969Z,1401920953.969 [HFRCMReconstructedInterpolator] Loaded
2014-06-04T22:29:13.970Z,1401920953.970 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2014-06-04T22:29:13.982Z,1401920953.982 [HFRCMSurfaceCurrentAtVehicleLocation] Loaded
2014-06-04T22:29:13.982Z,1401920953.982 [ComponentRegistry](DEBUG): SyncComponent "HFRCMSurfaceCurrentAtVehicleLocation" handled in the control thread.
2014-06-04T22:29:14.009Z,1401920954.009 [HFRCMVirtualSurfaceDrifter] Loaded
2014-06-04T22:29:14.009Z,1401920954.009 [ComponentRegistry](DEBUG): SyncComponent "HFRCMVirtualSurfaceDrifter" handled in the control thread.
2014-06-04T22:29:14.010Z,1401920954.010 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2014-06-04T22:29:14.010Z,1401920954.010 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2014-06-04T22:29:14.108Z,1401920954.108 [BuoyancyServo] Loaded
2014-06-04T22:29:14.108Z,1401920954.108 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2014-06-04T22:29:14.121Z,1401920954.121 [ElevatorServo] Loaded
2014-06-04T22:29:14.121Z,1401920954.121 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2014-06-04T22:29:14.132Z,1401920954.132 [MassServo] Loaded
2014-06-04T22:29:14.133Z,1401920954.133 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2014-06-04T22:29:14.144Z,1401920954.144 [RudderServo] Loaded
2014-06-04T22:29:14.145Z,1401920954.145 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2014-06-04T22:29:14.156Z,1401920954.156 [ThrusterServo] Loaded
2014-06-04T22:29:14.156Z,1401920954.156 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2014-06-04T22:29:14.157Z,1401920954.157 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2014-06-04T22:29:14.157Z,1401920954.157 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2014-06-04T22:29:14.181Z,1401920954.181 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2014-06-04T22:29:14.183Z,1401920954.183 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2014-06-04T22:29:14.183Z,1401920954.183 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2014-06-04T22:29:14.190Z,1401920954.190 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2014-06-04T22:29:14.191Z,1401920954.191 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD34E0
2014-06-04T22:29:14.191Z,1401920954.191 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 8888
2014-06-04T22:29:14.196Z,1401920954.196 [Supervisor](INFO): Main Thread ID is 8799
2014-06-04T22:29:14.196Z,1401920954.196 [Supervisor](DEBUG): Running supervisor.
2014-06-04T22:29:14.197Z,1401920954.197 [CommandLine ThreadHandler](INFO): Handler Thread ID is 8889
2014-06-04T22:29:14.199Z,1401920954.199 [controlThread ThreadHandler](INFO): Handler Thread ID is 8890
2014-06-04T22:29:14.200Z,1401920954.200 [controlThread](DEBUG): Initializing ControlThread
2014-06-04T22:29:14.203Z,1401920954.203 [logger ThreadHandler](INFO): Handler Thread ID is 8891
2014-06-04T22:29:14.221Z,1401920954.221 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 8892
2014-06-04T22:29:14.238Z,1401920954.238 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 8893
2014-06-04T22:29:14.238Z,1401920954.238 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2014-06-04T22:29:14.241Z,1401920954.241 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-06-04T22:29:14.251Z,1401920954.251 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 8895
2014-06-04T22:29:14.252Z,1401920954.252 [WetLabsBB2FL](INFO): Powering down
2014-06-04T22:29:14.280Z,1401920954.280 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 8896
2014-06-04T22:29:14.283Z,1401920954.283 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2014-06-04T22:29:14.284Z,1401920954.284 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2014-06-04T22:29:14.284Z,1401920954.284 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2014-06-04T22:29:14.284Z,1401920954.284 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2014-06-04T22:29:14.285Z,1401920954.285 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2014-06-04T22:29:14.285Z,1401920954.285 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2014-06-04T22:29:14.286Z,1401920954.286 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2014-06-04T22:29:14.286Z,1401920954.286 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2014-06-04T22:29:14.286Z,1401920954.286 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2014-06-04T22:29:16.115Z,1401920956.115 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2014-06-04T22:29:16.147Z,1401920956.147 [InternalSim](DEBUG):  InternalSim initializing...
2014-06-04T22:29:16.261Z,1401920956.261 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-06-04T22:29:16.261Z,1401920956.261 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2014-06-04T22:29:16.262Z,1401920956.262 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component.
2014-06-04T22:29:16.262Z,1401920956.262 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component.
2014-06-04T22:29:16.262Z,1401920956.262 [DeadReckonUsingCompactModelForecast](DEBUG): Initializing DeadReckonUsingCompactModelForecast component.
2014-06-04T22:29:16.263Z,1401920956.263 [NavChart](DEBUG): Initialize NavChart Navigation.
2014-06-04T22:29:16.263Z,1401920956.263 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2014-06-04T22:29:16.263Z,1401920956.263 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2014-06-04T22:29:16.280Z,1401920956.280 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2014-06-04T22:29:16.281Z,1401920956.281 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2014-06-04T22:29:16.282Z,1401920956.282 [LoopControl](DEBUG): Initialize LoopControlComponent.
2014-06-04T22:29:16.282Z,1401920956.282 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-06-04T22:29:16.282Z,1401920956.282 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2014-06-04T22:29:16.283Z,1401920956.283 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2014-06-04T22:29:16.283Z,1401920956.283 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2014-06-04T22:29:16.284Z,1401920956.284 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2014-06-04T22:29:16.285Z,1401920956.285 [SBIT](INFO): Initialize SBIT Component.
2014-06-04T22:29:16.286Z,1401920956.286 [SBIT](IMPORTANT): Tethys CM Info: 
 $Rev:11372
2014-06-04T22:29:16.286Z,1401920956.286 [SBIT](IMPORTANT): Kernel Release:2.6.27.8
2014-06-04T22:29:16.287Z,1401920956.287 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2014-06-04T22:29:16.287Z,1401920956.287 [IBIT](INFO): Initialize IBIT Component.
2014-06-04T22:29:16.296Z,1401920956.296 [CBIT](DEBUG): Initialize CBIT Component.
2014-06-04T22:29:16.297Z,1401920956.297 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2014-06-04T22:29:16.327Z,1401920956.327 [HFRadarCompactModelForecaster](DEBUG): Found new ECs!
2014-06-04T22:29:16.916Z,1401920956.916 [Radio_Freewave](INFO): Powering up
2014-06-04T22:29:17.727Z,1401920957.727 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0
2014-06-04T22:29:25.326Z,1401920965.326 [HFRadarCompactModelForecaster](IMPORTANT): forecast time 201406041900: published 50 modes in rows, 61 hours in columns
2014-06-04T22:29:25.330Z,1401920965.330 [HFRadarCompactModelForecaster](IMPORTANT): expansionCoefficients_[0][48] = 4.618326 for 2014-06-04T19:00:00.000Z
2014-06-04T22:29:25.335Z,1401920965.335 [HFRCMSpaceInterpolator](DEBUG): Initializing HFRCMSpaceInterpolator component with verbosity level 0.
2014-06-04T22:29:25.337Z,1401920965.337 [HFRCMSpaceInterpolator](INFO): gridIdxRev_: 541 by 1, [25.000000, 718.000000]
2014-06-04T22:29:25.338Z,1401920965.338 [HFRCMSpaceInterpolator](INFO): gridIdx_: 25 by 29, [nan, nan]
2014-06-04T22:29:25.339Z,1401920965.339 [HFRCMSpaceInterpolator](INFO): longitude grid: 25 by 29, [-122.743156, -121.797913]
2014-06-04T22:29:25.340Z,1401920965.340 [HFRCMSpaceInterpolator](INFO): latitude grid: 25 by 29, [36.341251, 36.990059]
2014-06-04T22:29:25.348Z,1401920965.348 [HFRCMTimeInterpolator](DEBUG): Initializing HFRCMTimeInterpolator component.
2014-06-04T22:29:25.348Z,1401920965.348 [HFRCMReconstructedInterpolator](DEBUG): Initializing HFRCMReconstructedInterpolator component.
2014-06-04T22:29:25.349Z,1401920965.349 [HFRCMReconstructedInterpolator](INFO): velocityAccuracy_ = 0.300000 m/s
2014-06-04T22:29:25.364Z,1401920965.364 [HFRCMReconstructedInterpolator](INFO): gridIdxRev_: 541 by 1, [25.000000, 718.000000]
2014-06-04T22:29:25.365Z,1401920965.365 [HFRCMReconstructedInterpolator](INFO): gridIdx_: 25 by 29, [nan, nan]
2014-06-04T22:29:25.366Z,1401920965.366 [HFRCMReconstructedInterpolator](INFO): longitude grid: 25 by 29, [-122.743156, -121.797913]
2014-06-04T22:29:25.371Z,1401920965.371 [HFRCMReconstructedInterpolator](INFO): latitude grid: 25 by 29, [36.341251, 36.990059]
2014-06-04T22:29:25.372Z,1401920965.372 [HFRCMSurfaceCurrentAtVehicleLocation](DEBUG): Initializing HFRCMSurfaceCurrentAtVehicleLocation component.
2014-06-04T22:29:25.372Z,1401920965.372 [HFRCMVirtualSurfaceDrifter](DEBUG): Initializing HFRCMVirtualSurfaceDrifter component.
2014-06-04T22:29:25.375Z,1401920965.375 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2014-06-04T22:29:25.430Z,1401920965.430 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-04T22:29:25.443Z,1401920965.443 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2014-06-04T22:29:25.444Z,1401920965.444 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2014-06-04T22:29:25.529Z,1401920965.529 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2014-06-04T22:29:25.540Z,1401920965.540 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2014-06-04T22:29:25.552Z,1401920965.552 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-04T22:29:25.576Z,1401920965.576 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2014-06-04T22:29:25.591Z,1401920965.591 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2014-06-04T22:29:25.598Z,1401920965.598 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2014-06-04T22:29:25.638Z,1401920965.638 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct.
2014-06-04T22:29:25.656Z,1401920965.656 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

    <Aggregate Id="GPS">

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

<!-- Run at high speed -->

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

<!-- Get to the surface -->

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

<!-- Get GPS fix -->

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

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

    </Aggregate>

    <Aggregate Id="Iridium">

        <Sequence/>

<!-- Run at high speed -->

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

<!-- Get to the surface -->

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

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="CallIridium">

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

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

        <Call RefId="Iridium"/>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2014-06-04T22:29:25.670Z,1401920965.670 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRadarModelCalc,HFRadarCompactModelForecaster,HFRCMSpaceInterpolator,HFRCMTimeInterpolator,HFRCMReconstructedInterpolator,HFRCMSurfaceCurrentAtVehicleLocation,HFRCMVirtualSurfaceDrifter,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,DeadReckonUsingCompactModelForecast,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2014-06-04T22:29:25.734Z,1401920965.734 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2014-06-04T22:29:26.184Z,1401920966.184 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2014-06-04T22:29:26.216Z,1401920966.216 [DVL_micro](INFO): Initializing
2014-06-04T22:29:26.236Z,1401920966.236 [NAL9602](INFO): Powering up NAL9602
2014-06-04T22:29:32.844Z,1401920972.843 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2014-06-04T22:29:32.850Z,1401920972.850 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2014-06-04T22:29:32.856Z,1401920972.856 [ElevatorServo](DEBUG): Initializing EZServoServo.
2014-06-04T22:29:32.873Z,1401920972.873 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2014-06-04T22:29:32.879Z,1401920972.879 [MassServo](DEBUG): Initializing EZServoServo.
2014-06-04T22:29:32.886Z,1401920972.886 [MassServo](DEBUG): Initializing MassServo.
2014-06-04T22:29:32.892Z,1401920972.892 [RudderServo](DEBUG): Initializing EZServoServo.
2014-06-04T22:29:32.898Z,1401920972.898 [RudderServo](DEBUG): Initializing RudderServo.
2014-06-04T22:29:32.904Z,1401920972.904 [ThrusterServo](DEBUG): Initializing EZServoServo.
2014-06-04T22:29:32.910Z,1401920972.910 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2014-06-04T22:29:33.892Z,1401920973.892 [SBIT](IMPORTANT): Beginning Startup BIT
2014-06-04T22:29:33.895Z,1401920973.895 [CBIT](IMPORTANT): Beginning GF scan
2014-06-04T22:29:36.269Z,1401920976.269 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 45 of 46
2014-06-04T22:29:36.269Z,1401920976.269 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.6 0.6 0.2 0.5 1753.3 -793.1 -287.5 611.5 0 0 0 0 0 0 0 0 2723.7 -1874.6 346.3 1 2953.5 -1144.4 1010.0 1 0 0 0 0 0 0 0 0 -4.16 -11.34 14.0 0.2 18.6 .0 1489 111
2014-06-04T22:29:37.001Z,1401920977.001 [NAL9602](INFO): NAL9602 initialized
2014-06-04T22:29:57.308Z,1401920997.308 [CommandLine](IMPORTANT): got command show stack
2014-06-04T22:29:57.308Z,1401920997.308 [CommandLine](IMPORTANT): Behavior Stack:

2014-06-04T22:29:57.308Z,1401920997.308 [MissionManager](IMPORTANT): Mission loaded, but not running.
2014-06-04T22:30:00.607Z,1401921000.607 [CBIT](FAULT): Low side GF detected
mA:
CHAN 5 (24V): 0.391695
CHAN 4 (Batt): 0.391695
CHAN 2 (12V): 0.391695
CHAN 1 (5V): 0.391695
CHAN 0 (3.3V): 0.338513
OPEN: 0.000670
Full Scale Calc: 0.392
2014-06-04T22:30:10.140Z,1401921010.140 [CommandLine](IMPORTANT): got command show stack
2014-06-04T22:30:10.140Z,1401921010.140 [CommandLine](IMPORTANT): Behavior Stack:

2014-06-04T22:30:10.140Z,1401921010.140 [MissionManager](IMPORTANT): Mission loaded, but not running.
2014-06-04T22:30:12.394Z,1401921012.394 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 28 of 46
2014-06-04T22:30:12.394Z,1401921012.394 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.5 0.6 0.2 0.5 2314.6 335.6 -449.6 932.6 0 0 0 0 0 0 0 0 3689.2 -796.8 844.8 1 3738.1 -327.2 9374
2014-06-04T22:30:27.938Z,1401921027.938 [SBIT](IMPORTANT): SBIT PASSED
2014-06-04T22:30:28.339Z,1401921028.339 [MissionManager](IMPORTANT): Started mission Startup
2014-06-04T22:30:28.339Z,1401921028.339 [Startup] Running Loop=1
2014-06-04T22:30:28.339Z,1401921028.339 [Startup](INFO): Aggregate::initialize Startup
2014-06-04T22:30:28.339Z,1401921028.339 [Startup:A.GoToSurface] Running Loop=1
2014-06-04T22:30:28.339Z,1401921028.339 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-04T22:30:28.340Z,1401921028.340 [Startup:A.GoToSurface](ERROR): No speed setting specified. Using default value of 0.500000
2014-06-04T22:30:28.346Z,1401921028.346 [Startup:StartupSatComms] Running Loop=1
2014-06-04T22:30:28.346Z,1401921028.346 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2014-06-04T22:30:28.346Z,1401921028.346 [Startup:StartupSatComms:A] Running Loop=1
2014-06-04T22:30:28.842Z,1401921028.842 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-06-04T22:30:31.866Z,1401921031.866 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tank_weight.xml
2014-06-04T22:30:31.866Z,1401921031.866 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tank_weight.xml
2014-06-04T22:30:31.935Z,1401921031.935 [MissionManager](INFO): DefineArg tank_weight.BuoyancyLimitHiCC = 0.000955 n/a
2014-06-04T22:30:31.939Z,1401921031.939 [MissionManager](INFO): DefineArg tank_weight.BuoyancyLimitLoCC = 0.000080 n/a
2014-06-04T22:30:31.940Z,1401921031.940 [tank_weight:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2014-06-04T22:30:31.966Z,1401921031.966 [tank_weight:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2014-06-04T22:30:31.980Z,1401921031.980 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2014-06-04T22:30:32.161Z,1401921032.161 [MissionManager](INFO): DefineArg tank_weight:Science.SampleISUS = 0 bool
2014-06-04T22:30:32.164Z,1401921032.164 [MissionManager](INFO): DefineArg tank_weight:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2014-06-04T22:30:32.168Z,1401921032.168 [MissionManager](INFO): DefineArg tank_weight:Science.SampleISUSminPitch = -60.000000 arcdeg
2014-06-04T22:30:32.171Z,1401921032.171 [MissionManager](INFO): DefineArg tank_weight:Science.PeakDetectChlActive = 0 bool
2014-06-04T22:30:32.174Z,1401921032.174 [MissionManager](INFO): DefineArg tank_weight:Science.PeakDetectNO3Active = 0 bool
2014-06-04T22:30:32.177Z,1401921032.177 [MissionManager](INFO): DefineArg tank_weight:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2014-06-04T22:30:32.192Z,1401921032.192 [MissionManager](INFO): DefineArg tank_weight:Science.ComputeWaterCurrent = 0 bool
2014-06-04T22:30:32.197Z,1401921032.197 [MissionManager](INFO): DefineArg tank_weight:Science.ComputeWaterCurrentMinDepth = 2.000000 m
2014-06-04T22:30:32.208Z,1401921032.208 [MissionManager](INFO): DefineArg tank_weight:Science.ComputeWaterCurrentMaxDepth = 5.000000 m
2014-06-04T22:30:32.216Z,1401921032.216 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledAanderaaO2 = 0.000000 n/a
2014-06-04T22:30:32.220Z,1401921032.220 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledNeilBrown = 1.000000 n/a
2014-06-04T22:30:32.236Z,1401921032.236 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledTurbulence_NPS = 0.000000 n/a
2014-06-04T22:30:32.240Z,1401921032.240 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledWetLabsBB2FL = 1.000000 n/a
2014-06-04T22:30:32.255Z,1401921032.255 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledDVL = 1.000000 n/a
2014-06-04T22:30:32.259Z,1401921032.259 [MissionManager](INFO): DefineArg tank_weight:Science.EnabledISUS = 1.000000 n/a
2014-06-04T22:30:32.262Z,1401921032.262 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakChl = 0.000000 ug/l
2014-06-04T22:30:32.265Z,1401921032.265 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakChlDepth = 0.000000 m
2014-06-04T22:30:32.269Z,1401921032.269 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakChlLatitude = nan arcdeg
2014-06-04T22:30:32.280Z,1401921032.280 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakChlLongitude = nan arcdeg
2014-06-04T22:30:32.284Z,1401921032.284 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakNO3 = 0.000000 umol/l
2014-06-04T22:30:32.287Z,1401921032.287 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakNO3Depth = 0.000000 m
2014-06-04T22:30:32.296Z,1401921032.296 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakNO3Latitude = nan arcdeg
2014-06-04T22:30:32.307Z,1401921032.307 [MissionManager](INFO): DefineOutput tank_weight:Science.PeakNO3Longitude = nan arcdeg
2014-06-04T22:30:32.357Z,1401921032.357 [tank_weight:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2014-06-04T22:30:32.386Z,1401921032.386 [tank_weight:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2014-06-04T22:30:32.411Z,1401921032.411 [MissionManager](INFO): RedefineArg tank_weight:Science.SampleISUS = value:1 bool
2014-06-04T22:30:32.413Z,1401921032.413 [tank_weight:D:A.SetSpeed](DEBUG): Construct.
2014-06-04T22:30:32.437Z,1401921032.437 [tank_weight:D:BuoyancyLo:A.Buoyancy](DEBUG): Construct Buoyancy.
2014-06-04T22:30:32.441Z,1401921032.441 [tank_weight:D:BuoyancyLo:B.Pitch](DEBUG): Construct.
2014-06-04T22:30:32.477Z,1401921032.477 [tank_weight:D:BuoyancyLo:C.Wait](DEBUG): Construct Wait.
2014-06-04T22:30:32.484Z,1401921032.484 [tank_weight:D:BuoyancyHi:A.Buoyancy](DEBUG): Construct Buoyancy.
2014-06-04T22:30:32.499Z,1401921032.499 [tank_weight:D:BuoyancyHi:B.Pitch](DEBUG): Construct.
2014-06-04T22:30:32.510Z,1401921032.510 [tank_weight:D:BuoyancyHi:C.Wait](DEBUG): Construct Wait.
2014-06-04T22:30:32.549Z,1401921032.549 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Trigger="Tethys/Trigger" 
       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="tank_weight">

    <DefineArg Name="BuoyancyLimitHiCC"><Control:VerticalControl.buoyancyLimitHiCC/></DefineArg>

    <DefineArg Name="BuoyancyLimitLoCC"><Control:VerticalControl.buoyancyLimitLoCC/></DefineArg>

    <Timeout Duration="P75M"/>

    <Guidance:AltitudeEnvelope>
        <Parallel/>
        <Setting><Guidance:AltitudeEnvelope.minAltitude/><Units:meter/><Value>0</Value></Setting>
    </Guidance:AltitudeEnvelope>

    <Guidance:DepthEnvelope>
        <Parallel/>
        <Setting><Guidance:DepthEnvelope.minDepth/><Units:meter/><Value>0</Value></Setting>
        <Setting><Guidance:DepthEnvelope.maxDepth/><Units:meter/><Value>15</Value></Setting>
    </Guidance:DepthEnvelope>

    <Insert Filename="Insert/Science.xml">
        <RedefineArg Name="SampleISUS"><True/></RedefineArg>
    </Insert>

    <Aggregate>

        <Sequence/>

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
        </Guidance:SetSpeed>

        <Aggregate Id="BuoyancyLo">

            <Sequence/>

            <Guidance:Buoyancy>
                <Parallel/>
                <Setting><Guidance:Buoyancy.position/><Arg Name="BuoyancyLimitLoCC"/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Pitch>
                <Parallel/>
                <Setting><Guidance:Pitch.massPosition/><Units:meter/><Value>0</Value></Setting>
                <Setting><Guidance:Pitch.depth/><Units:meter/><Value>15</Value></Setting>
            </Guidance:Pitch>

            <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Units:minute/><Value>65</Value></Setting>
            </Guidance:Wait>

        </Aggregate>

        <Aggregate Id="BuoyancyHi">

            <Sequence/>

            <Guidance:Buoyancy>
                <Parallel/>
                <Setting><Guidance:Buoyancy.position/><Arg Name="BuoyancyLimitHiCC"/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Pitch>
                <Parallel/>
                <Setting><Guidance:Pitch.massPosition/><Units:meter/><Value>0</Value></Setting>
                <Setting><Guidance:Pitch.depth/><Units:meter/><Value>15</Value></Setting>
            </Guidance:Pitch>

            <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
            </Guidance:Wait>

        </Aggregate>

    </Aggregate>

</Mission>


2014-06-04T22:30:32.556Z,1401921032.556 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tank_weight.xml
2014-06-04T22:30:33.997Z,1401921033.997 [CommandLine](IMPORTANT): got command show stack
2014-06-04T22:30:33.997Z,1401921033.997 [CommandLine](IMPORTANT): Behavior Stack:

2014-06-04T22:30:33.997Z,1401921033.997 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2014-06-04T22:30:33.998Z,1401921033.998 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2014-06-04T22:30:36.080Z,1401921036.080 [CommandLine](IMPORTANT): got command show variable isus
2014-06-04T22:30:36.090Z,1401921036.090 [CommandLine](IMPORTANT): ISUS.loadControl (none)
2014-06-04T22:30:36.090Z,1401921036.090 [CommandLine](IMPORTANT): ISUS.uart (none)
2014-06-04T22:30:36.091Z,1401921036.091 [CommandLine](IMPORTANT): ISUS.baud (bit_per_second)
2014-06-04T22:30:36.135Z,1401921036.135 [CommandLine](IMPORTANT): ISUS.loadAtStartup (bool)
2014-06-04T22:30:36.135Z,1401921036.135 [CommandLine](IMPORTANT): ISUS.simulateHardware (bool)
2014-06-04T22:30:36.140Z,1401921036.140 [CommandLine](IMPORTANT): ISUS.power (watt)
2014-06-04T22:30:36.140Z,1401921036.140 [CommandLine](IMPORTANT): ISUS.nitrateAccuracy (micromole_per_liter)
2014-06-04T22:30:36.195Z,1401921036.195 [CommandLine](IMPORTANT): ISUS.dateDataString (second)
2014-06-04T22:30:36.195Z,1401921036.195 [CommandLine](IMPORTANT): ISUS.mole_concentration_of_nitrate_in_sea_water (micromole_per_liter)
2014-06-04T22:30:36.201Z,1401921036.201 [CommandLine](IMPORTANT): ISUS.component_voltage (volt)
2014-06-04T22:30:36.202Z,1401921036.202 [CommandLine](IMPORTANT): ISUS.component_avgVoltage (volt)
2014-06-04T22:30:36.202Z,1401921036.202 [CommandLine](IMPORTANT): ISUS.component_current (milliampere)
2014-06-04T22:30:36.202Z,1401921036.202 [CommandLine](IMPORTANT): ISUS.component_avgCurrent (milliampere)
2014-06-04T22:30:36.203Z,1401921036.203 [CommandLine](IMPORTANT): ISUS.durationOfLastRun (second)
2014-06-04T22:30:36.207Z,1401921036.207 [CommandLine](IMPORTANT): tank_weight:Science.SampleISUS (bool)
2014-06-04T22:30:36.207Z,1401921036.207 [CommandLine](IMPORTANT): tank_weight:Science.SampleISUSmaxPitch (degree)
2014-06-04T22:30:36.208Z,1401921036.208 [CommandLine](IMPORTANT): tank_weight:Science.SampleISUSminPitch (degree)
2014-06-04T22:30:36.210Z,1401921036.210 [CommandLine](IMPORTANT): tank_weight:Science.EnabledISUS (none)
2014-06-04T22:30:43.428Z,1401921043.428 [CommandLine](IMPORTANT): got command report touch ISUS.mole_concentration_of_nitrate_in_sea_water
2014-06-04T22:30:46.088Z,1401921046.088 [CommandLine](IMPORTANT): got command show stack
2014-06-04T22:30:46.088Z,1401921046.088 [CommandLine](IMPORTANT): Behavior Stack:

2014-06-04T22:30:46.088Z,1401921046.088 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2014-06-04T22:30:46.088Z,1401921046.088 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2014-06-04T22:30:54.926Z,1401921054.926 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2014-06-04T22:30:55.120Z,1401921055.120 [Startup:StartupSatComms:A] Stopped
2014-06-04T22:30:55.120Z,1401921055.120 [Startup:StartupSatComms:B] Running Loop=1
2014-06-04T22:30:55.576Z,1401921055.576 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-06-04T22:31:05.919Z,1401921065.919 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2014-06-04T22:31:09.948Z,1401921069.948 [HFRadarModelCalc](IMPORTANT): Forecast time 20140604T200000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-04T22:31:09.951Z,1401921069.951 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = 0.899224 for 2014-06-04T20:00:00.000Z
2014-06-04T22:31:10.794Z,1401921070.794 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-04T22:31:10.815Z,1401921070.815 [Startup:StartupSatComms:B] Stopped
2014-06-04T22:31:10.816Z,1401921070.816 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2014-06-04T22:31:10.816Z,1401921070.816 [Startup:StartupSatComms] Stopped
2014-06-04T22:31:10.816Z,1401921070.816 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2014-06-04T22:31:10.817Z,1401921070.817 [Startup](INFO): Completed Startup
2014-06-04T22:31:10.817Z,1401921070.817 [Startup] Stopped
2014-06-04T22:31:10.817Z,1401921070.817 [Startup](INFO): Aggregate::uninitialize Startup
2014-06-04T22:31:10.817Z,1401921070.817 [Startup:A.GoToSurface] Stopped
2014-06-04T22:31:10.817Z,1401921070.817 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-04T22:31:11.247Z,1401921071.247 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2014-06-04T22:31:14.837Z,1401921074.837 [HFRadarModelCalc](IMPORTANT): Forecast time 20140604T200000: published 50 modes in rows, 61 hours in columns, 3050 elements.
2014-06-04T22:31:14.839Z,1401921074.839 [HFRadarModelCalc](IMPORTANT): expansionCoefficients_[0][48] = 0.899224 for 2014-06-04T20:00:00.000Z
2014-06-04T22:31:15.540Z,1401921075.540 [HFRadarCompactModelForecaster](DEBUG): Did not find new historical expansion coefficients.
2014-06-04T22:31:15.553Z,1401921075.553 [MissionManager](IMPORTANT): Started mission tank_weight
2014-06-04T22:31:15.553Z,1401921075.553 [tank_weight] Running Loop=1
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight](INFO): Aggregate::initialize tank_weight
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:A.AltitudeEnvelope] Running Loop=1
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:B.DepthEnvelope] Running Loop=1
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:Science] Running Loop=1
2014-06-04T22:31:15.554Z,1401921075.554 [tank_weight:Science](INFO): Aggregate::initialize tank_weight:Science
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:A] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:B] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:C] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:D] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:E] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:F] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:G] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:PeakDetectChl] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:PeakDetectChl](INFO): Aggregate::initialize tank_weight:Science:PeakDetectChl
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2014-06-04T22:31:15.555Z,1401921075.555 [tank_weight:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2014-06-04T22:31:15.557Z,1401921075.557 [tank_weight:Science:PeakDetectNO3] Running Loop=1
2014-06-04T22:31:15.557Z,1401921075.557 [tank_weight:Science:PeakDetectNO3](INFO): Aggregate::initialize tank_weight:Science:PeakDetectNO3
2014-06-04T22:31:15.557Z,1401921075.557 [tank_weight:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2014-06-04T22:31:15.557Z,1401921075.557 [tank_weight:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D] Running Loop=1
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D](INFO): Aggregate::initialize tank_weight:D
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:A.SetSpeed] Running Loop=1
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:A.SetSpeed](DEBUG): Initialize.
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:BuoyancyLo] Running Loop=1
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:BuoyancyLo](INFO): Aggregate::initialize tank_weight:D:BuoyancyLo
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:BuoyancyLo:A.Buoyancy] Running Loop=1
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:BuoyancyLo:A.Buoyancy](DEBUG): Initialize Buoyancy Component.
2014-06-04T22:31:15.559Z,1401921075.559 [tank_weight:D:BuoyancyLo:B.Pitch] Running Loop=1
2014-06-04T22:31:15.560Z,1401921075.560 [tank_weight:D:BuoyancyLo:B.Pitch](DEBUG): Initialize.
2014-06-04T22:31:15.560Z,1401921075.560 [tank_weight:D:BuoyancyLo:C.Wait] Running Loop=1
2014-06-04T22:31:15.560Z,1401921075.560 [tank_weight:D:BuoyancyLo:C.Wait](DEBUG): Initialize Wait Component.
2014-06-04T22:31:15.588Z,1401921075.588 [tank_weight:D:BuoyancyLo:B.Pitch] Running Loop=1
2014-06-04T22:31:15.606Z,1401921075.606 [tank_weight:D:BuoyancyLo:A.Buoyancy] Running Loop=1
2014-06-04T22:31:15.611Z,1401921075.611 [tank_weight:D:A.SetSpeed] Running Loop=1
2014-06-04T22:31:15.615Z,1401921075.615 [tank_weight:Science] Running Loop=1
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectNO3] Stopped
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectNO3](INFO): Aggregate::uninitialize tank_weight:Science:PeakDetectNO3
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectChl] Stopped
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectChl](INFO): Aggregate::uninitialize tank_weight:Science:PeakDetectChl
2014-06-04T22:31:15.632Z,1401921075.632 [tank_weight:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2014-06-04T22:31:15.633Z,1401921075.633 [tank_weight:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2014-06-04T22:31:15.633Z,1401921075.633 [tank_weight:Science:G] Running Loop=1
2014-06-04T22:31:15.633Z,1401921075.633 [tank_weight:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2014-06-04T22:31:15.635Z,1401921075.635 [tank_weight:Science:F] Stopped
2014-06-04T22:31:15.635Z,1401921075.635 [tank_weight:Science:E] Stopped
2014-06-04T22:31:15.635Z,1401921075.635 [tank_weight:Science:D] Running Loop=1
2014-06-04T22:31:15.636Z,1401921075.636 [tank_weight:Science:D](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2014-06-04T22:31:15.636Z,1401921075.636 [tank_weight:Science:D](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2014-06-04T22:31:15.638Z,1401921075.638 [tank_weight:Science:C] Stopped
2014-06-04T22:31:15.638Z,1401921075.638 [tank_weight:Science:B] Running Loop=1
2014-06-04T22:31:15.638Z,1401921075.638 [tank_weight:Science:B](DEBUG): Initialize ReadDataComponent to sense mole_concentration_of_nitrate_in_sea_water
2014-06-04T22:31:15.640Z,1401921075.640 [tank_weight:Science:A] Stopped
2014-06-04T22:31:15.640Z,1401921075.640 [tank_weight:B.DepthEnvelope] Running Loop=1
2014-06-04T22:31:15.657Z,1401921075.657 [tank_weight:A.AltitudeEnvelope] Running Loop=1
2014-06-04T22:31:15.802Z,1401921075.802 [WetLabsBB2FL](INFO): Opening uart, block timeout 10ths=4
2014-06-04T22:31:15.802Z,1401921075.802 [WetLabsBB2FL](INFO): Powering up
2014-06-04T22:31:16.023Z,1401921076.023 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4
2014-06-04T22:31:16.341Z,1401921076.341 [Depth_Keller](ERROR): Pressure reading out of range: 1011.887390 decibar
2014-06-04T22:31:16.924Z,1401921076.924 [ISUS](INFO): Powering up
2014-06-04T22:31:20.870Z,1401921080.870 [CTD_NeilBrown](ERROR): Bad response:  33.4527
2014-06-04T22:31:22.252Z,1401921082.252 [NAL9602](INFO): Powering down
2014-06-04T22:31:28.858Z,1401921088.858 [CommandLine](IMPORTANT): got command get depth
2014-06-04T22:31:28.859Z,1401921088.859 [CommandLine](IMPORTANT): depth 0.091032 m
2014-06-04T22:31:35.244Z,1401921095.244 [CommandLine](IMPORTANT): got command report
2014-06-04T22:31:35.244Z,1401921095.244 [Reporter](INFO): ISUS.mole_concentration_of_nitrate_in_sea_water reporting when touched
2014-06-04T22:31:48.737Z,1401921108.737 [CommandLine](IMPORTANT): got command get ISUS.component_avgCurrent
2014-06-04T22:31:48.738Z,1401921108.738 [CommandLine](IMPORTANT): ISUS.component_avgCurrent 0.000000 mA
2014-06-04T22:31:50.215Z,1401921110.215 [ISUS](FAULT): ISUS initialization failed.
2014-06-04T22:31:50.215Z,1401921110.215 [ISUS] Communications Fault, FailCount= 1
2014-06-04T22:31:50.215Z,1401921110.215 [ISUS](ERROR): Communications Fault
2014-06-04T22:31:50.343Z,1401921110.343 [CBIT](ERROR): Communications Fault in component: ISUS
2014-06-04T22:31:50.925Z,1401921110.925 [Reporter](INFO): ISUS.mole_concentration_of_nitrate_in_sea_water no_value
2014-06-04T22:31:51.964Z,1401921111.964 [CBIT](INFO): Clearing failed state for component ISUS
2014-06-04T22:31:51.964Z,1401921111.964 [ISUS] No Fault, FailCount= 1
2014-06-04T22:31:52.369Z,1401921112.369 [ISUS](INFO): Powering up
2014-06-04T22:31:55.531Z,1401921115.531 [CommandLine](IMPORTANT): got command get ISUS.component_avgCurrent
2014-06-04T22:31:55.532Z,1401921115.532 [CommandLine](IMPORTANT): ISUS.component_avgCurrent 0.000000 mA
2014-06-04T22:32:15.827Z,1401921135.827 [CommandLine](IMPORTANT): got command get ISUS.component_avgCurrent
2014-06-04T22:32:15.827Z,1401921135.827 [CommandLine](IMPORTANT): ISUS.component_avgCurrent 0.000000 mA
2014-06-04T22:32:25.518Z,1401921145.518 [ISUS](FAULT): ISUS initialization failed.
2014-06-04T22:32:25.519Z,1401921145.519 [ISUS] Communications Fault, FailCount= 2
2014-06-04T22:32:25.519Z,1401921145.519 [ISUS](ERROR): Communications Fault
2014-06-04T22:32:25.628Z,1401921145.628 [CBIT](ERROR): Communications Fault in component: ISUS
2014-06-04T22:32:26.228Z,1401921146.228 [Reporter](INFO): ISUS.mole_concentration_of_nitrate_in_sea_water no_value
2014-06-04T22:32:27.248Z,1401921147.248 [CBIT](INFO): Clearing failed state for component ISUS
2014-06-04T22:32:27.248Z,1401921147.248 [ISUS] No Fault, FailCount= 2
2014-06-04T22:32:27.628Z,1401921147.628 [ISUS](INFO): Powering up
2014-06-04T22:33:00.034Z,1401921180.034 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 45 of 46
2014-06-04T22:33:00.035Z,1401921180.035 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.6 0.6 0.2 0.8 -1472.5 -1885.3 -706.2 -993.5 0 0 0 0 0 0 0 0 -1022.7 -1190.2 -1363.7 1 -482.2 -1429.0 -1430.9 1 0 0 0 0 0 0 0 0 -.28 12.1 0.2 18.7 0.005 35.0 1489 95
2014-06-04T22:33:00.871Z,1401921180.871 [ISUS](FAULT): ISUS initialization failed.
2014-06-04T22:33:00.871Z,1401921180.871 [ISUS] Communications Fault, FailCount= 3
2014-06-04T22:33:00.872Z,1401921180.872 [ISUS](ERROR): Communications Fault
2014-06-04T22:33:01.063Z,1401921181.063 [CBIT](ERROR): Communications Fault in component: ISUS
2014-06-04T22:33:01.063Z,1401921181.063 [CBIT](FAULT): Communications Fault in component: ISUS
2014-06-04T22:33:01.460Z,1401921181.460 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 43 of 46
2014-06-04T22:33:01.460Z,1401921181.460 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.6 0.5 0.2 0.8 -1506.6 -2115.5 -710.7 -1030.2 0 0 0 0 -1062.2 -1448.5 -1446.1 1 -451.3 -1693.4 -1498.8 1 0 0 0 0 0 0 0 0 -4.35 -10.31 12.1 0.2 18.7 0.005 35.0 1489 107
2014-06-04T22:33:01.710Z,1401921181.710 [Reporter](INFO): ISUS.mole_concentration_of_nitrate_in_sea_water no_value
2014-06-04T22:33:05.044Z,1401921185.044 [CommandLine](IMPORTANT): got command failComponent
2014-06-04T22:33:05.044Z,1401921185.044 [CommandLine](IMPORTANT): Failed components:
2014-06-04T22:33:05.044Z,1401921185.044 [CommandLine](IMPORTANT): ISUS: Communications Fault
2014-06-04T22:33:07.864Z,1401921187.864 [CommandLine](IMPORTANT): got command failComponent none ISUS
2014-06-04T22:33:07.864Z,1401921187.864 [ISUS] No Fault, FailCount= 3
2014-06-04T22:33:07.864Z,1401921187.864 [CommandLine](IMPORTANT): ISUS failureMode is No Fault
2014-06-04T22:33:08.408Z,1401921188.408 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 43 of 46
2014-06-04T22:33:08.409Z,1401921188.409 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.5 0.5 0.2 0.8 -1748.8 -1838.9 -673.2 -1004.2 0 0 0 0 -1435.5 -1114.0 -1419.7 1 -876.6 -1445.3 -1568.5 1 0 0 0 0 0 0 0 0 -4.31 -10.44 12.2 0.2 18.7 0.005 35.0 1489 97
2014-06-04T22:33:08.419Z,1401921188.419 [ISUS](INFO): Powering up
2014-06-04T22:33:21.465Z,1401921201.465 [DVL_micro](ERROR): NQ1 string checksum mismatch. Reported:90 Calculated:75
2014-06-04T22:33:21.465Z,1401921201.465 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 0.6 0.6 0.2 0.8 -1664.6 -1866.3 -652.3 -936.6 0 0 0 0 0 0 0 0 -1351.1 -1240.5 1 -755.7 -1548.6 -1517.1 1 0 0 0 0 0 0 0 0 -4.07 -10.77 12.7 0.2 18.7 0.005 35.0 1489 90
2014-06-04T22:33:35.238Z,1401921215.238 [CommandLine](IMPORTANT): got command quit
2014-06-04T22:33:36.246Z,1401921216.246 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:36.247Z,1401921216.247 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.363Z,1401921216.363 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2014-06-04T22:33:36.363Z,1401921216.363 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.364Z,1401921216.364 [CommandLine](INFO): Join timeout helper Thread ID is 8956
2014-06-04T22:33:36.365Z,1401921216.365 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2014-06-04T22:33:36.365Z,1401921216.365 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.365Z,1401921216.365 [NavChartDb](INFO): Join timeout helper Thread ID is 8957
2014-06-04T22:33:36.426Z,1401921216.426 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:36.428Z,1401921216.428 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.445Z,1401921216.445 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2014-06-04T22:33:36.445Z,1401921216.445 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.446Z,1401921216.446 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 8958
2014-06-04T22:33:36.547Z,1401921216.547 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:36.636Z,1401921216.636 [WetLabsBB2FL](INFO): Powering down
2014-06-04T22:33:36.637Z,1401921216.637 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.644Z,1401921216.644 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2014-06-04T22:33:36.644Z,1401921216.644 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.644Z,1401921216.644 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 8959
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight](INFO): Aggregate::uninitialize tank_weight
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:A.AltitudeEnvelope] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:B.DepthEnvelope] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:B.DepthEnvelope](DEBUG): Uninitialize.
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:Science] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:Science](INFO): Aggregate::uninitialize tank_weight:Science
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:Science:B] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:Science:D] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:Science:G] Stopped
2014-06-04T22:33:36.707Z,1401921216.707 [tank_weight:D] Stopped
2014-06-04T22:33:36.712Z,1401921216.712 [tank_weight:D](INFO): Aggregate::uninitialize tank_weight:D
2014-06-04T22:33:36.712Z,1401921216.712 [tank_weight:D:A.SetSpeed] Stopped
2014-06-04T22:33:36.712Z,1401921216.712 [tank_weight:D:A.SetSpeed](DEBUG): Uninitialize.
2014-06-04T22:33:36.712Z,1401921216.712 [tank_weight:D:BuoyancyLo] Stopped
2014-06-04T22:33:36.712Z,1401921216.712 [tank_weight:D:BuoyancyLo](INFO): Aggregate::uninitialize tank_weight:D:BuoyancyLo
2014-06-04T22:33:36.713Z,1401921216.713 [tank_weight:D:BuoyancyLo:A.Buoyancy] Stopped
2014-06-04T22:33:36.713Z,1401921216.713 [tank_weight:D:BuoyancyLo:A.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2014-06-04T22:33:36.713Z,1401921216.713 [tank_weight:D:BuoyancyLo:B.Pitch] Stopped
2014-06-04T22:33:36.713Z,1401921216.713 [tank_weight:D:BuoyancyLo:C.Wait] Stopped
2014-06-04T22:33:36.713Z,1401921216.713 [tank_weight:D:BuoyancyLo:C.Wait](DEBUG): Uninitialize Wait Component.
2014-06-04T22:33:36.870Z,1401921216.870 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:36.989Z,1401921216.989 [CTD_NeilBrown](INFO): Powering down
2014-06-04T22:33:36.990Z,1401921216.990 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.992Z,1401921216.992 [ComponentRegistry](INFO): Shutting down Radio_Freewave ThreadHandler
2014-06-04T22:33:36.992Z,1401921216.992 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:36.993Z,1401921216.993 [Radio_Freewave](INFO): Join timeout helper Thread ID is 8960
2014-06-04T22:33:37.231Z,1401921217.231 [MissionManager](IMPORTANT): Started mission Default
2014-06-04T22:33:37.232Z,1401921217.232 [Default] Running Loop=1
2014-06-04T22:33:37.232Z,1401921217.232 [Default](INFO): Aggregate::initialize Default
2014-06-04T22:33:37.233Z,1401921217.233 [Default:Iridium] Running Loop=1
2014-06-04T22:33:37.233Z,1401921217.233 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2014-06-04T22:33:37.233Z,1401921217.233 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-04T22:33:37.233Z,1401921217.233 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2014-06-04T22:33:37.235Z,1401921217.235 [Default:Iridium:B.GoToSurface] Running Loop=1
2014-06-04T22:33:37.235Z,1401921217.235 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-04T22:33:37.235Z,1401921217.235 [Default:Iridium:B.GoToSurface](ERROR): No speed setting specified. Using default value of 0.500000
2014-06-04T22:33:37.248Z,1401921217.248 [Default:Iridium:Read_Iridium] Running Loop=1
2014-06-04T22:33:37.248Z,1401921217.248 [Default:Iridium:A.SetSpeed] Running Loop=1
2014-06-04T22:33:37.269Z,1401921217.269 [Default:GPS] Running Loop=1
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS:A.SetSpeed] Running Loop=1
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS:B.GoToSurface] Running Loop=1
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2014-06-04T22:33:37.270Z,1401921217.270 [Default:GPS:B.GoToSurface](ERROR): No speed setting specified. Using default value of 0.500000
2014-06-04T22:33:37.280Z,1401921217.280 [Default:GPS:Read_GPS] Running Loop=1
2014-06-04T22:33:37.280Z,1401921217.280 [Default:GPS:A.SetSpeed] Running Loop=1
2014-06-04T22:33:37.389Z,1401921217.389 [Radio_Freewave ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:37.530Z,1401921217.530 [Radio_Freewave](INFO): Powering down
2014-06-04T22:33:37.876Z,1401921217.876 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2014-06-04T22:33:37.881Z,1401921217.881 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2014-06-04T22:33:37.946Z,1401921217.946 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:37.959Z,1401921217.959 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2014-06-04T22:33:37.959Z,1401921217.959 [logger ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:37.959Z,1401921217.959 [logger](INFO): Join timeout helper Thread ID is 8963
2014-06-04T22:33:37.966Z,1401921217.966 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:37.966Z,1401921217.966 [logger ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:37.968Z,1401921217.968 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2014-06-04T22:33:37.968Z,1401921217.968 [CommandLine ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:37.968Z,1401921217.968 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2014-06-04T22:33:37.968Z,1401921217.968 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:37.969Z,1401921217.969 [controlThread](INFO): Join timeout helper Thread ID is 8964
2014-06-04T22:33:38.161Z,1401921218.161 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2014-06-04T22:33:38.162Z,1401921218.162 [controlThread](DEBUG): Uninitializing ControlThread
2014-06-04T22:33:38.162Z,1401921218.162 [AHRS_sp3003D](INFO): Powering down
2014-06-04T22:33:38.322Z,1401921218.322 [DVL_micro](INFO): uninitialize:Powering down
2014-06-04T22:33:38.324Z,1401921218.324 [NAL9602](INFO): Powering down
2014-06-04T22:33:38.329Z,1401921218.329 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2014-06-04T22:33:38.332Z,1401921218.332 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2014-06-04T22:33:38.332Z,1401921218.332 [Default] Stopped
2014-06-04T22:33:38.332Z,1401921218.332 [Default](INFO): Aggregate::uninitialize Default
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS:A.SetSpeed] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS:B.GoToSurface] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-04T22:33:38.333Z,1401921218.333 [Default:GPS:Read_GPS] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:Iridium] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2014-06-04T22:33:38.333Z,1401921218.333 [Default:Iridium:A.SetSpeed] Stopped
2014-06-04T22:33:38.333Z,1401921218.333 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2014-06-04T22:33:38.334Z,1401921218.334 [Default:Iridium:B.GoToSurface] Stopped
2014-06-04T22:33:38.334Z,1401921218.334 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2014-06-04T22:33:38.334Z,1401921218.334 [Default:Iridium:Read_Iridium] Stopped
2014-06-04T22:33:38.338Z,1401921218.338 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2014-06-04T22:33:38.338Z,1401921218.338 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2014-06-04T22:33:38.339Z,1401921218.339 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2014-06-04T22:33:38.339Z,1401921218.339 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2014-06-04T22:33:38.339Z,1401921218.339 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2014-06-04T22:33:38.344Z,1401921218.344 [BuoyancyServo](INFO): Powering down
2014-06-04T22:33:38.359Z,1401921218.359 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2014-06-04T22:33:38.359Z,1401921218.359 [ElevatorServo](INFO): Powering down
2014-06-04T22:33:38.360Z,1401921218.360 [MassServo](DEBUG): Uninitialize Mass Servo.
2014-06-04T22:33:38.360Z,1401921218.360 [MassServo](INFO): Powering down
2014-06-04T22:33:38.361Z,1401921218.361 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2014-06-04T22:33:38.361Z,1401921218.361 [RudderServo](INFO): Powering down
2014-06-04T22:33:38.362Z,1401921218.362 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2014-06-04T22:33:38.362Z,1401921218.362 [ThrusterServo](INFO): Powering down
2014-06-04T22:33:38.363Z,1401921218.363 [SBIT](DEBUG): Uninitialize SBIT Component.
2014-06-04T22:33:38.364Z,1401921218.364 [IBIT](DEBUG): Uninitialize IBIT Component.
2014-06-04T22:33:38.364Z,1401921218.364 [CBIT](DEBUG): Uninitialize CBIT Component.
2014-06-04T22:33:38.408Z,1401921218.408 [controlThread ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:38.410Z,1401921218.410 [Radio_Freewave ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:38.483Z,1401921218.483 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:38.486Z,1401921218.486 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:38.774Z,1401921218.774 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2014-06-04T22:33:38.808Z,1401921218.808 [logger ThreadHandler](INFO): Thread cancelled.