2015-01-28T17:06:04.436Z,1422464764.436 [Supervisor](DEBUG): Initializing supervisor.
2015-01-28T17:06:04.439Z,1422464764.439 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-28T17:06:04.440Z,1422464764.440 [SyncHandler](INFO): Protected caller Thread ID is 2038
2015-01-28T17:06:04.440Z,1422464764.440 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-28T17:06:04.441Z,1422464764.441 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-28T17:06:04.441Z,1422464764.441 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2039
2015-01-28T17:06:04.444Z,1422464764.444 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-28T17:06:04.456Z,1422464764.456 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-28T17:06:04.457Z,1422464764.457 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-28T17:06:04.457Z,1422464764.457 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2040
2015-01-28T17:06:04.458Z,1422464764.458 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-28T17:06:04.459Z,1422464764.459 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-28T17:06:04.459Z,1422464764.459 [logger ThreadHandler](INFO): Protected caller Thread ID is 2041
2015-01-28T17:06:04.462Z,1422464764.462 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-28T17:06:04.462Z,1422464764.462 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-28T17:06:04.463Z,1422464764.463 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-28T17:06:04.963Z,1422464764.963 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-28T17:06:04.963Z,1422464764.963 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-28T17:06:05.124Z,1422464765.124 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-28T17:06:05.125Z,1422464765.125 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-28T17:06:05.237Z,1422464765.237 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-28T17:06:05.238Z,1422464765.238 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-28T17:06:05.365Z,1422464765.365 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-28T17:06:05.366Z,1422464765.366 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-28T17:06:05.452Z,1422464765.452 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-28T17:06:05.618Z,1422464765.618 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-28T17:06:05.619Z,1422464765.619 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-28T17:06:05.709Z,1422464765.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-28T17:06:05.709Z,1422464765.709 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-28T17:06:05.923Z,1422464765.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-28T17:06:05.924Z,1422464765.924 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-28T17:06:06.305Z,1422464766.305 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-28T17:06:06.306Z,1422464766.306 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-28T17:06:06.636Z,1422464766.636 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-28T17:06:06.637Z,1422464766.637 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-28T17:06:07.170Z,1422464767.170 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-28T17:06:07.170Z,1422464767.170 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-28T17:06:07.370Z,1422464767.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-28T17:06:07.370Z,1422464767.370 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-28T17:06:07.565Z,1422464767.565 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-28T17:06:07.566Z,1422464767.566 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-28T17:06:07.995Z,1422464767.995 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-28T17:06:07.996Z,1422464767.996 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-28T17:06:08.110Z,1422464768.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-28T17:06:08.112Z,1422464768.112 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-28T17:06:08.113Z,1422464768.113 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-28T17:06:08.356Z,1422464768.356 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-28T17:06:08.356Z,1422464768.356 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-28T17:06:08.474Z,1422464768.474 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-28T17:06:08.574Z,1422464768.574 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-28T17:06:08.673Z,1422464768.673 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-28T17:06:08.789Z,1422464768.789 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-28T17:06:08.933Z,1422464768.933 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-28T17:06:09.106Z,1422464769.106 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-28T17:06:09.212Z,1422464769.212 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-28T17:06:16.258Z,1422464776.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-28T17:06:22.392Z,1422464782.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-28T17:06:24.172Z,1422464784.172 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-28T17:06:24.357Z,1422464784.357 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2015-01-28T17:06:24.358Z,1422464784.358 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-01-28T17:06:24.375Z,1422464784.375 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-28T17:06:24.440Z,1422464784.440 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-28T17:06:24.560Z,1422464784.560 [VerticalControl] Loaded
2015-01-28T17:06:24.560Z,1422464784.560 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-28T17:06:24.561Z,1422464784.561 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-28T17:06:24.633Z,1422464784.633 [HorizontalControl] Loaded
2015-01-28T17:06:24.633Z,1422464784.633 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-28T17:06:24.634Z,1422464784.634 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-28T17:06:24.640Z,1422464784.640 [SpeedControl] Loaded
2015-01-28T17:06:24.640Z,1422464784.640 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-28T17:06:24.641Z,1422464784.641 [LoopControl](DEBUG): Construct LoopControl.
2015-01-28T17:06:24.641Z,1422464784.641 [LoopControl] Loaded
2015-01-28T17:06:24.641Z,1422464784.641 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-28T17:06:24.642Z,1422464784.642 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-28T17:06:24.642Z,1422464784.642 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-28T17:06:24.761Z,1422464784.761 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-28T17:06:24.772Z,1422464784.772 [SBIT] Loaded
2015-01-28T17:06:24.772Z,1422464784.772 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-28T17:06:24.773Z,1422464784.773 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-28T17:06:24.802Z,1422464784.802 [IBIT] Loaded
2015-01-28T17:06:24.802Z,1422464784.802 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-28T17:06:24.804Z,1422464784.804 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-28T17:06:24.925Z,1422464784.925 [CBIT] Loaded
2015-01-28T17:06:24.926Z,1422464784.926 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-28T17:06:24.926Z,1422464784.926 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-28T17:06:24.927Z,1422464784.927 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-28T17:06:24.953Z,1422464784.953 [DepthRateCalculator] Loaded
2015-01-28T17:06:24.954Z,1422464784.954 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-28T17:06:24.959Z,1422464784.959 [PitchRateCalculator] Loaded
2015-01-28T17:06:24.960Z,1422464784.960 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-28T17:06:24.971Z,1422464784.971 [SpeedCalculator] Loaded
2015-01-28T17:06:24.972Z,1422464784.972 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-28T17:06:24.989Z,1422464784.989 [TempGradientCalculator] Loaded
2015-01-28T17:06:24.989Z,1422464784.989 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-28T17:06:24.994Z,1422464784.994 [YawRateCalculator] Loaded
2015-01-28T17:06:24.995Z,1422464784.995 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-28T17:06:24.995Z,1422464784.995 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-28T17:06:24.996Z,1422464784.996 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-28T17:06:25.078Z,1422464785.078 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-28T17:06:25.079Z,1422464785.079 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-28T17:06:25.341Z,1422464785.341 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-28T17:06:25.342Z,1422464785.342 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-28T17:06:25.444Z,1422464785.444 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-01-28T17:06:25.445Z,1422464785.445 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-01-28T17:06:25.462Z,1422464785.462 [NavChart] Loaded
2015-01-28T17:06:25.462Z,1422464785.462 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-28T17:06:25.467Z,1422464785.467 [UniversalFixResidualReporter] Loaded
2015-01-28T17:06:25.467Z,1422464785.467 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-28T17:06:25.467Z,1422464785.467 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-28T17:06:25.469Z,1422464785.469 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-28T17:06:25.482Z,1422464785.482 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-28T17:06:25.483Z,1422464785.483 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-28T17:06:25.600Z,1422464785.600 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-28T17:06:25.601Z,1422464785.601 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-28T17:06:25.964Z,1422464785.964 [DataOverHttps] Loaded
2015-01-28T17:06:25.965Z,1422464785.965 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-28T17:06:26.048Z,1422464786.048 [Depth_Keller] Loaded
2015-01-28T17:06:26.049Z,1422464786.049 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-28T17:06:26.144Z,1422464786.144 [NAL9602] Loaded
2015-01-28T17:06:26.144Z,1422464786.144 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-28T17:06:26.187Z,1422464786.187 [Onboard] Loaded
2015-01-28T17:06:26.187Z,1422464786.187 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-28T17:06:26.194Z,1422464786.194 [Radio_Surface] Loaded
2015-01-28T17:06:26.195Z,1422464786.195 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-28T17:06:26.196Z,1422464786.196 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-28T17:06:26.196Z,1422464786.196 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2124
2015-01-28T17:06:26.246Z,1422464786.246 [PNI_TCM] Loaded
2015-01-28T17:06:26.246Z,1422464786.246 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2015-01-28T17:06:28.100Z,1422464788.100 [BPC1] Loaded
2015-01-28T17:06:28.100Z,1422464788.100 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-28T17:06:28.101Z,1422464788.101 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-28T17:06:28.101Z,1422464788.101 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-28T17:06:30.849Z,1422464790.849 [BuoyancyServo] Loaded
2015-01-28T17:06:30.849Z,1422464790.849 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-28T17:06:30.862Z,1422464790.862 [ElevatorServo] Loaded
2015-01-28T17:06:30.862Z,1422464790.862 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-28T17:06:30.874Z,1422464790.874 [RudderServo] Loaded
2015-01-28T17:06:30.874Z,1422464790.874 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-28T17:06:30.886Z,1422464790.886 [ThrusterServo] Loaded
2015-01-28T17:06:30.886Z,1422464790.886 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-28T17:06:30.886Z,1422464790.886 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-28T17:06:30.887Z,1422464790.887 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-28T17:06:31.933Z,1422464791.933 [ExternalSim] Loaded
2015-01-28T17:06:31.934Z,1422464791.934 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2015-01-28T17:06:31.934Z,1422464791.934 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-28T17:06:31.935Z,1422464791.935 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-28T17:06:31.974Z,1422464791.974 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-28T17:06:31.976Z,1422464791.976 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-28T17:06:31.977Z,1422464791.977 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-28T17:06:31.984Z,1422464791.984 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-28T17:06:31.985Z,1422464791.985 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-28T17:06:31.985Z,1422464791.985 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2125
2015-01-28T17:06:31.990Z,1422464791.990 [Supervisor](INFO): Main Thread ID is 2037
2015-01-28T17:06:31.990Z,1422464791.990 [Supervisor](DEBUG): Running supervisor.
2015-01-28T17:06:31.991Z,1422464791.991 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2126
2015-01-28T17:06:31.995Z,1422464791.995 [controlThread ThreadHandler](INFO): Handler Thread ID is 2127
2015-01-28T17:06:31.995Z,1422464791.995 [controlThread](DEBUG): Initializing ControlThread
2015-01-28T17:06:31.996Z,1422464791.996 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-28T17:06:31.998Z,1422464791.998 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-28T17:06:31.999Z,1422464791.999 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-28T17:06:31.999Z,1422464791.999 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-28T17:06:31.999Z,1422464791.999 [SBIT](INFO): Initialize SBIT Component.
2015-01-28T17:06:31.000Z,1422464792.000 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-28T17:06:32.000Z,1422464792.000 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-28T17:06:32.000Z,1422464792.000 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-28T17:06:32.001Z,1422464792.001 [IBIT](INFO): Initialize IBIT Component.
2015-01-28T17:06:32.002Z,1422464792.002 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-28T17:06:32.002Z,1422464792.002 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-28T17:06:32.003Z,1422464792.003 [logger ThreadHandler](INFO): Handler Thread ID is 2128
2015-01-28T17:06:32.023Z,1422464792.023 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2129
2015-01-28T17:06:32.027Z,1422464792.027 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-28T17:06:32.027Z,1422464792.027 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-28T17:06:32.027Z,1422464792.027 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-28T17:06:32.028Z,1422464792.028 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-28T17:06:32.028Z,1422464792.028 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-28T17:06:32.029Z,1422464792.029 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T17:06:32.029Z,1422464792.029 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-28T17:06:32.030Z,1422464792.030 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-28T17:06:32.036Z,1422464792.036 [ExternalSim](INFO): ExternalSim initializing...
2015-01-28T17:06:32.051Z,1422464792.051 [Radio_Surface](INFO): Powering up
2015-01-28T17:06:32.063Z,1422464792.063 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2130
2015-01-28T17:06:32.074Z,1422464792.074 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-28T17:06:32.075Z,1422464792.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-28T17:06:32.075Z,1422464792.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-28T17:06:32.076Z,1422464792.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-28T17:06:32.076Z,1422464792.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-28T17:06:32.076Z,1422464792.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-28T17:06:32.076Z,1422464792.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-28T17:06:32.077Z,1422464792.077 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-28T17:06:32.077Z,1422464792.077 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-28T17:06:32.269Z,1422464792.269 [ExternalSim](DEBUG): beaconLat = 36.80340
2015-01-28T17:06:32.269Z,1422464792.269 [ExternalSim](DEBUG): beaconLon = -121.82230
2015-01-28T17:06:32.270Z,1422464792.270 [ExternalSim](DEBUG): beaconDepth = 25.00
2015-01-28T17:06:32.431Z,1422464792.431 [ExternalSim](DEBUG): Simulator initialized
2015-01-28T17:06:32.437Z,1422464792.437 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-28T17:06:32.450Z,1422464792.450 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-28T17:06:32.474Z,1422464792.474 [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-01-28T17:06:32.475Z,1422464792.475 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-28T17:06:32.560Z,1422464792.560 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-28T17:06:32.579Z,1422464792.579 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-28T17:06:32.583Z,1422464792.583 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-28T17:06:32.600Z,1422464792.600 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-28T17:06:32.630Z,1422464792.630 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-28T17:06:32.647Z,1422464792.647 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-28T17:06:32.681Z,1422464792.681 [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-01-28T17:06:32.686Z,1422464792.686 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,DataOverHttps,Depth_Keller,NAL9602,Onboard,PNI_TCM,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2015-01-28T17:06:33.191Z,1422464793.191 [NAL9602](INFO): Start
2015-01-28T17:06:33.191Z,1422464793.191 [NAL9602](INFO): Powering up NAL9602
2015-01-28T17:06:33.515Z,1422464793.515 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:33.649Z,1422464793.649 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:06:33.657Z,1422464793.657 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-28T17:06:33.668Z,1422464793.668 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:06:33.673Z,1422464793.673 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-28T17:06:33.695Z,1422464793.695 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:06:33.701Z,1422464793.701 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-28T17:06:33.715Z,1422464793.715 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:06:33.721Z,1422464793.721 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-28T17:06:34.021Z,1422464794.021 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:42.658Z,1422464802.658 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:43.391Z,1422464803.391 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:43.617Z,1422464803.617 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:43.932Z,1422464803.932 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003606
2015-01-28T17:06:43.935Z,1422464803.935 [NAL9602](INFO): ************** CMDMODE **************

2015-01-28T17:06:43.935Z,1422464803.935 [NAL9602](INFO): NAL9602 initialized
2015-01-28T17:06:44.233Z,1422464804.233 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:06:46.514Z,1422464806.514 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:06:47.464Z,1422464807.464 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:06:47.537Z,1422464807.537 [CommandLine](IMPORTANT): got command report mod NAL9602.sigQuality
2015-01-28T17:06:47.624Z,1422464807.624 [SBIT](IMPORTANT): Beginning Startup BIT
2015-01-28T17:06:47.639Z,1422464807.639 [CBIT](IMPORTANT): Beginning GF scan
2015-01-28T17:06:47.641Z,1422464807.641 [Reporter](INFO): NAL9602.sigQuality 0 count
2015-01-28T17:06:51.382Z,1422464811.382 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:06:52.159Z,1422464812.159 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:00.729Z,1422464820.729 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:07:00.957Z,1422464820.957 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:04.588Z,1422464824.588 [BPC1](FAULT): Failed to receive battery data
2015-01-28T17:07:04.588Z,1422464824.588 [BPC1] Communications Fault, FailCount= 1
2015-01-28T17:07:04.588Z,1422464824.588 [BPC1](ERROR): Communications Fault
2015-01-28T17:07:04.705Z,1422464824.705 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-28T17:07:05.882Z,1422464825.882 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T17:07:05.882Z,1422464825.882 [BPC1] No Fault, FailCount= 1
2015-01-28T17:07:09.358Z,1422464829.358 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:14.252Z,1422464834.252 [CBIT](IMPORTANT): No ground fault detected
2015-01-28T17:07:17.551Z,1422464837.551 [NAL9602](INFO): Requesting MT sbdi session. Quality is:
2015-01-28T17:07:17.722Z,1422464837.722 [Reporter](INFO): NAL9602.sigQuality 1 count
2015-01-28T17:07:17.943Z,1422464837.943 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:18.352Z,1422464838.352 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:18.748Z,1422464838.748 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:19.193Z,1422464839.193 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:19.549Z,1422464839.549 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:19.950Z,1422464839.950 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:20.363Z,1422464840.363 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:20.743Z,1422464840.743 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:21.140Z,1422464841.140 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:21.549Z,1422464841.549 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:21.949Z,1422464841.949 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:22.370Z,1422464842.370 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:22.751Z,1422464842.751 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:23.151Z,1422464843.151 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:23.548Z,1422464843.548 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:23.973Z,1422464843.973 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:24.354Z,1422464844.354 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:24.754Z,1422464844.754 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:25.155Z,1422464845.155 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:25.547Z,1422464845.547 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:25.972Z,1422464845.972 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:26.344Z,1422464846.344 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:26.765Z,1422464846.765 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:27.146Z,1422464847.146 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:27.303Z,1422464847.303 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:07:27.303Z,1422464847.303 [SBIT](FAULT): Control surface position failure.
2015-01-28T17:07:27.558Z,1422464847.558 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:27.938Z,1422464847.938 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:28.348Z,1422464848.348 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:28.764Z,1422464848.764 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:29.449Z,1422464849.449 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:29.745Z,1422464849.745 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:30.130Z,1422464850.130 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:30.543Z,1422464850.543 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:30.940Z,1422464850.940 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:31.332Z,1422464851.332 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:31.737Z,1422464851.737 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:32.135Z,1422464852.135 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:32.534Z,1422464852.534 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:32.955Z,1422464852.955 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:33.335Z,1422464853.335 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:33.736Z,1422464853.736 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:39.781Z,1422464859.781 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-28T17:07:39.783Z,1422464859.783 [NAL9602](INFO): SBD MO Status=2, MOMSN=5457, MT Status=2, MTMSN=0
2015-01-28T17:07:39.783Z,1422464859.783 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2015-01-28T17:07:40.022Z,1422464860.022 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:40.472Z,1422464860.472 [Reporter](INFO): NAL9602.sigQuality 0 count
2015-01-28T17:07:40.807Z,1422464860.807 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:40.939Z,1422464860.939 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:07:40.939Z,1422464860.939 [SBIT](FAULT): Control surface position failure.
2015-01-28T17:07:41.230Z,1422464861.230 [SBIT](CRITICAL): SBIT FAILED
2015-01-28T17:07:41.231Z,1422464861.231 [CommandLine](FAULT): Scheduling is paused
2015-01-28T17:07:41.619Z,1422464861.619 [MissionManager](IMPORTANT): Started mission Startup
2015-01-28T17:07:41.620Z,1422464861.620 [Startup] Running Loop=1
2015-01-28T17:07:41.620Z,1422464861.620 [Startup](INFO): Aggregate::initialize Startup
2015-01-28T17:07:41.620Z,1422464861.620 [Startup:A.GoToSurface] Running Loop=1
2015-01-28T17:07:41.620Z,1422464861.620 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-28T17:07:41.620Z,1422464861.620 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-28T17:07:41.621Z,1422464861.621 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-28T17:07:41.621Z,1422464861.621 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-28T17:07:41.627Z,1422464861.627 [Startup:StartupSatComms] Running Loop=1
2015-01-28T17:07:41.627Z,1422464861.627 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-01-28T17:07:41.627Z,1422464861.627 [Startup:StartupSatComms:A] Running Loop=1
2015-01-28T17:07:41.998Z,1422464861.998 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-28T17:07:43.980Z,1422464863.980 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:07:52.786Z,1422464872.786 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:01.179Z,1422464881.179 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:09.984Z,1422464889.984 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:18.778Z,1422464898.778 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:25.176Z,1422464905.176 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:27.178Z,1422464907.178 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:31.578Z,1422464911.578 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:37.436Z,1422464917.436 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:40.608Z,1422464920.608 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:41.409Z,1422464921.409 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:41.826Z,1422464921.826 [Startup:StartupSatComms:A](INFO): Timed out from 2015-01-28T17:07:41.6Z
2015-01-28T17:08:41.826Z,1422464921.826 [Startup:StartupSatComms:A] Stopped
2015-01-28T17:08:41.827Z,1422464921.827 [Startup:StartupSatComms:B] Running Loop=1
2015-01-28T17:08:42.227Z,1422464922.227 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-28T17:08:48.266Z,1422464928.266 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:48.434Z,1422464928.434 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20150128T010138/Courier0344.lzma
2015-01-28T17:08:48.816Z,1422464928.816 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:50.025Z,1422464930.025 [DataOverHttps](INFO): Moved sent file to Logs/20150128T010138/Courier0344.lzma.bak
2015-01-28T17:08:50.025Z,1422464930.025 [DataOverHttps](INFO): SBD MOMSN=1510207
2015-01-28T17:08:54.359Z,1422464934.359 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:55.135Z,1422464935.135 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:08:59.418Z,1422464939.418 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:00.216Z,1422464940.216 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:04.481Z,1422464944.481 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:05.282Z,1422464945.282 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:09.717Z,1422464949.717 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:10.522Z,1422464950.522 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:14.780Z,1422464954.780 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150128T170604/Courier0000.lzma
2015-01-28T17:09:14.793Z,1422464954.793 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:15.566Z,1422464955.566 [DataOverHttps](INFO): Moved sent file to Logs/20150128T170604/Courier0000.lzma.bak
2015-01-28T17:09:15.567Z,1422464955.567 [DataOverHttps](INFO): SBD MOMSN=1510209
2015-01-28T17:09:15.588Z,1422464955.588 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:19.957Z,1422464959.957 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:20.763Z,1422464960.763 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:25.113Z,1422464965.113 [DataOverHttps](INFO): Sending 387 bytes from file Logs/20150128T010138/Express0345.lzma
2015-01-28T17:09:25.118Z,1422464965.118 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:25.910Z,1422464965.910 [DataOverHttps](INFO): Moved sent file to Logs/20150128T010138/Express0345.lzma.bak
2015-01-28T17:09:25.911Z,1422464965.911 [DataOverHttps](INFO): SBD MOMSN=1510213
2015-01-28T17:09:25.923Z,1422464965.923 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:30.269Z,1422464970.269 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:31.070Z,1422464971.070 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:35.121Z,1422464975.121 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-28T17:09:35.121Z,1422464975.121 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-01-28T17:09:35.121Z,1422464975.121 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-28T17:09:35.131Z,1422464975.131 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-28T17:09:35.225Z,1422464975.225 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:35.253Z,1422464975.253 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-28T17:09:35.253Z,1422464975.253 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-01-28T17:09:35.692Z,1422464975.692 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T17:09:36.046Z,1422464976.046 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:36.092Z,1422464976.092 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:09:36.441Z,1422464976.441 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:09:36.846Z,1422464976.846 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:09:37.999Z,1422464977.999 [CommandLine](IMPORTANT): got command get latitude
2015-01-28T17:09:37.999Z,1422464977.999 [CommandLine](FAULT): Element has no value
2015-01-28T17:09:39.200Z,1422464979.200 [CommandLine](IMPORTANT): got command quit
2015-01-28T17:09:40.210Z,1422464980.210 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-28T17:09:40.210Z,1422464980.210 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.299Z,1422464980.299 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2015-01-28T17:09:40.299Z,1422464980.299 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.300Z,1422464980.300 [CommandLine](INFO): Join timeout helper Thread ID is 2138
2015-01-28T17:09:40.307Z,1422464980.307 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-01-28T17:09:40.307Z,1422464980.307 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.308Z,1422464980.308 [NavChartDb](INFO): Join timeout helper Thread ID is 2139
2015-01-28T17:09:40.375Z,1422464980.375 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-28T17:09:40.376Z,1422464980.376 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.387Z,1422464980.387 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-01-28T17:09:40.388Z,1422464980.388 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.388Z,1422464980.388 [Radio_Surface](INFO): Join timeout helper Thread ID is 2140
2015-01-28T17:09:40.452Z,1422464980.452 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:09:40.609Z,1422464980.609 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:09:40.642Z,1422464980.642 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:09:40.676Z,1422464980.676 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-28T17:09:40.676Z,1422464980.676 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.684Z,1422464980.684 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-01-28T17:09:40.684Z,1422464980.684 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.684Z,1422464980.684 [logger](INFO): Join timeout helper Thread ID is 2141
2015-01-28T17:09:40.696Z,1422464980.696 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-28T17:09:40.696Z,1422464980.696 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.712Z,1422464980.712 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-01-28T17:09:40.712Z,1422464980.712 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.712Z,1422464980.712 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-01-28T17:09:40.712Z,1422464980.712 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:40.713Z,1422464980.713 [controlThread](INFO): Join timeout helper Thread ID is 2142
2015-01-28T17:09:40.884Z,1422464980.884 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-28T17:09:40.884Z,1422464980.884 [controlThread](DEBUG): Uninitializing ControlThread
2015-01-28T17:09:40.888Z,1422464980.888 [NAL9602](INFO): Uninitialize
2015-01-28T17:09:40.888Z,1422464980.888 [NAL9602](INFO): Powering down
2015-01-28T17:09:40.890Z,1422464980.890 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-28T17:09:40.892Z,1422464980.892 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-01-28T17:09:40.895Z,1422464980.895 [Startup] Stopped
2015-01-28T17:09:40.895Z,1422464980.895 [Startup](INFO): Aggregate::uninitialize Startup
2015-01-28T17:09:40.895Z,1422464980.895 [Startup:A.GoToSurface] Stopped
2015-01-28T17:09:40.895Z,1422464980.895 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-28T17:09:40.895Z,1422464980.895 [Startup:StartupSatComms] Stopped
2015-01-28T17:09:40.896Z,1422464980.896 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-01-28T17:09:40.896Z,1422464980.896 [Startup:StartupSatComms:B] Stopped
2015-01-28T17:09:40.897Z,1422464980.897 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-01-28T17:09:40.897Z,1422464980.897 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-01-28T17:09:40.898Z,1422464980.898 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-01-28T17:09:40.898Z,1422464980.898 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-01-28T17:09:40.898Z,1422464980.898 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-28T17:09:40.899Z,1422464980.899 [BuoyancyServo](INFO): Powering down
2015-01-28T17:09:40.912Z,1422464980.912 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-01-28T17:09:40.912Z,1422464980.912 [ElevatorServo](INFO): Powering down
2015-01-28T17:09:40.913Z,1422464980.913 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-01-28T17:09:40.913Z,1422464980.913 [RudderServo](INFO): Powering down
2015-01-28T17:09:40.914Z,1422464980.914 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-01-28T17:09:40.914Z,1422464980.914 [ThrusterServo](INFO): Powering down
2015-01-28T17:09:40.915Z,1422464980.915 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-01-28T17:09:40.915Z,1422464980.915 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-01-28T17:09:40.916Z,1422464980.916 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-01-28T17:09:40.949Z,1422464980.949 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:41.053Z,1422464981.053 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:41.097Z,1422464981.097 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-28T17:09:41.146Z,1422464981.146 [logger ThreadHandler](INFO): Thread cancelled.