2015-01-28T17:53:42.990Z,1422467622.990 [Supervisor](DEBUG): Initializing supervisor.
2015-01-28T17:53:42.993Z,1422467622.993 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0
2015-01-28T17:53:42.993Z,1422467622.993 [SyncHandler](INFO): Protected caller Thread ID is 780
2015-01-28T17:53:42.994Z,1422467622.994 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2015-01-28T17:53:42.995Z,1422467622.995 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0
2015-01-28T17:53:42.995Z,1422467622.995 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 781
2015-01-28T17:53:43.011Z,1422467623.011 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2015-01-28T17:53:43.024Z,1422467623.024 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2015-01-28T17:53:43.025Z,1422467623.025 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0
2015-01-28T17:53:43.025Z,1422467623.025 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 782
2015-01-28T17:53:43.026Z,1422467623.026 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2015-01-28T17:53:43.027Z,1422467623.027 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0
2015-01-28T17:53:43.027Z,1422467623.027 [logger ThreadHandler](INFO): Protected caller Thread ID is 783
2015-01-28T17:53:43.029Z,1422467623.029 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2015-01-28T17:53:43.030Z,1422467623.030 [Supervisor](INFO): Looking for Config files in directory: Config/
2015-01-28T17:53:43.033Z,1422467623.033 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2015-01-28T17:53:43.371Z,1422467623.371 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2015-01-28T17:53:43.374Z,1422467623.374 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2015-01-28T17:53:43.535Z,1422467623.535 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2015-01-28T17:53:43.536Z,1422467623.536 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2015-01-28T17:53:43.647Z,1422467623.647 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2015-01-28T17:53:43.648Z,1422467623.648 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2015-01-28T17:53:43.773Z,1422467623.773 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2015-01-28T17:53:43.774Z,1422467623.774 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2015-01-28T17:53:43.862Z,1422467623.862 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2015-01-28T17:53:44.027Z,1422467624.027 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2015-01-28T17:53:44.028Z,1422467624.028 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2015-01-28T17:53:44.116Z,1422467624.116 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2015-01-28T17:53:44.117Z,1422467624.117 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2015-01-28T17:53:44.330Z,1422467624.330 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2015-01-28T17:53:44.330Z,1422467624.330 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2015-01-28T17:53:44.707Z,1422467624.707 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2015-01-28T17:53:44.708Z,1422467624.708 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2015-01-28T17:53:45.031Z,1422467625.031 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2015-01-28T17:53:45.031Z,1422467625.031 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2015-01-28T17:53:45.531Z,1422467625.531 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2015-01-28T17:53:45.532Z,1422467625.532 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2015-01-28T17:53:45.737Z,1422467625.737 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2015-01-28T17:53:45.737Z,1422467625.737 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2015-01-28T17:53:45.845Z,1422467625.845 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2015-01-28T17:53:45.846Z,1422467625.846 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2015-01-28T17:53:46.442Z,1422467626.442 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2015-01-28T17:53:46.443Z,1422467626.443 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2015-01-28T17:53:46.556Z,1422467626.556 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2015-01-28T17:53:46.558Z,1422467626.558 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2015-01-28T17:53:46.563Z,1422467626.563 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2015-01-28T17:53:46.808Z,1422467626.808 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2015-01-28T17:53:58.251Z,1422467638.251 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2015-01-28T17:53:58.546Z,1422467638.546 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Estimation.cfg
2015-01-28T17:53:59.565Z,1422467639.565 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2015-01-28T17:53:59.667Z,1422467639.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2015-01-28T17:53:59.785Z,1422467639.785 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2015-01-28T17:53:59.929Z,1422467639.929 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2015-01-28T17:54:00.104Z,1422467640.104 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2015-01-28T17:54:00.210Z,1422467640.210 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2015-01-28T17:54:00.303Z,1422467640.303 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2015-01-28T17:54:00.407Z,1422467640.407 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2015-01-28T17:54:00.506Z,1422467640.506 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2015-01-28T17:54:00.691Z,1422467640.691 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2015-01-28T17:54:00.713Z,1422467640.713 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2015-01-28T17:54:00.787Z,1422467640.787 [VerticalControl](DEBUG): Construct VerticalControl.
2015-01-28T17:54:00.906Z,1422467640.906 [VerticalControl] Loaded
2015-01-28T17:54:00.906Z,1422467640.906 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2015-01-28T17:54:00.907Z,1422467640.907 [HorizontalControl](DEBUG): Construct HorizontalControl.
2015-01-28T17:54:00.978Z,1422467640.978 [HorizontalControl] Loaded
2015-01-28T17:54:00.979Z,1422467640.979 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2015-01-28T17:54:00.979Z,1422467640.979 [SpeedControl](DEBUG): Construct SpeedControl.
2015-01-28T17:54:00.985Z,1422467640.985 [SpeedControl] Loaded
2015-01-28T17:54:00.985Z,1422467640.985 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2015-01-28T17:54:00.986Z,1422467640.986 [LoopControl](DEBUG): Construct LoopControl.
2015-01-28T17:54:00.987Z,1422467640.987 [LoopControl] Loaded
2015-01-28T17:54:00.987Z,1422467640.987 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2015-01-28T17:54:00.987Z,1422467640.987 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2015-01-28T17:54:00.988Z,1422467640.988 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2015-01-28T17:54:01.111Z,1422467641.111 [SBIT](DEBUG): Construct Startup Built In Test.
2015-01-28T17:54:01.122Z,1422467641.122 [SBIT] Loaded
2015-01-28T17:54:01.123Z,1422467641.123 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2015-01-28T17:54:01.123Z,1422467641.123 [IBIT](DEBUG): Construct Initiated Built In Test.
2015-01-28T17:54:01.152Z,1422467641.152 [IBIT] Loaded
2015-01-28T17:54:01.153Z,1422467641.153 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2015-01-28T17:54:01.155Z,1422467641.155 [CBIT](DEBUG): Construct CBIT Built In Test.
2015-01-28T17:54:01.274Z,1422467641.274 [CBIT] Loaded
2015-01-28T17:54:01.274Z,1422467641.274 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2015-01-28T17:54:01.275Z,1422467641.275 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2015-01-28T17:54:01.275Z,1422467641.275 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2015-01-28T17:54:01.305Z,1422467641.305 [DepthRateCalculator] Loaded
2015-01-28T17:54:01.305Z,1422467641.305 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2015-01-28T17:54:01.311Z,1422467641.311 [PitchRateCalculator] Loaded
2015-01-28T17:54:01.311Z,1422467641.311 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2015-01-28T17:54:01.323Z,1422467641.323 [SpeedCalculator] Loaded
2015-01-28T17:54:01.323Z,1422467641.323 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2015-01-28T17:54:01.340Z,1422467641.340 [TempGradientCalculator] Loaded
2015-01-28T17:54:01.340Z,1422467641.340 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2015-01-28T17:54:01.346Z,1422467641.346 [YawRateCalculator] Loaded
2015-01-28T17:54:01.346Z,1422467641.346 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2015-01-28T17:54:01.346Z,1422467641.346 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2015-01-28T17:54:01.347Z,1422467641.347 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2015-01-28T17:54:01.438Z,1422467641.438 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2015-01-28T17:54:01.441Z,1422467641.441 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2015-01-28T17:54:01.714Z,1422467641.714 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2015-01-28T17:54:01.715Z,1422467641.715 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2015-01-28T17:54:01.823Z,1422467641.823 [DeadReckonUsingMultipleVelocitySources] Loaded
2015-01-28T17:54:01.824Z,1422467641.824 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2015-01-28T17:54:01.841Z,1422467641.841 [NavChart] Loaded
2015-01-28T17:54:01.841Z,1422467641.841 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2015-01-28T17:54:01.846Z,1422467641.846 [UniversalFixResidualReporter] Loaded
2015-01-28T17:54:01.846Z,1422467641.846 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2015-01-28T17:54:01.846Z,1422467641.846 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2015-01-28T17:54:01.847Z,1422467641.847 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2015-01-28T17:54:01.856Z,1422467641.856 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2015-01-28T17:54:01.857Z,1422467641.857 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2015-01-28T17:54:01.973Z,1422467641.973 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2015-01-28T17:54:01.974Z,1422467641.974 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2015-01-28T17:54:02.613Z,1422467642.613 [DataOverHttps] Loaded
2015-01-28T17:54:02.614Z,1422467642.614 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2015-01-28T17:54:02.694Z,1422467642.694 [Depth_Keller] Loaded
2015-01-28T17:54:02.694Z,1422467642.694 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2015-01-28T17:54:02.788Z,1422467642.788 [NAL9602] Loaded
2015-01-28T17:54:02.788Z,1422467642.788 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2015-01-28T17:54:02.831Z,1422467642.831 [Onboard] Loaded
2015-01-28T17:54:02.831Z,1422467642.831 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2015-01-28T17:54:02.838Z,1422467642.838 [Radio_Surface] Loaded
2015-01-28T17:54:02.839Z,1422467642.839 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2015-01-28T17:54:02.840Z,1422467642.840 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2015-01-28T17:54:02.840Z,1422467642.840 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 867
2015-01-28T17:54:02.950Z,1422467642.950 [PNI_TCM] Loaded
2015-01-28T17:54:02.950Z,1422467642.950 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2015-01-28T17:54:04.776Z,1422467644.776 [BPC1] Loaded
2015-01-28T17:54:04.776Z,1422467644.776 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2015-01-28T17:54:04.776Z,1422467644.776 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2015-01-28T17:54:04.777Z,1422467644.777 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2015-01-28T17:54:13.057Z,1422467653.057 [BuoyancyServo] Loaded
2015-01-28T17:54:13.057Z,1422467653.057 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2015-01-28T17:54:13.070Z,1422467653.070 [ElevatorServo] Loaded
2015-01-28T17:54:13.071Z,1422467653.071 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2015-01-28T17:54:13.083Z,1422467653.083 [RudderServo] Loaded
2015-01-28T17:54:13.083Z,1422467653.083 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2015-01-28T17:54:13.094Z,1422467653.094 [ThrusterServo] Loaded
2015-01-28T17:54:13.095Z,1422467653.095 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2015-01-28T17:54:13.095Z,1422467653.095 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2015-01-28T17:54:13.096Z,1422467653.096 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2015-01-28T17:54:13.367Z,1422467653.367 [ExternalSim] Loaded
2015-01-28T17:54:13.368Z,1422467653.368 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread.
2015-01-28T17:54:13.368Z,1422467653.368 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2015-01-28T17:54:13.369Z,1422467653.369 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2015-01-28T17:54:13.411Z,1422467653.411 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2015-01-28T17:54:13.413Z,1422467653.413 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2015-01-28T17:54:13.414Z,1422467653.414 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2015-01-28T17:54:13.420Z,1422467653.420 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2015-01-28T17:54:13.421Z,1422467653.421 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4083C4E0
2015-01-28T17:54:13.422Z,1422467653.422 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 868
2015-01-28T17:54:13.426Z,1422467653.426 [Supervisor](INFO): Main Thread ID is 778
2015-01-28T17:54:13.426Z,1422467653.426 [Supervisor](DEBUG): Running supervisor.
2015-01-28T17:54:13.427Z,1422467653.427 [CommandLine ThreadHandler](INFO): Handler Thread ID is 869
2015-01-28T17:54:13.431Z,1422467653.431 [controlThread ThreadHandler](INFO): Handler Thread ID is 870
2015-01-28T17:54:13.432Z,1422467653.432 [controlThread](DEBUG): Initializing ControlThread
2015-01-28T17:54:13.433Z,1422467653.433 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2015-01-28T17:54:13.434Z,1422467653.434 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2015-01-28T17:54:13.435Z,1422467653.435 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2015-01-28T17:54:13.435Z,1422467653.435 [LoopControl](DEBUG): Initialize LoopControlComponent.
2015-01-28T17:54:13.436Z,1422467653.436 [SBIT](INFO): Initialize SBIT Component.
2015-01-28T17:54:13.436Z,1422467653.436 [SBIT](IMPORTANT): Tethys CM Info: SVN revision:11963
2015-01-28T17:54:13.437Z,1422467653.437 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2015-01-28T17:54:13.437Z,1422467653.437 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
2015-01-28T17:54:13.437Z,1422467653.437 [IBIT](INFO): Initialize IBIT Component.
2015-01-28T17:54:13.438Z,1422467653.438 [CBIT](DEBUG): Initialize CBIT Component.
2015-01-28T17:54:13.439Z,1422467653.439 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2015-01-28T17:54:13.440Z,1422467653.440 [logger ThreadHandler](INFO): Handler Thread ID is 871
2015-01-28T17:54:13.464Z,1422467653.464 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2015-01-28T17:54:13.464Z,1422467653.464 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2015-01-28T17:54:13.464Z,1422467653.464 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2015-01-28T17:54:13.465Z,1422467653.465 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2015-01-28T17:54:13.465Z,1422467653.465 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2015-01-28T17:54:13.466Z,1422467653.466 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T17:54:13.466Z,1422467653.466 [NavChart](DEBUG): Initialize NavChart Navigation.
2015-01-28T17:54:13.466Z,1422467653.466 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2015-01-28T17:54:13.470Z,1422467653.470 [ExternalSim](INFO): ExternalSim initializing...
2015-01-28T17:54:13.476Z,1422467653.476 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 872
2015-01-28T17:54:13.483Z,1422467653.483 [Radio_Surface](INFO): Powering up
2015-01-28T17:54:13.501Z,1422467653.501 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 873
2015-01-28T17:54:13.514Z,1422467653.514 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2015-01-28T17:54:13.517Z,1422467653.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2015-01-28T17:54:13.517Z,1422467653.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2015-01-28T17:54:13.517Z,1422467653.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2015-01-28T17:54:13.517Z,1422467653.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2015-01-28T17:54:13.518Z,1422467653.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2015-01-28T17:54:13.518Z,1422467653.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2015-01-28T17:54:13.518Z,1422467653.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2015-01-28T17:54:13.518Z,1422467653.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2015-01-28T17:54:13.708Z,1422467653.708 [ExternalSim](DEBUG): beaconLat = 36.80340
2015-01-28T17:54:13.709Z,1422467653.709 [ExternalSim](DEBUG): beaconLon = -121.82230
2015-01-28T17:54:13.709Z,1422467653.709 [ExternalSim](DEBUG): beaconDepth = 25.00
2015-01-28T17:54:13.982Z,1422467653.982 [ExternalSim](DEBUG): Simulator initialized
2015-01-28T17:54:14.090Z,1422467654.090 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2015-01-28T17:54:14.131Z,1422467654.131 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-28T17:54:14.155Z,1422467654.155 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2015-01-28T17:54:14.156Z,1422467654.156 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2015-01-28T17:54:14.250Z,1422467654.250 [MissionManager](INFO): DefineArg Default.TimeMissionWasStarted = 0.000000 h
2015-01-28T17:54:14.266Z,1422467654.266 [MissionManager](INFO): DefineArg Default.ElapsedSinceMissionWasStarted = 0.000000 h
2015-01-28T17:54:14.270Z,1422467654.270 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2015-01-28T17:54:14.291Z,1422467654.291 [Default:CheckIn:A.SetSpeed](DEBUG): Construct.
2015-01-28T17:54:14.330Z,1422467654.330 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2015-01-28T17:54:14.355Z,1422467654.355 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Construct.
2015-01-28T17:54:14.361Z,1422467654.361 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

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

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

    <Aggregate Id="StartClock">

        <Sequence/>

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

    </Aggregate>

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

    <Aggregate Id="CheckIn">

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

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

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

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

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

<!-- Do data comms -->

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

    </Aggregate>

    <Aggregate Id="UpdateAndReportMinutesSinceMissionStarted">

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

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

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

    </Aggregate>

    <Aggregate Id="WaitAtTheSurface">

        <Sequence/>

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

    </Aggregate>

</Mission>


2015-01-28T17:54:14.381Z,1422467654.381 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,DataOverHttps,Depth_Keller,NAL9602,Onboard,PNI_TCM,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2015-01-28T17:54:14.601Z,1422467654.601 [NAL9602](INFO): Start
2015-01-28T17:54:14.602Z,1422467654.602 [NAL9602](INFO): Powering up NAL9602
2015-01-28T17:54:14.883Z,1422467654.883 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:14.994Z,1422467654.994 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:54:15.002Z,1422467655.002 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-28T17:54:15.021Z,1422467655.021 [ElevatorServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:54:15.026Z,1422467655.026 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2015-01-28T17:54:15.044Z,1422467655.044 [RudderServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:54:15.050Z,1422467655.050 [RudderServo](DEBUG): Initializing RudderServo.
2015-01-28T17:54:15.076Z,1422467655.076 [ThrusterServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:54:15.082Z,1422467655.082 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2015-01-28T17:54:15.667Z,1422467655.667 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:16.024Z,1422467656.024 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2015-01-28T17:54:16.024Z,1422467656.024 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2015-01-28T17:54:16.024Z,1422467656.024 [BuoyancyServo] Communications Fault, FailCount= 1
2015-01-28T17:54:16.024Z,1422467656.024 [BuoyancyServo](ERROR): Communications Fault
2015-01-28T17:54:16.230Z,1422467656.230 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2015-01-28T17:54:24.636Z,1422467664.636 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:24.642Z,1422467664.642 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2015-01-28T17:54:24.644Z,1422467664.644 [BuoyancyServo](INFO): Powering down
2015-01-28T17:54:24.836Z,1422467664.836 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:25.243Z,1422467665.243 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:25.592Z,1422467665.592 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003606
2015-01-28T17:54:25.600Z,1422467665.600 [NAL9602](INFO): ************** CMDMODE **************

2015-01-28T17:54:25.600Z,1422467665.600 [NAL9602](INFO): NAL9602 initialized
2015-01-28T17:54:25.643Z,1422467665.643 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:54:26.478Z,1422467666.478 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T17:54:26.819Z,1422467666.819 [NAL9602](INFO): ************** GetFix **************

2015-01-28T17:54:27.012Z,1422467667.012 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2015-01-28T17:54:27.012Z,1422467667.012 [BuoyancyServo] No Fault, FailCount= 1
2015-01-28T17:54:27.325Z,1422467667.325 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2015-01-28T17:54:27.446Z,1422467667.446 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2015-01-28T17:54:27.709Z,1422467667.709 [CommandLine](IMPORTANT): got command report mod NAL9602.sigQuality
2015-01-28T17:54:27.745Z,1422467667.745 [Reporter](INFO): NAL9602.sigQuality no_value
2015-01-28T17:54:28.953Z,1422467668.953 [SBIT](IMPORTANT): Beginning Startup BIT
2015-01-28T17:54:28.956Z,1422467668.956 [CBIT](IMPORTANT): Beginning GF scan
2015-01-28T17:54:29.218Z,1422467669.218 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:31.024Z,1422467671.024 [Reporter](INFO): NAL9602.sigQuality 0 count
2015-01-28T17:54:31.217Z,1422467671.217 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:35.824Z,1422467675.824 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:41.970Z,1422467681.970 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:54:44.225Z,1422467684.225 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:48.648Z,1422467688.648 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:52.795Z,1422467692.795 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:53.584Z,1422467693.584 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:55.749Z,1422467695.749 [CBIT](IMPORTANT): No ground fault detected
2015-01-28T17:54:57.594Z,1422467697.594 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:54:58.383Z,1422467698.383 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:02.405Z,1422467702.405 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:03.183Z,1422467703.183 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:07.674Z,1422467707.674 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:08.511Z,1422467708.511 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:08.652Z,1422467708.652 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:55:08.652Z,1422467708.652 [SBIT](FAULT): Control surface position failure.
2015-01-28T17:55:12.942Z,1422467712.942 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:13.759Z,1422467713.759 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:20.818Z,1422467720.818 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:21.627Z,1422467721.627 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:22.072Z,1422467722.072 [SBIT](ERROR): Could not read massPosReader_.
2015-01-28T17:55:22.072Z,1422467722.072 [SBIT](FAULT): Control surface position failure.
2015-01-28T17:55:22.503Z,1422467722.503 [SBIT](CRITICAL): SBIT FAILED
2015-01-28T17:55:22.504Z,1422467722.504 [CommandLine](FAULT): Scheduling is paused
2015-01-28T17:55:22.842Z,1422467722.842 [MissionManager](IMPORTANT): Started mission Startup
2015-01-28T17:55:22.843Z,1422467722.843 [Startup] Running Loop=1
2015-01-28T17:55:22.843Z,1422467722.843 [Startup](INFO): Aggregate::initialize Startup
2015-01-28T17:55:22.843Z,1422467722.843 [Startup:A.GoToSurface] Running Loop=1
2015-01-28T17:55:22.843Z,1422467722.843 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-28T17:55:22.844Z,1422467722.844 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-28T17:55:22.844Z,1422467722.844 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-28T17:55:22.844Z,1422467722.844 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-28T17:55:22.850Z,1422467722.850 [Startup:StartupSatComms] Running Loop=1
2015-01-28T17:55:22.850Z,1422467722.850 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2015-01-28T17:55:22.851Z,1422467722.851 [Startup:StartupSatComms:A] Running Loop=1
2015-01-28T17:55:23.311Z,1422467723.311 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-28T17:55:26.006Z,1422467726.006 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:26.839Z,1422467726.839 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:31.214Z,1422467731.214 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:32.028Z,1422467732.028 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:36.414Z,1422467736.414 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:37.228Z,1422467737.228 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:41.634Z,1422467741.634 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:42.443Z,1422467742.443 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:46.818Z,1422467746.818 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:47.628Z,1422467747.628 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:52.043Z,1422467752.043 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:52.815Z,1422467752.815 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:57.223Z,1422467757.223 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:55:58.049Z,1422467758.049 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:02.423Z,1422467762.423 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:03.220Z,1422467763.220 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:07.651Z,1422467767.651 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:08.424Z,1422467768.424 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:12.852Z,1422467772.852 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:13.620Z,1422467773.620 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:18.652Z,1422467778.652 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:19.433Z,1422467779.433 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:23.040Z,1422467783.040 [Startup:StartupSatComms:A](INFO): Timed out from 2015-01-28T17:55:22.9Z
2015-01-28T17:56:23.040Z,1422467783.040 [Startup:StartupSatComms:A] Stopped
2015-01-28T17:56:23.040Z,1422467783.040 [Startup:StartupSatComms:B] Running Loop=1
2015-01-28T17:56:23.467Z,1422467783.467 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-28T17:56:24.395Z,1422467784.395 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:27.817Z,1422467787.817 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:28.029Z,1422467788.029 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20150128T173628/Courier0008.lzma
2015-01-28T17:56:28.739Z,1422467788.739 [DataOverHttps](INFO): Moved sent file to Logs/20150128T173628/Courier0008.lzma.bak
2015-01-28T17:56:28.739Z,1422467788.739 [DataOverHttps](INFO): SBD MOMSN=1510341
2015-01-28T17:56:29.785Z,1422467789.785 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:33.179Z,1422467793.179 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:34.781Z,1422467794.781 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:38.186Z,1422467798.186 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20150128T175342/Courier0000.lzma
2015-01-28T17:56:38.194Z,1422467798.194 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:38.983Z,1422467798.983 [DataOverHttps](INFO): Moved sent file to Logs/20150128T175342/Courier0000.lzma.bak
2015-01-28T17:56:38.984Z,1422467798.984 [DataOverHttps](INFO): SBD MOMSN=1510343
2015-01-28T17:56:40.145Z,1422467800.145 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:43.538Z,1422467803.538 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:45.145Z,1422467805.145 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:48.543Z,1422467808.543 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20150128T173628/Express0009.lzma
2015-01-28T17:56:48.554Z,1422467808.554 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:49.339Z,1422467809.339 [DataOverHttps](INFO): Moved sent file to Logs/20150128T173628/Express0009.lzma.bak
2015-01-28T17:56:49.339Z,1422467809.339 [DataOverHttps](INFO): SBD MOMSN=1510347
2015-01-28T17:56:50.444Z,1422467810.444 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:53.875Z,1422467813.875 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:55.469Z,1422467815.469 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:58.850Z,1422467818.850 [DataOverHttps](INFO): Sending 585 bytes from file Logs/20150128T175342/Express0001.lzma
2015-01-28T17:56:58.862Z,1422467818.862 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:56:59.646Z,1422467819.646 [DataOverHttps](INFO): Moved sent file to Logs/20150128T175342/Express0001.lzma.bak
2015-01-28T17:56:59.646Z,1422467819.646 [DataOverHttps](INFO): SBD MOMSN=1510353
2015-01-28T17:57:00.503Z,1422467820.503 [Startup:StartupSatComms:B] Stopped
2015-01-28T17:57:00.503Z,1422467820.503 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2015-01-28T17:57:00.503Z,1422467820.503 [Startup:StartupSatComms] Stopped
2015-01-28T17:57:00.503Z,1422467820.503 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2015-01-28T17:57:00.504Z,1422467820.504 [Startup](INFO): Completed Startup
2015-01-28T17:57:00.504Z,1422467820.504 [Startup] Stopped
2015-01-28T17:57:00.505Z,1422467820.505 [Startup](INFO): Aggregate::uninitialize Startup
2015-01-28T17:57:00.505Z,1422467820.505 [Startup:A.GoToSurface] Stopped
2015-01-28T17:57:00.505Z,1422467820.505 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2015-01-28T17:57:00.638Z,1422467820.638 [MissionManager](IMPORTANT): Started mission Default
2015-01-28T17:57:00.638Z,1422467820.638 [Default] Running Loop=1
2015-01-28T17:57:00.638Z,1422467820.638 [Default](INFO): Aggregate::initialize Default
2015-01-28T17:57:00.638Z,1422467820.638 [Default:B.GoToSurface] Running Loop=1
2015-01-28T17:57:00.638Z,1422467820.638 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2015-01-28T17:57:00.639Z,1422467820.639 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2015-01-28T17:57:00.639Z,1422467820.639 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2015-01-28T17:57:00.639Z,1422467820.639 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 0.500000 m/s.
2015-01-28T17:57:00.644Z,1422467820.644 [Default:StartClock] Running Loop=1
2015-01-28T17:57:00.644Z,1422467820.644 [Default:StartClock](INFO): Aggregate::initialize Default:StartClock
2015-01-28T17:57:00.644Z,1422467820.644 [Default:StartClock:A] Running Loop=1
2015-01-28T17:57:00.657Z,1422467820.657 [Default:StartClock:A] Stopped
2015-01-28T17:57:00.657Z,1422467820.657 [Default:StartClock](INFO): Completed Default:StartClock
2015-01-28T17:57:00.657Z,1422467820.657 [Default:StartClock] Stopped
2015-01-28T17:57:00.657Z,1422467820.657 [Default:StartClock](INFO): Aggregate::uninitialize Default:StartClock
2015-01-28T17:57:03.834Z,1422467823.834 [Default:WaitAtTheSurface] Running Loop=1
2015-01-28T17:57:03.834Z,1422467823.834 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface
2015-01-28T17:57:03.834Z,1422467823.834 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-28T17:57:03.834Z,1422467823.834 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed](DEBUG): Initialize.
2015-01-28T17:57:03.972Z,1422467823.972 [Default:WaitAtTheSurface:RunApplicationAtLowSpeed.SetSpeed] Running Loop=1
2015-01-28T17:57:13.935Z,1422467833.935 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:57:14.001Z,1422467834.001 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-28T17:57:14.001Z,1422467834.001 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2015-01-28T17:57:14.002Z,1422467834.002 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-28T17:57:14.013Z,1422467834.013 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-28T17:57:18.984Z,1422467838.984 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-28T17:57:18.984Z,1422467838.984 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2015-01-28T17:57:23.942Z,1422467843.942 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:57:24.012Z,1422467844.012 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T17:57:29.011Z,1422467849.011 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:33.953Z,1422467853.953 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:57:34.010Z,1422467854.010 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:39.017Z,1422467859.017 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:43.949Z,1422467863.949 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:57:43.968Z,1422467863.968 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:48.970Z,1422467868.970 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:54.059Z,1422467874.059 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T17:57:58.936Z,1422467878.936 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:08.953Z,1422467888.953 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:18.952Z,1422467898.952 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:28.952Z,1422467908.952 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:38.966Z,1422467918.966 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:48.951Z,1422467928.951 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:58:58.962Z,1422467938.962 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:59:08.969Z,1422467948.969 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:59:16.775Z,1422467956.775 [BPC1](FAULT): Failed to receive battery data
2015-01-28T17:59:16.775Z,1422467956.775 [BPC1] Communications Fault, FailCount= 1
2015-01-28T17:59:16.775Z,1422467956.775 [BPC1](ERROR): Communications Fault
2015-01-28T17:59:16.784Z,1422467956.784 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-28T17:59:16.784Z,1422467956.784 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T17:59:16.784Z,1422467956.784 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-28T17:59:16.786Z,1422467956.786 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-28T17:59:16.786Z,1422467956.786 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-28T17:59:16.828Z,1422467956.828 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-28T17:59:18.940Z,1422467958.940 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:59:18.988Z,1422467958.988 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 2.222188 min 
2015-01-28T17:59:18.989Z,1422467958.989 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-28T17:59:18.990Z,1422467958.990 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T17:59:18.990Z,1422467958.990 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-28T17:59:18.990Z,1422467958.990 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T17:59:28.924Z,1422467968.924 [NAL9602](INFO): MT Sig Qty requested
2015-01-28T17:59:28.993Z,1422467968.993 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T17:59:28.993Z,1422467968.993 [BPC1] No Fault, FailCount= 1
2015-01-28T17:59:33.936Z,1422467973.936 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2015-01-28T17:59:43.939Z,1422467983.939 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T17:59:49.016Z,1422467989.016 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:00:08.942Z,1422468008.942 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:00:13.943Z,1422468013.943 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:00:28.977Z,1422468028.977 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-28T18:00:28.977Z,1422468028.977 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2015-01-28T18:00:28.977Z,1422468028.977 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-28T18:00:29.009Z,1422468029.009 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-28T18:00:33.958Z,1422468033.958 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:00:34.106Z,1422468034.106 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-28T18:00:34.106Z,1422468034.106 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2015-01-28T18:00:38.938Z,1422468038.938 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:00:38.969Z,1422468038.969 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T18:00:44.011Z,1422468044.011 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:00:48.968Z,1422468048.968 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:00:54.007Z,1422468054.007 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:00:58.940Z,1422468058.940 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:00:59.043Z,1422468059.043 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:01:03.945Z,1422468063.945 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:01:04.030Z,1422468064.030 [BPC1](DEBUG): Received data from all battery sticks
2015-01-28T18:01:04.051Z,1422468064.051 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:01:08.973Z,1422468068.973 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:01:23.951Z,1422468083.951 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:01:28.940Z,1422468088.940 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:01:48.942Z,1422468108.942 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:01:53.947Z,1422468113.947 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:04.002Z,1422468124.002 [Default:CheckIn] Running Loop=1
2015-01-28T18:02:04.002Z,1422468124.002 [Default:CheckIn](INFO): Aggregate::initialize Default:CheckIn
2015-01-28T18:02:04.002Z,1422468124.002 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-28T18:02:04.002Z,1422468124.002 [Default:CheckIn:A.SetSpeed](DEBUG): Initialize.
2015-01-28T18:02:04.002Z,1422468124.002 [Default:CheckIn:Read_GPS] Running Loop=1
2015-01-28T18:02:04.003Z,1422468124.003 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2015-01-28T18:02:04.005Z,1422468124.005 [Default:CheckIn:A.SetSpeed] Running Loop=1
2015-01-28T18:02:04.732Z,1422468124.732 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:05.148Z,1422468125.148 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:07.291Z,1422468127.291 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:07.543Z,1422468127.543 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:12.919Z,1422468132.919 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:13.313Z,1422468133.313 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:15.315Z,1422468135.315 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:15.712Z,1422468135.712 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:18.111Z,1422468138.111 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:18.513Z,1422468138.513 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:21.304Z,1422468141.304 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:21.710Z,1422468141.710 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:24.116Z,1422468144.116 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:24.514Z,1422468144.514 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:27.334Z,1422468147.334 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:27.760Z,1422468147.760 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:30.134Z,1422468150.134 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:30.520Z,1422468150.520 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:33.319Z,1422468153.319 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:33.721Z,1422468153.721 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:36.120Z,1422468156.120 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:36.532Z,1422468156.532 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:39.304Z,1422468159.304 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:39.706Z,1422468159.706 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:42.104Z,1422468162.104 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:42.524Z,1422468162.524 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:45.306Z,1422468165.306 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:45.711Z,1422468165.711 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:48.226Z,1422468168.226 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:48.531Z,1422468168.531 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:48.964Z,1422468168.964 [BPC1](FAULT): Failed to receive battery data
2015-01-28T18:02:48.965Z,1422468168.965 [BPC1] Communications Fault, FailCount= 1
2015-01-28T18:02:48.965Z,1422468168.965 [BPC1](ERROR): Communications Fault
2015-01-28T18:02:49.021Z,1422468169.021 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-28T18:02:50.155Z,1422468170.155 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T18:02:50.155Z,1422468170.155 [BPC1] No Fault, FailCount= 1
2015-01-28T18:02:51.306Z,1422468171.306 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:51.712Z,1422468171.712 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:54.111Z,1422468174.111 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:54.512Z,1422468174.512 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:02:57.333Z,1422468177.333 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:02:57.706Z,1422468177.706 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:00.112Z,1422468180.112 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:00.538Z,1422468180.538 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:03.307Z,1422468183.307 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:03.747Z,1422468183.747 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:06.138Z,1422468186.138 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:06.511Z,1422468186.511 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:09.343Z,1422468189.343 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:09.716Z,1422468189.716 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:15.120Z,1422468195.120 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:15.521Z,1422468195.521 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:18.317Z,1422468198.317 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:18.913Z,1422468198.913 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:21.150Z,1422468201.150 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:21.531Z,1422468201.531 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:24.326Z,1422468204.326 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:24.383Z,1422468204.383 [BPC1](ERROR): Failed to parse message.
2015-01-28T18:03:24.383Z,1422468204.383 [BPC1](FAULT): Failed to parse bank B battery data
2015-01-28T18:03:24.383Z,1422468204.383 [BPC1] Data Fault, FailCount= 1
2015-01-28T18:03:24.383Z,1422468204.383 [BPC1](ERROR): Data Fault
2015-01-28T18:03:24.457Z,1422468204.457 [CBIT](ERROR): Data Fault in component: BPC1
2015-01-28T18:03:24.732Z,1422468204.732 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:25.582Z,1422468205.582 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T18:03:25.582Z,1422468205.582 [BPC1] No Fault, FailCount= 1
2015-01-28T18:03:27.110Z,1422468207.110 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:27.536Z,1422468207.536 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:30.339Z,1422468210.339 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:30.732Z,1422468210.732 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:33.140Z,1422468213.140 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:33.521Z,1422468213.521 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:36.337Z,1422468216.337 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:36.743Z,1422468216.743 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:39.117Z,1422468219.117 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:39.154Z,1422468219.154 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-28T18:03:39.154Z,1422468219.154 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2015-01-28T18:03:39.154Z,1422468219.154 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-28T18:03:39.233Z,1422468219.233 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-28T18:03:39.531Z,1422468219.531 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:39.621Z,1422468219.621 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-28T18:03:39.621Z,1422468219.621 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2015-01-28T18:03:39.997Z,1422468219.997 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T18:03:40.378Z,1422468220.378 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:40.776Z,1422468220.776 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:41.195Z,1422468221.195 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:41.556Z,1422468221.556 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:41.952Z,1422468221.952 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:42.330Z,1422468222.330 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:42.401Z,1422468222.401 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:03:42.732Z,1422468222.732 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:45.146Z,1422468225.146 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:45.540Z,1422468225.540 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:48.368Z,1422468228.368 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:48.765Z,1422468228.765 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:51.144Z,1422468231.144 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:51.565Z,1422468231.565 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:54.365Z,1422468234.365 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:54.855Z,1422468234.855 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:03:57.462Z,1422468237.462 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:03:57.995Z,1422468237.995 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:04:01.800Z,1422468241.800 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:04:03.220Z,1422468243.220 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:04:04.747Z,1422468244.747 [CommandLine](IMPORTANT): got command get latitude
2015-01-28T18:04:04.747Z,1422468244.747 [CommandLine](FAULT): Element has no value
2015-01-28T18:04:16.864Z,1422468256.864 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:04:16.960Z,1422468256.960 [Default:UpdateAndReportMinutesSinceMissionStarted] Running Loop=1
2015-01-28T18:04:16.961Z,1422468256.961 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::initialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T18:04:16.961Z,1422468256.961 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Running Loop=1
2015-01-28T18:04:16.961Z,1422468256.961 [Default:UpdateAndReportMinutesSinceMissionStarted:A] Stopped
2015-01-28T18:04:16.961Z,1422468256.961 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Running Loop=1
2015-01-28T18:04:22.902Z,1422468262.902 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:04:22.970Z,1422468262.970 [Default:UpdateAndReportMinutesSinceMissionStarted:B](IMPORTANT): Default mission has been running for 7.185842 min 
2015-01-28T18:04:22.970Z,1422468262.970 [Default:UpdateAndReportMinutesSinceMissionStarted:B] Stopped
2015-01-28T18:04:22.970Z,1422468262.970 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Completed Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T18:04:22.970Z,1422468262.970 [Default:UpdateAndReportMinutesSinceMissionStarted] Stopped
2015-01-28T18:04:22.970Z,1422468262.970 [Default:UpdateAndReportMinutesSinceMissionStarted](INFO): Aggregate::uninitialize Default:UpdateAndReportMinutesSinceMissionStarted
2015-01-28T18:05:00.299Z,1422468300.299 [NAL9602](FAULT): GPS failed to acquire within timeout.
2015-01-28T18:05:00.300Z,1422468300.300 [NAL9602] Data Fault, FailCount= 1
2015-01-28T18:05:00.300Z,1422468300.300 [NAL9602](ERROR): Data Fault
2015-01-28T18:05:00.334Z,1422468300.334 [BPC1](FAULT): Failed to receive battery data
2015-01-28T18:05:00.334Z,1422468300.334 [BPC1] Communications Fault, FailCount= 1
2015-01-28T18:05:00.334Z,1422468300.334 [BPC1](ERROR): Communications Fault
2015-01-28T18:05:00.410Z,1422468300.410 [CBIT](ERROR): Data Fault in component: NAL9602
2015-01-28T18:05:00.410Z,1422468300.410 [CBIT](ERROR): Communications Fault in component: BPC1
2015-01-28T18:05:00.423Z,1422468300.423 [Reporter](INFO): NAL9602.sigQuality no_value
2015-01-28T18:05:05.387Z,1422468305.387 [NAL9602](INFO): Stop
2015-01-28T18:05:05.387Z,1422468305.387 [NAL9602](INFO): Uninitialize
2015-01-28T18:05:05.387Z,1422468305.387 [NAL9602](INFO): Powering down
2015-01-28T18:05:09.365Z,1422468309.365 [NAL9602](INFO): Stopping
2015-01-28T18:05:13.441Z,1422468313.441 [CBIT](INFO): Clearing failed state for component NAL9602
2015-01-28T18:05:13.442Z,1422468313.442 [NAL9602] No Fault, FailCount= 1
2015-01-28T18:05:13.442Z,1422468313.442 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T18:05:13.442Z,1422468313.442 [BPC1] No Fault, FailCount= 1
2015-01-28T18:05:14.541Z,1422468314.541 [NAL9602](INFO): Start
2015-01-28T18:05:14.541Z,1422468314.541 [NAL9602](INFO): Powering up NAL9602
2015-01-28T18:05:24.766Z,1422468324.766 [Reporter](INFO): NAL9602.sigQuality 0 count
2015-01-28T18:05:25.507Z,1422468325.507 [NAL9602](INFO): ************** CMDMODE **************

2015-01-28T18:05:25.507Z,1422468325.507 [NAL9602](INFO): NAL9602 initialized
2015-01-28T18:05:26.310Z,1422468326.310 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:27.018Z,1422468327.018 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:29.217Z,1422468329.217 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:29.607Z,1422468329.607 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:31.220Z,1422468331.220 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:31.607Z,1422468331.607 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:34.424Z,1422468334.424 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:34.822Z,1422468334.822 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:37.241Z,1422468337.241 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:37.590Z,1422468337.590 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:39.192Z,1422468339.192 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:39.597Z,1422468339.597 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:41.191Z,1422468341.191 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:41.596Z,1422468341.596 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:43.210Z,1422468343.210 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:43.609Z,1422468343.609 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:45.237Z,1422468345.237 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:45.623Z,1422468345.623 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:47.465Z,1422468347.465 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:47.637Z,1422468347.637 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:49.260Z,1422468349.260 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:49.661Z,1422468349.661 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:50.490Z,1422468350.490 [BPC1](ERROR): A bank expecting battery number:1 and read number: uart read:X
$S,01,270F,02,00,04,5C%51
$C1,01,FF,02,00,03,FF,04,00,05,00,06,00,07,00%72
$B11,0A,0000%33
$B12,0A,FFFD%32
$B13,0A,FFFC%34
$B14,0A,FFFC%33
$B15,0A,0000%37
$B16,0A,0000%34
$B17,0A,0000%35
$B18,0A,0000%3A
$S,01,270F,02,00,04,5C%51
$C1,01,FF,02,00,03,FF,04,00,05,00,06,00,07,00%72
$B11,02,000A,01,026C,03,0001,08,0B8A,09,3C0E,0A,0000,0B,0001%48
$B11,0C,0001,0D,0064,0E,005B,0F,15DD,10,1641,11,FFFF,12,FFFF%36
$B11,13,1770,14,0000,15,41A0,16,00E0,17,0002,18,1838,19,3840%4E
$B11,1A,0031,1B,4357,1C,009D%49
$B12,02,000A,01,026C,03,0001,08,0B93,09,3C22,0A,FFFC,0B,FFFE%4A
$B12,0C,0001,0D,0052,0E,0051,0F,1362,10,17B2,11,FFFF,12,FFFF%35
$B12,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%42
$B12,1A,0031,1B,4357,1C,0093%3D
$B13,02,000A,01,026C,03,0001,08,0B99,09,3C22,0A,FFFC,0B,FFFE%41
$B13,0C,0001,0D,005B,0E,004E,0F,12B8,10,16D7,11,FFFF,12,FFFF%4C
$B13,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%43
$B13,1A,0031,1B,4333,1C,0068%3A
$B14,02,000A,01,026C,03,0001,08,0B95,09,3C22,0A,FFFC,0B,FFFE%4A
$B14,0C,0001,0D,0052,0E,004D,0F,126A,10,168C,11,FFFF,12,FFFF%3F
$B14,13,FFFF,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%44
$B14,1A,0031,1B,4357,1C,008D%4D
$B15,02,000A,01,026C,03,0001,08,0B97,09,3C08,0A,0000,0B,0001%46
$B15,0C,0001,0D,0064,0E,005B,0F,1602,10,16B6,11,FFFF,12,FFFF%42
$B15,13,2A30,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%38
$B15,1A,0031,1B,4357,1C,008A%49
$B16,02,000A,01,026C,03,0001,08,0B8F,09,3C10,0A,0000,0B,0001%3C
$B16,0C,0001,0D,0064,0E,005E,0F,16AB,10,16AB,11,FFFF,12,FFFF%30
$B16,13,0000,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%4B
$B16,1A,0031,1B,4357,1C,00B9%48
$B17,02,000A,01,026C,03,0001,08,0B95,09,3C09,0A,0000,0B,0001%47
$B17,0C,0001,0D,0064,0E,005F,0F,16DB,10,1701,11,FFFF,12,FFFF%34
$B17,13,08E8,14,0000,15,41A0,16,00E0,17,0001,18,1838,19,3840%3F
$B17,1A,0031,1B,4357,1C,00A5%46
$B18,02,000A,01,026C,03,0001,08,0B9A,09,3BB2,0A,0000,0B,0001%44
$B18,0C,0001,0D,0056,0E,004F,0F,12E5,10,16A5,11,FFFF,12,FFFF%3D
$B18,13,E100,14,0BB8,15,41A0,16,00C0,17,0002,18,1838,19,3840%3C
$B18,1A,0031,1B,4357,1C,00AE%39

2015-01-28T18:05:50.490Z,1422468350.490 [BPC1](FAULT): Failed to parse bank A battery data
2015-01-28T18:05:50.490Z,1422468350.490 [BPC1] Data Fault, FailCount= 1
2015-01-28T18:05:50.490Z,1422468350.490 [BPC1](ERROR): Data Fault
2015-01-28T18:05:50.508Z,1422468350.508 [CBIT](ERROR): Data Fault in component: BPC1
2015-01-28T18:05:51.714Z,1422468351.714 [CBIT](INFO): Clearing failed state for component BPC1
2015-01-28T18:05:51.714Z,1422468351.714 [BPC1] No Fault, FailCount= 1
2015-01-28T18:05:52.613Z,1422468352.613 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:52.867Z,1422468352.867 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:55.265Z,1422468355.265 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:55.638Z,1422468355.638 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:57.264Z,1422468357.264 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:57.714Z,1422468357.714 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:05:59.287Z,1422468359.287 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:05:59.644Z,1422468359.644 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:01.267Z,1422468361.267 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:01.652Z,1422468361.652 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:03.237Z,1422468363.237 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:03.668Z,1422468363.668 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:06.458Z,1422468366.458 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:06.876Z,1422468366.876 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:09.312Z,1422468369.312 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:09.700Z,1422468369.700 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:12.492Z,1422468372.492 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:13.054Z,1422468373.054 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:17.860Z,1422468377.860 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:18.294Z,1422468378.294 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:20.264Z,1422468380.264 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:20.686Z,1422468380.686 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:23.473Z,1422468383.473 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:23.878Z,1422468383.878 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:26.261Z,1422468386.261 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:26.674Z,1422468386.674 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:29.462Z,1422468389.462 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:29.863Z,1422468389.863 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:32.262Z,1422468392.262 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:32.668Z,1422468392.668 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:35.467Z,1422468395.467 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:35.864Z,1422468395.864 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:38.268Z,1422468398.268 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:38.708Z,1422468398.708 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:40.323Z,1422468400.323 [DeadReckonUsingMultipleVelocitySources](FAULT): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2015-01-28T18:06:40.323Z,1422468400.323 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2015-01-28T18:06:40.323Z,1422468400.323 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2015-01-28T18:06:40.370Z,1422468400.370 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2015-01-28T18:06:40.694Z,1422468400.694 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2015-01-28T18:06:40.694Z,1422468400.694 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2015-01-28T18:06:41.098Z,1422468401.098 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2015-01-28T18:06:41.469Z,1422468401.469 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:41.532Z,1422468401.532 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 0 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:41.858Z,1422468401.858 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:41.911Z,1422468401.911 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 1 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:42.290Z,1422468402.290 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 2 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:42.703Z,1422468402.703 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 3 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:43.092Z,1422468403.092 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 4 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:43.701Z,1422468403.701 [DeadReckonUsingMultipleVelocitySources](DEBUG): No bottom track data -- 5 cycles since last successful read, accepting data for 5 cycles.
2015-01-28T18:06:44.277Z,1422468404.277 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:44.658Z,1422468404.658 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:47.506Z,1422468407.506 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:47.884Z,1422468407.884 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:50.286Z,1422468410.286 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:50.692Z,1422468410.692 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:53.484Z,1422468413.484 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:53.965Z,1422468413.965 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:56.294Z,1422468416.294 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:56.694Z,1422468416.694 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:06:59.461Z,1422468419.461 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:06:59.878Z,1422468419.878 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:02.295Z,1422468422.295 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:02.678Z,1422468422.678 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:04.319Z,1422468424.319 [Default:CheckIn:Read_GPS](INFO): Timed out from 2015-01-28T18:02:04.0Z
2015-01-28T18:07:04.319Z,1422468424.319 [Default:CheckIn:Read_GPS] Stopped
2015-01-28T18:07:04.319Z,1422468424.319 [Default:CheckIn:Read_Iridium] Running Loop=1
2015-01-28T18:07:04.715Z,1422468424.715 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2015-01-28T18:07:05.506Z,1422468425.506 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:08.738Z,1422468428.738 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:08.943Z,1422468428.943 [DataOverHttps](INFO): Sending 192 bytes from file Logs/20150128T175342/Courier0004.lzma
2015-01-28T18:07:19.098Z,1422468439.098 [DataOverHttps](INFO): Moved sent file to Logs/20150128T175342/Courier0004.lzma.bak
2015-01-28T18:07:19.098Z,1422468439.098 [DataOverHttps](INFO): SBD MOMSN=1510368
2015-01-28T18:07:19.103Z,1422468439.103 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:20.291Z,1422468440.291 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:24.255Z,1422468444.255 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:24.703Z,1422468444.703 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:28.771Z,1422468448.771 [DataOverHttps](INFO): Sending 637 bytes from file Logs/20150128T175342/Express0005.lzma
2015-01-28T18:07:29.183Z,1422468449.183 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:29.853Z,1422468449.853 [DataOverHttps](INFO): Moved sent file to Logs/20150128T175342/Express0005.lzma.bak
2015-01-28T18:07:29.854Z,1422468449.854 [DataOverHttps](INFO): SBD MOMSN=1510370
2015-01-28T18:07:29.865Z,1422468449.865 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:07:30.534Z,1422468450.534 [Default:CheckIn:Read_Iridium] Stopped
2015-01-28T18:07:30.534Z,1422468450.534 [Default:CheckIn](INFO): Completed Default:CheckIn
2015-01-28T18:07:30.534Z,1422468450.534 [Default:CheckIn] Stopped
2015-01-28T18:07:30.535Z,1422468450.535 [Default:CheckIn](INFO): Aggregate::uninitialize Default:CheckIn
2015-01-28T18:07:30.535Z,1422468450.535 [Default:CheckIn:A.SetSpeed] Stopped
2015-01-28T18:07:30.535Z,1422468450.535 [Default:CheckIn:A.SetSpeed](DEBUG): Uninitialize.
2015-01-28T18:07:45.641Z,1422468465.641 [NAL9602](INFO): ************** Request Fix **************

2015-01-28T18:07:50.638Z,1422468470.638 [NAL9602](INFO): ************** GetFix **************

2015-01-28T18:08:10.764Z,1422468490.764 [NAL9602](INFO): ************** Request Fix **************

2015-01