2019-07-11T00:21:37.466Z,1562804497.466 [Supervisor](DEBUG): Initializing supervisor.
2019-07-11T00:21:37.469Z,1562804497.469 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-11T00:21:37.469Z,1562804497.469 [SyncHandler](INFO): Protected caller Thread ID is 3078
2019-07-11T00:21:37.469Z,1562804497.469 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-11T00:21:37.470Z,1562804497.470 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-11T00:21:37.471Z,1562804497.471 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3079
2019-07-11T00:21:37.473Z,1562804497.473 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-11T00:21:37.484Z,1562804497.484 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-11T00:21:37.485Z,1562804497.485 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-11T00:21:37.485Z,1562804497.485 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3080
2019-07-11T00:21:37.486Z,1562804497.486 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-11T00:21:37.487Z,1562804497.487 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-11T00:21:37.487Z,1562804497.487 [logger ThreadHandler](INFO): Protected caller Thread ID is 3081
2019-07-11T00:21:37.489Z,1562804497.489 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-11T00:21:37.490Z,1562804497.490 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-11T00:21:37.491Z,1562804497.491 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-11T00:21:37.898Z,1562804497.898 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-11T00:21:37.899Z,1562804497.899 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-11T00:21:37.995Z,1562804497.995 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-11T00:21:37.996Z,1562804497.996 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-11T00:21:38.304Z,1562804498.304 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-11T00:21:38.304Z,1562804498.304 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-11T00:21:38.443Z,1562804498.443 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-11T00:21:38.443Z,1562804498.443 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-11T00:21:38.631Z,1562804498.631 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-11T00:21:38.632Z,1562804498.632 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-11T00:21:39.068Z,1562804499.068 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-11T00:21:39.068Z,1562804499.068 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-11T00:21:39.270Z,1562804499.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-11T00:21:39.270Z,1562804499.270 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-11T00:21:39.444Z,1562804499.444 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-11T00:21:39.445Z,1562804499.445 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-11T00:21:39.673Z,1562804499.673 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-11T00:21:39.673Z,1562804499.673 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-11T00:21:39.771Z,1562804499.771 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-11T00:21:39.772Z,1562804499.772 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-11T00:21:40.063Z,1562804500.063 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-11T00:21:40.063Z,1562804500.063 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-11T00:21:40.144Z,1562804500.144 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-11T00:21:40.245Z,1562804500.245 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-11T00:21:40.245Z,1562804500.246 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-11T00:21:40.818Z,1562804500.818 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-11T00:21:40.818Z,1562804500.818 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-11T00:21:41.197Z,1562804501.197 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-11T00:21:41.199Z,1562804501.199 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-07-11T00:21:41.200Z,1562804501.200 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-07-11T00:21:41.403Z,1562804501.403 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-07-11T00:21:41.503Z,1562804501.503 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-07-11T00:21:41.601Z,1562804501.601 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-07-11T00:21:41.888Z,1562804501.888 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-11T00:21:41.889Z,1562804501.889 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-07-11T00:21:41.975Z,1562804501.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-07-11T00:21:42.145Z,1562804502.145 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-07-11T00:21:42.398Z,1562804502.398 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-07-11T00:21:42.563Z,1562804502.563 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-07-11T00:21:42.669Z,1562804502.669 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-07-11T00:21:42.843Z,1562804502.843 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-07-11T00:21:42.971Z,1562804502.971 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-07-11T00:21:42.972Z,1562804502.972 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-07-11T00:21:42.973Z,1562804502.973 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-11T00:21:43.365Z,1562804503.365 [AHRS_M2] Loaded
2019-07-11T00:21:43.365Z,1562804503.365 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-11T00:21:43.438Z,1562804503.438 [DataOverHttps] Loaded
2019-07-11T00:21:43.438Z,1562804503.438 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-11T00:21:43.439Z,1562804503.439 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407654E0
2019-07-11T00:21:43.439Z,1562804503.439 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3161
2019-07-11T00:21:43.452Z,1562804503.452 [Depth_Keller] Loaded
2019-07-11T00:21:43.452Z,1562804503.452 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-11T00:21:43.457Z,1562804503.457 [DropWeight] Loaded
2019-07-11T00:21:43.457Z,1562804503.457 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-07-11T00:21:43.512Z,1562804503.512 [DUSBL_Hydroid] Loaded
2019-07-11T00:21:43.512Z,1562804503.512 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-07-11T00:21:43.559Z,1562804503.559 [Micromodem] Loaded
2019-07-11T00:21:43.559Z,1562804503.559 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-07-11T00:21:43.654Z,1562804503.654 [NAL9602] Loaded
2019-07-11T00:21:43.654Z,1562804503.654 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-11T00:21:43.669Z,1562804503.669 [Onboard] Loaded
2019-07-11T00:21:43.670Z,1562804503.670 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-11T00:21:43.676Z,1562804503.676 [PowerOnly] Loaded
2019-07-11T00:21:43.676Z,1562804503.676 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-07-11T00:21:43.682Z,1562804503.682 [Radio_Surface] Loaded
2019-07-11T00:21:43.682Z,1562804503.682 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-11T00:21:43.683Z,1562804503.683 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407954E0
2019-07-11T00:21:43.684Z,1562804503.684 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3162
2019-07-11T00:21:43.726Z,1562804503.726 [RDI_Pathfinder] Loaded
2019-07-11T00:21:43.726Z,1562804503.726 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-07-11T00:21:45.164Z,1562804505.164 [BPC1] Loaded
2019-07-11T00:21:45.164Z,1562804505.164 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-11T00:21:45.164Z,1562804505.164 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-11T00:21:45.165Z,1562804505.165 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-11T00:21:45.179Z,1562804505.179 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-11T00:21:45.179Z,1562804505.179 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-11T00:21:45.284Z,1562804505.284 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-11T00:21:45.284Z,1562804505.284 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-11T00:21:45.304Z,1562804505.304 [NavChart] Loaded
2019-07-11T00:21:45.304Z,1562804505.304 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-11T00:21:45.308Z,1562804505.308 [UniversalFixResidualReporter] Loaded
2019-07-11T00:21:45.308Z,1562804505.308 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-11T00:21:45.308Z,1562804505.308 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-11T00:21:45.309Z,1562804505.309 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-11T00:21:45.413Z,1562804505.413 [BuoyancyServo] Loaded
2019-07-11T00:21:45.413Z,1562804505.413 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-11T00:21:45.428Z,1562804505.428 [ElevatorServo] Loaded
2019-07-11T00:21:45.428Z,1562804505.428 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-11T00:21:45.442Z,1562804505.442 [MassServo] Loaded
2019-07-11T00:21:45.443Z,1562804505.443 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-11T00:21:45.457Z,1562804505.457 [RudderServo] Loaded
2019-07-11T00:21:45.457Z,1562804505.457 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-11T00:21:45.472Z,1562804505.472 [ThrusterServo] Loaded
2019-07-11T00:21:45.472Z,1562804505.472 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-11T00:21:45.472Z,1562804505.472 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-11T00:21:45.473Z,1562804505.473 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-11T00:21:45.720Z,1562804505.720 [CTD_NeilBrown] Loaded
2019-07-11T00:21:45.720Z,1562804505.720 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-07-11T00:21:45.721Z,1562804505.721 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E04E0
2019-07-11T00:21:45.721Z,1562804505.721 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3163
2019-07-11T00:21:45.764Z,1562804505.764 [WetLabsSeaOWL_UV_A] Loaded
2019-07-11T00:21:45.764Z,1562804505.764 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-07-11T00:21:45.765Z,1562804505.765 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409104E0
2019-07-11T00:21:45.766Z,1562804505.766 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3164
2019-07-11T00:21:45.766Z,1562804505.766 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-11T00:21:45.767Z,1562804505.767 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-11T00:21:46.051Z,1562804506.051 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-11T00:21:46.052Z,1562804506.052 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-11T00:21:46.093Z,1562804506.093 [DepthRateCalculator] Loaded
2019-07-11T00:21:46.093Z,1562804506.093 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-11T00:21:46.098Z,1562804506.098 [PitchRateCalculator] Loaded
2019-07-11T00:21:46.099Z,1562804506.099 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-11T00:21:46.111Z,1562804506.111 [SpeedCalculator] Loaded
2019-07-11T00:21:46.111Z,1562804506.111 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-11T00:21:46.131Z,1562804506.131 [TempGradientCalculator] Loaded
2019-07-11T00:21:46.131Z,1562804506.131 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-11T00:21:46.136Z,1562804506.136 [YawRateCalculator] Loaded
2019-07-11T00:21:46.137Z,1562804506.137 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-11T00:21:46.176Z,1562804506.176 [ElevatorOffsetCalculator] Loaded
2019-07-11T00:21:46.176Z,1562804506.176 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-11T00:21:46.177Z,1562804506.177 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-11T00:21:46.177Z,1562804506.177 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-11T00:21:46.309Z,1562804506.309 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-11T00:21:46.330Z,1562804506.330 [SBIT] Loaded
2019-07-11T00:21:46.331Z,1562804506.331 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-11T00:21:46.331Z,1562804506.331 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-11T00:21:46.343Z,1562804506.343 [IBIT] Loaded
2019-07-11T00:21:46.343Z,1562804506.343 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-11T00:21:46.346Z,1562804506.346 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-11T00:21:46.481Z,1562804506.481 [CBIT] Loaded
2019-07-11T00:21:46.482Z,1562804506.482 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-11T00:21:46.482Z,1562804506.482 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-11T00:21:46.483Z,1562804506.483 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-11T00:21:46.564Z,1562804506.564 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-11T00:21:46.564Z,1562804506.564 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-11T00:21:46.660Z,1562804506.660 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-11T00:21:46.660Z,1562804506.660 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-11T00:21:46.726Z,1562804506.726 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-11T00:21:46.807Z,1562804506.807 [VerticalControl] Loaded
2019-07-11T00:21:46.807Z,1562804506.807 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-11T00:21:46.808Z,1562804506.808 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-11T00:21:46.863Z,1562804506.863 [HorizontalControl] Loaded
2019-07-11T00:21:46.864Z,1562804506.864 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-11T00:21:46.864Z,1562804506.864 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-11T00:21:46.866Z,1562804506.866 [SpeedControl] Loaded
2019-07-11T00:21:46.866Z,1562804506.866 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-11T00:21:46.867Z,1562804506.867 [LoopControl](DEBUG): Construct LoopControl.
2019-07-11T00:21:46.867Z,1562804506.867 [LoopControl] Loaded
2019-07-11T00:21:46.868Z,1562804506.868 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-11T00:21:46.868Z,1562804506.868 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-11T00:21:46.869Z,1562804506.869 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-11T00:21:46.900Z,1562804506.900 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-11T00:21:46.923Z,1562804506.923 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-11T00:21:46.924Z,1562804506.924 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-11T00:21:46.947Z,1562804506.947 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-11T00:21:46.948Z,1562804506.948 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEC4E0
2019-07-11T00:21:46.948Z,1562804506.948 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3165
2019-07-11T00:21:46.953Z,1562804506.953 [Supervisor](INFO): Main Thread ID is 3077
2019-07-11T00:21:46.953Z,1562804506.953 [Supervisor](DEBUG): Running supervisor.
2019-07-11T00:21:46.953Z,1562804506.953 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3166
2019-07-11T00:21:46.991Z,1562804506.991 [controlThread ThreadHandler](INFO): Handler Thread ID is 3167
2019-07-11T00:21:46.991Z,1562804506.991 [controlThread](DEBUG): Initializing ControlThread
2019-07-11T00:21:46.998Z,1562804506.998 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-11T00:21:46.998Z,1562804506.998 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-11T00:21:46.000Z,1562804507.000 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-11T00:21:46.000Z,1562804507.000 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-11T00:21:47.000Z,1562804507.000 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-11T00:21:47.001Z,1562804507.001 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-11T00:21:47.001Z,1562804507.001 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-11T00:21:47.002Z,1562804507.002 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-11T00:21:47.002Z,1562804507.002 [SBIT](INFO): Initialize SBIT Component.
2019-07-11T00:21:47.003Z,1562804507.003 [SBIT](IMPORTANT): git: 2019-07-01-2-g8df750c
2019-07-11T00:21:47.003Z,1562804507.003 [SBIT](INFO): git hash: 8df750cfd7ab665d8785a0cb54650bf6fbbccb32
2019-07-11T00:21:47.003Z,1562804507.003 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-11T00:21:47.005Z,1562804507.005 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-07-11T00:21:47.006Z,1562804507.006 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-07-11T00:21:47.006Z,1562804507.006 [IBIT](INFO): Initialize IBIT Component.
2019-07-11T00:21:47.007Z,1562804507.007 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-11T00:21:47.008Z,1562804507.008 [logger ThreadHandler](INFO): Handler Thread ID is 3168
2019-07-11T00:21:47.018Z,1562804507.018 [CBIT](DEBUG): Initialized mux pins.
2019-07-11T00:21:47.018Z,1562804507.018 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-07-11T00:21:47.019Z,1562804507.019 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-11T00:21:47.035Z,1562804507.035 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3169
2019-07-11T00:21:47.036Z,1562804507.036 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-11T00:21:47.039Z,1562804507.039 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3170
2019-07-11T00:21:47.041Z,1562804507.041 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3171
2019-07-11T00:21:47.041Z,1562804507.041 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3172
2019-07-11T00:21:47.042Z,1562804507.042 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-11T00:21:47.043Z,1562804507.043 [CBIT](DEBUG): Initializing heartbeat.
2019-07-11T00:21:47.044Z,1562804507.044 [CTD_NeilBrown](INFO): Powering down
2019-07-11T00:21:47.065Z,1562804507.065 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-11T00:21:47.087Z,1562804507.087 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3173
2019-07-11T00:21:47.092Z,1562804507.092 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-11T00:21:47.092Z,1562804507.092 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-11T00:21:47.092Z,1562804507.092 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-11T00:21:47.092Z,1562804507.092 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-11T00:21:47.093Z,1562804507.093 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-11T00:21:47.094Z,1562804507.094 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-11T00:21:47.094Z,1562804507.094 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-11T00:21:47.094Z,1562804507.094 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-11T00:21:47.094Z,1562804507.094 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-11T00:21:47.095Z,1562804507.095 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-11T00:21:47.095Z,1562804507.095 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-11T00:21:47.114Z,1562804507.114 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-11T00:21:47.114Z,1562804507.114 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-11T00:21:47.150Z,1562804507.150 [CBIT](DEBUG): Backplane powered.
2019-07-11T00:21:47.151Z,1562804507.151 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-11T00:21:47.152Z,1562804507.152 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-11T00:21:47.153Z,1562804507.153 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-11T00:21:47.153Z,1562804507.153 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-11T00:21:47.155Z,1562804507.155 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-11T00:21:47.166Z,1562804507.166 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-11T00:21:47.185Z,1562804507.185 [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-07-11T00:21:47.186Z,1562804507.186 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-11T00:21:47.266Z,1562804507.266 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-11T00:21:47.267Z,1562804507.267 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-11T00:21:47.269Z,1562804507.269 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-11T00:21:47.316Z,1562804507.316 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-11T00:21:47.318Z,1562804507.318 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-11T00:21:47.340Z,1562804507.340 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-11T00:21:47.343Z,1562804507.343 [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-07-11T00:21:47.355Z,1562804507.355 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,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-07-11T00:21:47.366Z,1562804507.366 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-11T00:21:47.400Z,1562804507.400 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-07-11T00:21:47.400Z,1562804507.400 [DUSBL_Hydroid](INFO): Powering up
2019-07-11T00:21:47.401Z,1562804507.401 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-11T00:21:47.442Z,1562804507.442 [Radio_Surface](INFO): Powering up
2019-07-11T00:21:47.475Z,1562804507.475 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-11T00:21:47.492Z,1562804507.492 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-11T00:21:47.499Z,1562804507.499 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-11T00:21:47.500Z,1562804507.500 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-11T00:21:47.507Z,1562804507.507 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-11T00:21:47.507Z,1562804507.507 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-11T00:21:47.515Z,1562804507.515 [MassServo](DEBUG): Initializing MassServo.
2019-07-11T00:21:47.515Z,1562804507.515 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-11T00:21:47.523Z,1562804507.523 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-11T00:21:47.524Z,1562804507.524 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-11T00:21:47.531Z,1562804507.531 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-11T00:21:47.780Z,1562804507.780 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-07-11T00:21:47.780Z,1562804507.780 [DropWeight] Hardware Fault, FailCount= 1
2019-07-11T00:21:47.780Z,1562804507.780 [DropWeight](ERROR): Hardware Fault
2019-07-11T00:21:47.782Z,1562804507.782 [Micromodem](INFO): Powering up
2019-07-11T00:21:47.782Z,1562804507.782 [Micromodem](DEBUG): Initializing Micromodem.
2019-07-11T00:21:47.819Z,1562804507.819 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-11T00:21:47.827Z,1562804507.827 [CommandLine](FAULT): Scheduling is paused
2019-07-11T00:21:47.827Z,1562804507.827 [CBIT](INFO): Critical error at 20190711T002147
2019-07-11T00:21:47.827Z,1562804507.827 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-07-11T00:21:47.830Z,1562804507.830 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-07-11T00:21:47.830Z,1562804507.830 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-07-11T00:21:48.464Z,1562804508.464 [CBIT](INFO): Critical error at 20190711T002147
2019-07-11T00:21:52.673Z,1562804512.673 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-07-11T00:21:55.489Z,1562804515.489 [Micromodem](INFO): Nmea in: $CATMG,2019-07-11T00:21:54Z,RTC,RTC*71

2019-07-11T00:21:55.489Z,1562804515.489 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-07-11T00:21:54Z,RTC,RTC*71

2019-07-11T00:22:00.746Z,1562804520.746 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-07-11T00:22:03.953Z,1562804523.953 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-07-11T00:22:04.756Z,1562804524.756 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-07-11T00:22:04.757Z,1562804524.757 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-07-11T00:22:05.165Z,1562804525.165 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-07-11T00:22:05.166Z,1562804525.166 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-07-11T00:22:05.568Z,1562804525.568 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-11T00:22:05.579Z,1562804525.579 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-07-11T00:22:05.580Z,1562804525.580 [Micromodem](INFO): Nmea out: $CCCFG,nav.nst,1*4D

2019-07-11T00:22:05.968Z,1562804525.968 [Micromodem](INFO): Nmea in: $CACFG,nav.nst,1*4F

2019-07-11T00:22:05.969Z,1562804525.969 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-07-11T00:22:06.372Z,1562804526.372 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-07-11T00:22:06.372Z,1562804526.372 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-07-11T00:22:06.776Z,1562804526.776 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-07-11T00:22:06.776Z,1562804526.776 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-07-11T00:22:07.180Z,1562804527.180 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-07-11T00:22:07.180Z,1562804527.180 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-07-11T00:22:07.591Z,1562804527.591 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-07-11T00:22:07.591Z,1562804527.591 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-07-11T00:22:07.988Z,1562804527.988 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-07-11T00:22:07.989Z,1562804527.989 [Micromodem](INFO): Nmea out: $CCCLK,2019,07,11,00,22,08*41

2019-07-11T00:22:08.392Z,1562804528.392 [Micromodem](INFO): Nmea in: $CACLK,2019,7,11,0,22,8*73

2019-07-11T00:22:08.394Z,1562804528.394 [Micromodem](INFO): Nmea in: $CATMS,0,2019-07-11T00:22:09Z*72

2019-07-11T00:22:08.395Z,1562804528.395 [Micromodem](INFO): Nmea in: $CATMG,2019-07-11T00:22:09Z,USER_CMD,RTC*3B

2019-07-11T00:22:14.050Z,1562804534.050 [NAL9602](INFO): Powering up NAL9602
2019-07-11T00:22:15.716Z,1562804535.716 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-11T00:22:15.725Z,1562804535.725 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-11T00:22:19.023Z,1562804539.023 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-07-11T00:22:19.024Z,1562804539.024 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  93.42,  93.93,   0.00
2019-07-11T00:22:25.073Z,1562804545.073 [NAL9602](INFO): NAL9602 initialized
2019-07-11T00:22:25.890Z,1562804545.890 [NAL9602](DEBUG): Fix Requested
2019-07-11T00:22:26.811Z,1562804546.811 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.022012
CHAN A1 (24V): -0.026557
CHAN A2 (12V): -0.006623
CHAN A3 (5V): -0.002074
CHAN B0 (3.3V): 0.000360
CHAN B1 (3.15aV): 0.000027
CHAN B2 (3.15bV): -0.000010
CHAN B3 (GND): 0.001792
OPEN: 0.007087
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-11T00:23:09.109Z,1562804589.109 [SBIT](IMPORTANT): SBIT PASSED
2019-07-11T00:23:09.140Z,1562804589.140 [CommandLine](IMPORTANT): got command configSet list
2019-07-11T00:23:09.140Z,1562804589.140 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-11T00:23:09.141Z,1562804589.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 count;

2019-07-11T00:23:09.141Z,1562804589.141 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-11T00:23:09.495Z,1562804589.495 [MissionManager](IMPORTANT): Started mission Startup
2019-07-11T00:23:09.496Z,1562804589.496 [Startup] Running Loop=1
2019-07-11T00:23:09.496Z,1562804589.496 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-11T00:23:09.496Z,1562804589.496 [Startup:A.GoToSurface] Running Loop=1
2019-07-11T00:23:09.496Z,1562804589.496 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-11T00:23:09.497Z,1562804589.497 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-11T00:23:09.497Z,1562804589.497 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-11T00:23:09.497Z,1562804589.497 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-11T00:23:09.498Z,1562804589.498 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-11T00:23:09.515Z,1562804589.515 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-11T00:23:09.536Z,1562804589.536 [Startup:StartupSatComms] Running Loop=1
2019-07-11T00:23:09.536Z,1562804589.536 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-11T00:23:09.536Z,1562804589.536 [Startup:StartupSatComms:A] Running Loop=1
2019-07-11T00:23:09.891Z,1562804589.891 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-11T00:24:09.724Z,1562804649.724 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-11T00:23:09.5Z
2019-07-11T00:24:09.724Z,1562804649.724 [Startup:StartupSatComms:A] Stopped
2019-07-11T00:24:09.724Z,1562804649.724 [Startup:StartupSatComms:B] Running Loop=1
2019-07-11T00:24:10.080Z,1562804650.080 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-11T00:24:12.141Z,1562804652.141 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 1181265D000000005D00000400900000000000000000151D80030C5669BF31555EAE1409A708CE2489B0D24F922C4E73F3619C1A3D5DFEC97D4617D39DECC9F9
2019-07-11T00:24:12.141Z,1562804652.141 [Micromodem](INFO): Outgoing frame #2, 64 bytes: D53C4BCCB3E287252A0F75D34D5CC5B45B73849F9612E27BC07A9EC687446AA2DC793D8E56D125DA2BD13BD8EF67D9AA879A8F0E8F6659C4ED5479DFD096FB49
2019-07-11T00:24:12.142Z,1562804652.142 [Micromodem](INFO): Outgoing frame #3, 12 bytes: B957159E68DB0BEE7B2C8000
2019-07-11T00:24:12.142Z,1562804652.142 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:24:12.349Z,1562804652.349 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-11T00:24:12.684Z,1562804652.684 [Micromodem](INFO): Nmea in: $CADRQ,002412,1,9,0,64,1*4B

2019-07-11T00:24:12.685Z,1562804652.685 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,1181265D000000005D00000400900000000000000000151D80030C5669BF31555EAE1409A708CE2489B0D24F922C4E73F3619C1A3D5DFEC97D4617D39DECC9F9*75

2019-07-11T00:24:13.088Z,1562804653.088 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T00:24:13.492Z,1562804653.492 [Micromodem](INFO): Nmea in: $CADRQ,002413,1,9,0,64,2*49

2019-07-11T00:24:13.493Z,1562804653.493 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,D53C4BCCB3E287252A0F75D34D5CC5B45B73849F9612E27BC07A9EC687446AA2DC793D8E56D125DA2BD13BD8EF67D9AA879A8F0E8F6659C4ED5479DFD096FB49*70

2019-07-11T00:24:13.896Z,1562804653.896 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T00:24:14.304Z,1562804654.304 [Micromodem](INFO): Nmea in: $CADRQ,002414,1,9,0,64,3*4F

2019-07-11T00:24:14.305Z,1562804654.305 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,B957159E68DB0BEE7B2C8000*06

2019-07-11T00:24:14.704Z,1562804654.704 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,12*70

2019-07-11T00:24:14.903Z,1562804654.903 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005107
2019-07-11T00:24:15.112Z,1562804655.112 [Micromodem](INFO): Nmea in: $CATXP,140*47

2019-07-11T00:24:18.748Z,1562804658.748 [Micromodem](INFO): Nmea in: $CATXF,140*51

2019-07-11T00:24:19.149Z,1562804659.149 [Micromodem](INFO): Nmea in: $CAXST,6,20190711,002415.071507,3,0,200,4000,10000,1,1,9,1,3,3,3,140*44

2019-07-11T00:24:20.970Z,1562804660.970 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20190711T002137/Courier0000.lzma
2019-07-11T00:24:21.776Z,1562804661.776 [DataOverHttps](INFO): Moved sent file to Logs/20190711T002137/Courier0000.lzma.bak
2019-07-11T00:24:21.776Z,1562804661.776 [DataOverHttps](INFO): SBD MOMSN=11438509
2019-07-11T00:24:26.368Z,1562804666.368 [CommandLine](IMPORTANT): got command show stack
2019-07-11T00:24:26.368Z,1562804666.368 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-11T00:24:26.368Z,1562804666.368 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-07-11T00:24:26.369Z,1562804666.369 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-07-11T00:24:34.702Z,1562804674.702 [DataOverHttps](INFO): Sending 100 bytes from file Logs/20190711T000810/Express0008.lzma
2019-07-11T00:24:35.508Z,1562804675.508 [DataOverHttps](INFO): Moved sent file to Logs/20190711T000810/Express0008.lzma.bak
2019-07-11T00:24:35.508Z,1562804675.508 [DataOverHttps](INFO): SBD MOMSN=11438514
2019-07-11T00:24:47.054Z,1562804687.054 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-11T00:24:47.054Z,1562804687.054 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-11T00:24:47.069Z,1562804687.069 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-11T00:24:47.501Z,1562804687.501 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-11T00:24:47.501Z,1562804687.501 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-11T00:24:49.331Z,1562804689.331 [DataOverHttps](INFO): Sending 697 bytes from file Logs/20190711T002137/Express0001.lzma
2019-07-11T00:24:50.136Z,1562804690.136 [DataOverHttps](INFO): Moved sent file to Logs/20190711T002137/Express0001.lzma.bak
2019-07-11T00:24:50.136Z,1562804690.136 [DataOverHttps](INFO): SBD MOMSN=11438517
2019-07-11T00:24:52.734Z,1562804692.734 [Startup:StartupSatComms:B] Stopped
2019-07-11T00:24:52.734Z,1562804692.734 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-11T00:24:52.734Z,1562804692.734 [Startup:StartupSatComms] Stopped
2019-07-11T00:24:52.758Z,1562804692.758 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-11T00:24:52.759Z,1562804692.759 [Startup](INFO): Completed Startup
2019-07-11T00:24:52.759Z,1562804692.759 [MissionManager](INFO): Startup is completed.
2019-07-11T00:24:52.759Z,1562804692.759 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-11T00:24:52.760Z,1562804692.760 [Startup] Stopped
2019-07-11T00:24:52.760Z,1562804692.760 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-11T00:24:52.760Z,1562804692.760 [Startup:A.GoToSurface] Stopped
2019-07-11T00:24:52.760Z,1562804692.760 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-11T00:24:53.124Z,1562804693.124 [MissionManager](IMPORTANT): Started mission Default
2019-07-11T00:24:53.124Z,1562804693.124 [Default] Running Loop=1
2019-07-11T00:24:53.124Z,1562804693.124 [Default](DEBUG): Aggregate::initialize Default
2019-07-11T00:24:53.124Z,1562804693.124 [Default:B.GoToSurface] Running Loop=1
2019-07-11T00:24:53.124Z,1562804693.124 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-11T00:24:53.124Z,1562804693.124 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-11T00:24:53.125Z,1562804693.125 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-11T00:24:53.125Z,1562804693.125 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-11T00:24:53.125Z,1562804693.125 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-11T00:24:53.126Z,1562804693.126 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-11T00:24:53.126Z,1562804693.126 [Default:A.Wait] Running Loop=1
2019-07-11T00:24:53.126Z,1562804693.126 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-11T00:25:06.446Z,1562804706.446 [Default:A.Wait](INFO): Done Waiting.
2019-07-11T00:25:06.446Z,1562804706.446 [Default:A.Wait] Stopped
2019-07-11T00:25:06.446Z,1562804706.446 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T00:25:06.944Z,1562804706.944 [Default:CheckIn] Running Loop=1
2019-07-11T00:25:06.944Z,1562804706.944 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-11T00:25:06.945Z,1562804706.945 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-11T00:25:07.265Z,1562804707.265 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-11T00:25:31.062Z,1562804731.062 [NAL9602](INFO): SBD MO Status=2, MOMSN=8108, MT Status=2, MTMSN=0
2019-07-11T00:25:31.063Z,1562804731.063 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-11T00:26:05.406Z,1562804765.406 [NAL9602](INFO): SBD MO Status=2, MOMSN=8108, MT Status=2, MTMSN=0
2019-07-11T00:26:05.406Z,1562804765.406 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-11T00:26:22.774Z,1562804782.774 [NAL9602](INFO): SBD MO Status=2, MOMSN=8108, MT Status=2, MTMSN=0
2019-07-11T00:26:22.774Z,1562804782.774 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-11T00:26:27.936Z,1562804787.936 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-07-11T00:26:27.936Z,1562804787.936 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-07-11T00:26:27.962Z,1562804787.962 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 5.000000 min
2019-07-11T00:26:27.966Z,1562804787.966 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-11T00:26:27.985Z,1562804787.985 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-07-11T00:26:27.994Z,1562804787.994 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-11T00:26:28.001Z,1562804788.001 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-11T00:26:28.028Z,1562804788.028 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-11T00:26:28.075Z,1562804788.075 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-11T00:26:28.253Z,1562804788.253 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-11T00:26:28.261Z,1562804788.261 [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="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

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

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</Value></DefineArg>
    
    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <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>

    
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>
        
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-07-11T00:26:28.268Z,1562804788.268 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-07-11T00:26:28.455Z,1562804788.455 [Default] Stopped
2019-07-11T00:26:28.455Z,1562804788.455 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-11T00:26:28.455Z,1562804788.455 [Default:B.GoToSurface] Stopped
2019-07-11T00:26:28.456Z,1562804788.456 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-11T00:26:28.456Z,1562804788.456 [Default:CheckIn] Stopped
2019-07-11T00:26:28.456Z,1562804788.456 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-11T00:26:28.456Z,1562804788.456 [Default:CheckIn:Read_GPS] Stopped
2019-07-11T00:26:28.456Z,1562804788.456 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-11T00:26:28.456Z,1562804788.456 [DUSBL] Running Loop=1
2019-07-11T00:26:28.456Z,1562804788.456 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-11T00:26:28.456Z,1562804788.456 [DUSBL:A.Pitch] Running Loop=1
2019-07-11T00:26:28.456Z,1562804788.456 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-11T00:26:28.457Z,1562804788.457 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-11T00:26:28.457Z,1562804788.457 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-11T00:26:28.457Z,1562804788.457 [DUSBL:C.] Running Loop=1
2019-07-11T00:26:28.457Z,1562804788.457 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-11T00:26:28.457Z,1562804788.457 [DUSBL:RequestRepeater] Running Loop=1
2019-07-11T00:26:28.458Z,1562804788.458 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-11T00:26:28.458Z,1562804788.458 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-11T00:26:28.458Z,1562804788.458 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-11T00:26:28.458Z,1562804788.458 [DUSBL:C.] Running Loop=1
2019-07-11T00:26:28.459Z,1562804788.459 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-11T00:26:28.459Z,1562804788.459 [DUSBL:A.Pitch] Running Loop=1
2019-07-11T00:26:32.500Z,1562804792.500 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:33.287Z,1562804793.287 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:33.686Z,1562804793.686 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:36.523Z,1562804796.523 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:26:36.546Z,1562804796.546 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:37.317Z,1562804797.317 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:37.726Z,1562804797.726 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:40.556Z,1562804800.556 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:26:40.645Z,1562804800.645 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:41.357Z,1562804801.357 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:41.762Z,1562804801.762 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:44.600Z,1562804804.600 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:26:44.683Z,1562804804.683 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:45.401Z,1562804805.401 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:45.802Z,1562804805.802 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:48.647Z,1562804808.647 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:26:48.650Z,1562804808.650 [NAL9602](INFO): SBD MO Status=2, MOMSN=8108, MT Status=2, MTMSN=0
2019-07-11T00:26:48.651Z,1562804808.651 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-11T00:26:48.731Z,1562804808.731 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:49.437Z,1562804809.437 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:49.853Z,1562804809.853 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:52.676Z,1562804812.676 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:26:53.120Z,1562804813.120 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:53.927Z,1562804813.927 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:26:54.294Z,1562804814.294 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:26:57.155Z,1562804817.155 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:26:57.520Z,1562804817.520 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:01.178Z,1562804821.178 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:01.969Z,1562804821.969 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:02.374Z,1562804822.374 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:05.208Z,1562804825.208 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:05.236Z,1562804825.236 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:06.009Z,1562804826.009 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:06.418Z,1562804826.418 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:07.646Z,1562804827.646 [NAL9602](INFO): SBD MO Status=2, MOMSN=8108, MT Status=2, MTMSN=0
2019-07-11T00:27:07.646Z,1562804827.646 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-11T00:27:09.244Z,1562804829.244 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:09.272Z,1562804829.272 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:10.053Z,1562804830.053 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:10.454Z,1562804830.454 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:13.284Z,1562804833.284 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:13.312Z,1562804833.312 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:14.089Z,1562804834.089 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:14.494Z,1562804834.494 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:17.324Z,1562804837.324 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:17.368Z,1562804837.368 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:18.133Z,1562804838.133 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:18.538Z,1562804838.538 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:21.368Z,1562804841.368 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:21.424Z,1562804841.424 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:22.173Z,1562804842.173 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:22.589Z,1562804842.589 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:22.998Z,1562804842.998 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-07-11T00:27:22.998Z,1562804842.998 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,    -5,    -4,    E,    -5,    -4,    +0,A
2019-07-11T00:27:25.408Z,1562804845.408 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:25.440Z,1562804845.440 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:26.213Z,1562804846.213 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:26.646Z,1562804846.646 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:28.245Z,1562804848.245 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-11T00:27:29.058Z,1562804849.058 [NAL9602](DEBUG): Fix Requested
2019-07-11T00:27:29.448Z,1562804849.448 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:29.451Z,1562804849.451 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002615.00,A,3648.16223,N,12147.28045,W,0.544,0.00,110719,,,A*71
2019-07-11T00:27:29.455Z,1562804849.455 [NAL9602](INFO): GPS fix at 20190711T002615: (36.802704, -121.788008)
2019-07-11T00:27:29.480Z,1562804849.480 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:30.261Z,1562804850.261 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:30.661Z,1562804850.661 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:33.487Z,1562804853.487 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:33.513Z,1562804853.513 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:34.296Z,1562804854.296 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:34.701Z,1562804854.701 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:37.532Z,1562804857.532 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:37.594Z,1562804857.594 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:38.336Z,1562804858.336 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:38.741Z,1562804858.741 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:41.567Z,1562804861.567 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:41.598Z,1562804861.598 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:42.377Z,1562804862.377 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:42.782Z,1562804862.782 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:45.629Z,1562804865.629 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:45.717Z,1562804865.717 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:46.424Z,1562804866.424 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:46.825Z,1562804866.825 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:49.656Z,1562804869.656 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:49.721Z,1562804869.721 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:50.465Z,1562804870.465 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:50.881Z,1562804870.881 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:53.687Z,1562804873.687 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:53.730Z,1562804873.730 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:54.497Z,1562804874.497 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:54.901Z,1562804874.901 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:27:57.735Z,1562804877.735 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:27:57.781Z,1562804877.781 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:27:58.536Z,1562804878.536 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:27:58.941Z,1562804878.941 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:01.065Z,1562804881.065 [NAL9602](INFO): Powering down
2019-07-11T00:28:01.786Z,1562804881.786 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:01.898Z,1562804881.898 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:02.592Z,1562804882.592 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:02.993Z,1562804882.993 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:05.827Z,1562804885.827 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:06.243Z,1562804886.243 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:07.024Z,1562804887.024 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:07.441Z,1562804887.441 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:10.260Z,1562804890.260 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:10.303Z,1562804890.303 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:11.068Z,1562804891.068 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:11.474Z,1562804891.474 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:14.299Z,1562804894.299 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:14.352Z,1562804894.352 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:15.109Z,1562804895.109 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:15.513Z,1562804895.513 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:18.339Z,1562804898.339 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:18.371Z,1562804898.371 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:19.148Z,1562804899.148 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:19.561Z,1562804899.561 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:22.379Z,1562804902.379 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:22.405Z,1562804902.405 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:23.188Z,1562804903.188 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:23.597Z,1562804903.597 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:26.416Z,1562804906.416 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:26.450Z,1562804906.450 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:27.222Z,1562804907.222 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:27.648Z,1562804907.648 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:30.459Z,1562804910.459 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:30.502Z,1562804910.502 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:31.268Z,1562804911.268 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:31.673Z,1562804911.673 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:34.496Z,1562804914.496 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:34.551Z,1562804914.551 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:35.304Z,1562804915.304 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:35.709Z,1562804915.709 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:38.538Z,1562804918.538 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:38.565Z,1562804918.565 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:39.353Z,1562804919.353 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:39.757Z,1562804919.757 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:42.580Z,1562804922.580 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:42.630Z,1562804922.630 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:43.388Z,1562804923.388 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:43.789Z,1562804923.789 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:46.644Z,1562804926.644 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:46.682Z,1562804926.682 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:47.428Z,1562804927.428 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:47.833Z,1562804927.833 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:50.670Z,1562804930.670 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:50.704Z,1562804930.704 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:51.469Z,1562804931.469 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:51.868Z,1562804931.868 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:54.695Z,1562804934.695 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:54.761Z,1562804934.761 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:55.508Z,1562804935.508 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:55.909Z,1562804935.909 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:28:58.740Z,1562804938.740 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:28:58.818Z,1562804938.818 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:28:59.548Z,1562804939.548 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:28:59.953Z,1562804939.953 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:29:02.779Z,1562804942.779 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:29:03.211Z,1562804943.211 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:29:03.989Z,1562804943.989 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:29:04.393Z,1562804944.393 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:29:07.224Z,1562804947.224 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:29:07.305Z,1562804947.305 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:29:08.028Z,1562804948.028 [Micromodem](INFO): Nmea out: $CCPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*54

2019-07-11T00:29:08.433Z,1562804948.433 [Micromodem](INFO): Nmea in: $SNPGT,10000,28,4A1C0370,1000,24000,0,0,0,0,4000,0*49

2019-07-11T00:29:11.260Z,1562804951.260 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-11T00:29:11.304Z,1562804951.304 [CommandLine](IMPORTANT): got command stop
2019-07-11T00:29:11.304Z,1562804951.304 [CommandLine](IMPORTANT): Scheduling is paused
2019-07-11T00:29:11.304Z,1562804951.304 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-11T00:29:11.702Z,1562804951.702 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-11T00:29:11.703Z,1562804951.703 [MissionManager](INFO): MissionManager is completed.
2019-07-11T00:29:11.703Z,1562804951.703 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL] Stopped
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL:A.Pitch] Stopped
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL:B.SetSpeed] Stopped
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-11T00:29:11.703Z,1562804951.703 [DUSBL:C.] Stopped
2019-07-11T00:29:11.704Z,1562804951.704 [DUSBL:RequestRepeater] Stopped
2019-07-11T00:29:11.704Z,1562804951.704 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-11T00:29:11.704Z,1562804951.704 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-11T00:29:11.704Z,1562804951.704 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T00:29:12.100Z,1562804952.100 [MissionManager](IMPORTANT): Started mission Default
2019-07-11T00:29:12.100Z,1562804952.100 [Default] Running Loop=1
2019-07-11T00:29:12.101Z,1562804952.101 [Default](DEBUG): Aggregate::initialize Default
2019-07-11T00:29:12.101Z,1562804952.101 [Default:B.GoToSurface] Running Loop=1
2019-07-11T00:29:12.101Z,1562804952.101 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-11T00:29:12.101Z,1562804952.101 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-11T00:29:12.101Z,1562804952.101 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-11T00:29:12.102Z,1562804952.102 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-11T00:29:12.102Z,1562804952.102 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-11T00:29:12.102Z,1562804952.102 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-11T00:29:12.103Z,1562804952.103 [Default:A.Wait] Running Loop=1
2019-07-11T00:29:12.103Z,1562804952.103 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-11T00:29:13.307Z,1562804953.307 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-11T00:29:13.310Z,1562804953.310 [BPC1](INFO): Received data from all battery sticks.
2019-07-11T00:29:25.014Z,1562804965.014 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-07-11T00:29:25.015Z,1562804965.015 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  93.43,  94.42,   0.00
2019-07-11T00:29:25.434Z,1562804965.434 [Default:A.Wait](INFO): Done Waiting.
2019-07-11T00:29:25.434Z,1562804965.434 [Default:A.Wait] Stopped
2019-07-11T00:29:25.434Z,1562804965.434 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T00:29:25.841Z,1562804965.841 [Default:CheckIn] Running Loop=1
2019-07-11T00:29:25.841Z,1562804965.841 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-11T00:29:25.841Z,1562804965.841 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-11T00:29:26.638Z,1562804966.638 [NAL9602](INFO): Powering up
2019-07-11T00:29:37.524Z,1562804977.524 [NAL9602](INFO): NAL9602 initialized
2019-07-11T00:29:38.342Z,1562804978.342 [NAL9602](DEBUG): Fix Requested
2019-07-11T00:30:09.440Z,1562805009.440 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-07-11T00:30:09.522Z,1562805009.522 [NAL9602](FAULT): received: 
+CSQ:1

OK08, 2, 0, 0, 0

OK
2019-07-11T00:30:09.522Z,1562805009.522 [NAL9602] Data Fault, FailCount= 1
2019-07-11T00:30:09.522Z,1562805009.522 [NAL9602](ERROR): Data Fault
2019-07-11T00:30:09.593Z,1562805009.593 [CBIT](ERROR): Data Fault in component: NAL9602
2019-07-11T00:30:09.840Z,1562805009.840 [NAL9602](INFO): Powering down
2019-07-11T00:30:10.693Z,1562805010.693 [CBIT](INFO): Clearing failed state for component NAL9602
2019-07-11T00:30:10.693Z,1562805010.693 [NAL9602] No Fault, FailCount= 1
2019-07-11T00:30:40.144Z,1562805040.144 [NAL9602](INFO): Powering up NAL9602
2019-07-11T00:30:51.056Z,1562805051.056 [NAL9602](INFO): NAL9602 initialized
2019-07-11T00:30:51.870Z,1562805051.870 [NAL9602](DEBUG): Fix Requested
2019-07-11T00:31:56.932Z,1562805116.932 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  93.93,  95.42,  92.93,   0.00
2019-07-11T00:34:26.023Z,1562805266.023 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-11T00:29:25.8Z
2019-07-11T00:34:26.023Z,1562805266.023 [Default:CheckIn:Read_GPS] Stopped
2019-07-11T00:34:26.023Z,1562805266.023 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-11T00:34:26.418Z,1562805266.418 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-11T00:34:26.948Z,1562805266.948 [Micromodem](ERROR): Buffer fill timout failure.
2019-07-11T00:34:29.021Z,1562805269.021 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 1181265D040001005D00000400270300000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567
2019-07-11T00:34:29.021Z,1562805269.021 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE
2019-07-11T00:34:29.022Z,1562805269.022 [Micromodem](INFO): Outgoing frame #3, 64 bytes: C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D185D02D3A531DAE1C60CC9420D9
2019-07-11T00:34:29.022Z,1562805269.022 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:34:30.523Z,1562805270.523 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20190711T002137/Courier0004.lzma
2019-07-11T00:34:31.332Z,1562805271.332 [DataOverHttps](INFO): Moved sent file to Logs/20190711T002137/Courier0004.lzma.bak
2019-07-11T00:34:31.332Z,1562805271.332 [DataOverHttps](INFO): SBD MOMSN=11438537
2019-07-11T00:34:40.092Z,1562805280.092 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:34:45.259Z,1562805285.259 [DataOverHttps](INFO): Sending 559 bytes from file Logs/20190711T002137/Express0005.lzma
2019-07-11T00:34:46.064Z,1562805286.064 [DataOverHttps](INFO): Moved sent file to Logs/20190711T002137/Express0005.lzma.bak
2019-07-11T00:34:46.064Z,1562805286.064 [DataOverHttps](INFO): SBD MOMSN=11438540
2019-07-11T00:34:46.554Z,1562805286.554 [NAL9602](INFO): SBD MO Status=0, MOMSN=8108, MT Status=0, MTMSN=0
2019-07-11T00:34:46.554Z,1562805286.554 [NAL9602](INFO): No messages in MT queue
2019-07-11T00:34:48.609Z,1562805288.609 [Default:CheckIn:Read_Iridium] Stopped
2019-07-11T00:34:48.609Z,1562805288.609 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-11T00:34:48.609Z,1562805288.609 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-11T00:34:51.400Z,1562805291.400 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:02.716Z,1562805302.716 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:14.023Z,1562805314.023 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:17.260Z,1562805317.260 [NAL9602](INFO): Powering down
2019-07-11T00:35:25.340Z,1562805325.340 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:36.648Z,1562805336.648 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:47.976Z,1562805347.976 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:35:49.640Z,1562805349.640 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-07-11T00:35:49.640Z,1562805349.640 [RDI_Pathfinder](ERROR): Failed to parse:
:TS68,-32768,V
2019-07-11T00:35:59.272Z,1562805359.272 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:36:10.621Z,1562805370.621 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:36:21.896Z,1562805381.896 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:36:33.211Z,1562805393.211 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:36:44.520Z,1562805404.520 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:36:47.798Z,1562805407.798 [CBIT](INFO): Clearing failed state for component DropWeight
2019-07-11T00:36:47.798Z,1562805407.798 [DropWeight] No Fault, FailCount= 1
2019-07-11T00:36:55.832Z,1562805415.832 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:37:07.141Z,1562805427.141 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:37:18.456Z,1562805438.456 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:37:29.768Z,1562805449.768 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:37:41.084Z,1562805461.084 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:37:52.396Z,1562805472.396 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:38:03.704Z,1562805483.704 [Micromodem](ERROR): Nmea resend: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:38:11.389Z,1562805491.389 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,$CAERR,00375$CAERR,003811,DATA_TIMEOUT,1*45

2019-07-11T00:38:11.390Z,1562805491.390 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACYC,0,1,9,1,0,$CAERR,00375$CAERR,003811,DATA_TIMEOUT,1*45
 expected 7D
2019-07-11T00:38:11.390Z,1562805491.390 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-11T00:38:11.789Z,1562805491.789 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-11T00:38:12.188Z,1562805492.188 [Micromodem](INFO): Nmea in: $CADRQ,003812,1,9,0,64,1*46

2019-07-11T00:38:12.189Z,1562805492.189 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,1181265D040001005D00000400270300000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*74

2019-07-11T00:38:12.604Z,1562805492.604 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T00:38:12.608Z,1562805492.608 [Micromodem](INFO): Nmea in: $CADRQ,003812,1,9,0,64,2*45

2019-07-11T00:38:12.609Z,1562805492.609 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE*74

2019-07-11T00:38:12.996Z,1562805492.996 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T00:38:12.997Z,1562805492.997 [Micromodem](INFO): Nmea in: $CADRQ,003813,1,9,0,64,3*45

2019-07-11T00:38:12.997Z,1562805492.997 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D185D02D3A531DAE1C60CC9420D9*03

2019-07-11T00:38:13.400Z,1562805493.400 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-11T00:38:13.401Z,1562805493.401 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-07-11T00:38:21.479Z,1562805501.479 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-07-11T00:38:21.887Z,1562805501.887 [Micromodem](INFO): Nmea in: $CAXST,6,20190711,003813.822300,3,0,200,2000,10000,1,1,9,1,3,3,3,192*49

2019-07-11T00:39:38.032Z,1562805578.032 [CommandLine](IMPORTANT): got command quit
2019-07-11T00:39:39.038Z,1562805579.038 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:39.039Z,1562805579.039 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.230Z,1562805579.230 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-11T00:39:39.230Z,1562805579.230 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.231Z,1562805579.231 [CommandLine](INFO): Join timeout helper Thread ID is 3217
2019-07-11T00:39:39.238Z,1562805579.238 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-11T00:39:39.238Z,1562805579.238 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.239Z,1562805579.239 [NavChartDb](INFO): Join timeout helper Thread ID is 3218
2019-07-11T00:39:39.306Z,1562805579.306 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:39.307Z,1562805579.307 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.326Z,1562805579.326 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-07-11T00:39:39.326Z,1562805579.326 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.327Z,1562805579.327 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 3219
2019-07-11T00:39:39.446Z,1562805579.446 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:39.447Z,1562805579.447 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-11T00:39:39.447Z,1562805579.447 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.448Z,1562805579.448 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-07-11T00:39:39.448Z,1562805579.448 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.448Z,1562805579.448 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3220
2019-07-11T00:39:39.555Z,1562805579.555 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:39.555Z,1562805579.555 [CTD_NeilBrown](INFO): Powering down
2019-07-11T00:39:39.566Z,1562805579.566 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.574Z,1562805579.574 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-11T00:39:39.574Z,1562805579.574 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.575Z,1562805579.575 [Radio_Surface](INFO): Join timeout helper Thread ID is 3221
2019-07-11T00:39:39.671Z,1562805579.671 [Radio_Surface](INFO): Powering down
2019-07-11T00:39:39.671Z,1562805579.671 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:39.672Z,1562805579.672 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.691Z,1562805579.691 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-11T00:39:39.691Z,1562805579.691 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:39.692Z,1562805579.692 [DataOverHttps](INFO): Join timeout helper Thread ID is 3222
2019-07-11T00:39:42.784Z,1562805582.784 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:42.788Z,1562805582.788 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:42.803Z,1562805582.803 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-11T00:39:42.803Z,1562805582.803 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:42.804Z,1562805582.804 [logger](INFO): Join timeout helper Thread ID is 3223
2019-07-11T00:39:42.814Z,1562805582.814 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:42.815Z,1562805582.815 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:42.823Z,1562805582.823 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-11T00:39:42.823Z,1562805582.823 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:42.823Z,1562805582.823 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-11T00:39:42.823Z,1562805582.823 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:42.824Z,1562805582.824 [controlThread](INFO): Join timeout helper Thread ID is 3224
2019-07-11T00:39:43.070Z,1562805583.070 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-11T00:39:43.071Z,1562805583.071 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-11T00:39:43.071Z,1562805583.071 [AHRS_M2](INFO): Powering down
2019-07-11T00:39:43.143Z,1562805583.143 [DUSBL_Hydroid](INFO): Powering down
2019-07-11T00:39:43.215Z,1562805583.215 [Micromodem](INFO): Powering down
2019-07-11T00:39:43.311Z,1562805583.311 [NAL9602](INFO): Powering down
2019-07-11T00:39:43.382Z,1562805583.382 [RDI_Pathfinder](INFO): Powering down
2019-07-11T00:39:43.384Z,1562805583.384 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-11T00:39:43.385Z,1562805583.385 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-11T00:39:43.385Z,1562805583.385 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-11T00:39:43.386Z,1562805583.386 [MissionManager](INFO): Uninitializing Mission Default
2019-07-11T00:39:43.386Z,1562805583.386 [Default] Stopped
2019-07-11T00:39:43.386Z,1562805583.386 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-11T00:39:43.386Z,1562805583.386 [Default:B.GoToSurface] Stopped
2019-07-11T00:39:43.386Z,1562805583.386 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-11T00:39:43.386Z,1562805583.386 [Default:CheckIn] Stopped
2019-07-11T00:39:43.386Z,1562805583.386 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-11T00:39:43.386Z,1562805583.386 [Default:CheckIn:C.Wait] Stopped
2019-07-11T00:39:43.386Z,1562805583.386 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-11T00:39:43.389Z,1562805583.389 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-11T00:39:43.389Z,1562805583.389 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-11T00:39:43.389Z,1562805583.389 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-11T00:39:43.390Z,1562805583.390 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-11T00:39:43.390Z,1562805583.390 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-11T00:39:43.390Z,1562805583.390 [BuoyancyServo](INFO): Powering down
2019-07-11T00:39:43.402Z,1562805583.402 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-11T00:39:43.403Z,1562805583.403 [ElevatorServo](INFO): Powering down
2019-07-11T00:39:43.403Z,1562805583.403 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-11T00:39:43.404Z,1562805583.404 [MassServo](INFO): Powering down
2019-07-11T00:39:43.404Z,1562805583.404 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-11T00:39:43.404Z,1562805583.404 [RudderServo](INFO): Powering down
2019-07-11T00:39:43.405Z,1562805583.405 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-11T00:39:43.405Z,1562805583.405 [ThrusterServo](INFO): Powering down
2019-07-11T00:39:43.406Z,1562805583.406 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-11T00:39:43.407Z,1562805583.407 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-11T00:39:43.407Z,1562805583.407 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-11T00:39:43.407Z,1562805583.407 [CBIT](DEBUG): Powering off loads.
2019-07-11T00:39:43.418Z,1562805583.418 [CBIT](DEBUG): Disabling WDT.
2019-07-11T00:39:43.430Z,1562805583.430 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-11T00:39:43.431Z,1562805583.431 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.479Z,1562805583.479 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.488Z,1562805583.488 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.528Z,1562805583.528 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.531Z,1562805583.531 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.587Z,1562805583.587 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-11T00:39:43.644Z,1562805583.644 [logger ThreadHandler](INFO): Thread cancelled.