2019-05-17T16:05:17.867Z,1558109117.867 [Supervisor](DEBUG): Initializing supervisor.
2019-05-17T16:05:17.870Z,1558109117.870 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-17T16:05:17.871Z,1558109117.871 [SyncHandler](INFO): Protected caller Thread ID is 5562
2019-05-17T16:05:17.871Z,1558109117.871 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-17T16:05:17.872Z,1558109117.872 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-17T16:05:17.872Z,1558109117.872 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5563
2019-05-17T16:05:17.876Z,1558109117.876 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-17T16:05:17.889Z,1558109117.889 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-17T16:05:17.890Z,1558109117.890 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-17T16:05:17.890Z,1558109117.890 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5564
2019-05-17T16:05:17.891Z,1558109117.891 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-17T16:05:17.892Z,1558109117.892 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-17T16:05:17.892Z,1558109117.892 [logger ThreadHandler](INFO): Protected caller Thread ID is 5565
2019-05-17T16:05:17.895Z,1558109117.895 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-17T16:05:17.895Z,1558109117.895 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-17T16:05:17.897Z,1558109117.897 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-17T16:05:18.109Z,1558109118.109 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-17T16:05:18.110Z,1558109118.110 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-17T16:05:18.190Z,1558109118.190 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-17T16:05:18.652Z,1558109118.652 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-17T16:05:18.653Z,1558109118.653 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-17T16:05:19.012Z,1558109119.012 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-17T16:05:19.012Z,1558109119.012 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-17T16:05:19.109Z,1558109119.109 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-17T16:05:19.109Z,1558109119.109 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-17T16:05:19.427Z,1558109119.427 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-17T16:05:19.427Z,1558109119.427 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-17T16:05:19.631Z,1558109119.631 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-17T16:05:19.632Z,1558109119.632 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-17T16:05:20.114Z,1558109120.114 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-17T16:05:20.115Z,1558109120.115 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-17T16:05:20.222Z,1558109120.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-17T16:05:20.222Z,1558109120.222 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-17T16:05:20.323Z,1558109120.323 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-17T16:05:20.324Z,1558109120.324 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-17T16:05:20.938Z,1558109120.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-17T16:05:20.939Z,1558109120.939 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-17T16:05:21.349Z,1558109121.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-17T16:05:21.349Z,1558109121.349 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-17T16:05:21.558Z,1558109121.558 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-17T16:05:21.559Z,1558109121.559 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-17T16:05:21.708Z,1558109121.708 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-17T16:05:21.709Z,1558109121.709 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-17T16:05:21.864Z,1558109121.864 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-17T16:05:21.866Z,1558109121.866 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2019-05-17T16:05:21.867Z,1558109121.867 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2019-05-17T16:05:21.958Z,1558109121.958 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2019-05-17T16:05:22.044Z,1558109122.044 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2019-05-17T16:05:22.148Z,1558109122.148 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2019-05-17T16:05:22.231Z,1558109122.231 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2019-05-17T16:05:22.327Z,1558109122.327 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2019-05-17T16:05:22.428Z,1558109122.428 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2019-05-17T16:05:22.648Z,1558109122.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2019-05-17T16:05:22.723Z,1558109122.723 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2019-05-17T16:05:23.073Z,1558109123.073 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2019-05-17T16:05:23.291Z,1558109123.291 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2019-05-17T16:05:23.508Z,1558109123.508 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2019-05-17T16:05:23.939Z,1558109123.939 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-17T16:05:23.940Z,1558109123.940 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2019-05-17T16:05:23.940Z,1558109123.940 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-17T16:05:23.955Z,1558109123.955 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-17T16:05:24.023Z,1558109124.023 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-17T16:05:24.143Z,1558109124.143 [VerticalControl] Loaded
2019-05-17T16:05:24.143Z,1558109124.143 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-17T16:05:24.144Z,1558109124.144 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-17T16:05:24.217Z,1558109124.217 [HorizontalControl] Loaded
2019-05-17T16:05:24.217Z,1558109124.217 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-17T16:05:24.218Z,1558109124.218 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-17T16:05:24.224Z,1558109124.224 [SpeedControl] Loaded
2019-05-17T16:05:24.224Z,1558109124.224 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-17T16:05:24.225Z,1558109124.225 [LoopControl](DEBUG): Construct LoopControl.
2019-05-17T16:05:24.226Z,1558109124.226 [LoopControl] Loaded
2019-05-17T16:05:24.226Z,1558109124.226 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-17T16:05:24.226Z,1558109124.226 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-17T16:05:24.227Z,1558109124.227 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-17T16:05:24.240Z,1558109124.240 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-17T16:05:24.241Z,1558109124.241 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-17T16:05:24.342Z,1558109124.342 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-17T16:05:24.343Z,1558109124.343 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-17T16:05:24.473Z,1558109124.473 [BuoyancyServo] Loaded
2019-05-17T16:05:24.473Z,1558109124.473 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-17T16:05:24.485Z,1558109124.485 [ElevatorServo] Loaded
2019-05-17T16:05:24.485Z,1558109124.485 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-17T16:05:24.497Z,1558109124.497 [MassServo] Loaded
2019-05-17T16:05:24.497Z,1558109124.497 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-17T16:05:24.509Z,1558109124.509 [RudderServo] Loaded
2019-05-17T16:05:24.509Z,1558109124.509 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-17T16:05:24.520Z,1558109124.520 [ThrusterServo] Loaded
2019-05-17T16:05:24.521Z,1558109124.521 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-17T16:05:24.521Z,1558109124.521 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-17T16:05:24.522Z,1558109124.522 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-17T16:05:24.634Z,1558109124.634 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-17T16:05:24.634Z,1558109124.634 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-17T16:05:24.656Z,1558109124.656 [NavChart] Loaded
2019-05-17T16:05:24.656Z,1558109124.656 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-17T16:05:24.660Z,1558109124.660 [UniversalFixResidualReporter] Loaded
2019-05-17T16:05:24.661Z,1558109124.661 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-17T16:05:24.661Z,1558109124.661 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-17T16:05:24.662Z,1558109124.662 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-17T16:05:24.734Z,1558109124.734 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-17T16:05:24.735Z,1558109124.735 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-17T16:05:25.079Z,1558109125.079 [DataOverHttps] Loaded
2019-05-17T16:05:25.079Z,1558109125.079 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-17T16:05:25.080Z,1558109125.080 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087B4E0
2019-05-17T16:05:25.081Z,1558109125.081 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5647
2019-05-17T16:05:25.095Z,1558109125.095 [Depth_Keller] Loaded
2019-05-17T16:05:25.095Z,1558109125.095 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-17T16:05:25.197Z,1558109125.197 [NAL9602] Loaded
2019-05-17T16:05:25.197Z,1558109125.197 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-17T16:05:25.215Z,1558109125.215 [Onboard] Loaded
2019-05-17T16:05:25.215Z,1558109125.215 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-17T16:05:25.218Z,1558109125.218 [Radio_Surface] Loaded
2019-05-17T16:05:25.219Z,1558109125.219 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-17T16:05:25.220Z,1558109125.220 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AB4E0
2019-05-17T16:05:25.220Z,1558109125.220 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5648
2019-05-17T16:05:25.356Z,1558109125.356 [DAT] Loaded
2019-05-17T16:05:25.357Z,1558109125.357 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-05-17T16:05:25.357Z,1558109125.357 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-17T16:05:25.358Z,1558109125.358 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-17T16:05:25.400Z,1558109125.400 [DepthRateCalculator] Loaded
2019-05-17T16:05:25.400Z,1558109125.400 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-17T16:05:25.406Z,1558109125.406 [PitchRateCalculator] Loaded
2019-05-17T16:05:25.406Z,1558109125.406 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-17T16:05:25.419Z,1558109125.419 [SpeedCalculator] Loaded
2019-05-17T16:05:25.419Z,1558109125.419 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-17T16:05:25.442Z,1558109125.442 [TempGradientCalculator] Loaded
2019-05-17T16:05:25.442Z,1558109125.442 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-17T16:05:25.447Z,1558109125.447 [YawRateCalculator] Loaded
2019-05-17T16:05:25.448Z,1558109125.448 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-17T16:05:25.479Z,1558109125.479 [ElevatorOffsetCalculator] Loaded
2019-05-17T16:05:25.479Z,1558109125.479 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-17T16:05:25.480Z,1558109125.480 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-17T16:05:25.480Z,1558109125.480 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-17T16:05:25.748Z,1558109125.748 [CTD_NeilBrown] Loaded
2019-05-17T16:05:25.749Z,1558109125.749 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-17T16:05:25.750Z,1558109125.750 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409AD4E0
2019-05-17T16:05:25.750Z,1558109125.750 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5649
2019-05-17T16:05:25.781Z,1558109125.781 [ESPComponent] Loaded
2019-05-17T16:05:25.782Z,1558109125.782 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-05-17T16:05:25.797Z,1558109125.797 [PAR_Licor] Loaded
2019-05-17T16:05:25.797Z,1558109125.797 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-05-17T16:05:25.849Z,1558109125.849 [WetLabsBB2FL] Loaded
2019-05-17T16:05:25.849Z,1558109125.849 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-05-17T16:05:25.851Z,1558109125.851 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DD4E0
2019-05-17T16:05:25.851Z,1558109125.851 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5650
2019-05-17T16:05:25.852Z,1558109125.852 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-17T16:05:25.852Z,1558109125.852 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-17T16:05:25.884Z,1558109125.884 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-17T16:05:25.885Z,1558109125.885 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-17T16:05:26.191Z,1558109126.191 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-17T16:05:26.192Z,1558109126.192 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-17T16:05:26.331Z,1558109126.331 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-17T16:05:26.342Z,1558109126.342 [SBIT] Loaded
2019-05-17T16:05:26.342Z,1558109126.342 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-17T16:05:26.343Z,1558109126.343 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-17T16:05:26.356Z,1558109126.356 [IBIT] Loaded
2019-05-17T16:05:26.356Z,1558109126.356 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-17T16:05:26.360Z,1558109126.360 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-17T16:05:26.767Z,1558109126.767 [CBIT] Loaded
2019-05-17T16:05:26.768Z,1558109126.768 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-17T16:05:26.768Z,1558109126.768 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-17T16:05:26.772Z,1558109126.772 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-17T16:05:26.773Z,1558109126.773 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-17T16:05:26.780Z,1558109126.780 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-17T16:05:26.781Z,1558109126.781 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADC4E0
2019-05-17T16:05:26.781Z,1558109126.781 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5651
2019-05-17T16:05:26.786Z,1558109126.786 [Supervisor](INFO): Main Thread ID is 5250
2019-05-17T16:05:26.787Z,1558109126.787 [Supervisor](DEBUG): Running supervisor.
2019-05-17T16:05:26.787Z,1558109126.787 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5652
2019-05-17T16:05:26.790Z,1558109126.790 [controlThread ThreadHandler](INFO): Handler Thread ID is 5653
2019-05-17T16:05:26.790Z,1558109126.790 [controlThread](DEBUG): Initializing ControlThread
2019-05-17T16:05:26.791Z,1558109126.791 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-17T16:05:26.792Z,1558109126.792 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-17T16:05:26.793Z,1558109126.793 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-17T16:05:26.794Z,1558109126.794 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-17T16:05:26.795Z,1558109126.795 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-17T16:05:26.795Z,1558109126.795 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-17T16:05:26.799Z,1558109126.799 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-17T16:05:26.799Z,1558109126.799 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-17T16:05:26.799Z,1558109126.799 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-17T16:05:26.800Z,1558109126.800 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-17T16:05:26.800Z,1558109126.800 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-17T16:05:26.801Z,1558109126.801 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-17T16:05:26.802Z,1558109126.802 [SBIT](INFO): Initialize SBIT Component.
2019-05-17T16:05:26.803Z,1558109126.803 [SBIT](IMPORTANT): git: 2019-05-01-18-gebccc08
2019-05-17T16:05:26.803Z,1558109126.803 [SBIT](INFO): git hash: ebccc08b74c64e8c330b6ee85a06f50705035b59
2019-05-17T16:05:26.803Z,1558109126.803 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-17T16:05:26.804Z,1558109126.804 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
2019-05-17T16:05:26.805Z,1558109126.805 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2019-05-17T16:05:26.806Z,1558109126.806 [IBIT](INFO): Initialize IBIT Component.
2019-05-17T16:05:26.807Z,1558109126.807 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-17T16:05:26.808Z,1558109126.808 [logger ThreadHandler](INFO): Handler Thread ID is 5654
2019-05-17T16:05:26.818Z,1558109126.818 [CBIT](DEBUG): Initialized mux pins.
2019-05-17T16:05:26.818Z,1558109126.818 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-17T16:05:26.826Z,1558109126.826 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5655
2019-05-17T16:05:26.827Z,1558109126.827 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-17T16:05:26.838Z,1558109126.838 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5656
2019-05-17T16:05:26.842Z,1558109126.842 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-17T16:05:26.842Z,1558109126.842 [CBIT](DEBUG): Initializing heartbeat.
2019-05-17T16:05:26.850Z,1558109126.850 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5657
2019-05-17T16:05:26.851Z,1558109126.851 [CTD_NeilBrown](INFO): Powering down
2019-05-17T16:05:26.871Z,1558109126.871 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5658
2019-05-17T16:05:26.872Z,1558109126.872 [WetLabsBB2FL](INFO): Powering down
2019-05-17T16:05:26.903Z,1558109126.903 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5659
2019-05-17T16:05:26.906Z,1558109126.906 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-17T16:05:26.906Z,1558109126.906 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-17T16:05:26.906Z,1558109126.906 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-17T16:05:26.906Z,1558109126.906 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-17T16:05:26.907Z,1558109126.907 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-17T16:05:26.908Z,1558109126.908 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-17T16:05:26.908Z,1558109126.908 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-17T16:05:26.908Z,1558109126.908 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-17T16:05:26.908Z,1558109126.908 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-17T16:05:26.908Z,1558109126.908 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-17T16:05:26.909Z,1558109126.909 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-17T16:05:26.914Z,1558109126.914 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-17T16:05:26.914Z,1558109126.914 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-17T16:05:26.950Z,1558109126.950 [CBIT](DEBUG): Backplane powered.
2019-05-17T16:05:26.951Z,1558109126.951 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-17T16:05:26.961Z,1558109126.961 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-17T16:05:26.971Z,1558109126.971 [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://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.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>


2019-05-17T16:05:26.972Z,1558109126.972 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-17T16:05:27.057Z,1558109127.057 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-17T16:05:27.058Z,1558109127.058 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-17T16:05:27.060Z,1558109127.060 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-17T16:05:27.103Z,1558109127.103 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-17T16:05:27.105Z,1558109127.105 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-17T16:05:27.127Z,1558109127.127 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-17T16:05:27.130Z,1558109127.130 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

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

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

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

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-05-17T16:05:27.142Z,1558109127.142 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-17T16:05:27.184Z,1558109127.184 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2019-05-17T16:05:27.203Z,1558109127.203 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-05-17T16:05:27.203Z,1558109127.203 [DAT](INFO): Powering up
2019-05-17T16:05:27.203Z,1558109127.203 [DAT](DEBUG): Initializing DAT.
2019-05-17T16:05:27.242Z,1558109127.242 [Radio_Surface](INFO): Powering up
2019-05-17T16:05:27.286Z,1558109127.286 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-05-17T16:05:27.375Z,1558109127.375 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-17T16:05:27.412Z,1558109127.412 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:27.422Z,1558109127.422 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-17T16:05:27.423Z,1558109127.423 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:27.434Z,1558109127.434 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-17T16:05:27.435Z,1558109127.435 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:27.446Z,1558109127.446 [MassServo](DEBUG): Initializing MassServo.
2019-05-17T16:05:27.447Z,1558109127.447 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:27.458Z,1558109127.458 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-17T16:05:27.459Z,1558109127.459 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:27.470Z,1558109127.470 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-17T16:05:28.334Z,1558109128.334 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-17T16:05:28.334Z,1558109128.334 [RudderServo](FAULT): Rudder failed to initialize
2019-05-17T16:05:28.334Z,1558109128.334 [RudderServo] Communications Fault, FailCount= 1
2019-05-17T16:05:28.334Z,1558109128.334 [RudderServo](ERROR): Communications Fault
2019-05-17T16:05:28.445Z,1558109128.445 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-17T16:05:28.651Z,1558109128.651 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-17T16:05:28.651Z,1558109128.651 [RudderServo](INFO): Powering down
2019-05-17T16:05:29.348Z,1558109129.348 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-17T16:05:29.467Z,1558109129.467 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-17T16:05:29.471Z,1558109129.471 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-17T16:05:29.471Z,1558109129.471 [RudderServo] No Fault, FailCount= 1
2019-05-17T16:05:40.590Z,1558109140.590 [DAT](INFO): setting local address to 2
2019-05-17T16:05:40.995Z,1558109140.995 [DAT](INFO): set local address to 2
2019-05-17T16:05:55.520Z,1558109155.520 [NAL9602](INFO): Powering up NAL9602
2019-05-17T16:06:06.433Z,1558109166.433 [NAL9602](INFO): NAL9602 initialized
2019-05-17T16:06:07.254Z,1558109167.254 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:06:26.312Z,1558109186.312 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-17T16:06:26.316Z,1558109186.316 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-17T16:06:37.327Z,1558109197.327 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.008845
CHAN A1 (24V): -0.016284
CHAN A2 (12V): -0.001717
CHAN A3 (5V): -0.001259
CHAN B0 (3.3V): 0.000294
CHAN B1 (3.15aV): -0.000481
CHAN B2 (3.15bV): 0.000048
CHAN B3 (GND): 0.000038
OPEN: 0.004827
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-17T16:07:19.575Z,1558109239.575 [SBIT](IMPORTANT): SBIT PASSED
2019-05-17T16:07:19.651Z,1558109239.651 [CommandLine](IMPORTANT): got command configSet list
2019-05-17T16:07:19.652Z,1558109239.652 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=8 count;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-05-17T16:07:19.653Z,1558109239.653 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): Express none DVL_micro.height_above_sea_floor;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=90 cubic_centimeter;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): VerticalControl.massDefault=-1 centimeter;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-33 millimeter;

2019-05-17T16:07:19.654Z,1558109239.654 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=27 millimeter;

2019-05-17T16:07:19.981Z,1558109239.981 [MissionManager](IMPORTANT): Started mission Startup
2019-05-17T16:07:19.981Z,1558109239.981 [Startup] Running Loop=1
2019-05-17T16:07:19.981Z,1558109239.981 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-17T16:07:19.981Z,1558109239.981 [Startup:A.GoToSurface] Running Loop=1
2019-05-17T16:07:19.981Z,1558109239.981 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-17T16:07:19.983Z,1558109239.983 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-17T16:07:19.983Z,1558109239.983 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-17T16:07:19.983Z,1558109239.983 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-17T16:07:19.984Z,1558109239.984 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-17T16:07:19.984Z,1558109239.984 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-17T16:07:19.985Z,1558109239.985 [Startup:StartupSatComms] Running Loop=1
2019-05-17T16:07:19.986Z,1558109239.986 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-17T16:07:19.986Z,1558109239.986 [Startup:StartupSatComms:A] Running Loop=1
2019-05-17T16:07:20.396Z,1558109240.396 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-17T16:07:26.849Z,1558109246.849 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:07:26.850Z,1558109246.850 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-17T16:07:26.850Z,1558109246.850 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:07:26.860Z,1558109246.860 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:07:27.276Z,1558109247.276 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:07:27.276Z,1558109247.276 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-17T16:08:05.511Z,1558109285.511 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004361
2019-05-17T16:08:20.187Z,1558109300.187 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-17T16:07:19.0Z
2019-05-17T16:08:20.187Z,1558109300.187 [Startup:StartupSatComms:A] Stopped
2019-05-17T16:08:20.187Z,1558109300.187 [Startup:StartupSatComms:B] Running Loop=1
2019-05-17T16:08:20.592Z,1558109300.592 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-17T16:08:33.230Z,1558109313.230 [DataOverHttps](INFO): Sending 123 bytes from file Logs/20190517T154531/Courier0007.lzma
2019-05-17T16:08:34.036Z,1558109314.036 [DataOverHttps](INFO): Moved sent file to Logs/20190517T154531/Courier0007.lzma.bak
2019-05-17T16:08:34.036Z,1558109314.036 [DataOverHttps](INFO): SBD MOMSN=11094885
2019-05-17T16:08:46.347Z,1558109326.347 [DataOverHttps](INFO): Sending 897 bytes from file Logs/20190517T154531/Express0008.lzma
2019-05-17T16:08:47.151Z,1558109327.151 [DataOverHttps](INFO): Moved sent file to Logs/20190517T154531/Express0008.lzma.bak
2019-05-17T16:08:47.152Z,1558109327.152 [DataOverHttps](INFO): SBD MOMSN=11094888
2019-05-17T16:08:59.775Z,1558109339.775 [DataOverHttps](INFO): Sending 1046 bytes from file Logs/20190517T160517/Express0001.lzma
2019-05-17T16:09:00.579Z,1558109340.579 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Express0001.lzma.bak
2019-05-17T16:09:00.579Z,1558109340.579 [DataOverHttps](INFO): SBD MOMSN=11094918
2019-05-17T16:09:03.434Z,1558109343.434 [Startup:StartupSatComms:B] Stopped
2019-05-17T16:09:03.434Z,1558109343.434 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-17T16:09:03.434Z,1558109343.434 [Startup:StartupSatComms] Stopped
2019-05-17T16:09:03.434Z,1558109343.434 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-17T16:09:03.435Z,1558109343.435 [Startup](INFO): Completed Startup
2019-05-17T16:09:03.435Z,1558109343.435 [MissionManager](INFO): Startup is completed.
2019-05-17T16:09:03.435Z,1558109343.435 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-17T16:09:03.435Z,1558109343.435 [Startup] Stopped
2019-05-17T16:09:03.436Z,1558109343.436 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-17T16:09:03.436Z,1558109343.436 [Startup:A.GoToSurface] Stopped
2019-05-17T16:09:03.436Z,1558109343.436 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-17T16:09:03.822Z,1558109343.822 [MissionManager](IMPORTANT): Started mission Default
2019-05-17T16:09:03.822Z,1558109343.822 [Default] Running Loop=1
2019-05-17T16:09:03.823Z,1558109343.823 [Default](DEBUG): Aggregate::initialize Default
2019-05-17T16:09:03.823Z,1558109343.823 [Default:B.GoToSurface] Running Loop=1
2019-05-17T16:09:03.823Z,1558109343.823 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-17T16:09:03.823Z,1558109343.823 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-17T16:09:03.823Z,1558109343.823 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-17T16:09:03.824Z,1558109343.824 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-17T16:09:03.824Z,1558109343.824 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-17T16:09:03.824Z,1558109343.824 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-17T16:09:03.825Z,1558109343.825 [Default:A.Wait] Running Loop=1
2019-05-17T16:09:03.825Z,1558109343.825 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:09:17.141Z,1558109357.141 [Default:A.Wait](INFO): Done Waiting.
2019-05-17T16:09:17.141Z,1558109357.141 [Default:A.Wait] Stopped
2019-05-17T16:09:17.141Z,1558109357.141 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:09:17.559Z,1558109357.559 [Default:CheckIn] Running Loop=1
2019-05-17T16:09:17.559Z,1558109357.559 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-17T16:09:17.559Z,1558109357.559 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-17T16:09:17.957Z,1558109357.957 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-17T16:09:28.062Z,1558109368.062 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:09:28.062Z,1558109368.062 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-17T16:09:28.062Z,1558109368.062 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:09:28.072Z,1558109368.072 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:09:28.475Z,1558109368.475 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:09:28.475Z,1558109368.475 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-17T16:11:09.832Z,1558109469.832 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-17T16:11:10.658Z,1558109470.658 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:15.502Z,1558109475.502 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:18.334Z,1558109478.334 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:21.566Z,1558109481.566 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:24.394Z,1558109484.394 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:27.622Z,1558109487.622 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:29.251Z,1558109489.251 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:11:29.251Z,1558109489.251 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-05-17T16:11:29.251Z,1558109489.251 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:11:29.296Z,1558109489.296 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:11:29.664Z,1558109489.664 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:11:29.665Z,1558109489.665 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-05-17T16:11:30.450Z,1558109490.450 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:33.282Z,1558109493.282 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:35.306Z,1558109495.306 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:38.534Z,1558109498.534 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:41.358Z,1558109501.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:44.590Z,1558109504.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:47.418Z,1558109507.418 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:50.650Z,1558109510.650 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:53.478Z,1558109513.478 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:56.310Z,1558109516.310 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:11:58.330Z,1558109518.330 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:00.350Z,1558109520.350 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:03.582Z,1558109523.582 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:06.406Z,1558109526.406 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:09.646Z,1558109529.646 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:12.470Z,1558109532.470 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:15.702Z,1558109535.702 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:18.526Z,1558109538.526 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:21.358Z,1558109541.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:23.378Z,1558109543.378 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:26.610Z,1558109546.610 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:29.434Z,1558109549.434 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:32.670Z,1558109552.670 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:35.498Z,1558109555.498 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:38.726Z,1558109558.726 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:41.558Z,1558109561.558 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:41.632Z,1558109561.632 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.000000 meter
2019-05-17T16:12:41.634Z,1558109561.634 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-05-17T16:12:41.995Z,1558109561.995 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-17T16:12:44.382Z,1558109564.382 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:46.402Z,1558109566.402 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:47.459Z,1558109567.459 [DataOverHttps](IMPORTANT): SBD MTMSN=20190517T161240
2019-05-17T16:12:49.634Z,1558109569.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:52.206Z,1558109572.206 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-17T16:12:52.232Z,1558109572.232 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-17T16:12:52.232Z,1558109572.232 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-17T16:12:52.255Z,1558109572.255 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-17T16:12:52.257Z,1558109572.257 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-17T16:12:52.260Z,1558109572.260 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-17T16:12:52.263Z,1558109572.263 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-17T16:12:52.265Z,1558109572.265 [sample:A.AbortSample](DEBUG): Construct.
2019-05-17T16:12:52.267Z,1558109572.267 [sample:B.Pitch](DEBUG): Construct.
2019-05-17T16:12:52.272Z,1558109572.272 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-17T16:12:52.275Z,1558109572.275 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-17T16:12:52.345Z,1558109572.345 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-17T16:12:52.352Z,1558109572.352 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-17T16:12:52.356Z,1558109572.356 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-17T16:12:52.367Z,1558109572.367 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-17T16:12:52.382Z,1558109572.382 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-17T16:12:52.389Z,1558109572.389 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-17T16:12:52.392Z,1558109572.392 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-17T16:12:52.400Z,1558109572.400 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-17T16:12:52.404Z,1558109572.404 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-17T16:12:52.415Z,1558109572.415 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-17T16:12:52.439Z,1558109572.439 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:12:52.454Z,1558109572.454 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-17T16:12:52.462Z,1558109572.462 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:52.493Z,1558109572.493 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-17T16:12:52.517Z,1558109572.517 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:12:52.547Z,1558109572.547 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:12:52.596Z,1558109572.596 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-17T16:12:52.597Z,1558109572.597 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-17T16:12:55.694Z,1558109575.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:58.017Z,1558109578.017 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-17T16:12:58.018Z,1558109578.018 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-17T16:12:58.019Z,1558109578.019 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-17T16:12:58.019Z,1558109578.019 [CommandLine](IMPORTANT): got command run 
2019-05-17T16:12:58.021Z,1558109578.021 [CommandLine](IMPORTANT): Running 
2019-05-17T16:12:58.235Z,1558109578.235 [Default] Stopped
2019-05-17T16:12:58.235Z,1558109578.235 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-17T16:12:58.235Z,1558109578.235 [Default:B.GoToSurface] Stopped
2019-05-17T16:12:58.235Z,1558109578.235 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-17T16:12:58.235Z,1558109578.235 [Default:CheckIn] Stopped
2019-05-17T16:12:58.235Z,1558109578.235 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-17T16:12:58.235Z,1558109578.235 [Default:CheckIn:Read_GPS] Stopped
2019-05-17T16:12:58.235Z,1558109578.235 [MissionManager](IMPORTANT): Started mission sample
2019-05-17T16:12:58.236Z,1558109578.236 [sample] Running Loop=1
2019-05-17T16:12:58.236Z,1558109578.236 [sample](DEBUG): Aggregate::initialize sample
2019-05-17T16:12:58.236Z,1558109578.236 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:12:58.236Z,1558109578.236 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-17T16:12:58.236Z,1558109578.236 [sample:B.Pitch] Running Loop=1
2019-05-17T16:12:58.236Z,1558109578.236 [sample:B.Pitch](DEBUG): Initialize.
2019-05-17T16:12:58.237Z,1558109578.237 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:12:58.237Z,1558109578.237 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-17T16:12:58.237Z,1558109578.237 [sample:E] Running Loop=1
2019-05-17T16:12:58.237Z,1558109578.237 [sample:E] Stopped
2019-05-17T16:12:58.237Z,1558109578.237 [sample:F] Running Loop=1
2019-05-17T16:12:58.237Z,1558109578.237 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:12:58.238Z,1558109578.238 [sample:B.Pitch] Running Loop=1
2019-05-17T16:12:58.242Z,1558109578.242 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:12:58.550Z,1558109578.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:12:58.576Z,1558109578.576 [sample:F] Stopped
2019-05-17T16:12:58.576Z,1558109578.576 [sample:SampleRepeater] Running Loop=1
2019-05-17T16:12:58.576Z,1558109578.576 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-17T16:12:58.576Z,1558109578.576 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-17T16:12:58.576Z,1558109578.576 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-17T16:12:58.972Z,1558109578.972 [sample:SampleAtDepth] Running Loop=1
2019-05-17T16:12:58.972Z,1558109578.972 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-17T16:12:58.973Z,1558109578.973 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-17T16:12:58.973Z,1558109578.973 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:12:58.973Z,1558109578.973 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-17T16:12:58.973Z,1558109578.973 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-17T16:12:58.973Z,1558109578.973 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-17T16:12:58.974Z,1558109578.974 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-17T16:12:58.974Z,1558109578.974 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-17T16:12:59.380Z,1558109579.380 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-17T16:12:59.381Z,1558109579.381 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-17T16:12:59.381Z,1558109579.381 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-17T16:12:59.381Z,1558109579.381 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-17T16:12:59.779Z,1558109579.779 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-17T16:12:59.779Z,1558109579.779 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-17T16:12:59.779Z,1558109579.779 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-17T16:12:59.779Z,1558109579.779 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:12:59.779Z,1558109579.779 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-17T16:13:01.778Z,1558109581.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:03.407Z,1558109583.407 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-17T16:13:03.407Z,1558109583.407 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-17T16:13:03.407Z,1558109583.407 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:13:03.408Z,1558109583.408 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-17T16:13:03.408Z,1558109583.408 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-17T16:13:03.408Z,1558109583.408 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-17T16:13:03.408Z,1558109583.408 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-17T16:13:03.408Z,1558109583.408 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-17T16:13:03.815Z,1558109583.815 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-17T16:13:03.815Z,1558109583.815 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-17T16:13:03.815Z,1558109583.815 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-17T16:13:03.815Z,1558109583.815 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-17T16:13:03.816Z,1558109583.816 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-17T16:13:03.816Z,1558109583.816 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-17T16:13:03.816Z,1558109583.816 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-17T16:13:03.816Z,1558109583.816 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-17T16:13:04.216Z,1558109584.216 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-17T16:13:04.606Z,1558109584.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:05.029Z,1558109585.029 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'
2019-05-17T16:13:05.031Z,1558109585.031 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"
2019-05-17T16:13:05.431Z,1558109585.431 [ESPComponent](INFO): powering up ESP
2019-05-17T16:13:05.431Z,1558109585.431 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-17T16:13:05.432Z,1558109585.432 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-05-17T16:13:05.563Z,1558109585.563 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-17T16:13:07.438Z,1558109587.438 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:09.454Z,1558109589.454 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:12.694Z,1558109592.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:15.518Z,1558109595.518 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:18.750Z,1558109598.750 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:21.574Z,1558109601.574 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:24.814Z,1558109604.814 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:27.638Z,1558109607.638 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:30.077Z,1558109610.077 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:13:30.077Z,1558109610.077 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-05-17T16:13:30.077Z,1558109610.077 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:13:30.119Z,1558109610.119 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:13:30.466Z,1558109610.466 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:30.534Z,1558109610.534 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:13:30.535Z,1558109610.535 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-05-17T16:13:32.482Z,1558109612.482 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:35.714Z,1558109615.714 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:36.147Z,1558109616.147 [CommandLine](IMPORTANT): got command show variable ESPComponent
2019-05-17T16:13:36.252Z,1558109616.252 [CommandLine](IMPORTANT): ESPComponent.loadControl (none)
2019-05-17T16:13:36.253Z,1558109616.253 [CommandLine](IMPORTANT): ESPComponent.loadControl2 (none)
2019-05-17T16:13:36.253Z,1558109616.253 [CommandLine](IMPORTANT): ESPComponent.uart (none)
2019-05-17T16:13:36.254Z,1558109616.254 [CommandLine](IMPORTANT): ESPComponent.consoleUart (none)
2019-05-17T16:13:36.254Z,1558109616.254 [CommandLine](IMPORTANT): ESPComponent.baud (bit_per_second)
2019-05-17T16:13:36.280Z,1558109616.280 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup (bool)
2019-05-17T16:13:36.281Z,1558109616.281 [CommandLine](IMPORTANT): ESPComponent.simulateHardware (bool)
2019-05-17T16:13:36.281Z,1558109616.281 [CommandLine](IMPORTANT): ESPComponent.connectTimeout (second)
2019-05-17T16:13:36.282Z,1558109616.282 [CommandLine](IMPORTANT): ESPComponent.debug (bool)
2019-05-17T16:13:36.282Z,1558109616.282 [CommandLine](IMPORTANT): ESPComponent.espLogFilterRegex (none)
2019-05-17T16:13:36.283Z,1558109616.283 [CommandLine](IMPORTANT): ESPComponent.espServerHost (none)
2019-05-17T16:13:36.283Z,1558109616.283 [CommandLine](IMPORTANT): ESPComponent.filterCompleteTimeout (minute)
2019-05-17T16:13:36.284Z,1558109616.284 [CommandLine](IMPORTANT): ESPComponent.filterResultTimeout (second)
2019-05-17T16:13:36.284Z,1558109616.284 [CommandLine](IMPORTANT): ESPComponent.initialPromptTimeout (second)
2019-05-17T16:13:36.285Z,1558109616.285 [CommandLine](IMPORTANT): ESPComponent.loadCartridgeTimeout (minute)
2019-05-17T16:13:36.285Z,1558109616.285 [CommandLine](IMPORTANT): ESPComponent.poTimeout (second)
2019-05-17T16:13:36.286Z,1558109616.286 [CommandLine](IMPORTANT): ESPComponent.power (watt)
2019-05-17T16:13:36.286Z,1558109616.286 [CommandLine](IMPORTANT): ESPComponent.pppConnect (none)
2019-05-17T16:13:36.287Z,1558109616.287 [CommandLine](IMPORTANT): ESPComponent.pppFlow (none)
2019-05-17T16:13:36.287Z,1558109616.287 [CommandLine](IMPORTANT): ESPComponent.processCompleteTimeout (minute)
2019-05-17T16:13:36.288Z,1558109616.288 [CommandLine](IMPORTANT): ESPComponent.processResultTimeout (second)
2019-05-17T16:13:36.288Z,1558109616.288 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout (minute)
2019-05-17T16:13:36.289Z,1558109616.289 [CommandLine](IMPORTANT): ESPComponent.socketServerPort (count)
2019-05-17T16:13:36.289Z,1558109616.289 [CommandLine](IMPORTANT): ESPComponent.stopResultTimeout (minute)
2019-05-17T16:13:36.338Z,1558109616.338 [CommandLine](IMPORTANT): ESPComponent.secLoadControl (none)
2019-05-17T16:13:36.390Z,1558109616.390 [CommandLine](IMPORTANT): ESPComponent.sampling (bool)
2019-05-17T16:13:36.390Z,1558109616.390 [CommandLine](IMPORTANT): ESPComponent.sampleVolume (milliliter)
2019-05-17T16:13:36.391Z,1558109616.391 [CommandLine](IMPORTANT): ESPComponent.sample_number (count)
2019-05-17T16:13:36.391Z,1558109616.391 [CommandLine](IMPORTANT): ESPComponent.stopSampling (bool)
2019-05-17T16:13:38.542Z,1558109618.542 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:41.778Z,1558109621.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:44.602Z,1558109624.602 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:46.214Z,1558109626.214 [CommandLine](IMPORTANT): got command get ESPComponent.loadControl2
2019-05-17T16:13:46.214Z,1558109626.214 [CommandLine](IMPORTANT): ESPComponent.loadControl2 /dev/loadA7
2019-05-17T16:13:47.838Z,1558109627.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:50.662Z,1558109630.662 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:53.490Z,1558109633.490 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:55.510Z,1558109635.510 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:13:57.719Z,1558109637.719 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadA6=7
2019-05-17T16:13:58.746Z,1558109638.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:00.420Z,1558109640.420 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadA7
2019-05-17T16:14:01.574Z,1558109641.574 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:04.806Z,1558109644.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:05.444Z,1558109645.444 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadA6
2019-05-17T16:14:06.056Z,1558109646.056 [ESPComponent](INFO): console:uImage
2019-05-17T16:14:07.642Z,1558109647.642 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:09.254Z,1558109649.254 [ESPComponent](INFO): console: 0.57] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:14:10.866Z,1558109650.866 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:11.297Z,1558109651.297 [ESPComponent](INFO): console:d Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-17T16:14:13.694Z,1558109653.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:16.522Z,1558109656.522 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:18.538Z,1558109658.538 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:20.558Z,1558109660.558 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:23.790Z,1558109663.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:25.823Z,1558109665.823 [ESPComponent](INFO): console:Sending discover...
2019-05-17T16:14:26.294Z,1558109666.294 [ESPComponent](INFO): console:

2019-05-17T16:14:26.622Z,1558109666.622 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:28.644Z,1558109668.644 [ESPComponent](INFO): console:Sending discover...
2019-05-17T16:14:29.122Z,1558109669.122 [ESPComponent](INFO): console:

2019-05-17T16:14:29.854Z,1558109669.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:31.876Z,1558109671.876 [ESPComponent](INFO): console:No lease, forking to background
2019-05-17T16:14:32.279Z,1558109672.279 [ESPComponent](INFO): console:
Bringing up interface eth0:10 ...
2019-05-17T16:14:32.678Z,1558109672.678 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:32.693Z,1558109672.693 [ESPComponent](INFO): console:
eth0:10 IP=10.10.10.10
2019-05-17T16:14:33.166Z,1558109673.166 [ESPComponent](INFO): console:

2019-05-17T16:14:35.918Z,1558109675.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:37.935Z,1558109677.935 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-17T16:14:38.742Z,1558109678.742 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:38.763Z,1558109678.763 [ESPComponent](IMPORTANT): [sample #1] Explicit cartridge argument not given
2019-05-17T16:14:38.763Z,1558109678.763 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-17T16:14:38.764Z,1558109678.764 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2019-05-17T16:14:38.776Z,1558109678.776 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-17T16:14:38.776Z,1558109678.776 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-17T16:14:39.180Z,1558109679.180 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-17T16:14:39.180Z,1558109679.180 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-17T16:14:39.181Z,1558109679.181 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-17T16:14:39.181Z,1558109679.181 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-17T16:14:39.181Z,1558109679.181 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-17T16:14:39.580Z,1558109679.580 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-17T16:14:39.961Z,1558109679.961 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2019-05-17T16:14:40.365Z,1558109680.365 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-05-17T16:14:41.566Z,1558109681.566 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:41.993Z,1558109681.993 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2019-05-17T16:14:43.590Z,1558109683.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:45.508Z,1558109685.508 [CommandLine](IMPORTANT): got command show variable abort
2019-05-17T16:14:45.547Z,1558109685.547 [CommandLine](IMPORTANT): CBIT.abortDepth (meter)
2019-05-17T16:14:45.547Z,1558109685.547 [CommandLine](IMPORTANT): CBIT.abortDepthTimeout (second)
2019-05-17T16:14:45.606Z,1558109685.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:48.838Z,1558109688.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:51.666Z,1558109691.666 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:54.902Z,1558109694.902 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:14:57.730Z,1558109697.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:00.628Z,1558109700.628 [CommandLine](IMPORTANT): got command show variable stopSamp
2019-05-17T16:15:00.741Z,1558109700.741 [CommandLine](IMPORTANT): ESPComponent.stopSampling (bool)
2019-05-17T16:15:00.966Z,1558109700.966 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:03.790Z,1558109703.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:06.618Z,1558109706.618 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:08.468Z,1558109708.468 [CommandLine](IMPORTANT): got command report touch ESPComponent.stopSampling
2019-05-17T16:15:08.634Z,1558109708.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:11.866Z,1558109711.866 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:12.431Z,1558109712.431 [CommandLine](IMPORTANT): got command get ESPComponent.stopSampling
2019-05-17T16:15:12.431Z,1558109712.431 [CommandLine](IMPORTANT): ESPComponent.stopSampling 0 bool
2019-05-17T16:15:14.698Z,1558109714.698 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:17.926Z,1558109717.926 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:20.754Z,1558109720.754 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:23.618Z,1558109723.618 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:25.630Z,1558109725.630 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:27.630Z,1558109727.630 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:29.650Z,1558109729.650 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:31.286Z,1558109731.286 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:15:31.286Z,1558109731.286 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-05-17T16:15:31.286Z,1558109731.286 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:15:31.298Z,1558109731.298 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:15:31.670Z,1558109731.670 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:31.719Z,1558109731.719 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:15:31.719Z,1558109731.719 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-05-17T16:15:34.906Z,1558109734.906 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:37.734Z,1558109737.734 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:40.962Z,1558109740.962 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:41.788Z,1558109741.788 [CommandLine](IMPORTANT): got command show stack
2019-05-17T16:15:41.788Z,1558109741.788 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-17T16:15:41.788Z,1558109741.788 [sample](IMPORTANT): Priority 0: sample:A.AbortSample
2019-05-17T16:15:41.789Z,1558109741.789 [sample](IMPORTANT): Priority 1: sample:B.Pitch
2019-05-17T16:15:41.789Z,1558109741.789 [sample](IMPORTANT): Priority 2: sample:C.SetSpeed
2019-05-17T16:15:41.789Z,1558109741.789 [sample:SampleAtDepth:SampleWrapper](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:A.Pitch
2019-05-17T16:15:41.791Z,1558109741.791 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 4: sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP
2019-05-17T16:15:43.790Z,1558109743.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:47.022Z,1558109747.022 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:49.854Z,1558109749.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:52.678Z,1558109752.678 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:54.702Z,1558109754.702 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:15:57.930Z,1558109757.930 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:00.758Z,1558109760.758 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:03.990Z,1558109763.990 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:06.818Z,1558109766.818 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:10.039Z,1558109770.039 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-17T16:16:10.039Z,1558109770.039 [NAL9602] Data Fault, FailCount= 1
2019-05-17T16:16:10.039Z,1558109770.039 [NAL9602](ERROR): Data Fault
2019-05-17T16:16:10.077Z,1558109770.077 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-17T16:16:10.443Z,1558109770.443 [NAL9602](INFO): Powering down
2019-05-17T16:16:11.293Z,1558109771.293 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-17T16:16:11.293Z,1558109771.293 [NAL9602] No Fault, FailCount= 1
2019-05-17T16:16:40.743Z,1558109800.743 [NAL9602](INFO): Powering up NAL9602
2019-05-17T16:16:51.651Z,1558109811.651 [NAL9602](INFO): NAL9602 initialized
2019-05-17T16:16:52.470Z,1558109812.470 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:55.302Z,1558109815.302 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:16:58.126Z,1558109818.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:01.358Z,1558109821.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:04.186Z,1558109824.186 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:07.014Z,1558109827.014 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:09.037Z,1558109829.037 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:11.054Z,1558109831.054 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:14.286Z,1558109834.286 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:17.118Z,1558109837.118 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:20.350Z,1558109840.350 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:23.174Z,1558109843.174 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:26.410Z,1558109846.410 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:29.238Z,1558109849.238 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:32.062Z,1558109852.062 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:32.495Z,1558109852.495 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:17:32.495Z,1558109852.495 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-05-17T16:17:32.495Z,1558109852.495 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:17:32.506Z,1558109852.506 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:17:32.944Z,1558109852.944 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:17:32.944Z,1558109852.944 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-05-17T16:17:34.082Z,1558109854.082 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:37.314Z,1558109857.314 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:40.146Z,1558109860.146 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:43.378Z,1558109863.378 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:46.205Z,1558109866.205 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:49.434Z,1558109869.434 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:52.262Z,1558109872.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:55.090Z,1558109875.090 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:17:57.114Z,1558109877.114 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:00.346Z,1558109880.346 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:03.170Z,1558109883.170 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:06.406Z,1558109886.406 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:09.230Z,1558109889.230 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:12.462Z,1558109892.462 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:15.290Z,1558109895.290 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:18.122Z,1558109898.122 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:20.142Z,1558109900.142 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:22.158Z,1558109902.158 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:25.390Z,1558109905.390 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:28.218Z,1558109908.218 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:31.454Z,1558109911.454 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:34.278Z,1558109914.278 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:37.510Z,1558109917.510 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:40.342Z,1558109920.342 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:43.166Z,1558109923.166 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:45.190Z,1558109925.190 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:48.422Z,1558109928.422 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:51.250Z,1558109931.250 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:54.478Z,1558109934.478 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:18:57.310Z,1558109937.310 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:00.538Z,1558109940.538 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:03.366Z,1558109943.366 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:03.381Z,1558109943.381 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@50)
2019-05-17T16:19:05.002Z,1558109945.002 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@0.0)
2019-05-17T16:19:05.799Z,1558109945.799 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@0.0)
2019-05-17T16:19:06.194Z,1558109946.194 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:08.218Z,1558109948.218 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:10.234Z,1558109950.234 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:13.466Z,1558109953.466 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:16.294Z,1558109956.294 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:19.526Z,1558109959.526 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:22.354Z,1558109962.354 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:25.590Z,1558109965.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:28.414Z,1558109968.414 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:31.246Z,1558109971.246 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:33.262Z,1558109973.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:33.694Z,1558109973.694 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:19:33.694Z,1558109973.694 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-05-17T16:19:33.695Z,1558109973.695 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:19:33.706Z,1558109973.706 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:19:34.108Z,1558109974.108 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:19:34.109Z,1558109974.109 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-05-17T16:19:36.494Z,1558109976.494 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:39.322Z,1558109979.322 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:42.558Z,1558109982.558 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:45.385Z,1558109985.385 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:48.614Z,1558109988.614 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:51.446Z,1558109991.446 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:54.270Z,1558109994.270 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:56.290Z,1558109996.290 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:19:58.310Z,1558109998.310 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:01.542Z,1558110001.542 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:04.374Z,1558110004.374 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:07.606Z,1558110007.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:10.438Z,1558110010.438 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:13.666Z,1558110013.666 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:16.494Z,1558110016.494 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:19.326Z,1558110019.326 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:21.346Z,1558110021.346 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:24.574Z,1558110024.574 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:27.402Z,1558110027.402 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:30.634Z,1558110030.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:33.462Z,1558110033.462 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:36.698Z,1558110036.698 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:39.526Z,1558110039.526 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:42.350Z,1558110042.350 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:44.370Z,1558110044.370 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:47.606Z,1558110047.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:50.430Z,1558110050.430 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:53.662Z,1558110053.662 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:56.494Z,1558110056.494 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:20:59.726Z,1558110059.726 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:02.550Z,1558110062.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:05.382Z,1558110065.382 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:07.402Z,1558110067.402 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:09.422Z,1558110069.422 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:12.650Z,1558110072.650 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:15.482Z,1558110075.482 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:18.710Z,1558110078.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:21.538Z,1558110081.538 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:24.770Z,1558110084.770 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:27.598Z,1558110087.598 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:30.430Z,1558110090.430 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:32.450Z,1558110092.450 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:32.874Z,1558110092.874 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2019-05-17T16:21:33.272Z,1558110093.272 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2019-05-17T16:21:34.886Z,1558110094.886 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:21:34.886Z,1558110094.886 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-05-17T16:21:34.886Z,1558110094.886 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:21:34.898Z,1558110094.898 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:21:35.304Z,1558110095.304 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:21:35.304Z,1558110095.304 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-05-17T16:21:35.678Z,1558110095.678 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:38.510Z,1558110098.510 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:41.738Z,1558110101.738 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:44.570Z,1558110104.570 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:47.798Z,1558110107.798 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:50.626Z,1558110110.626 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:53.457Z,1558110113.457 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:55.474Z,1558110115.474 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:21:57.498Z,1558110117.498 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:00.730Z,1558110120.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:03.554Z,1558110123.554 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:06.786Z,1558110126.786 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:09.618Z,1558110129.618 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:12.850Z,1558110132.850 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:15.674Z,1558110135.674 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:18.502Z,1558110138.502 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:20.522Z,1558110140.522 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:23.754Z,1558110143.754 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:26.586Z,1558110146.586 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:29.814Z,1558110149.814 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:32.642Z,1558110152.642 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:35.878Z,1558110155.878 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:38.702Z,1558110158.702 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:41.534Z,1558110161.534 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:43.550Z,1558110163.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:45.570Z,1558110165.570 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:48.806Z,1558110168.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:51.634Z,1558110171.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:54.862Z,1558110174.862 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:22:57.694Z,1558110177.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:00.926Z,1558110180.926 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:03.754Z,1558110183.754 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:06.578Z,1558110186.578 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:08.602Z,1558110188.602 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:11.834Z,1558110191.834 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:14.661Z,1558110194.661 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:17.898Z,1558110197.898 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:20.718Z,1558110200.718 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:23.954Z,1558110203.954 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:26.778Z,1558110206.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:29.606Z,1558110209.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:31.634Z,1558110211.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:34.862Z,1558110214.862 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:36.084Z,1558110216.084 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:23:36.084Z,1558110216.084 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2019-05-17T16:23:36.084Z,1558110216.084 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:23:36.115Z,1558110216.115 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:23:36.503Z,1558110216.503 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:23:36.503Z,1558110216.503 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2019-05-17T16:23:37.686Z,1558110217.686 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:40.918Z,1558110220.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:43.750Z,1558110223.750 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:46.978Z,1558110226.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:49.810Z,1558110229.810 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:52.634Z,1558110232.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:54.654Z,1558110234.654 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:56.674Z,1558110236.674 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:23:59.910Z,1558110239.910 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:02.738Z,1558110242.738 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:05.966Z,1558110245.966 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:08.798Z,1558110248.798 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:12.026Z,1558110252.026 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:14.854Z,1558110254.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:17.682Z,1558110257.682 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:19.710Z,1558110259.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:22.934Z,1558110262.934 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:25.762Z,1558110265.762 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:28.994Z,1558110268.994 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:31.822Z,1558110271.822 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:35.058Z,1558110275.058 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:37.886Z,1558110277.886 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:40.714Z,1558110280.714 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:42.730Z,1558110282.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:44.750Z,1558110284.750 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:47.982Z,1558110287.982 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:50.814Z,1558110290.814 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:54.045Z,1558110294.045 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:24:56.870Z,1558110296.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:00.102Z,1558110300.102 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:02.934Z,1558110302.934 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:05.758Z,1558110305.758 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:07.782Z,1558110307.782 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:11.013Z,1558110311.013 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:13.838Z,1558110313.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:17.070Z,1558110317.070 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:19.898Z,1558110319.898 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:23.130Z,1558110323.130 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:25.958Z,1558110325.958 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:28.786Z,1558110328.786 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:30.814Z,1558110330.814 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:32.830Z,1558110332.830 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:36.058Z,1558110336.058 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:36.902Z,1558110336.902 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:25:36.902Z,1558110336.902 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2019-05-17T16:25:36.902Z,1558110336.902 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:25:36.941Z,1558110336.941 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:25:37.316Z,1558110337.316 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:25:37.316Z,1558110337.316 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2019-05-17T16:25:38.886Z,1558110338.886 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:42.158Z,1558110342.158 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:44.946Z,1558110344.946 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:48.182Z,1558110348.182 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:51.010Z,1558110351.010 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:53.834Z,1558110353.834 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:55.854Z,1558110355.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:25:59.086Z,1558110359.086 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:01.918Z,1558110361.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:05.150Z,1558110365.150 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:07.978Z,1558110367.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:11.210Z,1558110371.210 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:14.042Z,1558110374.042 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:16.862Z,1558110376.862 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:18.886Z,1558110378.886 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:20.906Z,1558110380.906 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:24.134Z,1558110384.134 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:26.962Z,1558110386.962 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:30.194Z,1558110390.194 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:33.022Z,1558110393.022 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:36.258Z,1558110396.258 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:39.086Z,1558110399.086 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:41.914Z,1558110401.914 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:43.934Z,1558110403.934 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:47.162Z,1558110407.162 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:49.994Z,1558110409.994 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:26:53.211Z,1558110413.211 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-17T16:26:53.211Z,1558110413.211 [NAL9602] Data Fault, FailCount= 2
2019-05-17T16:26:53.211Z,1558110413.211 [NAL9602](ERROR): Data Fault
2019-05-17T16:26:53.242Z,1558110413.242 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-17T16:26:53.619Z,1558110413.619 [NAL9602](INFO): Powering down
2019-05-17T16:26:54.457Z,1558110414.457 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-17T16:26:54.457Z,1558110414.457 [NAL9602] No Fault, FailCount= 2
2019-05-17T16:27:23.919Z,1558110443.919 [NAL9602](INFO): Powering up NAL9602
2019-05-17T16:27:34.823Z,1558110454.823 [NAL9602](INFO): NAL9602 initialized
2019-05-17T16:27:35.646Z,1558110455.646 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:38.080Z,1558110458.080 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:27:38.080Z,1558110458.080 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2019-05-17T16:27:38.080Z,1558110458.080 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:27:38.091Z,1558110458.091 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:27:38.474Z,1558110458.474 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:38.509Z,1558110458.509 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:27:38.509Z,1558110458.509 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2019-05-17T16:27:41.302Z,1558110461.302 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:44.534Z,1558110464.534 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:47.358Z,1558110467.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:50.194Z,1558110470.194 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:52.210Z,1558110472.210 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:54.230Z,1558110474.230 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:27:57.466Z,1558110477.466 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:00.290Z,1558110480.290 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:03.522Z,1558110483.522 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:06.346Z,1558110486.346 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:09.582Z,1558110489.582 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:12.406Z,1558110492.406 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:15.238Z,1558110495.238 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:17.254Z,1558110497.254 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:20.490Z,1558110500.490 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:23.318Z,1558110503.318 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:26.550Z,1558110506.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:29.374Z,1558110509.374 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:32.610Z,1558110512.610 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:35.438Z,1558110515.438 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:38.266Z,1558110518.266 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:39.404Z,1558110519.404 [CommandLine](IMPORTANT): got command show stack
2019-05-17T16:28:39.404Z,1558110519.404 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-17T16:28:39.404Z,1558110519.404 [sample](IMPORTANT): Priority 0: sample:A.AbortSample
2019-05-17T16:28:39.405Z,1558110519.405 [sample](IMPORTANT): Priority 1: sample:B.Pitch
2019-05-17T16:28:39.405Z,1558110519.405 [sample](IMPORTANT): Priority 2: sample:C.SetSpeed
2019-05-17T16:28:39.405Z,1558110519.405 [sample:SampleAtDepth:SampleWrapper](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:A.Pitch
2019-05-17T16:28:39.406Z,1558110519.406 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 4: sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP
2019-05-17T16:28:40.282Z,1558110520.282 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:42.302Z,1558110522.302 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:45.538Z,1558110525.538 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:48.264Z,1558110528.264 [CommandLine](IMPORTANT): got command stop
2019-05-17T16:28:48.264Z,1558110528.264 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-17T16:28:48.264Z,1558110528.264 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-17T16:28:48.390Z,1558110528.390 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:48.415Z,1558110528.415 [MissionManager](INFO): MissionManager is completed.
2019-05-17T16:28:48.415Z,1558110528.415 [MissionManager](INFO): Uninitializing Mission sample
2019-05-17T16:28:48.415Z,1558110528.415 [sample] Stopped
2019-05-17T16:28:48.415Z,1558110528.415 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-17T16:28:48.415Z,1558110528.415 [sample:A.AbortSample] Stopped
2019-05-17T16:28:48.415Z,1558110528.415 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-17T16:28:48.416Z,1558110528.416 [sample:B.Pitch] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:C.SetSpeed] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-17T16:28:48.416Z,1558110528.416 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-17T16:28:48.417Z,1558110528.417 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-17T16:28:48.417Z,1558110528.417 [sample:SampleRepeater] Stopped
2019-05-17T16:28:48.417Z,1558110528.417 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-17T16:28:48.417Z,1558110528.417 [sample:SampleRepeater:Sample] Stopped
2019-05-17T16:28:48.417Z,1558110528.417 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-17T16:28:48.433Z,1558110528.433 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-17T16:28:48.795Z,1558110528.795 [MissionManager](IMPORTANT): Started mission Default
2019-05-17T16:28:48.795Z,1558110528.795 [Default] Running Loop=1
2019-05-17T16:28:48.796Z,1558110528.796 [Default](DEBUG): Aggregate::initialize Default
2019-05-17T16:28:48.796Z,1558110528.796 [Default:B.GoToSurface] Running Loop=1
2019-05-17T16:28:48.796Z,1558110528.796 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-17T16:28:48.796Z,1558110528.796 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-17T16:28:48.796Z,1558110528.796 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-17T16:28:48.797Z,1558110528.797 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-17T16:28:48.797Z,1558110528.797 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-17T16:28:48.797Z,1558110528.797 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-17T16:28:48.799Z,1558110528.799 [Default:A.Wait] Running Loop=1
2019-05-17T16:28:48.799Z,1558110528.799 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:28:51.598Z,1558110531.598 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:54.422Z,1558110534.422 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:28:57.654Z,1558110537.654 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:00.482Z,1558110540.482 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:02.120Z,1558110542.120 [Default:A.Wait](INFO): Done Waiting.
2019-05-17T16:29:02.120Z,1558110542.120 [Default:A.Wait] Stopped
2019-05-17T16:29:02.120Z,1558110542.120 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:29:02.520Z,1558110542.520 [Default:CheckIn] Running Loop=1
2019-05-17T16:29:02.520Z,1558110542.520 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-17T16:29:02.520Z,1558110542.520 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-17T16:29:03.314Z,1558110543.314 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:05.330Z,1558110545.330 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:08.566Z,1558110548.566 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:11.394Z,1558110551.394 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:14.622Z,1558110554.622 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:17.450Z,1558110557.450 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:20.686Z,1558110560.686 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:23.510Z,1558110563.510 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:26.342Z,1558110566.342 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:28.358Z,1558110568.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:30.378Z,1558110570.378 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:33.614Z,1558110573.614 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:36.438Z,1558110576.438 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:39.283Z,1558110579.283 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:29:39.283Z,1558110579.283 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2019-05-17T16:29:39.283Z,1558110579.283 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:29:39.335Z,1558110579.335 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:29:39.674Z,1558110579.674 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:39.750Z,1558110579.750 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:29:39.751Z,1558110579.751 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2019-05-17T16:29:42.502Z,1558110582.502 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:45.730Z,1558110585.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:48.562Z,1558110588.562 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:51.390Z,1558110591.390 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:53.406Z,1558110593.406 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:56.638Z,1558110596.638 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:29:59.466Z,1558110599.466 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:02.702Z,1558110602.702 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:05.533Z,1558110605.533 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:08.762Z,1558110608.762 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:11.590Z,1558110611.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:14.418Z,1558110614.418 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:16.438Z,1558110616.438 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:19.666Z,1558110619.666 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:22.498Z,1558110622.498 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:25.730Z,1558110625.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:28.554Z,1558110628.554 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:31.790Z,1558110631.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:34.614Z,1558110634.614 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:37.446Z,1558110637.446 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:39.466Z,1558110639.466 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:41.486Z,1558110641.486 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:44.718Z,1558110644.718 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:47.008Z,1558110647.008 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/sample.xml
2019-05-17T16:30:47.008Z,1558110647.008 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-17T16:30:47.032Z,1558110647.032 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-17T16:30:47.035Z,1558110647.035 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-17T16:30:47.037Z,1558110647.037 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-17T16:30:47.063Z,1558110647.063 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-17T16:30:47.064Z,1558110647.064 [sample:A.AbortSample](DEBUG): Construct.
2019-05-17T16:30:47.065Z,1558110647.065 [sample:B.Pitch](DEBUG): Construct.
2019-05-17T16:30:47.074Z,1558110647.074 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-17T16:30:47.084Z,1558110647.084 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-17T16:30:47.151Z,1558110647.151 [ESPComponent](IMPORTANT): [sample #1] Stop sampling requested.
2019-05-17T16:30:47.225Z,1558110647.225 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-17T16:30:47.227Z,1558110647.227 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-17T16:30:47.230Z,1558110647.230 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-17T16:30:47.232Z,1558110647.232 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-17T16:30:47.235Z,1558110647.235 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-17T16:30:47.237Z,1558110647.237 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-17T16:30:47.239Z,1558110647.239 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-17T16:30:47.242Z,1558110647.242 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-17T16:30:47.244Z,1558110647.244 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-17T16:30:47.275Z,1558110647.275 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-17T16:30:47.284Z,1558110647.284 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:30:47.287Z,1558110647.287 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-17T16:30:47.296Z,1558110647.296 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-17T16:30:47.313Z,1558110647.313 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:30:47.328Z,1558110647.328 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:30:47.380Z,1558110647.380 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-17T16:30:47.390Z,1558110647.390 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/sample.xml
2019-05-17T16:30:47.542Z,1558110647.542 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:47.559Z,1558110647.559 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.pauseFiltering
2019-05-17T16:30:47.583Z,1558110647.583 [Default] Stopped
2019-05-17T16:30:47.584Z,1558110647.584 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-17T16:30:47.584Z,1558110647.584 [Default:B.GoToSurface] Stopped
2019-05-17T16:30:47.584Z,1558110647.584 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-17T16:30:47.584Z,1558110647.584 [Default:CheckIn] Stopped
2019-05-17T16:30:47.584Z,1558110647.584 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-17T16:30:47.584Z,1558110647.584 [Default:CheckIn:Read_GPS] Stopped
2019-05-17T16:30:47.584Z,1558110647.584 [MissionManager](IMPORTANT): Started mission sample
2019-05-17T16:30:47.584Z,1558110647.584 [sample] Running Loop=1
2019-05-17T16:30:47.585Z,1558110647.585 [sample](DEBUG): Aggregate::initialize sample
2019-05-17T16:30:47.585Z,1558110647.585 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:30:47.585Z,1558110647.585 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-17T16:30:47.585Z,1558110647.585 [sample:B.Pitch] Running Loop=1
2019-05-17T16:30:47.585Z,1558110647.585 [sample:B.Pitch](DEBUG): Initialize.
2019-05-17T16:30:47.585Z,1558110647.585 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:30:47.585Z,1558110647.585 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-17T16:30:47.585Z,1558110647.585 [sample:E] Running Loop=1
2019-05-17T16:30:47.586Z,1558110647.586 [sample:E] Stopped
2019-05-17T16:30:47.586Z,1558110647.586 [sample:F] Running Loop=1
2019-05-17T16:30:47.586Z,1558110647.586 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:30:47.586Z,1558110647.586 [sample:B.Pitch] Running Loop=1
2019-05-17T16:30:47.587Z,1558110647.587 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:30:47.595Z,1558110647.595 [Reporter](INFO): ESPComponent.stopSampling 0 bool
2019-05-17T16:30:47.983Z,1558110647.983 [sample:F] Stopped
2019-05-17T16:30:47.983Z,1558110647.983 [sample:SampleRepeater] Running Loop=1
2019-05-17T16:30:47.983Z,1558110647.983 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-17T16:30:47.984Z,1558110647.984 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-17T16:30:47.984Z,1558110647.984 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-17T16:30:48.379Z,1558110648.379 [sample:SampleAtDepth] Running Loop=1
2019-05-17T16:30:48.379Z,1558110648.379 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-17T16:30:48.380Z,1558110648.380 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-17T16:30:48.380Z,1558110648.380 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:30:48.380Z,1558110648.380 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-17T16:30:48.380Z,1558110648.380 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2019-05-17T16:30:48.380Z,1558110648.380 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-17T16:30:48.381Z,1558110648.381 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-17T16:30:48.381Z,1558110648.381 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-17T16:30:50.774Z,1558110650.774 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:52.132Z,1558110652.132 [CommandLine](IMPORTANT): got command stop
2019-05-17T16:30:52.132Z,1558110652.132 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-17T16:30:52.408Z,1558110652.408 [MissionManager](INFO): MissionManager is completed.
2019-05-17T16:30:52.409Z,1558110652.409 [MissionManager](INFO): Uninitializing Mission sample
2019-05-17T16:30:52.409Z,1558110652.409 [sample] Stopped
2019-05-17T16:30:52.409Z,1558110652.409 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-17T16:30:52.409Z,1558110652.409 [sample:A.AbortSample] Stopped
2019-05-17T16:30:52.409Z,1558110652.409 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-17T16:30:52.409Z,1558110652.409 [sample:B.Pitch] Stopped
2019-05-17T16:30:52.409Z,1558110652.409 [sample:C.SetSpeed] Stopped
2019-05-17T16:30:52.409Z,1558110652.409 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-17T16:30:52.409Z,1558110652.409 [sample:SampleAtDepth] Stopped
2019-05-17T16:30:52.409Z,1558110652.409 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-17T16:30:52.409Z,1558110652.409 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleRepeater] Stopped
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleRepeater:Sample] Stopped
2019-05-17T16:30:52.410Z,1558110652.410 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-17T16:30:52.475Z,1558110652.475 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-17T16:30:52.815Z,1558110652.815 [MissionManager](IMPORTANT): Started mission Default
2019-05-17T16:30:52.816Z,1558110652.816 [Default] Running Loop=1
2019-05-17T16:30:52.816Z,1558110652.816 [Default](DEBUG): Aggregate::initialize Default
2019-05-17T16:30:52.816Z,1558110652.816 [Default:B.GoToSurface] Running Loop=1
2019-05-17T16:30:52.816Z,1558110652.816 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-17T16:30:52.816Z,1558110652.816 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-17T16:30:52.816Z,1558110652.816 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-17T16:30:52.817Z,1558110652.817 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-17T16:30:52.817Z,1558110652.817 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-17T16:30:52.817Z,1558110652.817 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-17T16:30:52.818Z,1558110652.818 [Default:A.Wait] Running Loop=1
2019-05-17T16:30:52.818Z,1558110652.818 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:30:53.203Z,1558110653.203 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@461.424)
2019-05-17T16:30:53.203Z,1558110653.203 [ESPComponent](DEBUG): Writing sampleVolume=461.424011
2019-05-17T16:30:53.610Z,1558110653.610 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:53.625Z,1558110653.625 [ESPComponent](IMPORTANT): In S_PAUSED received result: 461.424

2019-05-17T16:30:54.028Z,1558110654.028 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@461.424)
2019-05-17T16:30:56.440Z,1558110656.440 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@50)
2019-05-17T16:30:56.838Z,1558110656.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:30:59.662Z,1558110659.662 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:02.494Z,1558110662.494 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:04.514Z,1558110664.514 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:06.142Z,1558110666.142 [Default:A.Wait](INFO): Done Waiting.
2019-05-17T16:31:06.142Z,1558110666.142 [Default:A.Wait] Stopped
2019-05-17T16:31:06.142Z,1558110666.142 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:31:06.548Z,1558110666.548 [Default:CheckIn] Running Loop=1
2019-05-17T16:31:06.548Z,1558110666.548 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-17T16:31:06.548Z,1558110666.548 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-17T16:31:07.746Z,1558110667.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:10.578Z,1558110670.578 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:13.806Z,1558110673.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:16.630Z,1558110676.630 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:19.866Z,1558110679.866 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:22.694Z,1558110682.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:25.522Z,1558110685.522 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:27.542Z,1558110687.542 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:29.558Z,1558110689.558 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:32.794Z,1558110692.794 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:35.622Z,1558110695.622 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:38.850Z,1558110698.850 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:40.480Z,1558110700.480 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:31:40.480Z,1558110700.480 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2019-05-17T16:31:40.480Z,1558110700.480 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:31:40.490Z,1558110700.490 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:31:40.899Z,1558110700.899 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:31:40.899Z,1558110700.899 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2019-05-17T16:31:41.686Z,1558110701.686 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:44.914Z,1558110704.914 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:47.742Z,1558110707.742 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:50.570Z,1558110710.570 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:52.590Z,1558110712.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:55.818Z,1558110715.818 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:31:58.650Z,1558110718.650 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:01.878Z,1558110721.878 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:04.710Z,1558110724.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:07.938Z,1558110727.938 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:10.770Z,1558110730.770 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:13.598Z,1558110733.598 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:15.618Z,1558110735.618 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:17.638Z,1558110737.638 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:20.870Z,1558110740.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:23.694Z,1558110743.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:26.930Z,1558110746.930 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:29.754Z,1558110749.754 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:32.990Z,1558110752.990 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:35.818Z,1558110755.818 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:38.646Z,1558110758.646 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:40.666Z,1558110760.666 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:43.898Z,1558110763.898 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:46.726Z,1558110766.726 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:47.820Z,1558110767.820 [CommandLine](IMPORTANT): got command report
2019-05-17T16:32:47.820Z,1558110767.820 [Reporter](INFO): ESPComponent.stopSampling reporting when touched
2019-05-17T16:32:49.958Z,1558110769.958 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:52.786Z,1558110772.786 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:56.018Z,1558110776.018 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:32:58.846Z,1558110778.846 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:01.670Z,1558110781.670 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:03.694Z,1558110783.694 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:05.315Z,1558110785.315 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@50)
2019-05-17T16:33:05.710Z,1558110785.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:08.946Z,1558110788.946 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:11.774Z,1558110791.774 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:15.006Z,1558110795.006 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:17.838Z,1558110797.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:21.066Z,1558110801.066 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:23.890Z,1558110803.890 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:26.722Z,1558110806.722 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:28.738Z,1558110808.738 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:30.360Z,1558110810.360 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2019-05-17T16:33:30.361Z,1558110810.361 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=1
2019-05-17T16:33:30.763Z,1558110810.763 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@09:18:54.41 Selecting Cartridge 50
@09:30:49.65 Cmd::Paused in FILTERING --  during Sample Pump (SP) move after sampling 461.424ml

2019-05-17T16:33:30.764Z,1558110810.764 [ESPComponent](INFO): powering down ESP
2019-05-17T16:33:30.765Z,1558110810.765 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-17T16:33:31.974Z,1558110811.974 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:34.802Z,1558110814.802 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:38.034Z,1558110818.034 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:40.862Z,1558110820.862 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:41.690Z,1558110821.690 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:33:41.690Z,1558110821.690 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2019-05-17T16:33:41.690Z,1558110821.690 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:33:41.701Z,1558110821.701 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:33:42.095Z,1558110822.095 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:33:42.095Z,1558110822.095 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2019-05-17T16:33:44.094Z,1558110824.094 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:46.918Z,1558110826.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:49.750Z,1558110829.750 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:51.766Z,1558110831.766 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:54.998Z,1558110834.998 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:33:57.830Z,1558110837.830 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:01.058Z,1558110841.058 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:03.890Z,1558110843.890 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:07.122Z,1558110847.122 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:09.950Z,1558110849.950 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:12.782Z,1558110852.782 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:14.798Z,1558110854.798 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:16.818Z,1558110856.818 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:20.050Z,1558110860.050 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:22.878Z,1558110862.878 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:26.110Z,1558110866.110 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:28.938Z,1558110868.938 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:32.166Z,1558110872.166 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:34.998Z,1558110874.998 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:37.826Z,1558110877.826 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:39.846Z,1558110879.846 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:43.078Z,1558110883.078 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:45.906Z,1558110885.906 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:49.134Z,1558110889.134 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:51.966Z,1558110891.966 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:55.198Z,1558110895.198 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:34:58.026Z,1558110898.026 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:00.850Z,1558110900.850 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:02.870Z,1558110902.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:04.894Z,1558110904.894 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:08.126Z,1558110908.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:10.954Z,1558110910.954 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:14.182Z,1558110914.182 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:17.014Z,1558110917.014 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:20.246Z,1558110920.246 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:23.074Z,1558110923.074 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:25.902Z,1558110925.902 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:27.918Z,1558110927.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:31.150Z,1558110931.150 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:33.978Z,1558110933.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:37.210Z,1558110937.210 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:40.038Z,1558110940.038 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:42.884Z,1558110942.884 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:35:42.884Z,1558110942.884 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15
2019-05-17T16:35:42.884Z,1558110942.884 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:35:42.895Z,1558110942.895 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:35:43.278Z,1558110943.278 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:43.316Z,1558110943.316 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:35:43.316Z,1558110943.316 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15
2019-05-17T16:35:46.098Z,1558110946.098 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:48.930Z,1558110948.930 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:50.946Z,1558110950.946 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:52.970Z,1558110952.970 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:56.202Z,1558110956.202 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:35:59.030Z,1558110959.030 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:02.258Z,1558110962.258 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:05.090Z,1558110965.090 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:06.719Z,1558110966.719 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-17T16:31:06.5Z
2019-05-17T16:36:06.719Z,1558110966.719 [Default:CheckIn:Read_GPS] Stopped
2019-05-17T16:36:06.719Z,1558110966.719 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-17T16:36:07.134Z,1558110967.134 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-17T16:36:08.386Z,1558110968.386 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:11.210Z,1558110971.210 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:14.042Z,1558110974.042 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:17.270Z,1558110977.270 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:20.102Z,1558110980.102 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:23.330Z,1558110983.330 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:26.158Z,1558110986.158 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:28.990Z,1558110988.990 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:31.006Z,1558110991.006 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:33.026Z,1558110993.026 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:36.262Z,1558110996.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:39.086Z,1558110999.086 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:42.322Z,1558111002.322 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:45.146Z,1558111005.146 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:46.509Z,1558111006.509 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190517T160517/Courier0004.lzma
2019-05-17T16:36:47.315Z,1558111007.315 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Courier0004.lzma.bak
2019-05-17T16:36:47.316Z,1558111007.316 [DataOverHttps](INFO): SBD MOMSN=11095069
2019-05-17T16:36:48.378Z,1558111008.378 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:51.206Z,1558111011.206 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:54.038Z,1558111014.038 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:56.054Z,1558111016.054 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:36:58.273Z,1558111018.273 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190517T160517/Courier0007.lzma
2019-05-17T16:36:59.079Z,1558111019.079 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Courier0007.lzma.bak
2019-05-17T16:36:59.080Z,1558111019.080 [DataOverHttps](INFO): SBD MOMSN=11095075
2019-05-17T16:36:59.286Z,1558111019.286 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:02.114Z,1558111022.114 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:05.346Z,1558111025.346 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:08.178Z,1558111028.178 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:11.406Z,1558111031.406 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:12.453Z,1558111032.453 [DataOverHttps](INFO): Sending 2345 bytes from file Logs/20190517T160517/Express0005.lzma
2019-05-17T16:37:13.255Z,1558111033.255 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Express0005.lzma.bak
2019-05-17T16:37:13.256Z,1558111033.256 [DataOverHttps](INFO): SBD MOMSN=11095105
2019-05-17T16:37:14.237Z,1558111034.237 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:14.956Z,1558111034.956 [CommandLine](IMPORTANT): got command report 
2019-05-17T16:37:14.956Z,1558111034.956 [Reporter](INFO): ESPComponent.stopSampling reporting when touched
2019-05-17T16:37:17.062Z,1558111037.062 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:19.082Z,1558111039.082 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:21.102Z,1558111041.102 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:21.610Z,1558111041.610 [CommandLine](IMPORTANT): got command get ESPComponent.stopSampling
2019-05-17T16:37:21.611Z,1558111041.611 [CommandLine](IMPORTANT): ESPComponent.stopSampling 1 bool
2019-05-17T16:37:24.334Z,1558111044.334 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:26.089Z,1558111046.089 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190517T160517/Express0008.lzma
2019-05-17T16:37:26.895Z,1558111046.895 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Express0008.lzma.bak
2019-05-17T16:37:26.896Z,1558111046.896 [DataOverHttps](INFO): SBD MOMSN=11095226
2019-05-17T16:37:27.170Z,1558111047.170 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:29.603Z,1558111049.603 [Default:CheckIn:Read_Iridium] Stopped
2019-05-17T16:37:29.603Z,1558111049.603 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-17T16:37:29.603Z,1558111049.603 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:37:30.394Z,1558111050.394 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:33.222Z,1558111053.222 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:37:36.447Z,1558111056.447 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-17T16:37:36.447Z,1558111056.447 [NAL9602] Data Fault, FailCount= 3
2019-05-17T16:37:36.447Z,1558111056.447 [NAL9602](ERROR): Data Fault
2019-05-17T16:37:36.476Z,1558111056.476 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-17T16:37:36.847Z,1558111056.847 [NAL9602](INFO): Powering down
2019-05-17T16:37:37.688Z,1558111057.688 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-17T16:37:37.689Z,1558111057.689 [NAL9602] No Fault, FailCount= 3
2019-05-17T16:37:43.731Z,1558111063.731 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:37:43.731Z,1558111063.731 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16
2019-05-17T16:37:43.731Z,1558111063.731 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:37:43.742Z,1558111063.742 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:37:44.155Z,1558111064.155 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:37:44.156Z,1558111064.156 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16
2019-05-17T16:38:07.147Z,1558111087.147 [NAL9602](INFO): Powering up NAL9602
2019-05-17T16:38:18.059Z,1558111098.059 [NAL9602](INFO): NAL9602 initialized
2019-05-17T16:38:18.874Z,1558111098.874 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:21.706Z,1558111101.706 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:24.534Z,1558111104.534 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:27.766Z,1558111107.766 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:30.594Z,1558111110.594 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:33.422Z,1558111113.422 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:35.442Z,1558111115.442 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:37.462Z,1558111117.462 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:40.690Z,1558111120.690 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:43.522Z,1558111123.522 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:46.750Z,1558111126.750 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:49.582Z,1558111129.582 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:52.810Z,1558111132.810 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:55.642Z,1558111135.642 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:38:58.470Z,1558111138.470 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:00.489Z,1558111140.489 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:03.718Z,1558111143.718 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:06.550Z,1558111146.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:09.778Z,1558111149.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:12.606Z,1558111152.606 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:15.838Z,1558111155.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:18.670Z,1558111158.670 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:21.498Z,1558111161.498 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:23.518Z,1558111163.518 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:26.746Z,1558111166.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:29.578Z,1558111169.578 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:32.806Z,1558111172.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:35.638Z,1558111175.638 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:38.866Z,1558111178.866 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:41.698Z,1558111181.698 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:44.526Z,1558111184.526 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:44.945Z,1558111184.945 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:39:44.945Z,1558111184.945 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17
2019-05-17T16:39:44.945Z,1558111184.945 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:39:44.955Z,1558111184.955 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:39:45.363Z,1558111185.363 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:39:45.363Z,1558111185.363 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17
2019-05-17T16:39:46.550Z,1558111186.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:48.570Z,1558111188.570 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:51.798Z,1558111191.798 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:54.630Z,1558111194.630 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:39:57.858Z,1558111197.858 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:00.682Z,1558111200.682 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:03.918Z,1558111203.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:06.742Z,1558111206.742 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:09.570Z,1558111209.570 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:11.590Z,1558111211.590 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:14.826Z,1558111214.826 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:17.654Z,1558111217.654 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:20.886Z,1558111220.886 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:23.710Z,1558111223.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:26.950Z,1558111226.950 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:29.770Z,1558111229.770 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:32.602Z,1558111232.602 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:34.622Z,1558111234.622 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:36.642Z,1558111236.642 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:39.870Z,1558111239.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:42.702Z,1558111242.702 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:45.934Z,1558111245.934 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:48.762Z,1558111248.762 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:51.994Z,1558111251.994 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:54.822Z,1558111254.822 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:57.646Z,1558111257.646 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:40:59.670Z,1558111259.670 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:02.902Z,1558111262.902 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:05.730Z,1558111265.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:08.962Z,1558111268.962 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:11.790Z,1558111271.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:15.022Z,1558111275.022 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:17.854Z,1558111277.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:20.674Z,1558111280.674 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:22.698Z,1558111282.698 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:24.718Z,1558111284.718 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:27.950Z,1558111287.950 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:30.778Z,1558111290.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:34.010Z,1558111294.010 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:36.838Z,1558111296.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:40.070Z,1558111300.070 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:42.898Z,1558111302.898 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:45.730Z,1558111305.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:46.153Z,1558111306.153 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:41:46.153Z,1558111306.153 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18
2019-05-17T16:41:46.153Z,1558111306.153 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:41:46.164Z,1558111306.164 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:41:46.567Z,1558111306.567 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:41:46.568Z,1558111306.568 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18
2019-05-17T16:41:47.746Z,1558111307.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:50.974Z,1558111310.974 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:53.802Z,1558111313.802 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:57.034Z,1558111317.034 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:41:59.866Z,1558111319.866 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:03.094Z,1558111323.094 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:05.926Z,1558111325.926 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:08.754Z,1558111328.754 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:10.774Z,1558111330.774 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:12.790Z,1558111332.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:16.026Z,1558111336.026 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:18.850Z,1558111338.850 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:22.086Z,1558111342.086 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:24.910Z,1558111344.910 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:28.150Z,1558111348.150 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:30.177Z,1558111350.177 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-17T16:42:30.177Z,1558111350.177 [Default:CheckIn:C.Wait] Stopped
2019-05-17T16:42:30.177Z,1558111350.177 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:42:30.177Z,1558111350.177 [Default:CheckIn:D] Running Loop=1
2019-05-17T16:42:30.579Z,1558111350.579 [Default:CheckIn:D] Stopped
2019-05-17T16:42:30.579Z,1558111350.579 [Default:CheckIn:E] Running Loop=1
2019-05-17T16:42:30.970Z,1558111350.970 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:30.991Z,1558111350.991 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.629391 min 
2019-05-17T16:42:30.991Z,1558111350.991 [Default:CheckIn:E] Stopped
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn] Stopped
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn](INFO): Running loop #2
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn] Running Loop=2
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-17T16:42:30.992Z,1558111350.992 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-17T16:42:33.798Z,1558111353.798 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:35.818Z,1558111355.818 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:39.054Z,1558111359.054 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:41.878Z,1558111361.878 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:44.115Z,1558111364.115 [DataOverHttps](IMPORTANT): SBD MTMSN=20190517T164234
2019-05-17T16:42:45.118Z,1558111365.118 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:47.938Z,1558111367.938 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:48.894Z,1558111368.894 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-17T16:42:48.907Z,1558111368.907 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-17T16:42:48.907Z,1558111368.907 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-17T16:42:48.929Z,1558111368.929 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-17T16:42:48.931Z,1558111368.931 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-17T16:42:48.933Z,1558111368.933 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-17T16:42:48.936Z,1558111368.936 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-17T16:42:48.937Z,1558111368.937 [sample:A.AbortSample](DEBUG): Construct.
2019-05-17T16:42:48.938Z,1558111368.938 [sample:B.Pitch](DEBUG): Construct.
2019-05-17T16:42:48.942Z,1558111368.942 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-17T16:42:48.944Z,1558111368.944 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-17T16:42:49.039Z,1558111369.039 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-17T16:42:49.041Z,1558111369.041 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-17T16:42:49.043Z,1558111369.043 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-17T16:42:49.045Z,1558111369.045 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-17T16:42:49.048Z,1558111369.048 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-17T16:42:49.088Z,1558111369.088 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-17T16:42:49.090Z,1558111369.090 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-17T16:42:49.093Z,1558111369.093 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-17T16:42:49.096Z,1558111369.096 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-17T16:42:49.098Z,1558111369.098 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-17T16:42:49.103Z,1558111369.103 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:42:49.105Z,1558111369.105 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-17T16:42:49.110Z,1558111369.110 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-17T16:42:49.117Z,1558111369.117 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:42:49.123Z,1558111369.123 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-17T16:42:49.227Z,1558111369.227 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-17T16:42:49.227Z,1558111369.227 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-17T16:42:51.170Z,1558111371.170 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:53.369Z,1558111373.369 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-17T16:42:53.371Z,1558111373.371 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-17T16:42:53.372Z,1558111373.372 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-17T16:42:53.372Z,1558111373.372 [CommandLine](IMPORTANT): got command run 
2019-05-17T16:42:53.379Z,1558111373.379 [CommandLine](IMPORTANT): Running 
2019-05-17T16:42:53.612Z,1558111373.612 [Default] Stopped
2019-05-17T16:42:53.612Z,1558111373.612 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-17T16:42:53.612Z,1558111373.612 [Default:B.GoToSurface] Stopped
2019-05-17T16:42:53.613Z,1558111373.613 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-17T16:42:53.613Z,1558111373.613 [Default:CheckIn] Stopped
2019-05-17T16:42:53.613Z,1558111373.613 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-17T16:42:53.613Z,1558111373.613 [Default:CheckIn:Read_GPS] Stopped
2019-05-17T16:42:53.613Z,1558111373.613 [MissionManager](IMPORTANT): Started mission sample
2019-05-17T16:42:53.613Z,1558111373.613 [sample] Running Loop=1
2019-05-17T16:42:53.613Z,1558111373.613 [sample](DEBUG): Aggregate::initialize sample
2019-05-17T16:42:53.613Z,1558111373.613 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:42:53.614Z,1558111373.614 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-17T16:42:53.614Z,1558111373.614 [sample:B.Pitch] Running Loop=1
2019-05-17T16:42:53.614Z,1558111373.614 [sample:B.Pitch](DEBUG): Initialize.
2019-05-17T16:42:53.614Z,1558111373.614 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:42:53.614Z,1558111373.614 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-17T16:42:53.614Z,1558111373.614 [sample:E] Running Loop=1
2019-05-17T16:42:53.615Z,1558111373.615 [sample:E] Stopped
2019-05-17T16:42:53.615Z,1558111373.615 [sample:F] Running Loop=1
2019-05-17T16:42:53.615Z,1558111373.615 [sample:C.SetSpeed] Running Loop=1
2019-05-17T16:42:53.615Z,1558111373.615 [sample:B.Pitch] Running Loop=1
2019-05-17T16:42:53.616Z,1558111373.616 [sample:A.AbortSample] Running Loop=1
2019-05-17T16:42:53.625Z,1558111373.625 [Reporter](INFO): ESPComponent.stopSampling 0 bool
2019-05-17T16:42:54.006Z,1558111374.006 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:54.029Z,1558111374.029 [sample:F] Stopped
2019-05-17T16:42:54.029Z,1558111374.029 [sample:SampleRepeater] Running Loop=1
2019-05-17T16:42:54.030Z,1558111374.030 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-17T16:42:54.030Z,1558111374.030 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-17T16:42:54.030Z,1558111374.030 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-17T16:42:54.431Z,1558111374.431 [sample:SampleAtDepth] Running Loop=1
2019-05-17T16:42:54.431Z,1558111374.431 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-17T16:42:54.432Z,1558111374.432 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-17T16:42:54.432Z,1558111374.432 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:42:54.432Z,1558111374.432 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-17T16:42:54.432Z,1558111374.432 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-17T16:42:54.433Z,1558111374.433 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-17T16:42:54.433Z,1558111374.433 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-17T16:42:54.433Z,1558111374.433 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-17T16:42:54.835Z,1558111374.835 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-17T16:42:54.836Z,1558111374.836 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-17T16:42:54.837Z,1558111374.837 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-17T16:42:55.226Z,1558111375.226 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-17T16:42:55.227Z,1558111375.227 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-17T16:42:55.227Z,1558111375.227 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-17T16:42:55.227Z,1558111375.227 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:42:55.227Z,1558111375.227 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-17T16:42:56.826Z,1558111376.826 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:58.846Z,1558111378.846 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-17T16:42:58.873Z,1558111378.873 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-17T16:42:59.287Z,1558111379.287 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-17T16:42:59.680Z,1558111379.680 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-17T16:43:00.870Z,1558111380.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:00.955Z,1558111380.955 [ESPComponent](INFO): powering up ESP
2019-05-17T16:43:00.955Z,1558111380.955 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-17T16:43:00.956Z,1558111380.956 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-05-17T16:43:01.032Z,1558111381.032 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-17T16:43:01.352Z,1558111381.352 [ESPComponent](INFO): console:
2019-05-17T16:43:02.085Z,1558111382.085 [ESPComponent](INFO): console:

2019-05-17T16:43:02.487Z,1558111382.487 [ESPComponent](INFO): console:NAND:  256 MiB
2019-05-17T16:43:02.895Z,1558111382.895 [ESPComponent](INFO): console:
BOOTMODE: SPI
2019-05-17T16:43:03.366Z,1558111383.366 [ESPComponent](INFO): console:
reading SPI NOR..
2019-05-17T16:43:04.098Z,1558111384.098 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:04.521Z,1558111384.521 [ESPComponent](INFO): console:Done
2019-05-17T16:43:04.921Z,1558111384.921 [ESPComponent](INFO): console:

2019-05-17T16:43:05.318Z,1558111385.318 [ESPComponent](INFO): console:

2019-05-17T16:43:05.724Z,1558111385.724 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 13:08:14)
2019-05-17T16:43:06.127Z,1558111386.127 [ESPComponent](INFO): console:

2019-05-17T16:43:06.531Z,1558111386.531 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-05-17T16:43:06.930Z,1558111386.930 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:06.945Z,1558111386.945 [ESPComponent](INFO): console:
flash params are already written into flash
2019-05-17T16:43:07.349Z,1558111387.349 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-05-17T16:43:07.753Z,1558111387.753 [ESPComponent](INFO): console:
In:    serial
2019-05-17T16:43:08.143Z,1558111388.143 [ESPComponent](INFO): console:
Out:   serial
2019-05-17T16:43:08.548Z,1558111388.548 [ESPComponent](INFO): console:
Err:   serial
2019-05-17T16:43:08.954Z,1558111388.954 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-05-17T16:43:09.372Z,1558111389.372 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-05-17T16:43:09.763Z,1558111389.763 [ESPComponent](INFO): console:
mmc1 is available
2019-05-17T16:43:10.162Z,1558111390.162 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:10.178Z,1558111390.178 [ESPComponent](INFO): console:
reading uImage
2019-05-17T16:43:10.581Z,1558111390.581 [ESPComponent](INFO): console:

2019-05-17T16:43:10.981Z,1558111390.981 [ESPComponent](INFO): console:
1681452 bytes read
2019-05-17T16:43:11.383Z,1558111391.383 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-05-17T16:43:11.815Z,1558111391.815 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-05-17T16:43:12.189Z,1558111392.189 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-05-17T16:43:12.588Z,1558111392.588 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-05-17T16:43:12.986Z,1558111392.986 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:13.001Z,1558111393.001 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-05-17T16:43:13.413Z,1558111393.413 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-05-17T16:43:13.814Z,1558111393.814 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-05-17T16:43:14.203Z,1558111394.203 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-05-17T16:43:14.612Z,1558111394.612 [ESPComponent](INFO): console:
OK
2019-05-17T16:43:15.012Z,1558111395.012 [ESPComponent](INFO): console:

2019-05-17T16:43:15.419Z,1558111395.419 [ESPComponent](INFO): console:
Starting kernel ...
2019-05-17T16:43:15.819Z,1558111395.819 [ESPComponent](INFO): console:

2019-05-17T16:43:16.218Z,1558111396.218 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:16.235Z,1558111396.235 [ESPComponent](INFO): console:
Uncompressing Linux... done, booting the kernel.
2019-05-17T16:43:16.642Z,1558111396.642 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-05-17T16:43:17.042Z,1558111397.042 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT data cache, VIVT instruction cache
2019-05-17T16:43:17.435Z,1558111397.435 [ESPComponent](INFO): console:
[    0.00] Machine: NXP EA313X
2019-05-17T16:43:17.839Z,1558111397.839 [ESPComponent](INFO): console:
[    0.00] Memory policy: ECC disabled, Data cache writeback
2019-05-17T16:43:18.245Z,1558111398.245 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-05-17T16:43:18.656Z,1558111398.656 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-05-17T16:43:19.046Z,1558111399.046 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:19.066Z,1558111399.066 [ESPComponent](INFO): console:
[    0.30] MBARI ESP 3G
2019-05-17T16:43:19.476Z,1558111399.476 [ESPComponent](INFO): console:
[    0.40] bio: create slab <bio-0> at 0
2019-05-17T16:43:19.877Z,1558111399.877 [ESPComponent](INFO): console:
[    0.47] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:20.268Z,1558111400.268 [ESPComponent](INFO): console:
[    0.49] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:20.668Z,1558111400.668 [ESPComponent](INFO): console:
[    0.51] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:21.077Z,1558111401.077 [ESPComponent](INFO): console:
[    0.53] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:21.476Z,1558111401.476 [ESPComponent](INFO): console:
[    0.55] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:21.878Z,1558111401.878 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:21.895Z,1558111401.895 [ESPComponent](INFO): console:
[    0.57] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-17T16:43:22.302Z,1558111402.302 [ESPComponent](INFO): console:
[    0.57] NetWinder Floating Point Emulator V0.97 (double precision)
2019-05-17T16:43:22.706Z,1558111402.706 [ESPComponent](INFO): console:
[    0.59] yaffs Dec 14 2018 09:19:05 Installing. 
2019-05-17T16:43:23.096Z,1558111403.096 [ESPComponent](INFO): console:
[    0.73] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-05-17T16:43:23.500Z,1558111403.500 [ESPComponent](INFO): console:
[    2.44] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-05-17T16:43:23.902Z,1558111403.902 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:23.918Z,1558111403.918 [ESPComponent](INFO): console:

2019-05-17T16:43:24.317Z,1558111404.317 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-05-17T16:43:24.717Z,1558111404.717 [ESPComponent](INFO): console:

2019-05-17T16:43:25.112Z,1558111405.112 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-17T16:43:25.518Z,1558111405.518 [ESPComponent](INFO): console:
ESPmv1
2019-05-17T16:43:25.926Z,1558111405.926 [ESPComponent](INFO): console:

2019-05-17T16:43:26.327Z,1558111406.327 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-05-17T16:43:26.731Z,1558111406.731 [ESPComponent](INFO): console:

2019-05-17T16:43:27.126Z,1558111407.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:27.142Z,1558111407.142 [ESPComponent](INFO): console:Loading kernel modules
2019-05-17T16:43:27.551Z,1558111407.551 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-05-17T16:43:27.950Z,1558111407.950 [ESPComponent](INFO): console:
mount: /dev/mmcblk0p2 already mounted or /card busy
2019-05-17T16:43:28.344Z,1558111408.344 [ESPComponent](INFO): console:
Starting hotplug events dispatcher udevd
2019-05-17T16:43:28.748Z,1558111408.748 [ESPComponent](INFO): console:
Set system clock to:  Fri May 17 09:43:13 PDT 2019
2019-05-17T16:43:29.156Z,1558111409.156 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-05-17T16:43:29.559Z,1558111409.559 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-05-17T16:43:29.958Z,1558111409.958 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:29.973Z,1558111409.973 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-05-17T16:43:30.381Z,1558111410.381 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-05-17T16:43:30.778Z,1558111410.778 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-05-17T16:43:31.174Z,1558111411.174 [ESPComponent](INFO): console:
Starting portmap...
2019-05-17T16:43:31.574Z,1558111411.574 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-05-17T16:43:31.981Z,1558111411.981 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2019-05-17T16:43:32.388Z,1558111412.388 [ESPComponent](INFO): console:
Network unavailable:  Local time is Fri May 17 09:43:15 PDT 2019
2019-05-17T16:43:32.788Z,1558111412.788 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-05-17T16:43:33.186Z,1558111413.186 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:33.201Z,1558111413.201 [ESPComponent](INFO): console:
Starting thttpd...
2019-05-17T16:43:33.609Z,1558111413.609 [ESPComponent](INFO): console:
Sending discover...
2019-05-17T16:43:34.013Z,1558111414.013 [ESPComponent](INFO): console:

2019-05-17T16:43:34.403Z,1558111414.403 [ESPComponent](INFO): console:

2019-05-17T16:43:34.806Z,1558111414.806 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-17T16:43:35.629Z,1558111415.629 [ESPComponent](IMPORTANT): [sample #2] Explicit cartridge argument not given
2019-05-17T16:43:35.629Z,1558111415.629 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-17T16:43:35.629Z,1558111415.629 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2
2019-05-17T16:43:35.644Z,1558111415.644 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-17T16:43:35.644Z,1558111415.644 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-17T16:43:36.021Z,1558111416.021 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:36.048Z,1558111416.048 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-17T16:43:36.049Z,1558111416.049 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-17T16:43:36.049Z,1558111416.049 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-17T16:43:36.049Z,1558111416.049 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-17T16:43:36.049Z,1558111416.049 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-17T16:43:36.447Z,1558111416.447 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG
2019-05-17T16:43:36.460Z,1558111416.460 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-17T16:43:36.837Z,1558111416.837 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-05-17T16:43:38.849Z,1558111418.849 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE
2019-05-17T16:43:39.249Z,1558111419.249 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:42.078Z,1558111422.078 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:44.460Z,1558111424.460 [CommandLine](IMPORTANT): got command stop
2019-05-17T16:43:44.460Z,1558111424.460 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-17T16:43:44.516Z,1558111424.516 [MissionManager](INFO): MissionManager is completed.
2019-05-17T16:43:44.517Z,1558111424.517 [MissionManager](INFO): Uninitializing Mission sample
2019-05-17T16:43:44.517Z,1558111424.517 [sample] Stopped
2019-05-17T16:43:44.517Z,1558111424.517 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-17T16:43:44.517Z,1558111424.517 [sample:A.AbortSample] Stopped
2019-05-17T16:43:44.517Z,1558111424.517 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-17T16:43:44.517Z,1558111424.517 [sample:B.Pitch] Stopped
2019-05-17T16:43:44.517Z,1558111424.517 [sample:C.SetSpeed] Stopped
2019-05-17T16:43:44.517Z,1558111424.517 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-17T16:43:44.517Z,1558111424.517 [sample:SampleAtDepth] Stopped
2019-05-17T16:43:44.517Z,1558111424.517 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-17T16:43:44.517Z,1558111424.517 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleRepeater] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleRepeater:Sample] Stopped
2019-05-17T16:43:44.518Z,1558111424.518 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-17T16:43:44.578Z,1558111424.578 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-17T16:43:44.902Z,1558111424.902 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:44.931Z,1558111424.931 [MissionManager](IMPORTANT): Started mission Default
2019-05-17T16:43:44.932Z,1558111424.932 [Default] Running Loop=1
2019-05-17T16:43:44.932Z,1558111424.932 [Default](DEBUG): Aggregate::initialize Default
2019-05-17T16:43:44.932Z,1558111424.932 [Default:B.GoToSurface] Running Loop=1
2019-05-17T16:43:44.932Z,1558111424.932 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-17T16:43:44.932Z,1558111424.932 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-17T16:43:44.933Z,1558111424.933 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-17T16:43:44.933Z,1558111424.933 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-17T16:43:44.933Z,1558111424.933 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-17T16:43:44.933Z,1558111424.933 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-17T16:43:44.934Z,1558111424.934 [Default:A.Wait] Running Loop=1
2019-05-17T16:43:44.934Z,1558111424.934 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:43:46.922Z,1558111426.922 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:46.963Z,1558111426.963 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:43:46.963Z,1558111426.963 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19
2019-05-17T16:43:46.963Z,1558111426.963 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:43:47.011Z,1558111427.011 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:43:47.411Z,1558111427.411 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-17T16:43:47.411Z,1558111427.411 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19
2019-05-17T16:43:48.942Z,1558111428.942 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:52.174Z,1558111432.174 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:55.006Z,1558111435.006 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:58.238Z,1558111438.238 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:43:58.268Z,1558111438.268 [Default:A.Wait](INFO): Done Waiting.
2019-05-17T16:43:58.268Z,1558111438.268 [Default:A.Wait] Stopped
2019-05-17T16:43:58.268Z,1558111438.268 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:43:58.672Z,1558111438.672 [Default:CheckIn] Running Loop=1
2019-05-17T16:43:58.672Z,1558111438.672 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-17T16:43:58.672Z,1558111438.672 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-17T16:44:01.066Z,1558111441.066 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:04.298Z,1558111444.298 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:07.126Z,1558111447.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:09.950Z,1558111449.950 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:10.780Z,1558111450.780 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PRIMING (@40)
2019-05-17T16:44:11.970Z,1558111451.970 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:12.393Z,1558111452.393 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PRIMING (@0.0)
2019-05-17T16:44:13.188Z,1558111453.188 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_FILTERING (@0.0)
2019-05-17T16:44:15.206Z,1558111455.206 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:18.030Z,1558111458.030 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:21.262Z,1558111461.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:23.792Z,1558111463.792 [CommandLine](IMPORTANT): got command get ESPComponent.stopSampling
2019-05-17T16:44:23.793Z,1558111463.793 [CommandLine](IMPORTANT): ESPComponent.stopSampling 1 bool
2019-05-17T16:44:24.094Z,1558111464.094 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:27.326Z,1558111467.326 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:30.150Z,1558111470.150 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:32.978Z,1558111472.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:35.002Z,1558111475.002 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:38.230Z,1558111478.230 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:41.066Z,1558111481.066 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:44.294Z,1558111484.294 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:47.126Z,1558111487.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:50.354Z,1558111490.354 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:53.178Z,1558111493.178 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:56.010Z,1558111496.010 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:44:58.030Z,1558111498.030 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:00.050Z,1558111500.050 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:03.282Z,1558111503.282 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:06.110Z,1558111506.110 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:09.342Z,1558111509.342 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:12.170Z,1558111512.170 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:15.398Z,1558111515.398 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:18.226Z,1558111518.226 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:21.054Z,1558111521.054 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:23.074Z,1558111523.074 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:26.306Z,1558111526.306 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:29.142Z,1558111529.142 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:32.370Z,1558111532.370 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:35.194Z,1558111535.194 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:38.426Z,1558111538.426 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:41.258Z,1558111541.258 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:44.082Z,1558111544.082 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:46.106Z,1558111546.106 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:48.122Z,1558111548.122 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:48.158Z,1558111548.158 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-17T16:45:48.162Z,1558111548.162 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20
2019-05-17T16:45:48.162Z,1558111548.162 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-17T16:45:48.180Z,1558111548.180 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:45:48.181Z,1558111548.181 [CBIT](FAULT): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-17T16:45:51.358Z,1558111551.358 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:54.182Z,1558111554.182 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:45:57.418Z,1558111557.418 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:00.246Z,1558111560.246 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:03.478Z,1558111563.478 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:06.302Z,1558111566.302 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:09.134Z,1558111569.134 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:11.150Z,1558111571.150 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:14.386Z,1558111574.386 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:17.214Z,1558111577.214 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:20.442Z,1558111580.442 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:23.270Z,1558111583.270 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:26.506Z,1558111586.506 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:29.330Z,1558111589.330 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:32.158Z,1558111592.158 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:34.182Z,1558111594.182 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:36.202Z,1558111596.202 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:39.434Z,1558111599.434 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:40.257Z,1558111600.257 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_FILTERING (@0.0)
2019-05-17T16:46:40.649Z,1558111600.649 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2019-05-17T16:46:42.262Z,1558111602.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:45.494Z,1558111605.494 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:48.318Z,1558111608.318 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:51.554Z,1558111611.554 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:54.382Z,1558111614.382 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:57.206Z,1558111617.206 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:46:59.230Z,1558111619.230 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:02.462Z,1558111622.462 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:05.290Z,1558111625.290 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:08.523Z,1558111628.523 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:11.350Z,1558111631.350 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:14.582Z,1558111634.582 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:17.410Z,1558111637.410 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:20.234Z,1558111640.234 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:22.262Z,1558111642.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:25.490Z,1558111645.490 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:28.318Z,1558111648.318 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:31.550Z,1558111651.550 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:34.378Z,1558111654.378 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:37.610Z,1558111657.610 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:40.442Z,1558111660.442 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:43.262Z,1558111663.262 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:45.286Z,1558111665.286 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:47.306Z,1558111667.306 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:50.534Z,1558111670.534 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:53.366Z,1558111673.366 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:56.598Z,1558111676.598 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:47:59.430Z,1558111679.430 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:02.658Z,1558111682.658 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:05.482Z,1558111685.482 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:08.314Z,1558111688.314 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:10.334Z,1558111690.334 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:13.562Z,1558111693.562 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:16.394Z,1558111696.394 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:48:19.611Z,1558111699.611 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-17T16:48:19.611Z,1558111699.611 [NAL9602] Data Fault, FailCount= 4
2019-05-17T16:48:19.611Z,1558111699.611 [NAL9602](ERROR): Data Fault
2019-05-17T16:48:19.652Z,1558111699.652 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-17T16:48:20.017Z,1558111700.017 [NAL9602](INFO): Powering down
2019-05-17T16:48:20.883Z,1558111700.883 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-17T16:48:20.883Z,1558111700.883 [NAL9602] No Fault, FailCount= 4
2019-05-17T16:48:50.315Z,1558111730.315 [NAL9602](INFO): Powering up NAL9602
2019-05-17T16:48:58.823Z,1558111738.823 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-17T16:43:58.7Z
2019-05-17T16:48:58.823Z,1558111738.823 [Default:CheckIn:Read_GPS] Stopped
2019-05-17T16:48:58.824Z,1558111738.824 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-17T16:49:01.233Z,1558111741.233 [NAL9602](INFO): NAL9602 initialized
2019-05-17T16:49:02.042Z,1558111742.042 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:04.870Z,1558111744.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:05.473Z,1558111745.473 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190517T160517/Courier0009.lzma
2019-05-17T16:49:06.279Z,1558111746.279 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Courier0009.lzma.bak
2019-05-17T16:49:06.279Z,1558111746.279 [DataOverHttps](INFO): SBD MOMSN=11095297
2019-05-17T16:49:07.698Z,1558111747.698 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:10.930Z,1558111750.930 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:13.758Z,1558111753.758 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:16.586Z,1558111756.586 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:17.765Z,1558111757.765 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190517T160517/Courier0013.lzma
2019-05-17T16:49:18.571Z,1558111758.571 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Courier0013.lzma.bak
2019-05-17T16:49:18.572Z,1558111758.572 [DataOverHttps](INFO): SBD MOMSN=11095299
2019-05-17T16:49:18.611Z,1558111758.611 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:20.626Z,1558111760.626 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:23.858Z,1558111763.858 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:26.686Z,1558111766.686 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:29.918Z,1558111769.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:31.417Z,1558111771.417 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190517T160517/Express0010.lzma
2019-05-17T16:49:32.223Z,1558111772.223 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Express0010.lzma.bak
2019-05-17T16:49:32.224Z,1558111772.224 [DataOverHttps](INFO): SBD MOMSN=11095301
2019-05-17T16:49:32.746Z,1558111772.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:35.978Z,1558111775.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:38.806Z,1558111778.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:41.634Z,1558111781.634 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:43.654Z,1558111783.654 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:45.125Z,1558111785.125 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20190517T160517/Express0014.lzma
2019-05-17T16:49:45.931Z,1558111785.931 [DataOverHttps](INFO): Moved sent file to Logs/20190517T160517/Express0014.lzma.bak
2019-05-17T16:49:45.932Z,1558111785.932 [DataOverHttps](INFO): SBD MOMSN=11095303
2019-05-17T16:49:46.886Z,1558111786.886 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:48.930Z,1558111788.930 [Default:CheckIn:Read_Iridium] Stopped
2019-05-17T16:49:48.934Z,1558111788.934 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-17T16:49:48.934Z,1558111788.934 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-17T16:49:49.714Z,1558111789.714 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:52.946Z,1558111792.946 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:55.778Z,1558111795.778 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:49:59.006Z,1558111799.006 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:01.838Z,1558111801.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:04.666Z,1558111804.666 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:06.686Z,1558111806.686 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:09.918Z,1558111809.918 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:12.746Z,1558111812.746 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:15.978Z,1558111815.978 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:18.806Z,1558111818.806 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:22.038Z,1558111822.038 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:24.862Z,1558111824.862 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:27.690Z,1558111827.690 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:29.710Z,1558111829.710 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:31.730Z,1558111831.730 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:34.966Z,1558111834.966 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:37.790Z,1558111837.790 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:41.022Z,1558111841.022 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:43.854Z,1558111843.854 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:47.086Z,1558111847.086 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:49.910Z,1558111849.910 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:52.742Z,1558111852.742 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:54.762Z,1558111854.762 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:50:56.786Z,1558111856.786 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:00.010Z,1558111860.010 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:02.842Z,1558111862.842 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:06.074Z,1558111866.074 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:08.906Z,1558111868.906 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:12.134Z,1558111872.134 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:14.958Z,1558111874.958 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:17.786Z,1558111877.786 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:19.810Z,1558111879.810 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:23.042Z,1558111883.042 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:25.870Z,1558111885.870 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:29.098Z,1558111889.098 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:31.926Z,1558111891.926 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:35.162Z,1558111895.162 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:37.990Z,1558111897.990 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:40.814Z,1558111900.814 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:42.838Z,1558111902.838 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:46.070Z,1558111906.070 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:48.894Z,1558111908.894 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:52.126Z,1558111912.126 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:54.958Z,1558111914.958 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:51:58.186Z,1558111918.186 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:52:00.515Z,1558111920.515 [CommandLine](IMPORTANT): got command restart application
2019-05-17T16:52:01.014Z,1558111921.014 [NAL9602](DEBUG): Fix Requested
2019-05-17T16:52:01.518Z,1558111921.518 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:01.518Z,1558111921.518 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:01.718Z,1558111921.718 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-17T16:52:01.718Z,1558111921.718 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:01.719Z,1558111921.719 [CommandLine](INFO): Join timeout helper Thread ID is 5770
2019-05-17T16:52:01.720Z,1558111921.720 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-17T16:52:01.720Z,1558111921.720 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:01.721Z,1558111921.721 [NavChartDb](INFO): Join timeout helper Thread ID is 5771
2019-05-17T16:52:02.014Z,1558111922.014 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.015Z,1558111922.015 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.018Z,1558111922.018 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-17T16:52:02.018Z,1558111922.018 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.018Z,1558111922.018 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 5772
2019-05-17T16:52:02.354Z,1558111922.354 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.355Z,1558111922.355 [WetLabsBB2FL](INFO): Powering down
2019-05-17T16:52:02.355Z,1558111922.355 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.358Z,1558111922.358 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-17T16:52:02.358Z,1558111922.358 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.358Z,1558111922.358 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5773
2019-05-17T16:52:02.534Z,1558111922.534 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.535Z,1558111922.535 [CTD_NeilBrown](INFO): Powering down
2019-05-17T16:52:02.546Z,1558111922.546 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.558Z,1558111922.558 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-17T16:52:02.558Z,1558111922.558 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.558Z,1558111922.558 [Radio_Surface](INFO): Join timeout helper Thread ID is 5774
2019-05-17T16:52:02.838Z,1558111922.838 [Radio_Surface](INFO): Powering down
2019-05-17T16:52:02.839Z,1558111922.839 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.839Z,1558111922.839 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.847Z,1558111922.847 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-17T16:52:02.847Z,1558111922.847 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.847Z,1558111922.847 [DataOverHttps](INFO): Join timeout helper Thread ID is 5775
2019-05-17T16:52:02.882Z,1558111922.882 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.882Z,1558111922.882 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.891Z,1558111922.891 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-17T16:52:02.891Z,1558111922.891 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.891Z,1558111922.891 [logger](INFO): Join timeout helper Thread ID is 5776
2019-05-17T16:52:02.908Z,1558111922.908 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:02.908Z,1558111922.908 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.919Z,1558111922.919 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-17T16:52:02.919Z,1558111922.919 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.919Z,1558111922.919 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-17T16:52:02.919Z,1558111922.919 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:02.919Z,1558111922.919 [controlThread](INFO): Join timeout helper Thread ID is 5777
2019-05-17T16:52:03.014Z,1558111923.014 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-17T16:52:03.014Z,1558111923.014 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-17T16:52:03.015Z,1558111923.015 [NAL9602](INFO): Powering down
2019-05-17T16:52:03.016Z,1558111923.016 [DAT](INFO): Powering down
2019-05-17T16:52:03.023Z,1558111923.023 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-17T16:52:03.024Z,1558111923.024 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-17T16:52:03.025Z,1558111923.025 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-17T16:52:03.025Z,1558111923.025 [MissionManager](INFO): Uninitializing Mission Default
2019-05-17T16:52:03.025Z,1558111923.025 [Default] Stopped
2019-05-17T16:52:03.025Z,1558111923.025 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-17T16:52:03.025Z,1558111923.025 [Default:B.GoToSurface] Stopped
2019-05-17T16:52:03.026Z,1558111923.026 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-17T16:52:03.026Z,1558111923.026 [Default:CheckIn] Stopped
2019-05-17T16:52:03.028Z,1558111923.028 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-17T16:52:03.028Z,1558111923.028 [Default:CheckIn:C.Wait] Stopped
2019-05-17T16:52:03.028Z,1558111923.028 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-17T16:52:03.030Z,1558111923.030 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-17T16:52:03.031Z,1558111923.031 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-17T16:52:03.031Z,1558111923.031 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-17T16:52:03.031Z,1558111923.031 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-17T16:52:03.032Z,1558111923.032 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-17T16:52:03.032Z,1558111923.032 [BuoyancyServo](INFO): Powering down
2019-05-17T16:52:03.046Z,1558111923.046 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-17T16:52:03.046Z,1558111923.046 [ElevatorServo](INFO): Powering down
2019-05-17T16:52:03.047Z,1558111923.047 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-17T16:52:03.047Z,1558111923.047 [MassServo](INFO): Powering down
2019-05-17T16:52:03.048Z,1558111923.048 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-17T16:52:03.048Z,1558111923.048 [RudderServo](INFO): Powering down
2019-05-17T16:52:03.049Z,1558111923.049 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-17T16:52:03.049Z,1558111923.049 [ThrusterServo](INFO): Powering down
2019-05-17T16:52:03.050Z,1558111923.050 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-17T16:52:03.051Z,1558111923.051 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-17T16:52:03.051Z,1558111923.051 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-17T16:52:03.051Z,1558111923.051 [CBIT](DEBUG): Powering off loads.
2019-05-17T16:52:03.062Z,1558111923.062 [CBIT](DEBUG): Disabling WDT.
2019-05-17T16:52:03.074Z,1558111923.074 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-17T16:52:03.075Z,1558111923.075 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.128Z,1558111923.128 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.134Z,1558111923.134 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.162Z,1558111923.162 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.169Z,1558111923.169 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.206Z,1558111923.206 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-17T16:52:03.264Z,1558111923.264 [logger ThreadHandler](INFO): Thread cancelled.