2015-02-17T18:25:46.111Z,1424197546.111 [Supervisor](DEBUG): Initializing supervisor.
2015-02-17T18:25:46.114Z,1424197546.114 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-02-17T18:25:46.114Z,1424197546.114 [SyncHandler](INFO): Protected caller Thread ID is 1311
2015-02-17T18:25:46.115Z,1424197546.115 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-02-17T18:25:46.116Z,1424197546.116 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-02-17T18:25:46.116Z,1424197546.116 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1312
2015-02-17T18:25:46.119Z,1424197546.119 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-02-17T18:25:46.141Z,1424197546.141 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-02-17T18:25:46.142Z,1424197546.142 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-02-17T18:25:46.142Z,1424197546.142 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1313
2015-02-17T18:25:46.143Z,1424197546.143 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-02-17T18:25:46.144Z,1424197546.144 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-02-17T18:25:46.144Z,1424197546.144 [logger ThreadHandler](INFO): Protected caller Thread ID is 1314
2015-02-17T18:25:46.147Z,1424197546.147 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-02-17T18:25:46.147Z,1424197546.147 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-02-17T18:25:46.148Z,1424197546.148 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-02-17T18:25:46.500Z,1424197546.500 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-02-17T18:25:46.501Z,1424197546.501 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-02-17T18:25:46.690Z,1424197546.690 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-02-17T18:25:46.691Z,1424197546.691 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-02-17T18:25:46.815Z,1424197546.815 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-02-17T18:25:46.816Z,1424197546.816 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-02-17T18:25:46.955Z,1424197546.955 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-02-17T18:25:46.956Z,1424197546.956 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-02-17T18:25:47.067Z,1424197547.067 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-02-17T18:25:47.292Z,1424197547.292 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-02-17T18:25:47.295Z,1424197547.295 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-02-17T18:25:47.380Z,1424197547.380 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-02-17T18:25:47.380Z,1424197547.380 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-02-17T18:25:47.622Z,1424197547.622 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-02-17T18:25:47.623Z,1424197547.623 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-02-17T18:25:48.032Z,1424197548.032 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-02-17T18:25:48.033Z,1424197548.033 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-02-17T18:25:48.415Z,1424197548.415 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-02-17T18:25:48.416Z,1424197548.416 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-02-17T18:25:48.945Z,1424197548.945 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-02-17T18:25:48.946Z,1424197548.946 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-02-17T18:25:49.205Z,1424197549.205 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-02-17T18:25:49.206Z,1424197549.206 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-02-17T18:25:49.320Z,1424197549.320 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-02-17T18:25:49.320Z,1424197549.320 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-02-17T18:25:49.798Z,1424197549.798 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-02-17T18:25:49.799Z,1424197549.799 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-02-17T18:25:49.911Z,1424197549.911 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-02-17T18:25:49.922Z,1424197549.922 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-02-17T18:25:49.923Z,1424197549.923 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-02-17T18:25:50.191Z,1424197550.191 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-02-17T18:25:50.192Z,1424197550.192 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-02-17T18:25:50.321Z,1424197550.321 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-02-17T18:25:50.439Z,1424197550.439 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-02-17T18:25:50.554Z,1424197550.554 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-02-17T18:25:50.662Z,1424197550.662 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-02-17T18:25:50.808Z,1424197550.808 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-02-17T18:25:50.999Z,1424197550.999 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-02-17T18:25:51.138Z,1424197551.138 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-02-17T18:25:51.227Z,1424197551.227 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-02-17T18:25:51.332Z,1424197551.332 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-02-17T18:25:51.449Z,1424197551.449 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-02-17T18:25:51.646Z,1424197551.646 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2015-02-17T18:25:51.646Z,1424197551.646 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-02-17T18:25:51.660Z,1424197551.660 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-02-17T18:25:51.712Z,1424197551.712 [VerticalControl](DEBUG): Construct VerticalControl.
2015-02-17T18:25:51.838Z,1424197551.838 [VerticalControl] Loaded
2015-02-17T18:25:51.839Z,1424197551.839 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-02-17T18:25:51.839Z,1424197551.839 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-02-17T18:25:51.972Z,1424197551.972 [HorizontalControl] Loaded
2015-02-17T18:25:51.973Z,1424197551.973 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-02-17T18:25:51.973Z,1424197551.973 [SpeedControl](DEBUG): Construct SpeedControl.
2015-02-17T18:25:51.979Z,1424197551.979 [SpeedControl] Loaded
2015-02-17T18:25:51.979Z,1424197551.979 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-02-17T18:25:51.980Z,1424197551.980 [LoopControl](DEBUG): Construct LoopControl.
2015-02-17T18:25:51.981Z,1424197551.981 [LoopControl] Loaded
2015-02-17T18:25:51.981Z,1424197551.981 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-02-17T18:25:51.981Z,1424197551.981 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-02-17T18:25:51.982Z,1424197551.982 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-02-17T18:25:52.082Z,1424197552.082 [SBIT](DEBUG): Construct Startup Built In Test.
2015-02-17T18:25:52.094Z,1424197552.094 [SBIT] Loaded
2015-02-17T18:25:52.094Z,1424197552.094 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-02-17T18:25:52.095Z,1424197552.095 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-02-17T18:25:52.124Z,1424197552.124 [IBIT] Loaded
2015-02-17T18:25:52.124Z,1424197552.124 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-02-17T18:25:52.126Z,1424197552.126 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-02-17T18:25:52.273Z,1424197552.273 [CBIT] Loaded
2015-02-17T18:25:52.274Z,1424197552.274 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-02-17T18:25:52.274Z,1424197552.274 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-02-17T18:25:52.275Z,1424197552.275 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-02-17T18:25:52.294Z,1424197552.294 [DepthRateCalculator] Loaded
2015-02-17T18:25:52.294Z,1424197552.294 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-02-17T18:25:52.300Z,1424197552.300 [PitchRateCalculator] Loaded
2015-02-17T18:25:52.300Z,1424197552.300 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-02-17T18:25:52.311Z,1424197552.311 [SpeedCalculator] Loaded
2015-02-17T18:25:52.312Z,1424197552.312 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-02-17T18:25:52.334Z,1424197552.334 [TempGradientCalculator] Loaded
2015-02-17T18:25:52.334Z,1424197552.334 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-02-17T18:25:52.339Z,1424197552.339 [YawRateCalculator] Loaded
2015-02-17T18:25:52.340Z,1424197552.340 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-02-17T18:25:52.340Z,1424197552.340 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-02-17T18:25:52.341Z,1424197552.341 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-02-17T18:25:53.494Z,1424197553.494 [HFRCMReconstructedInterpolator] Loaded
2015-02-17T18:25:53.495Z,1424197553.495 [ComponentRegistry](DEBUG): SyncComponent "HFRCMReconstructedInterpolator" handled in the control thread.
2015-02-17T18:25:53.495Z,1424197553.495 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-02-17T18:25:53.496Z,1424197553.496 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-02-17T18:25:53.740Z,1424197553.740 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-02-17T18:25:53.741Z,1424197553.741 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-02-17T18:25:53.831Z,1424197553.831 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-02-17T18:25:53.832Z,1424197553.832 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-02-17T18:25:53.896Z,1424197553.896 [DeadReckonUsingSpeedCalculator] Loaded
2015-02-17T18:25:53.896Z,1424197553.896 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2015-02-17T18:25:53.943Z,1424197553.943 [DeadReckonWithRespectToWater] Loaded
2015-02-17T18:25:53.944Z,1424197553.944 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread.
2015-02-17T18:25:53.961Z,1424197553.961 [NavChart] Loaded
2015-02-17T18:25:53.961Z,1424197553.961 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-02-17T18:25:53.965Z,1424197553.965 [UniversalFixResidualReporter] Loaded
2015-02-17T18:25:53.966Z,1424197553.966 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-02-17T18:25:53.966Z,1424197553.966 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-02-17T18:25:53.967Z,1424197553.967 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-02-17T18:25:53.972Z,1424197553.972 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-02-17T18:25:53.973Z,1424197553.973 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-02-17T18:25:54.067Z,1424197554.067 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-02-17T18:25:54.068Z,1424197554.068 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-02-17T18:25:54.442Z,1424197554.442 [DataOverHttps] Loaded
2015-02-17T18:25:54.443Z,1424197554.443 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-02-17T18:25:54.529Z,1424197554.529 [Depth_Keller] Loaded
2015-02-17T18:25:54.530Z,1424197554.530 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-02-17T18:25:54.635Z,1424197554.635 [NAL9602] Loaded
2015-02-17T18:25:54.635Z,1424197554.635 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-02-17T18:25:54.688Z,1424197554.688 [Onboard] Loaded
2015-02-17T18:25:54.688Z,1424197554.688 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-02-17T18:25:54.695Z,1424197554.695 [Radio_Surface] Loaded
2015-02-17T18:25:54.696Z,1424197554.696 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-02-17T18:25:54.697Z,1424197554.697 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408074E0
2015-02-17T18:25:54.697Z,1424197554.697 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1396
2015-02-17T18:25:56.914Z,1424197556.914 [BPC1] Loaded
2015-02-17T18:25:56.914Z,1424197556.914 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-02-17T18:25:56.915Z,1424197556.915 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-02-17T18:25:56.917Z,1424197556.917 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-02-17T18:25:57.049Z,1424197557.049 [BuoyancyServo] Loaded
2015-02-17T18:25:57.049Z,1424197557.049 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-02-17T18:25:57.061Z,1424197557.061 [ElevatorServo] Loaded
2015-02-17T18:25:57.062Z,1424197557.062 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-02-17T18:25:57.088Z,1424197557.088 [MassServo] Loaded
2015-02-17T18:25:57.088Z,1424197557.088 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2015-02-17T18:25:57.101Z,1424197557.101 [RudderServo] Loaded
2015-02-17T18:25:57.101Z,1424197557.101 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-02-17T18:25:57.113Z,1424197557.113 [ThrusterServo] Loaded
2015-02-17T18:25:57.114Z,1424197557.114 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-02-17T18:25:57.114Z,1424197557.114 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-02-17T18:25:57.115Z,1424197557.115 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-02-17T18:25:57.367Z,1424197557.367 [ExternalSim] Loaded
2015-02-17T18:25:57.368Z,1424197557.368 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2015-02-17T18:25:57.369Z,1424197557.369 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-02-17T18:25:57.369Z,1424197557.369 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-02-17T18:25:57.395Z,1424197557.395 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-02-17T18:25:57.397Z,1424197557.397 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-02-17T18:25:57.398Z,1424197557.398 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-02-17T18:25:57.404Z,1424197557.404 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-02-17T18:25:57.405Z,1424197557.405 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408B84E0
2015-02-17T18:25:57.406Z,1424197557.406 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1397
2015-02-17T18:25:57.410Z,1424197557.410 [Supervisor](INFO): Main Thread ID is 1310
2015-02-17T18:25:57.410Z,1424197557.410 [Supervisor](DEBUG): Running supervisor.
2015-02-17T18:25:57.411Z,1424197557.411 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1398
2015-02-17T18:25:57.415Z,1424197557.415 [controlThread ThreadHandler](INFO): Handler Thread ID is 1399
2015-02-17T18:25:57.415Z,1424197557.415 [controlThread](DEBUG): Initializing ControlThread
2015-02-17T18:25:57.416Z,1424197557.416 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-02-17T18:25:57.418Z,1424197557.418 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-02-17T18:25:57.418Z,1424197557.418 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-02-17T18:25:57.419Z,1424197557.419 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-02-17T18:25:57.419Z,1424197557.419 [SBIT](INFO): Initialize SBIT Component.
2015-02-17T18:25:57.420Z,1424197557.420 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:12012
2015-02-17T18:25:57.420Z,1424197557.420 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-02-17T18:25:57.420Z,1424197557.420 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-02-17T18:25:57.421Z,1424197557.421 [IBIT](INFO): Initialize IBIT Component.
2015-02-17T18:25:57.422Z,1424197557.422 [CBIT](DEBUG): Initialize CBIT Component.
2015-02-17T18:25:57.422Z,1424197557.422 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-02-17T18:25:57.423Z,1424197557.423 [logger ThreadHandler](INFO): Handler Thread ID is 1400
2015-02-17T18:25:57.443Z,1424197557.443 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1401
2015-02-17T18:25:57.449Z,1424197557.449 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-02-17T18:25:57.449Z,1424197557.449 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-02-17T18:25:57.449Z,1424197557.449 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-02-17T18:25:57.449Z,1424197557.449 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-02-17T18:25:57.450Z,1424197557.450 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-02-17T18:25:57.451Z,1424197557.451 [HFRCMReconstructedInterpolator](INFO): Initializing HFRCMReconstructedInterpolator component with velocityAccuracy_ = 0.300000 m/s.
2015-02-17T18:25:57.453Z,1424197557.453 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-02-17T18:25:57.453Z,1424197557.453 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-02-17T18:25:57.454Z,1424197557.454 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2015-02-17T18:25:57.454Z,1424197557.454 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-02-17T18:25:57.454Z,1424197557.454 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-02-17T18:25:57.460Z,1424197557.460 [ExternalSim](INFO): ExternalSim initializing...
2015-02-17T18:25:57.465Z,1424197557.465 [Radio_Surface](INFO): Powering up
2015-02-17T18:25:57.489Z,1424197557.489 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1402
2015-02-17T18:25:57.492Z,1424197557.492 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-02-17T18:25:57.493Z,1424197557.493 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-02-17T18:25:57.493Z,1424197557.493 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-02-17T18:25:57.493Z,1424197557.493 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-02-17T18:25:57.494Z,1424197557.494 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-02-17T18:25:57.494Z,1424197557.494 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-02-17T18:25:57.495Z,1424197557.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-02-17T18:25:57.495Z,1424197557.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-02-17T18:25:57.495Z,1424197557.495 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-02-17T18:25:57.951Z,1424197557.951 [ExternalSim](DEBUG): beaconLat = 36.80340
2015-02-17T18:25:57.952Z,1424197557.952 [ExternalSim](DEBUG): beaconLon = -121.82230
2015-02-17T18:25:57.977Z,1424197557.977 [ExternalSim](DEBUG): beaconDepth = 25.00
2015-02-17T18:25:58.402Z,1424197558.402 [ExternalSim](DEBUG): Simulator initialized
2015-02-17T18:25:58.409Z,1424197558.409 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-02-17T18:25:58.426Z,1424197558.426 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-02-17T18:25:58.451Z,1424197558.451 [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>


2015-02-17T18:25:58.452Z,1424197558.452 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-02-17T18:25:58.562Z,1424197558.562 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-02-17T18:25:58.566Z,1424197558.566 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-02-17T18:25:58.580Z,1424197558.580 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-02-17T18:25:58.609Z,1424197558.609 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-02-17T18:25:58.658Z,1424197558.658 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-02-17T18:25:58.685Z,1424197558.685 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-02-17T18:25:58.691Z,1424197558.691 [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="TimeMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <DefineArg Name="ElapsedSinceMissionWasStarted"><Units:hour/><Value>0</Value></DefineArg>

    <Aggregate Id="StartClock">

        <Sequence/>

        <Assign><Arg Name="TimeMissionWasStarted"/><Universal:time/></Assign>

    </Aggregate>

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

    <Aggregate Id="CheckIn">

        <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>

<!-- TODO: Do we really want this When operating on platform_communications? or on something else like time_fix? -->

<!-- Run application at high speed -->

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

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
<!-- NOTE: Original Default.xml didn't have a timeout on the GPS read, so theoretically could have hung indefinitely there... -->
            <Universal:latitude_fix/>
        </ReadDatum>

<!-- 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="UpdateAndReportMinutesSinceMissionStarted">

        <When>
            <Elapsed><Arg Name="ElapsedSinceMissionWasStarted"/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
        </When>

        <Assign><Arg Name="ElapsedSinceMissionWasStarted"/><Universal:time/><Sub><Arg Name="TimeMissionWasStarted"/></Sub></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceMissionWasStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2015-02-17T18:25:58.722Z,1424197558.722 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,DataOverHttps,Depth_Keller,NAL9602,Onboard,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,HFRCMReconstructedInterpolator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToWater,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2015-02-17T18:25:59.549Z,1424197559.549 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:25:59.561Z,1424197559.561 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:25:59.772Z,1424197559.772 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-02-17T18:25:59.781Z,1424197559.781 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-02-17T18:25:59.815Z,1424197559.815 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-02-17T18:25:59.828Z,1424197559.828 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-02-17T18:25:59.851Z,1424197559.851 [MassServo](DEBUG): Initializing EZServoServo.
2015-02-17T18:25:59.857Z,1424197559.856 [MassServo](DEBUG): Initializing MassServo.
2015-02-17T18:25:59.867Z,1424197559.867 [RudderServo](DEBUG): Initializing EZServoServo.
2015-02-17T18:25:59.873Z,1424197559.873 [RudderServo](DEBUG): Initializing RudderServo.
2015-02-17T18:25:59.908Z,1424197559.908 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-02-17T18:25:59.916Z,1424197559.916 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-02-17T18:26:00.362Z,1424197560.362 [NAL9602](INFO): Powering up NAL9602
2015-02-17T18:26:00.431Z,1424197560.431 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:00.432Z,1424197560.432 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:10.851Z,1424197570.851 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:10.852Z,1424197570.852 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:11.163Z,1424197571.163 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:11.164Z,1424197571.164 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:11.532Z,1424197571.532 [NAL9602](INFO): NAL9602 initialized
2015-02-17T18:26:11.564Z,1424197571.564 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:11.565Z,1424197571.565 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:11.929Z,1424197571.929 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003506
2015-02-17T18:26:11.997Z,1424197571.997 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:11.998Z,1424197571.998 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:12.450Z,1424197572.450 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:13.016Z,1424197573.016 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:13.150Z,1424197573.150 [SBIT](IMPORTANT): Beginning Startup BIT
2015-02-17T18:26:13.153Z,1424197573.153 [CBIT](IMPORTANT): Beginning GF scan
2015-02-17T18:26:13.409Z,1424197573.409 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:14.226Z,1424197574.226 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:14.798Z,1424197574.798 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:15.219Z,1424197575.219 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:15.685Z,1424197575.685 [NAL9602](INFO): Flushing. SigQuality: -1
2015-02-17T18:26:15.685Z,1424197575.685 [NAL9602](INFO): Response:
$GPGSV,4,2,14,11,,,46,14,,,46,18,,,40,19,,,43*7D

OK
2015-02-17T18:26:15.833Z,1424197575.833 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:16.253Z,1424197576.253 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:16.768Z,1424197576.768 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:17.166Z,1424197577.166 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:17.831Z,1424197577.831 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:18.279Z,1424197578.279 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:18.812Z,1424197578.812 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:19.241Z,1424197579.241 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:19.946Z,1424197579.946 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:20.403Z,1424197580.403 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:20.811Z,1424197580.811 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:21.410Z,1424197581.410 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:21.977Z,1424197581.977 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:22.354Z,1424197582.354 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:22.925Z,1424197582.925 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:23.319Z,1424197583.319 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:23.753Z,1424197583.753 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:24.168Z,1424197584.168 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:24.605Z,1424197584.605 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:25.086Z,1424197585.086 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:25.654Z,1424197585.654 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:26.132Z,1424197586.132 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:26.499Z,1424197586.499 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:26.976Z,1424197586.976 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:27.502Z,1424197587.502 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:27.921Z,1424197587.921 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:28.800Z,1424197588.800 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:29.529Z,1424197589.529 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:30.431Z,1424197590.431 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:30.827Z,1424197590.827 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:31.308Z,1424197591.308 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:31.784Z,1424197591.784 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:32.310Z,1424197592.310 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:32.818Z,1424197592.818 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:33.275Z,1424197593.275 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:33.737Z,1424197593.737 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:34.176Z,1424197594.176 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:34.557Z,1424197594.557 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:35.305Z,1424197595.305 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:35.666Z,1424197595.666 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:36.061Z,1424197596.061 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:36.664Z,1424197596.664 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:37.100Z,1424197597.100 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:37.541Z,1424197597.541 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:37.968Z,1424197597.968 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:38.470Z,1424197598.470 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:39.016Z,1424197599.016 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:39.533Z,1424197599.533 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:40.222Z,1424197600.222 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:40.344Z,1424197600.344 [CBIT](IMPORTANT): No ground fault detected
2015-02-17T18:26:40.702Z,1424197600.702 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:41.291Z,1424197601.291 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:41.800Z,1424197601.800 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:42.389Z,1424197602.389 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:42.902Z,1424197602.902 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:43.379Z,1424197603.379 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:43.761Z,1424197603.761 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:44.312Z,1424197604.312 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:44.676Z,1424197604.676 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:45.324Z,1424197605.324 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2015-02-17T18:26:45.848Z,1424197605.848 [NAL9602](FAULT): received: 
2015-02-17T18:26:45.848Z,1424197605.848 [NAL9602] Data Fault, FailCount= 1
2015-02-17T18:26:45.848Z,1424197605.848 [NAL9602](ERROR): Data Fault
2015-02-17T18:26:45.927Z,1424197605.927 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:46.039Z,1424197606.039 [CBIT](ERROR): Data Fault in component: NAL9602
2015-02-17T18:26:46.378Z,1424197606.378 [NAL9602](INFO): Powering down
2015-02-17T18:26:46.427Z,1424197606.427 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:46.909Z,1424197606.909 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:47.426Z,1424197607.426 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:47.534Z,1424197607.534 [CBIT](INFO): Clearing failed state for component NAL9602
2015-02-17T18:26:47.535Z,1424197607.535 [NAL9602] No Fault, FailCount= 1
2015-02-17T18:26:47.890Z,1424197607.890 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:48.443Z,1424197608.443 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:48.802Z,1424197608.802 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:49.292Z,1424197609.292 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:49.691Z,1424197609.691 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:50.475Z,1424197610.475 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:50.998Z,1424197610.998 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:51.351Z,1424197611.351 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:51.730Z,1424197611.730 [NAL9602](INFO): Powering up NAL9602
2015-02-17T18:26:51.784Z,1424197611.784 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:52.192Z,1424197612.192 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:52.593Z,1424197612.593 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:53.213Z,1424197613.213 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:53.591Z,1424197613.591 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:54.058Z,1424197614.058 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:54.467Z,1424197614.467 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:54.932Z,1424197614.932 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:55.365Z,1424197615.365 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:56.078Z,1424197616.078 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:56.439Z,1424197616.439 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:56.875Z,1424197616.875 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:57.311Z,1424197617.311 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:57.817Z,1424197617.817 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:57.817Z,1424197617.817 [DeadReckonUsingMultipleVelocitySources](FAULT): The allowance for input measurements to start up has expired, but I still cannot determine the rotation from vehicle frame to navigation frame.
2015-02-17T18:26:57.818Z,1424197617.818 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-02-17T18:26:57.818Z,1424197617.818 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-02-17T18:26:57.819Z,1424197617.819 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-02-17T18:26:57.820Z,1424197617.820 [DeadReckonUsingSpeedCalculator](FAULT): The allowance for input measurements to start up has expired, but I still cannot determine the rotation from vehicle frame to navigation frame.
2015-02-17T18:26:57.820Z,1424197617.820 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2015-02-17T18:26:57.820Z,1424197617.820 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2015-02-17T18:26:57.821Z,1424197617.821 [DeadReckonUsingSpeedCalculator](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-02-17T18:26:57.822Z,1424197617.822 [DeadReckonWithRespectToWater](FAULT): The allowance for input measurements to start up has expired, but I still cannot determine the rotation from vehicle frame to navigation frame.
2015-02-17T18:26:57.822Z,1424197617.822 [DeadReckonWithRespectToWater] Software Fault, FailCount= 1
2015-02-17T18:26:57.822Z,1424197617.822 [DeadReckonWithRespectToWater](ERROR): Software Fault
2015-02-17T18:26:57.824Z,1424197617.824 [DeadReckonWithRespectToWater](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-02-17T18:26:57.982Z,1424197617.982 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-02-17T18:26:57.982Z,1424197617.982 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2015-02-17T18:26:57.983Z,1424197617.983 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToWater
2015-02-17T18:26:58.281Z,1424197618.281 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:58.454Z,1424197618.454 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-02-17T18:26:58.454Z,1424197618.454 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-02-17T18:26:58.455Z,1424197618.455 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2015-02-17T18:26:58.455Z,1424197618.455 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2015-02-17T18:26:58.456Z,1424197618.456 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToWater
2015-02-17T18:26:58.456Z,1424197618.456 [DeadReckonWithRespectToWater] No Fault, FailCount= 1
2015-02-17T18:26:59.006Z,1424197619.006 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:59.007Z,1424197619.007 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-02-17T18:26:59.007Z,1424197619.007 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2015-02-17T18:26:59.008Z,1424197619.008 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component.
2015-02-17T18:26:59.388Z,1424197619.388 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:59.389Z,1424197619.389 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:26:59.932Z,1424197619.932 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:26:59.933Z,1424197619.933 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:27:06.427Z,1424197626.427 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:06.428Z,1424197626.428 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:27:06.859Z,1424197626.859 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:06.860Z,1424197626.860 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:27:06.882Z,1424197626.882 [SBIT](IMPORTANT): SBIT PASSED
2015-02-17T18:27:07.086Z,1424197627.086 [NAL9602](INFO): NAL9602 initialized
2015-02-17T18:27:07.128Z,1424197627.128 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:07.129Z,1424197627.129 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:27:07.132Z,1424197627.132 [MissionManager](IMPORTANT): Started mission Startup
2015-02-17T18:27:07.137Z,1424197627.137 [Startup] Running Loop=1
2015-02-17T18:27:07.137Z,1424197627.137 [Startup](INFO): Aggregate::initialize Startup
2015-02-17T18:27:07.137Z,1424197627.137 [Startup:A.GoToSurface] Running Loop=1
2015-02-17T18:27:07.137Z,1424197627.137 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-02-17T18:27:07.138Z,1424197627.138 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-02-17T18:27:07.138Z,1424197627.138 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-02-17T18:27:07.138Z,1424197627.138 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-02-17T18:27:07.153Z,1424197627.153 [Startup:StartupSatComms] Running Loop=1
2015-02-17T18:27:07.153Z,1424197627.153 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-02-17T18:27:07.153Z,1424197627.153 [Startup:StartupSatComms:A] Running Loop=1
2015-02-17T18:27:07.546Z,1424197627.546 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:07.547Z,1424197627.547 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-02-17T18:27:07.551Z,1424197627.551 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-02-17T18:27:07.920Z,1424197627.920 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:08.567Z,1424197628.567 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:08.943Z,1424197628.943 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:09.563Z,1424197629.563 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:10.087Z,1424197630.087 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:10.465Z,1424197630.465 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:11.111Z,1424197631.111 [NAL9602](INFO): Flushing. SigQuality: -1
2015-02-17T18:27:11.111Z,1424197631.111 [NAL9602](INFO): Response:
$GPGSV,4,2,14,11,,,46,14,,,46,18,,,40,19,,,42*7C

OK
2015-02-17T18:27:11.120Z,1424197631.120 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:11.418Z,1424197631.418 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:11.822Z,1424197631.822 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:12.215Z,1424197632.215 [NAL9602](INFO): Flushing. SigQuality: 0
2015-02-17T18:27:12.216Z,1424197632.216 [NAL9602](INFO): Response:
+CSQ:0

OK4,11,,,46,14,,,46,18,,,40,19,,,42*7C

OK
2015-02-17T18:27:12.225Z,1424197632.225 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:12.599Z,1424197632.599 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:13.004Z,1424197633.004 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:13.433Z,1424197633.433 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:13.786Z,1424197633.786 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:14.191Z,1424197634.191 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:14.642Z,1424197634.642 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:15.084Z,1424197635.084 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:15.563Z,1424197635.563 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:16.017Z,1424197636.017 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:16.352Z,1424197636.352 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:16.753Z,1424197636.753 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:17.167Z,1424197637.167 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:17.713Z,1424197637.713 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:18.008Z,1424197638.008 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:18.502Z,1424197638.502 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:18.860Z,1424197638.860 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:19.291Z,1424197639.291 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:19.671Z,1424197639.671 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:20.072Z,1424197640.072 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:20.340Z,1424197640.340 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:20.749Z,1424197640.749 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:21.128Z,1424197641.128 [CommandLine](IMPORTANT): got command quit
2015-02-17T18:27:21.471Z,1424197641.471 [NAL9602](INFO): Flushing. SigQuality: 0
2015-02-17T18:27:21.471Z,1424197641.471 [NAL9602](INFO): Response:
+CSQ:0

OK4,11,,,46,14,,,46,18,,,40,19,,,42*7C

OK
2015-02-17T18:27:21.485Z,1424197641.485 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:21.879Z,1424197641.879 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:22.135Z,1424197642.135 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-02-17T18:27:22.135Z,1424197642.135 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.164Z,1424197642.164 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2015-02-17T18:27:22.164Z,1424197642.164 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.165Z,1424197642.165 [CommandLine](INFO): Join timeout helper Thread ID is 1420
2015-02-17T18:27:22.180Z,1424197642.180 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-02-17T18:27:22.180Z,1424197642.180 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.181Z,1424197642.181 [NavChartDb](INFO): Join timeout helper Thread ID is 1421
2015-02-17T18:27:22.220Z,1424197642.220 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:22.236Z,1424197642.236 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-02-17T18:27:22.237Z,1424197642.237 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.248Z,1424197642.248 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-02-17T18:27:22.248Z,1424197642.248 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.249Z,1424197642.249 [Radio_Surface](INFO): Join timeout helper Thread ID is 1422
2015-02-17T18:27:22.429Z,1424197642.429 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-02-17T18:27:22.429Z,1424197642.429 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.437Z,1424197642.437 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-02-17T18:27:22.437Z,1424197642.437 [logger ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.437Z,1424197642.437 [logger](INFO): Join timeout helper Thread ID is 1423
2015-02-17T18:27:22.457Z,1424197642.457 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-02-17T18:27:22.457Z,1424197642.457 [logger ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.477Z,1424197642.477 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-02-17T18:27:22.477Z,1424197642.477 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.477Z,1424197642.477 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-02-17T18:27:22.477Z,1424197642.477 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.477Z,1424197642.477 [controlThread](INFO): Join timeout helper Thread ID is 1424
2015-02-17T18:27:22.523Z,1424197642.523 [HFRCMReconstructedInterpolator](DEBUG): no valid forecast
2015-02-17T18:27:22.538Z,1424197642.538 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-02-17T18:27:22.538Z,1424197642.538 [controlThread](DEBUG): Uninitializing ControlThread
2015-02-17T18:27:22.539Z,1424197642.539 [NAL9602](INFO): Powering down
2015-02-17T18:27:22.542Z,1424197642.542 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-02-17T18:27:22.543Z,1424197642.543 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-02-17T18:27:22.546Z,1424197642.546 [Startup] Stopped
2015-02-17T18:27:22.547Z,1424197642.547 [Startup](INFO): Aggregate::uninitialize Startup
2015-02-17T18:27:22.547Z,1424197642.547 [Startup:A.GoToSurface] Stopped
2015-02-17T18:27:22.547Z,1424197642.547 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-02-17T18:27:22.547Z,1424197642.547 [Startup:StartupSatComms] Stopped
2015-02-17T18:27:22.547Z,1424197642.547 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-02-17T18:27:22.547Z,1424197642.547 [Startup:StartupSatComms:A] Stopped
2015-02-17T18:27:22.548Z,1424197642.548 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-02-17T18:27:22.549Z,1424197642.549 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-02-17T18:27:22.549Z,1424197642.549 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-02-17T18:27:22.549Z,1424197642.549 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-02-17T18:27:22.550Z,1424197642.550 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-02-17T18:27:22.550Z,1424197642.550 [BuoyancyServo](INFO): Powering down
2015-02-17T18:27:22.561Z,1424197642.561 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-02-17T18:27:22.561Z,1424197642.561 [ElevatorServo](INFO): Powering down
2015-02-17T18:27:22.562Z,1424197642.562 [MassServo](DEBUG): Uninitialize Mass Servo.
2015-02-17T18:27:22.562Z,1424197642.562 [MassServo](INFO): Powering down
2015-02-17T18:27:22.563Z,1424197642.563 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-02-17T18:27:22.563Z,1424197642.563 [RudderServo](INFO): Powering down
2015-02-17T18:27:22.564Z,1424197642.564 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-02-17T18:27:22.564Z,1424197642.564 [ThrusterServo](INFO): Powering down
2015-02-17T18:27:22.565Z,1424197642.565 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-02-17T18:27:22.565Z,1424197642.565 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-02-17T18:27:22.565Z,1424197642.565 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-02-17T18:27:22.598Z,1424197642.598 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.702Z,1424197642.702 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.747Z,1424197642.747 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-02-17T18:27:22.798Z,1424197642.798 [logger ThreadHandler](INFO): Thread cancelled.