2015-01-29T01:01:57.009Z,1422493317.009 [Supervisor](DEBUG): Initializing supervisor.
2015-01-29T01:01:57.011Z,1422493317.011 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-29T01:01:57.012Z,1422493317.012 [SyncHandler](INFO): Protected caller Thread ID is 8776
2015-01-29T01:01:57.012Z,1422493317.012 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-29T01:01:57.013Z,1422493317.013 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-29T01:01:57.013Z,1422493317.013 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 8777
2015-01-29T01:01:57.016Z,1422493317.016 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-29T01:01:57.028Z,1422493317.028 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-29T01:01:57.029Z,1422493317.029 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-29T01:01:57.029Z,1422493317.029 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 8778
2015-01-29T01:01:57.030Z,1422493317.030 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-29T01:01:57.031Z,1422493317.031 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-29T01:01:57.031Z,1422493317.031 [logger ThreadHandler](INFO): Protected caller Thread ID is 8779
2015-01-29T01:01:57.034Z,1422493317.034 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-29T01:01:57.034Z,1422493317.034 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-29T01:01:57.035Z,1422493317.035 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-29T01:01:57.363Z,1422493317.363 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-29T01:01:57.364Z,1422493317.364 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-29T01:01:57.522Z,1422493317.522 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-29T01:01:57.522Z,1422493317.522 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-29T01:01:57.629Z,1422493317.629 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-29T01:01:57.630Z,1422493317.630 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-29T01:01:57.751Z,1422493317.751 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-29T01:01:57.751Z,1422493317.751 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-29T01:01:57.835Z,1422493317.835 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-29T01:01:57.994Z,1422493317.994 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-29T01:01:57.995Z,1422493317.995 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-29T01:01:58.081Z,1422493318.081 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-29T01:01:58.081Z,1422493318.081 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-29T01:01:58.290Z,1422493318.290 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-29T01:01:58.291Z,1422493318.291 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-29T01:01:58.660Z,1422493318.660 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-29T01:01:58.661Z,1422493318.661 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-29T01:01:58.975Z,1422493318.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-29T01:01:58.976Z,1422493318.976 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-29T01:01:59.467Z,1422493319.467 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-29T01:01:59.468Z,1422493319.468 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-29T01:01:59.662Z,1422493319.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-29T01:01:59.662Z,1422493319.662 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-29T01:01:59.766Z,1422493319.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-29T01:01:59.766Z,1422493319.766 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-29T01:02:00.185Z,1422493320.185 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-29T01:02:00.186Z,1422493320.186 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-29T01:02:00.298Z,1422493320.298 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-29T01:02:00.301Z,1422493320.301 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-29T01:02:00.301Z,1422493320.301 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-29T01:02:00.538Z,1422493320.538 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-29T01:02:00.539Z,1422493320.539 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-29T01:02:00.654Z,1422493320.654 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-29T01:02:00.751Z,1422493320.751 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-29T01:02:00.847Z,1422493320.847 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-29T01:02:00.960Z,1422493320.960 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-29T01:02:01.100Z,1422493321.100 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-29T01:02:01.269Z,1422493321.269 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-29T01:02:01.368Z,1422493321.368 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-29T01:02:01.458Z,1422493321.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-29T01:02:01.558Z,1422493321.558 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-29T01:02:01.653Z,1422493321.653 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-29T01:02:01.835Z,1422493321.835 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-01-29T01:02:01.848Z,1422493321.848 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-29T01:02:01.898Z,1422493321.898 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-29T01:02:02.016Z,1422493322.016 [VerticalControl] Loaded
2015-01-29T01:02:02.016Z,1422493322.016 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-29T01:02:02.017Z,1422493322.017 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-29T01:02:02.088Z,1422493322.088 [HorizontalControl] Loaded
2015-01-29T01:02:02.088Z,1422493322.088 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-29T01:02:02.089Z,1422493322.089 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-29T01:02:02.095Z,1422493322.095 [SpeedControl] Loaded
2015-01-29T01:02:02.095Z,1422493322.095 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-29T01:02:02.096Z,1422493322.096 [LoopControl](DEBUG): Construct LoopControl.
2015-01-29T01:02:02.096Z,1422493322.096 [LoopControl] Loaded
2015-01-29T01:02:02.097Z,1422493322.097 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-29T01:02:02.097Z,1422493322.097 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-29T01:02:02.098Z,1422493322.098 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-29T01:02:02.191Z,1422493322.191 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-29T01:02:02.203Z,1422493322.203 [SBIT] Loaded
2015-01-29T01:02:02.203Z,1422493322.203 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-29T01:02:02.204Z,1422493322.204 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-29T01:02:02.232Z,1422493322.232 [IBIT] Loaded
2015-01-29T01:02:02.233Z,1422493322.233 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-29T01:02:02.235Z,1422493322.235 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-29T01:02:02.355Z,1422493322.355 [CBIT] Loaded
2015-01-29T01:02:02.355Z,1422493322.355 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-29T01:02:02.356Z,1422493322.356 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-29T01:02:02.356Z,1422493322.356 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-29T01:02:02.374Z,1422493322.374 [DepthRateCalculator] Loaded
2015-01-29T01:02:02.375Z,1422493322.375 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-29T01:02:02.380Z,1422493322.380 [PitchRateCalculator] Loaded
2015-01-29T01:02:02.380Z,1422493322.380 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-29T01:02:02.392Z,1422493322.392 [SpeedCalculator] Loaded
2015-01-29T01:02:02.393Z,1422493322.393 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-29T01:02:02.409Z,1422493322.409 [TempGradientCalculator] Loaded
2015-01-29T01:02:02.410Z,1422493322.410 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-29T01:02:02.415Z,1422493322.415 [YawRateCalculator] Loaded
2015-01-29T01:02:02.415Z,1422493322.415 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-29T01:02:02.416Z,1422493322.416 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-29T01:02:02.416Z,1422493322.416 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-29T01:02:02.466Z,1422493322.466 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-29T01:02:02.467Z,1422493322.467 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-29T01:02:02.697Z,1422493322.697 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-29T01:02:02.698Z,1422493322.698 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-29T01:02:02.784Z,1422493322.784 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-01-29T01:02:02.785Z,1422493322.785 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-01-29T01:02:02.802Z,1422493322.802 [NavChart] Loaded
2015-01-29T01:02:02.802Z,1422493322.802 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-29T01:02:02.806Z,1422493322.806 [UniversalFixResidualReporter] Loaded
2015-01-29T01:02:02.807Z,1422493322.807 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-29T01:02:02.807Z,1422493322.807 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-29T01:02:02.808Z,1422493322.808 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-29T01:02:02.813Z,1422493322.813 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-29T01:02:02.814Z,1422493322.814 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-29T01:02:02.898Z,1422493322.898 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-29T01:02:02.899Z,1422493322.899 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-29T01:02:03.197Z,1422493323.197 [DataOverHttps] Loaded
2015-01-29T01:02:03.197Z,1422493323.197 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-29T01:02:03.280Z,1422493323.280 [Depth_Keller] Loaded
2015-01-29T01:02:03.280Z,1422493323.280 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-29T01:02:03.374Z,1422493323.374 [NAL9602] Loaded
2015-01-29T01:02:03.381Z,1422493323.381 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-29T01:02:03.424Z,1422493323.424 [Onboard] Loaded
2015-01-29T01:02:03.424Z,1422493323.424 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-29T01:02:03.431Z,1422493323.431 [Radio_Surface] Loaded
2015-01-29T01:02:03.432Z,1422493323.432 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-29T01:02:03.433Z,1422493323.433 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-29T01:02:03.433Z,1422493323.433 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 8861
2015-01-29T01:02:03.481Z,1422493323.481 [PNI_TCM] Loaded
2015-01-29T01:02:03.481Z,1422493323.481 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2015-01-29T01:02:05.346Z,1422493325.346 [BPC1] Loaded
2015-01-29T01:02:05.346Z,1422493325.346 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-29T01:02:05.347Z,1422493325.347 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-29T01:02:05.347Z,1422493325.347 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-29T01:02:05.446Z,1422493325.446 [BuoyancyServo] Loaded
2015-01-29T01:02:05.447Z,1422493325.447 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-29T01:02:05.459Z,1422493325.459 [ElevatorServo] Loaded
2015-01-29T01:02:05.459Z,1422493325.459 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-29T01:02:05.471Z,1422493325.471 [RudderServo] Loaded
2015-01-29T01:02:05.471Z,1422493325.471 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-29T01:02:05.482Z,1422493325.482 [ThrusterServo] Loaded
2015-01-29T01:02:05.483Z,1422493325.483 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-29T01:02:05.483Z,1422493325.483 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-29T01:02:05.484Z,1422493325.484 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-29T01:02:05.726Z,1422493325.726 [ExternalSim] Loaded
2015-01-29T01:02:05.727Z,1422493325.727 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2015-01-29T01:02:05.727Z,1422493325.727 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-29T01:02:05.728Z,1422493325.728 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-29T01:02:05.752Z,1422493325.752 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-29T01:02:05.754Z,1422493325.754 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-29T01:02:05.755Z,1422493325.755 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-29T01:02:05.761Z,1422493325.761 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-29T01:02:05.763Z,1422493325.763 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-29T01:02:05.763Z,1422493325.763 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 8862
2015-01-29T01:02:05.768Z,1422493325.768 [Supervisor](INFO): Main Thread ID is 8775
2015-01-29T01:02:05.768Z,1422493325.768 [Supervisor](DEBUG): Running supervisor.
2015-01-29T01:02:05.769Z,1422493325.769 [CommandLine ThreadHandler](INFO): Handler Thread ID is 8863
2015-01-29T01:02:05.772Z,1422493325.772 [controlThread ThreadHandler](INFO): Handler Thread ID is 8864
2015-01-29T01:02:05.772Z,1422493325.772 [controlThread](DEBUG): Initializing ControlThread
2015-01-29T01:02:05.773Z,1422493325.773 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-29T01:02:05.775Z,1422493325.775 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-29T01:02:05.775Z,1422493325.775 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-29T01:02:05.776Z,1422493325.776 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-29T01:02:05.776Z,1422493325.776 [SBIT](INFO): Initialize SBIT Component.
2015-01-29T01:02:05.777Z,1422493325.777 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-29T01:02:05.777Z,1422493325.777 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-29T01:02:05.777Z,1422493325.777 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-29T01:02:05.778Z,1422493325.778 [IBIT](INFO): Initialize IBIT Component.
2015-01-29T01:02:05.779Z,1422493325.779 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-29T01:02:05.779Z,1422493325.779 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-29T01:02:05.780Z,1422493325.780 [logger ThreadHandler](INFO): Handler Thread ID is 8865
2015-01-29T01:02:05.801Z,1422493325.801 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 8866
2015-01-29T01:02:05.807Z,1422493325.807 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-29T01:02:05.807Z,1422493325.807 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-29T01:02:05.807Z,1422493325.807 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-29T01:02:05.808Z,1422493325.808 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-29T01:02:05.808Z,1422493325.808 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-29T01:02:05.809Z,1422493325.809 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-29T01:02:05.809Z,1422493325.809 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-29T01:02:05.809Z,1422493325.809 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-29T01:02:05.814Z,1422493325.814 [ExternalSim](INFO): ExternalSim initializing...
2015-01-29T01:02:05.821Z,1422493325.821 [Radio_Surface](INFO): Powering up
2015-01-29T01:02:05.837Z,1422493325.837 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 8867
2015-01-29T01:02:05.840Z,1422493325.840 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-29T01:02:05.841Z,1422493325.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-29T01:02:05.841Z,1422493325.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-29T01:02:05.841Z,1422493325.841 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-29T01:02:05.842Z,1422493325.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-29T01:02:05.842Z,1422493325.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-29T01:02:05.842Z,1422493325.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-29T01:02:05.842Z,1422493325.842 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-29T01:02:05.843Z,1422493325.843 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-29T01:02:06.070Z,1422493326.070 [ExternalSim](DEBUG): beaconLat = 36.80340
2015-01-29T01:02:06.070Z,1422493326.070 [ExternalSim](DEBUG): beaconLon = -121.82230
2015-01-29T01:02:06.070Z,1422493326.070 [ExternalSim](DEBUG): beaconDepth = 25.00
2015-01-29T01:02:06.152Z,1422493326.152 [ExternalSim](DEBUG): Simulator initialized
2015-01-29T01:02:06.159Z,1422493326.159 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-29T01:02:06.169Z,1422493326.169 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-29T01:02:06.194Z,1422493326.194 [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-29T01:02:06.194Z,1422493326.194 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-29T01:02:06.287Z,1422493326.287 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-29T01:02:06.291Z,1422493326.291 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-29T01:02:06.315Z,1422493326.315 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-29T01:02:06.343Z,1422493326.343 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-29T01:02:06.365Z,1422493326.365 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-29T01:02:06.390Z,1422493326.390 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-29T01:02:06.396Z,1422493326.396 [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-29T01:02:06.413Z,1422493326.413 [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-29T01:02:06.602Z,1422493326.602 [NAL9602](INFO): Start
2015-01-29T01:02:06.863Z,1422493326.863 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:06.963Z,1422493326.963 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-29T01:02:06.971Z,1422493326.971 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-29T01:02:06.985Z,1422493326.985 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-29T01:02:06.991Z,1422493326.991 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-29T01:02:07.012Z,1422493327.012 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-29T01:02:07.019Z,1422493327.019 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-29T01:02:07.029Z,1422493327.029 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-29T01:02:07.035Z,1422493327.035 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-29T01:02:07.227Z,1422493327.227 [NAL9602](INFO): Start
2015-01-29T01:02:07.475Z,1422493327.475 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:07.824Z,1422493327.824 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2015-01-29T01:02:07.824Z,1422493327.824 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2015-01-29T01:02:07.824Z,1422493327.824 [BuoyancyServo] Communications Fault, FailCount= 1
2015-01-29T01:02:07.824Z,1422493327.824 [BuoyancyServo](ERROR): Communications Fault
2015-01-29T01:02:08.030Z,1422493328.030 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2015-01-29T01:02:16.835Z,1422493336.835 [NAL9602](INFO): Start
2015-01-29T01:02:16.835Z,1422493336.835 [NAL9602](INFO): Powering up NAL9602
2015-01-29T01:02:16.913Z,1422493336.913 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:16.919Z,1422493336.919 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-29T01:02:16.919Z,1422493336.919 [BuoyancyServo](INFO): Powering down
2015-01-29T01:02:17.164Z,1422493337.164 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:17.615Z,1422493337.615 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:17.871Z,1422493337.871 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003500
2015-01-29T01:02:17.936Z,1422493337.936 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:02:19.329Z,1422493339.329 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2015-01-29T01:02:19.329Z,1422493339.329 [BuoyancyServo] No Fault, FailCount= 1
2015-01-29T01:02:19.617Z,1422493339.617 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-29T01:02:19.735Z,1422493339.735 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-29T01:02:21.312Z,1422493341.312 [SBIT](IMPORTANT): Beginning Startup BIT
2015-01-29T01:02:21.318Z,1422493341.318 [CBIT](IMPORTANT): Beginning GF scan
2015-01-29T01:02:27.720Z,1422493347.720 [NAL9602](INFO): ************** CMDMODE **************

2015-01-29T01:02:27.720Z,1422493347.720 [NAL9602](INFO): NAL9602 initialized
2015-01-29T01:02:28.521Z,1422493348.521 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:02:28.927Z,1422493348.927 [NAL9602](INFO): ************** GetFix **************

2015-01-29T01:02:32.633Z,1422493352.633 [BPC1](ERROR): A bank expecting battery number:1 and read number: uart read:X
$S,01,270F,02,00,04,5D%56
$C1,01,7F,02,00,03,7F,04,00,05,00,06,00,07,00%72
$B11,02,000A,01,026C,03,0001,08,0B91,09,3C27,0A,FFFA,0B,FFFC%4A
$B11,0C,0001,0D,0056,0E,0051,0F,1396,10,173A,11,C3DC,12,FFFF%4C
$B11,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%41
$B11,1A,0031,1B,4357,1C,00AD%31
$B12,02,000A,01,026C,03,0001,08,0B8C,09,3C28,0A,FFFB,0B,FFFD%31
$B12,0C,0001,0D,0058,0E,0052,0F,13BD,10,16AC,11,ECDC,12,FFFF%4C
$B12,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%42
$B12,1A,0031,1B,4357,1C,00AB%34
$B13,02,000A,01,026C,03,0001,08,0B88,09,3C24,0A,FFFA,0B,FFFB%42
$B13,0C,0001,0D,0061,0E,0051,0F,1390,10,16AE,11,C3A0,12,EAC0%3A
$B13,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%43
$B13,1A,0031,1B,4357,1C,00B1%45
$B14,02,000A,01,026C,03,0001,08,0B8F,09,3C23,0A,FFFC,0B,FFFC%3F
$B14,0C,0001,0D,0054,0E,004E,0F,12D1,10,1688,11,FFFF,12,FFFF%41
$B14,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%44
$B14,1A,0031,1B,4357,1C,00A0%40
$B15,02,000A,01,026C,03,0001,08,0B8F,09,3C06,0A,0000,0B,0000%39
$B15,0C,0001,0D,0064,0E,005C,0F,1615,10,1736,11,FFFF,12,FFFF%35
$B15,13,FFFF,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%48
$B15,1A,0031,1B,4357,1C,008B%4A
$B16,02,000A,01,026C,03,0001,08,0B84,09,3C21,0A,0000,0B,FFFF%4D
$B16,0C,0001,0D,0060,0E,0059,0F,157C,10,178C,11,FFFF,12,FFFF%45
$B16,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0001,18,1838,19,3840%45
$B16,1A,0031,1B,4339,1C,007F%4A
$B17,02,000A,01,026C,03,0001,08,0B82,09,3BFF,0A,0000,0B,0000%48
$B17,0C,0001,0D,0064,0E,005D,0F,1654,10,16E1,11,FFFF,12,FFFF%45
$B17,13,FFFF,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%4A
$B17,1A,0031,1B,4357,1C,00B4%44

2015-01-29T01:02:32.633Z,1422493352.633 [BPC1](FAULT): Failed to parse bank A battery data
2015-01-29T01:02:32.634Z,1422493352.634 [BPC1] Data Fault, FailCount= 1
2015-01-29T01:02:32.634Z,1422493352.634 [BPC1](ERROR): Data Fault
2015-01-29T01:02:32.754Z,1422493352.754 [CBIT](ERROR): Data Fault in component: BPC1
2015-01-29T01:02:33.867Z,1422493353.867 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-29T01:02:33.867Z,1422493353.867 [BPC1] No Fault, FailCount= 1
2015-01-29T01:02:34.323Z,1422493354.323 [SBIT](ERROR): Could not read massPosReader_.
2015-01-29T01:02:47.482Z,1422493367.482 [CBIT](IMPORTANT): No ground fault detected
2015-01-29T01:02:59.718Z,1422493379.718 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:03:00.131Z,1422493380.131 [NAL9602](INFO): MT Sig Qty requested
2015-01-29T01:03:01.153Z,1422493381.153 [SBIT](ERROR): Could not read massPosReader_.
2015-01-29T01:03:01.153Z,1422493381.153 [SBIT](FAULT): Control surface position failure.
2015-01-29T01:03:14.661Z,1422493394.661 [SBIT](ERROR): Could not read massPosReader_.
2015-01-29T01:03:14.661Z,1422493394.661 [SBIT](FAULT): Control surface position failure.
2015-01-29T01:03:15.109Z,1422493395.109 [SBIT](CRITICAL): SBIT FAILED
2015-01-29T01:03:15.110Z,1422493395.110 [CommandLine](FAULT): Scheduling is paused
2015-01-29T01:03:15.503Z,1422493395.503 [MissionManager](IMPORTANT): Started mission Startup
2015-01-29T01:03:15.503Z,1422493395.503 [Startup] Running Loop=1
2015-01-29T01:03:15.503Z,1422493395.503 [Startup](INFO): Aggregate::initialize Startup
2015-01-29T01:03:15.503Z,1422493395.503 [Startup:A.GoToSurface] Running Loop=1
2015-01-29T01:03:15.503Z,1422493395.503 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-29T01:03:15.504Z,1422493395.504 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-29T01:03:15.504Z,1422493395.504 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-29T01:03:15.504Z,1422493395.504 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-29T01:03:15.518Z,1422493395.518 [Startup:StartupSatComms] Running Loop=1
2015-01-29T01:03:15.518Z,1422493395.518 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-01-29T01:03:15.519Z,1422493395.519 [Startup:StartupSatComms:A] Running Loop=1
2015-01-29T01:03:15.843Z,1422493395.843 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-29T01:03:30.231Z,1422493410.231 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2015-01-29T01:03:30.749Z,1422493410.749 [NAL9602](FAULT): received: 
2015-01-29T01:03:30.749Z,1422493410.749 [NAL9602] Data Fault, FailCount= 1
2015-01-29T01:03:30.749Z,1422493410.749 [NAL9602](ERROR): Data Fault
2015-01-29T01:03:30.851Z,1422493410.851 [CBIT](ERROR): Data Fault in component: NAL9602
2015-01-29T01:03:30.928Z,1422493410.928 [NAL9602](INFO): Stop
2015-01-29T01:03:30.928Z,1422493410.928 [NAL9602](INFO): Uninitialize
2015-01-29T01:03:30.928Z,1422493410.928 [NAL9602](INFO): Powering down
2015-01-29T01:03:31.335Z,1422493411.335 [NAL9602](INFO): Stopping
2015-01-29T01:03:31.793Z,1422493411.793 [CBIT](INFO): Clearing failed state for component NAL9602
2015-01-29T01:03:31.794Z,1422493411.794 [NAL9602] No Fault, FailCount= 1
2015-01-29T01:03:32.132Z,1422493412.132 [NAL9602](INFO): Start
2015-01-29T01:03:32.533Z,1422493412.533 [NAL9602](INFO): Start
2015-01-29T01:03:32.934Z,1422493412.934 [NAL9602](INFO): Start
2015-01-29T01:03:33.334Z,1422493413.334 [NAL9602](INFO): Start
2015-01-29T01:03:33.735Z,1422493413.735 [NAL9602](INFO): Start
2015-01-29T01:03:34.136Z,1422493414.136 [NAL9602](INFO): Start
2015-01-29T01:03:34.532Z,1422493414.532 [NAL9602](INFO): Start
2015-01-29T01:03:34.933Z,1422493414.933 [NAL9602](INFO): Start
2015-01-29T01:03:35.333Z,1422493415.333 [NAL9602](INFO): Start
2015-01-29T01:03:35.730Z,1422493415.730 [NAL9602](INFO): Start
2015-01-29T01:03:36.134Z,1422493416.134 [NAL9602](INFO): Start
2015-01-29T01:03:36.135Z,1422493416.135 [NAL9602](INFO): Powering up NAL9602
2015-01-29T01:03:47.340Z,1422493427.340 [NAL9602](INFO): ************** CMDMODE **************

2015-01-29T01:03:47.340Z,1422493427.340 [NAL9602](INFO): NAL9602 initialized
2015-01-29T01:03:48.134Z,1422493428.134 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:03:48.536Z,1422493428.536 [NAL9602](INFO): ************** GetFix **************

2015-01-29T01:04:15.905Z,1422493455.905 [Startup:StartupSatComms:A](INFO): Timed out from 2015-01-29T01:03:15.5Z
2015-01-29T01:04:15.905Z,1422493455.905 [Startup:StartupSatComms:A] Stopped
2015-01-29T01:04:15.905Z,1422493455.905 [Startup:StartupSatComms:B] Running Loop=1
2015-01-29T01:04:16.291Z,1422493456.291 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-29T01:04:20.289Z,1422493460.289 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:04:20.406Z,1422493460.406 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150128T183411/Courier0024.lzma
2015-01-29T01:04:20.417Z,1422493460.417 [NAL9602](INFO): MT Sig Qty requested
2015-01-29T01:04:21.204Z,1422493461.204 [DataOverHttps](INFO): Moved sent file to Logs/20150128T183411/Courier0024.lzma.bak
2015-01-29T01:04:21.204Z,1422493461.204 [DataOverHttps](INFO): SBD MOMSN=1510547
2015-01-29T01:04:30.277Z,1422493470.277 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150129T010156/Courier0000.lzma
2015-01-29T01:04:31.074Z,1422493471.074 [DataOverHttps](INFO): Moved sent file to Logs/20150129T010156/Courier0000.lzma.bak
2015-01-29T01:04:31.074Z,1422493471.074 [DataOverHttps](INFO): SBD MOMSN=1510549
2015-01-29T01:04:48.628Z,1422493488.628 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20150128T183411/Express0025.lzma
2015-01-29T01:04:50.378Z,1422493490.378 [DataOverHttps](INFO): Moved sent file to Logs/20150128T183411/Express0025.lzma.bak
2015-01-29T01:04:50.378Z,1422493490.378 [DataOverHttps](INFO): SBD MOMSN=1510553
2015-01-29T01:04:50.413Z,1422493490.413 [BPC1](FAULT): Failed to receive battery data
2015-01-29T01:04:50.413Z,1422493490.413 [BPC1] Communications Fault, FailCount= 1
2015-01-29T01:04:50.413Z,1422493490.413 [BPC1](ERROR): Communications Fault
2015-01-29T01:04:50.429Z,1422493490.429 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-29T01:04:50.904Z,1422493490.904 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2015-01-29T01:04:51.422Z,1422493491.422 [NAL9602](FAULT): received: 
2015-01-29T01:04:51.422Z,1422493491.422 [NAL9602] Data Fault, FailCount= 2
2015-01-29T01:04:51.422Z,1422493491.422 [NAL9602](ERROR): Data Fault
2015-01-29T01:04:51.479Z,1422493491.479 [CBIT](ERROR): Data Fault in component: NAL9602
2015-01-29T01:04:51.545Z,1422493491.545 [NAL9602](INFO): Stop
2015-01-29T01:04:51.545Z,1422493491.545 [NAL9602](INFO): Uninitialize
2015-01-29T01:04:51.545Z,1422493491.545 [NAL9602](INFO): Powering down
2015-01-29T01:04:54.777Z,1422493494.777 [NAL9602](INFO): Stopping
2015-01-29T01:04:54.805Z,1422493494.805 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-29T01:04:54.805Z,1422493494.805 [BPC1] No Fault, FailCount= 1
2015-01-29T01:04:55.024Z,1422493495.024 [CBIT](INFO): Clearing failed state for component NAL9602
2015-01-29T01:04:55.024Z,1422493495.024 [NAL9602] No Fault, FailCount= 2
2015-01-29T01:04:55.305Z,1422493495.305 [NAL9602](INFO): Start
2015-01-29T01:04:55.719Z,1422493495.719 [NAL9602](INFO): Start
2015-01-29T01:04:56.123Z,1422493496.123 [NAL9602](INFO): Start
2015-01-29T01:04:56.524Z,1422493496.524 [NAL9602](INFO): Start
2015-01-29T01:04:59.701Z,1422493499.701 [NAL9602](INFO): Start
2015-01-29T01:04:59.702Z,1422493499.702 [NAL9602](INFO): Powering up NAL9602
2015-01-29T01:04:59.817Z,1422493499.817 [DataOverHttps](INFO): Sending 610 bytes from file Logs/20150129T010156/Express0001.lzma
2015-01-29T01:05:00.609Z,1422493500.609 [DataOverHttps](INFO): Moved sent file to Logs/20150129T010156/Express0001.lzma.bak
2015-01-29T01:05:00.609Z,1422493500.609 [DataOverHttps](INFO): SBD MOMSN=1510556
2015-01-29T01:05:01.441Z,1422493501.441 [Startup:StartupSatComms:B] Stopped
2015-01-29T01:05:01.441Z,1422493501.441 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2015-01-29T01:05:01.442Z,1422493501.442 [Startup:StartupSatComms] Stopped
2015-01-29T01:05:01.442Z,1422493501.442 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-01-29T01:05:01.442Z,1422493501.442 [Startup](INFO): Completed Startup
2015-01-29T01:05:01.443Z,1422493501.443 [Startup] Stopped
2015-01-29T01:05:01.443Z,1422493501.443 [Startup](INFO): Aggregate::uninitialize Startup
2015-01-29T01:05:01.443Z,1422493501.443 [Startup:A.GoToSurface] Stopped
2015-01-29T01:05:01.443Z,1422493501.443 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-29T01:05:01.544Z,1422493501.544 [MissionManager](IMPORTANT): Started mission Default
2015-01-29T01:05:01.544Z,1422493501.544 [Default] Running Loop=1
2015-01-29T01:05:01.544Z,1422493501.544 [Default](INFO): Aggregate::initialize Default
2015-01-29T01:05:01.544Z,1422493501.544 [Default:B.GoToSurface] Running Loop=1
2015-01-29T01:05:01.544Z,1422493501.544 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-29T01:05:01.544Z,1422493501.544 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-29T01:05:01.545Z,1422493501.545 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-29T01:05:01.545Z,1422493501.545 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-29T01:05:01.545Z,1422493501.545 [Default:StartClock] Running Loop=1
2015-01-29T01:05:01.545Z,1422493501.545 [Default:StartClock](INFO): Aggregate::initialize Default:StartClock
2015-01-29T01:05:01.546Z,1422493501.546 [Default:StartClock:A] Running Loop=1
2015-01-29T01:05:01.553Z,1422493501.553 [Default:StartClock:A] Stopped
2015-01-29T01:05:01.554Z,1422493501.554 [Default:StartClock](INFO): Completed Default:StartClock
2015-01-29T01:05:01.554Z,1422493501.554 [Default:StartClock] Stopped
2015-01-29T01:05:01.554Z,1422493501.554 [Default:StartClock](INFO): Aggregate::uninitialize Default:StartClock
2015-01-29T01:05:04.760Z,1422493504.760 [Default:WaitAtTheSurface] Running Loop=1
2015-01-29T01:05:04.761Z,1422493504.761 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2015-01-29T01:05:04.761Z,1422493504.761 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-29T01:05:04.761Z,1422493504.761 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2015-01-29T01:05:04.909Z,1422493504.909 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-29T01:05:09.962Z,1422493509.962 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-29T01:05:09.962Z,1422493509.962 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-01-29T01:05:09.962Z,1422493509.962 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-29T01:05:09.990Z,1422493509.990 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-29T01:05:14.944Z,1422493514.944 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-29T01:05:14.944Z,1422493514.944 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-01-29T01:05:19.880Z,1422493519.880 [NAL9602](INFO): ************** CMDMODE **************

2015-01-29T01:05:19.880Z,1422493519.880 [NAL9602](INFO): NAL9602 initialized
2015-01-29T01:05:19.942Z,1422493519.942 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-29T01:05:24.901Z,1422493524.901 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:05:29.884Z,1422493529.884 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:05:29.976Z,1422493529.976 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:05:34.888Z,1422493534.888 [NAL9602](INFO): ************** GetFix **************

2015-01-29T01:05:34.974Z,1422493534.974 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:05:39.938Z,1422493539.938 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:05:44.905Z,1422493544.905 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:05:49.963Z,1422493549.963 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:06:17.696Z,1422493577.696 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:06:19.885Z,1422493579.885 [NAL9602](INFO): MT Sig Qty requested
2015-01-29T01:06:49.886Z,1422493609.886 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2015-01-29T01:06:50.403Z,1422493610.403 [NAL9602](FAULT): received: 
2015-01-29T01:06:50.403Z,1422493610.403 [NAL9602] Data Fault, FailCount= 3
2015-01-29T01:06:50.403Z,1422493610.403 [NAL9602](ERROR): Data Fault
2015-01-29T01:06:50.490Z,1422493610.490 [CBIT](ERROR): Data Fault in component: NAL9602
2015-01-29T01:06:54.885Z,1422493614.885 [NAL9602](INFO): Stop
2015-01-29T01:06:54.885Z,1422493614.885 [NAL9602](INFO): Uninitialize
2015-01-29T01:06:54.885Z,1422493614.885 [NAL9602](INFO): Powering down
2015-01-29T01:06:59.885Z,1422493619.885 [NAL9602](INFO): Stopping
2015-01-29T01:07:04.912Z,1422493624.912 [CBIT](INFO): Clearing failed state for component NAL9602
2015-01-29T01:07:04.912Z,1422493624.912 [NAL9602] No Fault, FailCount= 3
2015-01-29T01:07:09.886Z,1422493629.886 [NAL9602](INFO): Start
2015-01-29T01:07:09.886Z,1422493629.886 [NAL9602](INFO): Powering up NAL9602
2015-01-29T01:07:09.988Z,1422493629.988 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-29T01:07:09.988Z,1422493629.988 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:07:09.988Z,1422493629.988 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-29T01:07:09.990Z,1422493629.990 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-29T01:07:09.990Z,1422493629.990 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-29T01:07:17.695Z,1422493637.695 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 2.139138 min 
2015-01-29T01:07:17.697Z,1422493637.697 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-29T01:07:17.697Z,1422493637.697 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:07:17.697Z,1422493637.697 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-29T01:07:17.697Z,1422493637.697 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:07:29.887Z,1422493649.887 [NAL9602](INFO): ************** CMDMODE **************

2015-01-29T01:07:29.888Z,1422493649.888 [NAL9602](INFO): NAL9602 initialized
2015-01-29T01:07:39.894Z,1422493659.894 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:07:44.889Z,1422493664.889 [NAL9602](INFO): ************** GetFix **************

2015-01-29T01:08:22.672Z,1422493702.672 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:08:22.700Z,1422493702.700 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-29T01:08:22.700Z,1422493702.700 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2015-01-29T01:08:22.700Z,1422493702.700 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-29T01:08:22.711Z,1422493702.711 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-29T01:08:24.889Z,1422493704.889 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2015-01-29T01:08:24.918Z,1422493704.918 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-29T01:08:24.918Z,1422493704.918 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2015-01-29T01:08:29.967Z,1422493709.967 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-29T01:08:34.889Z,1422493714.889 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:08:34.920Z,1422493714.920 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:08:39.938Z,1422493719.938 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:08:44.908Z,1422493724.908 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:08:49.934Z,1422493729.934 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:08:50.353Z,1422493730.353 [CommandLine](IMPORTANT): got command get latitude
2015-01-29T01:08:50.353Z,1422493730.353 [CommandLine](FAULT): Element has no value
2015-01-29T01:08:54.940Z,1422493734.940 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:08:59.908Z,1422493739.908 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:09:10.393Z,1422493750.393 [NAL9602](ERROR): getFix uart error: serial timeout
2015-01-29T01:09:49.886Z,1422493789.886 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:09:49.918Z,1422493789.918 [BPC1](DEBUG): Received data from all battery sticks
2015-01-29T01:09:54.903Z,1422493794.903 [BPC1](FAULT): Failed to receive battery data
2015-01-29T01:09:54.903Z,1422493794.903 [BPC1] Communications Fault, FailCount= 1
2015-01-29T01:09:54.903Z,1422493794.903 [BPC1](ERROR): Communications Fault
2015-01-29T01:09:54.919Z,1422493794.919 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-29T01:09:59.875Z,1422493799.875 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:10:04.907Z,1422493804.907 [Default:CheckIn] Running Loop=1
2015-01-29T01:10:04.908Z,1422493804.908 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2015-01-29T01:10:04.908Z,1422493804.908 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-29T01:10:04.908Z,1422493804.908 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2015-01-29T01:10:04.908Z,1422493804.908 [Default:CheckIn:Read_GPS] Running Loop=1
2015-01-29T01:10:04.909Z,1422493804.909 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-29T01:10:04.911Z,1422493804.911 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-29T01:10:05.322Z,1422493805.322 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-29T01:10:05.322Z,1422493805.322 [BPC1] No Fault, FailCount= 1
2015-01-29T01:10:30.694Z,1422493830.694 [NAL9602](ERROR): getFix uart error: serial timeout
2015-01-29T01:11:01.256Z,1422493861.256 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:11:02.057Z,1422493862.057 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:11:30.264Z,1422493890.264 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-29T01:11:30.264Z,1422493890.264 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2015-01-29T01:11:30.264Z,1422493890.264 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-29T01:11:30.275Z,1422493890.275 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-29T01:11:30.638Z,1422493890.638 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-29T01:11:30.638Z,1422493890.638 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2015-01-29T01:11:31.061Z,1422493891.061 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-29T01:11:31.459Z,1422493891.459 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:11:31.825Z,1422493891.825 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:11:32.710Z,1422493892.710 [NAL9602](ERROR): getFix uart error: serial timeout
2015-01-29T01:11:32.759Z,1422493892.759 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:11:32.889Z,1422493892.889 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:11:33.276Z,1422493893.276 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:11:33.675Z,1422493893.675 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-29T01:12:03.256Z,1422493923.256 [NAL9602](ERROR): parseGSV uart error: serial timeout
2015-01-29T01:12:04.057Z,1422493924.057 [NAL9602](INFO): ************** Request Fix **************

2015-01-29T01:12:10.076Z,1422493930.076 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-29T01:12:10.076Z,1422493930.076 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:12:10.076Z,1422493930.076 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-29T01:12:10.077Z,1422493930.077 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-29T01:12:10.077Z,1422493930.077 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-29T01:12:10.476Z,1422493930.476 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 7.142054 min 
2015-01-29T01:12:10.477Z,1422493930.477 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-29T01:12:10.477Z,1422493930.477 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:12:10.477Z,1422493930.477 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-29T01:12:10.477Z,1422493930.477 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-29T01:12:28.611Z,1422493948.611 [NAL9602](FAULT): GPS failed to acquire within timeout.
2015-01-29T01:12:28.611Z,1422493948.611 [NAL9602] Data Fault, FailCount= 4
2015-01-29T01:12:28.611Z,1422493948.611 [NAL9602](ERROR): Data Fault
2015-01-29T01:12:28.642Z,1422493948.642 [CBIT](ERROR): Data Fault in component: NAL9602
2015-01-29T01:12:29.008Z,1422493949.008 [NAL9602](INFO): Stop
2015-01-29T01:12:29.008Z,1422493949.008 [NAL9602](INFO): Uninitialize
2015-01-29T01:12:29.008Z,1422493949.008 [NAL9602](INFO): Powering down
2015-01-29T01:12:29.408Z,1422493949.408 [NAL9602](INFO): Stopping
2015-01-29T01:12:29.836Z,1422493949.836 [CBIT](INFO): Clearing failed state for component NAL9602
2015-01-29T01:12:29.836Z,1422493949.836 [NAL9602] No Fault, FailCount= 4
2015-01-29T01:12:30.191Z,1422493950.191 [NAL9602](INFO): Start
2015-01-29T01:12:30.606Z,1422493950.606 [NAL9602](INFO): Start
2015-01-29T01:12:31.006Z,1422493951.006 [NAL9602](INFO): Start
2015-01-29T01:12:31.407Z,1422493951.407 [NAL9602](INFO): Start
2015-01-29T01:12:31.809Z,1422493951.809 [NAL9602](INFO): Start
2015-01-29T01:12:32.208Z,1422493952.208 [NAL9602](INFO): Start
2015-01-29T01:12:32.613Z,1422493952.613 [NAL9602](INFO): Start
2015-01-29T01:12:33.010Z,1422493953.010 [NAL9602](INFO): Start
2015-01-29T01:12:33.402Z,1422493953.402 [NAL9602](INFO): Start
2015-01-29T01:12:33.811Z,1422493953.811 [NAL9602](INFO): Start
2015-01-29T01:12:34.207Z,1422493954.207 [NAL9602](INFO): Start
2015-01-29T01:12:34.