2015-01-27T21:53:54.781Z,1422395634.781 [Supervisor](DEBUG): Initializing supervisor.
2015-01-27T21:53:54.784Z,1422395634.784 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-27T21:53:54.785Z,1422395634.785 [SyncHandler](INFO): Protected caller Thread ID is 770
2015-01-27T21:53:54.785Z,1422395634.785 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-27T21:53:54.788Z,1422395634.788 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-27T21:53:54.788Z,1422395634.788 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 771
2015-01-27T21:53:54.791Z,1422395634.791 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-27T21:53:54.804Z,1422395634.804 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-27T21:53:54.808Z,1422395634.808 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-27T21:53:54.808Z,1422395634.808 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 772
2015-01-27T21:53:54.809Z,1422395634.809 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-27T21:53:54.812Z,1422395634.812 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-27T21:53:54.812Z,1422395634.812 [logger ThreadHandler](INFO): Protected caller Thread ID is 773
2015-01-27T21:53:54.814Z,1422395634.814 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-27T21:53:54.815Z,1422395634.815 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-27T21:53:54.819Z,1422395634.819 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-27T21:53:55.222Z,1422395635.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-27T21:53:55.224Z,1422395635.224 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-27T21:53:55.396Z,1422395635.396 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-27T21:53:55.397Z,1422395635.397 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-27T21:53:55.516Z,1422395635.516 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-27T21:53:55.517Z,1422395635.517 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-27T21:53:55.658Z,1422395635.658 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-27T21:53:55.659Z,1422395635.659 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-27T21:53:55.753Z,1422395635.753 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-27T21:53:55.934Z,1422395635.934 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-27T21:53:55.935Z,1422395635.935 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-27T21:53:56.033Z,1422395636.033 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-27T21:53:56.034Z,1422395636.034 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-27T21:53:56.267Z,1422395636.267 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-27T21:53:56.267Z,1422395636.267 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-27T21:53:56.686Z,1422395636.686 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-27T21:53:56.687Z,1422395636.687 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-27T21:53:57.044Z,1422395637.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-27T21:53:57.045Z,1422395637.045 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-27T21:53:57.606Z,1422395637.606 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-27T21:53:57.606Z,1422395637.606 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-27T21:53:57.834Z,1422395637.834 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-27T21:53:57.834Z,1422395637.834 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-27T21:53:57.950Z,1422395637.950 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-27T21:53:57.950Z,1422395637.950 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-27T21:53:58.429Z,1422395638.429 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-27T21:53:58.430Z,1422395638.430 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-27T21:54:02.160Z,1422395642.160 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-27T21:54:02.162Z,1422395642.162 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-27T21:54:09.274Z,1422395649.274 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-27T21:54:09.517Z,1422395649.517 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-27T21:54:10.193Z,1422395650.193 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-27T21:54:10.317Z,1422395650.317 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-27T21:54:10.417Z,1422395650.417 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-27T21:54:10.519Z,1422395650.519 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-27T21:54:10.636Z,1422395650.636 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-27T21:54:10.780Z,1422395650.780 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-27T21:54:10.955Z,1422395650.955 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-27T21:54:11.059Z,1422395651.059 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-27T21:54:11.151Z,1422395651.151 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-27T21:54:11.254Z,1422395651.254 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-27T21:54:11.353Z,1422395651.353 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-27T21:54:11.538Z,1422395651.538 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-01-27T21:54:11.561Z,1422395651.561 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-27T21:54:11.634Z,1422395651.634 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-27T21:54:11.753Z,1422395651.753 [VerticalControl] Loaded
2015-01-27T21:54:11.754Z,1422395651.754 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-27T21:54:11.755Z,1422395651.755 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-27T21:54:11.828Z,1422395651.828 [HorizontalControl] Loaded
2015-01-27T21:54:11.828Z,1422395651.828 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-27T21:54:11.829Z,1422395651.829 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-27T21:54:11.834Z,1422395651.834 [SpeedControl] Loaded
2015-01-27T21:54:11.835Z,1422395651.835 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-27T21:54:11.835Z,1422395651.835 [LoopControl](DEBUG): Construct LoopControl.
2015-01-27T21:54:11.836Z,1422395651.836 [LoopControl] Loaded
2015-01-27T21:54:11.836Z,1422395651.836 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-27T21:54:11.837Z,1422395651.837 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-27T21:54:11.838Z,1422395651.838 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-27T21:54:11.960Z,1422395651.960 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-27T21:54:11.972Z,1422395651.972 [SBIT] Loaded
2015-01-27T21:54:11.972Z,1422395651.972 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-27T21:54:11.973Z,1422395651.973 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-27T21:54:12.002Z,1422395652.002 [IBIT] Loaded
2015-01-27T21:54:12.003Z,1422395652.003 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-27T21:54:12.005Z,1422395652.005 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-27T21:54:12.125Z,1422395652.125 [CBIT] Loaded
2015-01-27T21:54:12.125Z,1422395652.125 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-27T21:54:12.126Z,1422395652.126 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-27T21:54:12.128Z,1422395652.128 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-27T21:54:12.158Z,1422395652.158 [DepthRateCalculator] Loaded
2015-01-27T21:54:12.158Z,1422395652.158 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-27T21:54:12.164Z,1422395652.164 [PitchRateCalculator] Loaded
2015-01-27T21:54:12.164Z,1422395652.164 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-27T21:54:12.176Z,1422395652.176 [SpeedCalculator] Loaded
2015-01-27T21:54:12.176Z,1422395652.176 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-27T21:54:12.193Z,1422395652.193 [TempGradientCalculator] Loaded
2015-01-27T21:54:12.193Z,1422395652.193 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-27T21:54:12.199Z,1422395652.199 [YawRateCalculator] Loaded
2015-01-27T21:54:12.199Z,1422395652.199 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-27T21:54:12.200Z,1422395652.200 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-27T21:54:12.200Z,1422395652.200 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-27T21:54:12.292Z,1422395652.292 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-27T21:54:12.294Z,1422395652.294 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-27T21:54:16.101Z,1422395656.101 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-27T21:54:16.102Z,1422395656.102 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-27T21:54:23.960Z,1422395663.960 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-01-27T21:54:23.960Z,1422395663.960 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-01-27T21:54:23.978Z,1422395663.978 [NavChart] Loaded
2015-01-27T21:54:23.978Z,1422395663.978 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-27T21:54:23.982Z,1422395663.982 [UniversalFixResidualReporter] Loaded
2015-01-27T21:54:23.983Z,1422395663.983 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-27T21:54:23.983Z,1422395663.983 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-27T21:54:23.984Z,1422395663.984 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-27T21:54:23.994Z,1422395663.994 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-27T21:54:23.995Z,1422395663.995 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-27T21:54:24.110Z,1422395664.110 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-27T21:54:24.111Z,1422395664.111 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-27T21:54:24.751Z,1422395664.751 [DataOverHttps] Loaded
2015-01-27T21:54:24.752Z,1422395664.752 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-27T21:54:24.834Z,1422395664.834 [Depth_Keller] Loaded
2015-01-27T21:54:24.834Z,1422395664.834 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-27T21:54:24.928Z,1422395664.928 [NAL9602] Loaded
2015-01-27T21:54:24.928Z,1422395664.928 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-27T21:54:24.971Z,1422395664.971 [Onboard] Loaded
2015-01-27T21:54:24.972Z,1422395664.972 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-27T21:54:24.979Z,1422395664.979 [Radio_Surface] Loaded
2015-01-27T21:54:24.979Z,1422395664.979 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-27T21:54:24.980Z,1422395664.980 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-27T21:54:24.981Z,1422395664.981 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 855
2015-01-27T21:54:25.029Z,1422395665.029 [PNI_TCM] Loaded
2015-01-27T21:54:25.029Z,1422395665.029 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2015-01-27T21:54:26.852Z,1422395666.852 [BPC1] Loaded
2015-01-27T21:54:26.852Z,1422395666.852 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-27T21:54:26.852Z,1422395666.852 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-27T21:54:26.853Z,1422395666.853 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-27T21:54:26.980Z,1422395666.980 [BuoyancyServo] Loaded
2015-01-27T21:54:26.981Z,1422395666.981 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-27T21:54:26.993Z,1422395666.993 [ElevatorServo] Loaded
2015-01-27T21:54:26.993Z,1422395666.993 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-27T21:54:27.005Z,1422395667.005 [RudderServo] Loaded
2015-01-27T21:54:27.006Z,1422395667.006 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-27T21:54:27.017Z,1422395667.017 [ThrusterServo] Loaded
2015-01-27T21:54:27.018Z,1422395667.018 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-27T21:54:27.018Z,1422395667.018 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-27T21:54:27.019Z,1422395667.019 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-27T21:54:27.293Z,1422395667.293 [ExternalSim] Loaded
2015-01-27T21:54:27.293Z,1422395667.293 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2015-01-27T21:54:27.294Z,1422395667.294 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-27T21:54:27.294Z,1422395667.294 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-27T21:54:27.336Z,1422395667.336 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-27T21:54:27.339Z,1422395667.339 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-27T21:54:27.339Z,1422395667.339 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-27T21:54:27.346Z,1422395667.346 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-27T21:54:27.347Z,1422395667.347 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-27T21:54:27.348Z,1422395667.348 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 856
2015-01-27T21:54:27.354Z,1422395667.354 [Supervisor](INFO): Main Thread ID is 769
2015-01-27T21:54:27.354Z,1422395667.354 [Supervisor](DEBUG): Running supervisor.
2015-01-27T21:54:27.355Z,1422395667.355 [CommandLine ThreadHandler](INFO): Handler Thread ID is 857
2015-01-27T21:54:27.357Z,1422395667.357 [controlThread ThreadHandler](INFO): Handler Thread ID is 858
2015-01-27T21:54:27.358Z,1422395667.358 [controlThread](DEBUG): Initializing ControlThread
2015-01-27T21:54:27.359Z,1422395667.359 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-27T21:54:27.360Z,1422395667.360 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-27T21:54:27.361Z,1422395667.361 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-27T21:54:27.362Z,1422395667.362 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-27T21:54:27.362Z,1422395667.362 [SBIT](INFO): Initialize SBIT Component.
2015-01-27T21:54:27.362Z,1422395667.362 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-27T21:54:27.363Z,1422395667.363 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-27T21:54:27.363Z,1422395667.363 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-27T21:54:27.364Z,1422395667.364 [IBIT](INFO): Initialize IBIT Component.
2015-01-27T21:54:27.364Z,1422395667.364 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-27T21:54:27.365Z,1422395667.365 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-27T21:54:27.366Z,1422395667.366 [logger ThreadHandler](INFO): Handler Thread ID is 859
2015-01-27T21:54:27.387Z,1422395667.387 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 860
2015-01-27T21:54:27.393Z,1422395667.393 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-27T21:54:27.393Z,1422395667.393 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-27T21:54:27.393Z,1422395667.393 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-27T21:54:27.394Z,1422395667.394 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-27T21:54:27.394Z,1422395667.394 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-27T21:54:27.395Z,1422395667.395 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-27T21:54:27.395Z,1422395667.395 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-27T21:54:27.395Z,1422395667.395 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-27T21:54:27.401Z,1422395667.401 [ExternalSim](INFO): ExternalSim initializing...
2015-01-27T21:54:27.407Z,1422395667.407 [Radio_Surface](INFO): Powering up
2015-01-27T21:54:27.428Z,1422395667.428 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 861
2015-01-27T21:54:27.441Z,1422395667.441 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-27T21:54:27.444Z,1422395667.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-27T21:54:27.444Z,1422395667.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-27T21:54:27.444Z,1422395667.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-27T21:54:27.444Z,1422395667.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-27T21:54:27.445Z,1422395667.445 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-27T21:54:27.445Z,1422395667.445 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-27T21:54:27.445Z,1422395667.445 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-27T21:54:27.445Z,1422395667.445 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-27T21:54:27.657Z,1422395667.657 [ExternalSim](DEBUG): beaconLat = 36.80340
2015-01-27T21:54:27.657Z,1422395667.657 [ExternalSim](DEBUG): beaconLon = -121.82230
2015-01-27T21:54:27.658Z,1422395667.658 [ExternalSim](DEBUG): beaconDepth = 25.00
2015-01-27T21:54:27.825Z,1422395667.825 [ExternalSim](DEBUG): Simulator initialized
2015-01-27T21:54:27.942Z,1422395667.942 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-27T21:54:27.970Z,1422395667.970 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-27T21:54:27.995Z,1422395667.995 [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-27T21:54:27.995Z,1422395667.995 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-27T21:54:28.093Z,1422395668.093 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-27T21:54:28.097Z,1422395668.097 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-27T21:54:28.129Z,1422395668.129 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-27T21:54:28.154Z,1422395668.154 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-27T21:54:28.160Z,1422395668.160 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-27T21:54:28.184Z,1422395668.184 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-27T21:54:28.206Z,1422395668.206 [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-27T21:54:28.210Z,1422395668.210 [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-27T21:54:28.436Z,1422395668.436 [NAL9602](INFO): Start
2015-01-27T21:54:28.669Z,1422395668.669 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:28.769Z,1422395668.769 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-27T21:54:28.777Z,1422395668.777 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-27T21:54:28.791Z,1422395668.791 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-27T21:54:28.797Z,1422395668.797 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-27T21:54:28.803Z,1422395668.803 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-27T21:54:28.809Z,1422395668.809 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-27T21:54:28.833Z,1422395668.833 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-27T21:54:28.841Z,1422395668.841 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-27T21:54:29.066Z,1422395669.066 [NAL9602](INFO): Start
2015-01-27T21:54:29.093Z,1422395669.093 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:37.911Z,1422395677.911 [NAL9602](INFO): Start
2015-01-27T21:54:37.911Z,1422395677.911 [NAL9602](INFO): Powering up NAL9602
2015-01-27T21:54:37.970Z,1422395677.970 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:38.423Z,1422395678.423 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:38.793Z,1422395678.793 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:39.142Z,1422395679.142 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003606
2015-01-27T21:54:39.257Z,1422395679.257 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:54:43.182Z,1422395683.182 [SBIT](IMPORTANT): Beginning Startup BIT
2015-01-27T21:54:43.184Z,1422395683.184 [CBIT](IMPORTANT): Beginning GF scan
2015-01-27T21:54:48.874Z,1422395688.874 [NAL9602](INFO): ************** CMDMODE **************

2015-01-27T21:54:48.875Z,1422395688.875 [NAL9602](INFO): NAL9602 initialized
2015-01-27T21:54:56.209Z,1422395696.209 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T21:55:09.870Z,1422395709.870 [CBIT](IMPORTANT): No ground fault detected
2015-01-27T21:55:23.067Z,1422395723.067 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T21:55:23.067Z,1422395723.067 [SBIT](FAULT): Control surface position failure.
2015-01-27T21:55:36.531Z,1422395736.531 [SBIT](ERROR): Could not read massPosReader_.
2015-01-27T21:55:36.531Z,1422395736.531 [SBIT](FAULT): Control surface position failure.
2015-01-27T21:55:36.955Z,1422395736.955 [SBIT](CRITICAL): SBIT FAILED
2015-01-27T21:55:36.956Z,1422395736.956 [CommandLine](FAULT): Scheduling is paused
2015-01-27T21:55:37.297Z,1422395737.297 [MissionManager](IMPORTANT): Started mission Startup
2015-01-27T21:55:37.297Z,1422395737.297 [Startup] Running Loop=1
2015-01-27T21:55:37.297Z,1422395737.297 [Startup](INFO): Aggregate::initialize Startup
2015-01-27T21:55:37.297Z,1422395737.297 [Startup:A.GoToSurface] Running Loop=1
2015-01-27T21:55:37.297Z,1422395737.297 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-27T21:55:37.298Z,1422395737.298 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-27T21:55:37.298Z,1422395737.298 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-27T21:55:37.299Z,1422395737.299 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-27T21:55:37.313Z,1422395737.313 [Startup:StartupSatComms] Running Loop=1
2015-01-27T21:55:37.313Z,1422395737.313 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-01-27T21:55:37.313Z,1422395737.313 [Startup:StartupSatComms:A] Running Loop=1
2015-01-27T21:55:37.708Z,1422395737.708 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-27T21:56:36.256Z,1422395796.256 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:36.657Z,1422395796.657 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:37.055Z,1422395797.055 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:37.454Z,1422395797.454 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:37.495Z,1422395797.495 [Startup:StartupSatComms:A](INFO): Timed out from 2015-01-27T21:55:37.3Z
2015-01-27T21:56:37.496Z,1422395797.496 [Startup:StartupSatComms:A] Stopped
2015-01-27T21:56:37.496Z,1422395797.496 [Startup:StartupSatComms:B] Running Loop=1
2015-01-27T21:56:37.855Z,1422395797.855 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:37.893Z,1422395797.893 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-27T21:56:38.744Z,1422395798.744 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:38.884Z,1422395798.884 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:42.069Z,1422395802.069 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:42.177Z,1422395802.177 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20150127T005047/Courier0396.lzma
2015-01-27T21:56:42.180Z,1422395802.180 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:42.575Z,1422395802.575 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:42.983Z,1422395802.983 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:43.369Z,1422395803.369 [DataOverHttps](INFO): Moved sent file to Logs/20150127T005047/Courier0396.lzma.bak
2015-01-27T21:56:43.369Z,1422395803.369 [DataOverHttps](INFO): SBD MOMSN=1508712
2015-01-27T21:56:43.393Z,1422395803.393 [NAL9602](INFO): ************** SESSION MT QUEUE VERIFY **************

2015-01-27T21:56:43.395Z,1422395803.395 [NAL9602](INFO): SBD MO Status=0, MOMSN=5440, MT Status=0, MTMSN=0
2015-01-27T21:56:43.395Z,1422395803.395 [NAL9602](INFO): sendFilename:resendFilename:
2015-01-27T21:56:43.395Z,1422395803.395 [NAL9602](INFO): No messages in MT queue
2015-01-27T21:57:17.157Z,1422395837.157 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150127T215354/Courier0000.lzma
2015-01-27T21:57:17.965Z,1422395837.965 [DataOverHttps](INFO): Moved sent file to Logs/20150127T215354/Courier0000.lzma.bak
2015-01-27T21:57:17.965Z,1422395837.965 [DataOverHttps](INFO): SBD MOMSN=1508715
2015-01-27T21:57:27.157Z,1422395847.157 [DataOverHttps](INFO): Sending 333 bytes from file Logs/20150127T005047/Express0397.lzma
2015-01-27T21:57:27.595Z,1422395847.595 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-27T21:57:27.596Z,1422395847.596 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-01-27T21:57:27.596Z,1422395847.596 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-27T21:57:27.606Z,1422395847.606 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-27T21:57:34.754Z,1422395854.754 [DataOverHttps](INFO): Moved sent file to Logs/20150127T005047/Express0397.lzma.bak
2015-01-27T21:57:34.754Z,1422395854.754 [DataOverHttps](INFO): SBD MOMSN=1508719
2015-01-27T21:57:34.841Z,1422395854.841 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-27T21:57:34.841Z,1422395854.841 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-01-27T21:57:35.314Z,1422395855.314 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-27T21:57:35.476Z,1422395855.476 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:57:38.661Z,1422395858.661 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:57:38.664Z,1422395858.664 [Startup:StartupSatComms:B](INFO): Timed out from 2015-01-27T21:56:37.5Z
2015-01-27T21:57:38.664Z,1422395858.664 [Startup:StartupSatComms:B] Stopped
2015-01-27T21:57:38.664Z,1422395858.664 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2015-01-27T21:57:38.664Z,1422395858.664 [Startup:StartupSatComms] Stopped
2015-01-27T21:57:38.664Z,1422395858.664 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-01-27T21:57:38.665Z,1422395858.665 [Startup](INFO): Completed Startup
2015-01-27T21:57:38.665Z,1422395858.665 [Startup] Stopped
2015-01-27T21:57:38.665Z,1422395858.665 [Startup](INFO): Aggregate::uninitialize Startup
2015-01-27T21:57:38.665Z,1422395858.665 [Startup:A.GoToSurface] Stopped
2015-01-27T21:57:38.665Z,1422395858.665 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-27T21:57:38.821Z,1422395858.821 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:57:38.823Z,1422395858.823 [MissionManager](IMPORTANT): Started mission Default
2015-01-27T21:57:38.823Z,1422395858.823 [Default] Running Loop=1
2015-01-27T21:57:38.823Z,1422395858.823 [Default](INFO): Aggregate::initialize Default
2015-01-27T21:57:38.823Z,1422395858.823 [Default:B.GoToSurface] Running Loop=1
2015-01-27T21:57:38.823Z,1422395858.823 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-27T21:57:38.823Z,1422395858.823 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-27T21:57:38.824Z,1422395858.824 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-27T21:57:38.824Z,1422395858.824 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-27T21:57:38.841Z,1422395858.841 [Default:StartClock] Running Loop=1
2015-01-27T21:57:38.841Z,1422395858.841 [Default:StartClock](INFO): Aggregate::initialize Default:StartClock
2015-01-27T21:57:38.841Z,1422395858.841 [Default:StartClock:A] Running Loop=1
2015-01-27T21:57:38.841Z,1422395858.841 [Default:CheckIn] Running Loop=1
2015-01-27T21:57:38.841Z,1422395858.841 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2015-01-27T21:57:38.842Z,1422395858.842 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-27T21:57:38.842Z,1422395858.842 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2015-01-27T21:57:38.842Z,1422395858.842 [Default:CheckIn:Read_GPS] Running Loop=1
2015-01-27T21:57:38.843Z,1422395858.843 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-27T21:57:38.845Z,1422395858.845 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-27T21:57:38.874Z,1422395858.874 [Default:StartClock:A] Stopped
2015-01-27T21:57:38.874Z,1422395858.874 [Default:StartClock](INFO): Completed Default:StartClock
2015-01-27T21:57:38.874Z,1422395858.874 [Default:StartClock] Stopped
2015-01-27T21:57:38.874Z,1422395858.874 [Default:StartClock](INFO): Aggregate::uninitialize Default:StartClock
2015-01-27T21:57:39.252Z,1422395859.252 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:57:39.255Z,1422395859.255 [Default:WaitAtTheSurface] Running Loop=1
2015-01-27T21:57:39.255Z,1422395859.255 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2015-01-27T21:57:39.255Z,1422395859.255 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-27T21:57:39.255Z,1422395859.255 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2015-01-27T21:57:39.654Z,1422395859.654 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:57:39.656Z,1422395859.656 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-27T21:57:40.052Z,1422395860.052 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T21:59:20.707Z,1422395960.707 [BPC1](FAULT): Failed to receive battery data
2015-01-27T21:59:20.707Z,1422395960.707 [BPC1] Communications Fault, FailCount= 1
2015-01-27T21:59:20.707Z,1422395960.707 [BPC1](ERROR): Communications Fault
2015-01-27T21:59:20.725Z,1422395960.725 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-27T21:59:21.922Z,1422395961.922 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-27T21:59:21.922Z,1422395961.922 [BPC1] No Fault, FailCount= 1
2015-01-27T21:59:28.312Z,1422395968.312 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-27T21:59:28.312Z,1422395968.312 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T21:59:28.312Z,1422395968.312 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-27T21:59:28.315Z,1422395968.315 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-27T21:59:28.315Z,1422395968.315 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-27T21:59:28.750Z,1422395968.750 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 1.824683 min 
2015-01-27T21:59:28.752Z,1422395968.752 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-27T21:59:28.752Z,1422395968.752 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T21:59:28.752Z,1422395968.752 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-27T21:59:28.753Z,1422395968.753 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T21:59:44.068Z,1422395984.068 [DataOverHttps](INFO): Sending 506 bytes from file Logs/20150127T215354/Express0001.lzma
2015-01-27T21:59:44.873Z,1422395984.873 [DataOverHttps](INFO): Moved sent file to Logs/20150127T215354/Express0001.lzma.bak
2015-01-27T21:59:44.873Z,1422395984.873 [DataOverHttps](INFO): SBD MOMSN=1508729
2015-01-27T22:00:35.741Z,1422396035.741 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-27T22:00:35.741Z,1422396035.741 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2015-01-27T22:00:35.741Z,1422396035.741 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-27T22:00:35.756Z,1422396035.756 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-27T22:00:36.119Z,1422396036.119 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-27T22:00:36.119Z,1422396036.119 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2015-01-27T22:00:36.508Z,1422396036.508 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-27T22:00:36.947Z,1422396036.947 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:00:37.322Z,1422396037.322 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:00:37.737Z,1422396037.737 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:00:38.137Z,1422396038.137 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:00:38.509Z,1422396038.509 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:00:38.941Z,1422396038.941 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:01:51.966Z,1422396111.966 [BPC1](FAULT): Failed to receive battery data
2015-01-27T22:01:51.966Z,1422396111.966 [BPC1] Communications Fault, FailCount= 1
2015-01-27T22:01:51.966Z,1422396111.966 [BPC1](ERROR): Communications Fault
2015-01-27T22:01:51.983Z,1422396111.983 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-27T22:01:53.181Z,1422396113.181 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-27T22:01:53.181Z,1422396113.181 [BPC1] No Fault, FailCount= 1
2015-01-27T22:02:09.566Z,1422396129.566 [BPC1](FAULT): Failed to receive battery data
2015-01-27T22:02:09.566Z,1422396129.566 [BPC1] Communications Fault, FailCount= 2
2015-01-27T22:02:09.566Z,1422396129.566 [BPC1](ERROR): Communications Fault
2015-01-27T22:02:09.583Z,1422396129.583 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-27T22:02:10.781Z,1422396130.781 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-27T22:02:10.781Z,1422396130.781 [BPC1] No Fault, FailCount= 2
2015-01-27T22:02:25.965Z,1422396145.965 [BPC1](DEBUG): Received data from all battery sticks
2015-01-27T22:02:39.234Z,1422396159.234 [Default:CheckIn:Read_GPS](INFO): Timed out from 2015-01-27T21:57:38.8Z
2015-01-27T22:02:39.234Z,1422396159.234 [Default:CheckIn:Read_GPS] Stopped
2015-01-27T22:02:39.234Z,1422396159.234 [Default:CheckIn:Read_Iridium] Running Loop=1
2015-01-27T22:02:39.580Z,1422396159.580 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-27T22:02:43.723Z,1422396163.723 [DataOverHttps](INFO): Sending 193 bytes from file Logs/20150127T215354/Courier0004.lzma
2015-01-27T22:02:44.528Z,1422396164.528 [DataOverHttps](INFO): Moved sent file to Logs/20150127T215354/Courier0004.lzma.bak
2015-01-27T22:02:44.528Z,1422396164.528 [DataOverHttps](INFO): SBD MOMSN=1508742
2015-01-27T22:02:53.712Z,1422396173.712 [DataOverHttps](INFO): Sending 445 bytes from file Logs/20150127T215354/Express0005.lzma
2015-01-27T22:02:54.518Z,1422396174.518 [DataOverHttps](INFO): Moved sent file to Logs/20150127T215354/Express0005.lzma.bak
2015-01-27T22:02:54.518Z,1422396174.518 [DataOverHttps](INFO): SBD MOMSN=1508744
2015-01-27T22:02:55.367Z,1422396175.367 [Default:CheckIn:Read_Iridium] Stopped
2015-01-27T22:02:55.367Z,1422396175.367 [Default:CheckIn](INFO): Completed Default:CheckIn
2015-01-27T22:02:55.367Z,1422396175.367 [Default:CheckIn] Stopped
2015-01-27T22:02:55.367Z,1422396175.367 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2015-01-27T22:02:55.368Z,1422396175.368 [Default:CheckIn:A.SetSpeed] Stopped
2015-01-27T22:02:55.368Z,1422396175.368 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2015-01-27T22:03:40.521Z,1422396220.521 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-27T22:03:40.521Z,1422396220.521 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2015-01-27T22:03:40.521Z,1422396220.521 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-27T22:03:40.532Z,1422396220.532 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-27T22:03:45.519Z,1422396225.519 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-27T22:03:45.519Z,1422396225.519 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2015-01-27T22:03:50.476Z,1422396230.476 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-27T22:03:55.527Z,1422396235.527 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:00.484Z,1422396240.484 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:08.344Z,1422396248.344 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:10.511Z,1422396250.511 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:15.514Z,1422396255.514 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:20.512Z,1422396260.512 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-27T22:04:30.548Z,1422396270.548 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-27T22:04:30.548Z,1422396270.548 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T22:04:30.548Z,1422396270.548 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-27T22:04:30.549Z,1422396270.549 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-27T22:04:30.549Z,1422396270.549 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-27T22:04:35.551Z,1422396275.551 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 6.860948 min 
2015-01-27T22:04:35.551Z,1422396275.551 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-27T22:04:35.552Z,1422396275.552 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T22:04:35.552Z,1422396275.552 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-27T22:04:35.552Z,1422396275.552 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-27T22:04:42.835Z,1422396282.835 [CommandLine](IMPORTANT): got command quit
2015-01-27T22:04:43.844Z,1422396283.844 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T22:04:43.851Z,1422396283.851 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:43.885Z,1422396283.885 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2015-01-27T22:04:43.885Z,1422396283.885 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:43.886Z,1422396283.886 [CommandLine](INFO): Join timeout helper Thread ID is 878
2015-01-27T22:04:43.887Z,1422396283.887 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2015-01-27T22:04:43.887Z,1422396283.887 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:43.887Z,1422396283.887 [NavChartDb](INFO): Join timeout helper Thread ID is 879
2015-01-27T22:04:43.926Z,1422396283.926 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T22:04:43.926Z,1422396283.926 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:43.945Z,1422396283.945 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2015-01-27T22:04:43.946Z,1422396283.946 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:43.946Z,1422396283.946 [Radio_Surface](INFO): Join timeout helper Thread ID is 880
2015-01-27T22:04:44.066Z,1422396284.066 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T22:04:44.066Z,1422396284.066 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:44.086Z,1422396284.086 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2015-01-27T22:04:44.086Z,1422396284.086 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:44.086Z,1422396284.086 [logger](INFO): Join timeout helper Thread ID is 881
2015-01-27T22:04:44.094Z,1422396284.094 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T22:04:44.094Z,1422396284.094 [logger ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:44.106Z,1422396284.106 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2015-01-27T22:04:44.106Z,1422396284.106 [CommandLine ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:44.106Z,1422396284.106 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2015-01-27T22:04:44.106Z,1422396284.106 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:44.107Z,1422396284.107 [controlThread](INFO): Join timeout helper Thread ID is 882
2015-01-27T22:04:45.380Z,1422396285.380 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2015-01-27T22:04:45.380Z,1422396285.380 [controlThread](DEBUG): Uninitializing ControlThread
2015-01-27T22:04:45.382Z,1422396285.382 [NAL9602](INFO): Uninitialize
2015-01-27T22:04:45.382Z,1422396285.382 [NAL9602](INFO): Powering down
2015-01-27T22:04:45.384Z,1422396285.384 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-27T22:04:45.385Z,1422396285.385 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2015-01-27T22:04:45.385Z,1422396285.385 [Default] Stopped
2015-01-27T22:04:45.385Z,1422396285.385 [Default](INFO): Aggregate::uninitialize Default
2015-01-27T22:04:45.385Z,1422396285.385 [Default:B.GoToSurface] Stopped
2015-01-27T22:04:45.385Z,1422396285.385 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-27T22:04:45.385Z,1422396285.385 [Default:WaitAtTheSurface] Stopped
2015-01-27T22:04:45.385Z,1422396285.385 [Default:WaitAtTheSurface](INFO): Aggregate::uninitialize Default:WaitAtTheSurface
2015-01-27T22:04:45.386Z,1422396285.386 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Stopped
2015-01-27T22:04:45.386Z,1422396285.386 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Uninitialize.
2015-01-27T22:04:45.389Z,1422396285.389 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2015-01-27T22:04:45.389Z,1422396285.389 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2015-01-27T22:04:45.390Z,1422396285.390 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2015-01-27T22:04:45.390Z,1422396285.390 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2015-01-27T22:04:45.390Z,1422396285.390 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-27T22:04:45.390Z,1422396285.390 [BuoyancyServo](INFO): Powering down
2015-01-27T22:04:45.404Z,1422396285.404 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2015-01-27T22:04:45.404Z,1422396285.404 [ElevatorServo](INFO): Powering down
2015-01-27T22:04:45.405Z,1422396285.405 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2015-01-27T22:04:45.405Z,1422396285.405 [RudderServo](INFO): Powering down
2015-01-27T22:04:45.406Z,1422396285.406 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2015-01-27T22:04:45.406Z,1422396285.406 [ThrusterServo](INFO): Powering down
2015-01-27T22:04:45.407Z,1422396285.407 [SBIT](DEBUG): Uninitialize SBIT Component.
2015-01-27T22:04:45.407Z,1422396285.407 [IBIT](DEBUG): Uninitialize IBIT Component.
2015-01-27T22:04:45.407Z,1422396285.407 [CBIT](DEBUG): Uninitialize CBIT Component.
2015-01-27T22:04:45.440Z,1422396285.440 [controlThread ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:45.545Z,1422396285.545 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:45.589Z,1422396285.589 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2015-01-27T22:04:45.643Z,1422396285.643 [logger ThreadHandler](INFO): Thread cancelled.