2019-03-27T18:37:21.219Z,1553711841.219 [Supervisor](DEBUG): Initializing supervisor.
2019-03-27T18:37:21.222Z,1553711841.222 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-03-27T18:37:21.223Z,1553711841.223 [SyncHandler](INFO): Protected caller Thread ID is 8215
2019-03-27T18:37:21.224Z,1553711841.224 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-03-27T18:37:21.225Z,1553711841.225 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-03-27T18:37:21.225Z,1553711841.225 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 8216
2019-03-27T18:37:21.228Z,1553711841.228 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-03-27T18:37:21.241Z,1553711841.241 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-03-27T18:37:21.242Z,1553711841.242 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-03-27T18:37:21.243Z,1553711841.243 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 8217
2019-03-27T18:37:21.243Z,1553711841.243 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-03-27T18:37:21.244Z,1553711841.244 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-03-27T18:37:21.245Z,1553711841.245 [logger ThreadHandler](INFO): Protected caller Thread ID is 8218
2019-03-27T18:37:21.247Z,1553711841.247 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-03-27T18:37:21.247Z,1553711841.247 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-03-27T18:37:21.249Z,1553711841.249 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-03-27T18:37:21.700Z,1553711841.700 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-03-27T18:37:21.700Z,1553711841.700 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-03-27T18:37:21.799Z,1553711841.799 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-03-27T18:37:21.800Z,1553711841.800 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-03-27T18:37:22.149Z,1553711842.149 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-03-27T18:37:22.150Z,1553711842.150 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-03-27T18:37:22.296Z,1553711842.296 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-03-27T18:37:22.296Z,1553711842.296 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-03-27T18:37:22.498Z,1553711842.498 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-03-27T18:37:22.498Z,1553711842.498 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-03-27T18:37:22.982Z,1553711842.982 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-03-27T18:37:22.983Z,1553711842.983 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-03-27T18:37:23.203Z,1553711843.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-03-27T18:37:23.204Z,1553711843.204 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-03-27T18:37:23.355Z,1553711843.355 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-03-27T18:37:23.356Z,1553711843.356 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-03-27T18:37:23.564Z,1553711843.564 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-03-27T18:37:23.565Z,1553711843.565 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-03-27T18:37:23.662Z,1553711843.662 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-03-27T18:37:23.663Z,1553711843.663 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-03-27T18:37:24.008Z,1553711844.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-03-27T18:37:24.009Z,1553711844.009 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-03-27T18:37:24.090Z,1553711844.090 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-03-27T18:37:24.195Z,1553711844.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-03-27T18:37:24.195Z,1553711844.195 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-03-27T18:37:24.781Z,1553711844.781 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-03-27T18:37:24.782Z,1553711844.782 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-03-27T18:37:25.667Z,1553711845.667 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-03-27T18:37:25.669Z,1553711845.669 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-03-27T18:37:25.670Z,1553711845.670 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-03-27T18:37:25.891Z,1553711845.891 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-03-27T18:37:25.994Z,1553711845.994 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-03-27T18:37:26.095Z,1553711846.095 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-03-27T18:37:26.328Z,1553711846.328 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-03-27T18:37:26.329Z,1553711846.329 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-03-27T18:37:26.414Z,1553711846.414 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-03-27T18:37:26.509Z,1553711846.509 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-03-27T18:37:26.608Z,1553711846.608 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-03-27T18:37:26.691Z,1553711846.691 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-03-27T18:37:26.806Z,1553711846.806 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-03-27T18:37:26.000Z,1553711847.000 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-03-27T18:37:27.138Z,1553711847.138 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-03-27T18:37:27.139Z,1553711847.139 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-03-27T18:37:27.145Z,1553711847.145 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-03-27T18:37:27.537Z,1553711847.537 [AHRS_M2] Loaded
2019-03-27T18:37:27.538Z,1553711847.538 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-03-27T18:37:27.612Z,1553711847.612 [DataOverHttps] Loaded
2019-03-27T18:37:27.612Z,1553711847.612 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-03-27T18:37:27.613Z,1553711847.613 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075B4E0
2019-03-27T18:37:27.613Z,1553711847.613 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 8297
2019-03-27T18:37:27.627Z,1553711847.627 [Depth_Keller] Loaded
2019-03-27T18:37:27.628Z,1553711847.628 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-03-27T18:37:27.633Z,1553711847.633 [DropWeight] Loaded
2019-03-27T18:37:27.633Z,1553711847.633 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-03-27T18:37:27.688Z,1553711847.688 [DUSBL_Hydroid] Loaded
2019-03-27T18:37:27.688Z,1553711847.688 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-03-27T18:37:27.730Z,1553711847.730 [Micromodem] Loaded
2019-03-27T18:37:27.730Z,1553711847.730 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-03-27T18:37:27.832Z,1553711847.832 [NAL9602] Loaded
2019-03-27T18:37:27.833Z,1553711847.833 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-03-27T18:37:27.849Z,1553711847.849 [Onboard] Loaded
2019-03-27T18:37:27.850Z,1553711847.850 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-03-27T18:37:27.856Z,1553711847.856 [PowerOnly] Loaded
2019-03-27T18:37:27.856Z,1553711847.856 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-03-27T18:37:27.863Z,1553711847.863 [Radio_Surface] Loaded
2019-03-27T18:37:27.863Z,1553711847.863 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-03-27T18:37:27.864Z,1553711847.864 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078B4E0
2019-03-27T18:37:27.865Z,1553711847.865 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 8298
2019-03-27T18:37:27.927Z,1553711847.927 [RDI_Pathfinder] Loaded
2019-03-27T18:37:27.927Z,1553711847.927 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-03-27T18:37:27.950Z,1553711847.950 [RDI_PathfinderUp] Loaded
2019-03-27T18:37:27.950Z,1553711847.950 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-03-27T18:37:29.483Z,1553711849.483 [BPC1] Loaded
2019-03-27T18:37:29.483Z,1553711849.483 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-03-27T18:37:29.483Z,1553711849.483 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-03-27T18:37:29.484Z,1553711849.484 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-03-27T18:37:29.497Z,1553711849.497 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-03-27T18:37:29.498Z,1553711849.498 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-03-27T18:37:29.608Z,1553711849.608 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-03-27T18:37:29.608Z,1553711849.608 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-03-27T18:37:29.672Z,1553711849.672 [DeadReckonUsingSpeedCalculator] Loaded
2019-03-27T18:37:29.672Z,1553711849.672 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-03-27T18:37:29.734Z,1553711849.734 [DeadReckonWithRespectToSeafloor] Loaded
2019-03-27T18:37:29.734Z,1553711849.734 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread.
2019-03-27T18:37:29.755Z,1553711849.755 [NavChart] Loaded
2019-03-27T18:37:29.756Z,1553711849.756 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-03-27T18:37:29.760Z,1553711849.760 [UniversalFixResidualReporter] Loaded
2019-03-27T18:37:29.760Z,1553711849.760 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-03-27T18:37:29.760Z,1553711849.760 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-03-27T18:37:29.761Z,1553711849.761 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-03-27T18:37:30.112Z,1553711850.112 [BuoyancyServo] Loaded
2019-03-27T18:37:30.112Z,1553711850.112 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-03-27T18:37:30.128Z,1553711850.128 [ElevatorServo] Loaded
2019-03-27T18:37:30.129Z,1553711850.129 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-03-27T18:37:30.144Z,1553711850.144 [MassServo] Loaded
2019-03-27T18:37:30.144Z,1553711850.144 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-03-27T18:37:30.161Z,1553711850.161 [RudderServo] Loaded
2019-03-27T18:37:30.161Z,1553711850.161 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-03-27T18:37:30.203Z,1553711850.203 [ThrusterServo] Loaded
2019-03-27T18:37:30.204Z,1553711850.204 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-03-27T18:37:30.204Z,1553711850.204 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-03-27T18:37:30.277Z,1553711850.277 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-03-27T18:37:30.535Z,1553711850.535 [CTD_NeilBrown] Loaded
2019-03-27T18:37:30.535Z,1553711850.535 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-03-27T18:37:30.536Z,1553711850.536 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D04E0
2019-03-27T18:37:30.537Z,1553711850.537 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 8299
2019-03-27T18:37:30.584Z,1553711850.584 [WetLabsSeaOWL_UV_A] Loaded
2019-03-27T18:37:30.585Z,1553711850.585 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-03-27T18:37:30.586Z,1553711850.586 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409004E0
2019-03-27T18:37:30.586Z,1553711850.586 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 8300
2019-03-27T18:37:30.587Z,1553711850.587 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-03-27T18:37:30.587Z,1553711850.587 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-03-27T18:37:30.863Z,1553711850.863 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-03-27T18:37:30.864Z,1553711850.864 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-03-27T18:37:30.905Z,1553711850.905 [DepthRateCalculator] Loaded
2019-03-27T18:37:30.905Z,1553711850.905 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-03-27T18:37:30.912Z,1553711850.912 [PitchRateCalculator] Loaded
2019-03-27T18:37:30.912Z,1553711850.912 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-03-27T18:37:30.925Z,1553711850.925 [SpeedCalculator] Loaded
2019-03-27T18:37:30.926Z,1553711850.926 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-03-27T18:37:30.948Z,1553711850.948 [TempGradientCalculator] Loaded
2019-03-27T18:37:30.948Z,1553711850.948 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-03-27T18:37:30.984Z,1553711850.984 [YawRateCalculator] Loaded
2019-03-27T18:37:30.984Z,1553711850.984 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-03-27T18:37:31.106Z,1553711851.106 [ElevatorOffsetCalculator] Loaded
2019-03-27T18:37:31.106Z,1553711851.106 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-03-27T18:37:31.107Z,1553711851.107 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-03-27T18:37:31.107Z,1553711851.107 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-03-27T18:37:31.244Z,1553711851.244 [SBIT](DEBUG): Construct Startup Built In Test.
2019-03-27T18:37:31.267Z,1553711851.267 [SBIT] Loaded
2019-03-27T18:37:31.267Z,1553711851.267 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-03-27T18:37:31.268Z,1553711851.268 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-03-27T18:37:31.280Z,1553711851.280 [IBIT] Loaded
2019-03-27T18:37:31.280Z,1553711851.280 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-03-27T18:37:31.284Z,1553711851.284 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-03-27T18:37:31.431Z,1553711851.431 [CBIT] Loaded
2019-03-27T18:37:31.431Z,1553711851.431 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-03-27T18:37:31.432Z,1553711851.432 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-03-27T18:37:31.432Z,1553711851.432 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-03-27T18:37:31.503Z,1553711851.503 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-03-27T18:37:31.504Z,1553711851.504 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-03-27T18:37:31.604Z,1553711851.604 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-03-27T18:37:31.604Z,1553711851.604 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-03-27T18:37:31.672Z,1553711851.672 [VerticalControl](DEBUG): Construct VerticalControl.
2019-03-27T18:37:31.761Z,1553711851.761 [VerticalControl] Loaded
2019-03-27T18:37:31.761Z,1553711851.761 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-03-27T18:37:31.762Z,1553711851.762 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-03-27T18:37:31.823Z,1553711851.823 [HorizontalControl] Loaded
2019-03-27T18:37:31.824Z,1553711851.824 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-03-27T18:37:31.824Z,1553711851.824 [SpeedControl](DEBUG): Construct SpeedControl.
2019-03-27T18:37:31.826Z,1553711851.826 [SpeedControl] Loaded
2019-03-27T18:37:31.827Z,1553711851.827 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-03-27T18:37:31.827Z,1553711851.827 [LoopControl](DEBUG): Construct LoopControl.
2019-03-27T18:37:31.828Z,1553711851.828 [LoopControl] Loaded
2019-03-27T18:37:31.828Z,1553711851.828 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-03-27T18:37:31.829Z,1553711851.829 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-03-27T18:37:31.829Z,1553711851.829 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-03-27T18:37:31.857Z,1553711851.857 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-03-27T18:37:31.860Z,1553711851.860 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-03-27T18:37:31.861Z,1553711851.861 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-03-27T18:37:31.868Z,1553711851.868 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-03-27T18:37:31.869Z,1553711851.869 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-03-27T18:37:31.870Z,1553711851.870 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 8301
2019-03-27T18:37:31.875Z,1553711851.875 [Supervisor](INFO): Main Thread ID is 7788
2019-03-27T18:37:31.875Z,1553711851.875 [Supervisor](DEBUG): Running supervisor.
2019-03-27T18:37:31.876Z,1553711851.876 [CommandLine ThreadHandler](INFO): Handler Thread ID is 8302
2019-03-27T18:37:31.878Z,1553711851.878 [controlThread ThreadHandler](INFO): Handler Thread ID is 8303
2019-03-27T18:37:31.878Z,1553711851.878 [controlThread](DEBUG): Initializing ControlThread
2019-03-27T18:37:31.884Z,1553711851.884 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-27T18:37:31.885Z,1553711851.885 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-03-27T18:37:31.885Z,1553711851.885 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-03-27T18:37:31.886Z,1553711851.886 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-03-27T18:37:31.887Z,1553711851.887 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-03-27T18:37:31.887Z,1553711851.887 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-03-27T18:37:31.887Z,1553711851.887 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-03-27T18:37:31.888Z,1553711851.888 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-03-27T18:37:31.888Z,1553711851.888 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-03-27T18:37:31.888Z,1553711851.888 [SBIT](INFO): Initialize SBIT Component.
2019-03-27T18:37:31.889Z,1553711851.889 [SBIT](IMPORTANT): git: 2019-03-18-26-gc8399b8
2019-03-27T18:37:31.889Z,1553711851.889 [SBIT](INFO): git hash: c8399b8e53db2b8366337064c7df5542bc2caf88
2019-03-27T18:37:31.890Z,1553711851.890 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-03-27T18:37:31.890Z,1553711851.890 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-03-27T18:37:31.891Z,1553711851.891 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-03-27T18:37:31.891Z,1553711851.891 [IBIT](INFO): Initialize IBIT Component.
2019-03-27T18:37:31.892Z,1553711851.892 [CBIT](DEBUG): Initialize CBIT Component.
2019-03-27T18:37:31.893Z,1553711851.893 [logger ThreadHandler](INFO): Handler Thread ID is 8304
2019-03-27T18:37:31.905Z,1553711851.905 [CBIT](DEBUG): Initialized mux pins.
2019-03-27T18:37:31.905Z,1553711851.905 [CBIT](DEBUG): Initializing the watchdog timer.
2019-03-27T18:37:31.913Z,1553711851.913 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 8305
2019-03-27T18:37:31.914Z,1553711851.914 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-03-27T18:37:31.925Z,1553711851.925 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 8306
2019-03-27T18:37:31.929Z,1553711851.929 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-03-27T18:37:31.929Z,1553711851.929 [CBIT](DEBUG): Initializing heartbeat.
2019-03-27T18:37:31.937Z,1553711851.937 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 8307
2019-03-27T18:37:31.938Z,1553711851.938 [CTD_NeilBrown](INFO): Powering down
2019-03-27T18:37:31.973Z,1553711851.973 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 8308
2019-03-27T18:37:31.974Z,1553711851.974 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-27T18:37:32.001Z,1553711852.001 [CBIT](DEBUG): Deactivating GF circuits.
2019-03-27T18:37:32.001Z,1553711852.001 [CBIT](DEBUG): Deactivating emergency mode.
2019-03-27T18:37:32.002Z,1553711852.002 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 8309
2019-03-27T18:37:32.005Z,1553711852.005 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-03-27T18:37:32.005Z,1553711852.005 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-03-27T18:37:32.005Z,1553711852.005 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-03-27T18:37:32.005Z,1553711852.005 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-03-27T18:37:32.006Z,1553711852.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-03-27T18:37:32.007Z,1553711852.007 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-03-27T18:37:32.007Z,1553711852.007 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-03-27T18:37:32.007Z,1553711852.007 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-03-27T18:37:32.007Z,1553711852.007 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-03-27T18:37:32.007Z,1553711852.007 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-03-27T18:37:32.008Z,1553711852.008 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-03-27T18:37:32.037Z,1553711852.037 [CBIT](DEBUG): Backplane powered.
2019-03-27T18:37:32.037Z,1553711852.037 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-03-27T18:37:32.039Z,1553711852.039 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-03-27T18:37:32.039Z,1553711852.039 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-03-27T18:37:32.040Z,1553711852.040 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-03-27T18:37:32.041Z,1553711852.041 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-03-27T18:37:32.050Z,1553711852.050 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-27T18:37:32.077Z,1553711852.077 [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-03-27T18:37:32.078Z,1553711852.078 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-03-27T18:37:32.149Z,1553711852.149 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-03-27T18:37:32.150Z,1553711852.150 [Default:A.Wait](DEBUG): Construct Wait.
2019-03-27T18:37:32.151Z,1553711852.151 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-03-27T18:37:32.174Z,1553711852.174 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-03-27T18:37:32.201Z,1553711852.201 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-03-27T18:37:32.206Z,1553711852.206 [Default:E.Execute](DEBUG): Construct Execute.
2019-03-27T18:37:32.225Z,1553711852.225 [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-03-27T18:37:32.230Z,1553711852.230 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,RDI_PathfinderUp,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-03-27T18:37:32.241Z,1553711852.241 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-03-27T18:37:32.306Z,1553711852.306 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-03-27T18:37:32.306Z,1553711852.306 [DUSBL_Hydroid](INFO): Powering up
2019-03-27T18:37:32.307Z,1553711852.307 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-03-27T18:37:32.329Z,1553711852.329 [Radio_Surface](INFO): Powering up
2019-03-27T18:37:32.389Z,1553711852.389 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-03-27T18:37:32.410Z,1553711852.410 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:37:32.417Z,1553711852.417 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-03-27T18:37:32.418Z,1553711852.418 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:37:32.433Z,1553711852.433 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-03-27T18:37:32.434Z,1553711852.434 [MassServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:37:32.441Z,1553711852.441 [MassServo](DEBUG): Initializing MassServo.
2019-03-27T18:37:32.442Z,1553711852.442 [RudderServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:37:32.449Z,1553711852.449 [RudderServo](DEBUG): Initializing RudderServo.
2019-03-27T18:37:32.450Z,1553711852.450 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-03-27T18:37:32.469Z,1553711852.469 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-03-27T18:37:32.659Z,1553711852.659 [Micromodem](INFO): Powering up
2019-03-27T18:37:32.659Z,1553711852.659 [Micromodem](DEBUG): Initializing Micromodem.
2019-03-27T18:37:32.765Z,1553711852.765 [RDI_PathfinderUp](INFO): Powering down
2019-03-27T18:37:32.817Z,1553711852.817 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-03-27T18:37:37.527Z,1553711857.527 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-03-27T18:37:45.596Z,1553711865.596 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-03-27T18:37:48.807Z,1553711868.807 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-03-27T18:37:50.419Z,1553711870.419 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-03-27T18:37:58.096Z,1553711878.096 [NAL9602](INFO): Powering up NAL9602
2019-03-27T18:38:00.115Z,1553711880.115 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-03-27T18:38:00.584Z,1553711880.584 [SBIT](IMPORTANT): Beginning Startup BIT
2019-03-27T18:38:00.601Z,1553711880.601 [CBIT](IMPORTANT): Beginning ground fault scan
2019-03-27T18:38:07.583Z,1553711887.583 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-03-27T18:38:09.203Z,1553711889.203 [NAL9602](INFO): NAL9602 initialized
2019-03-27T18:38:10.021Z,1553711890.021 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:38:11.297Z,1553711891.297 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010031
CHAN A1 (24V): -0.026933
CHAN A2 (12V): -0.006994
CHAN A3 (5V): -0.001904
CHAN B0 (3.3V): 0.000249
CHAN B1 (3.15aV): 0.000284
CHAN B2 (3.15bV): -0.000026
CHAN B3 (GND): 0.001981
OPEN: 0.006983
Full Scale Calc: 4.765 mA, -1.589 mA
2019-03-27T18:38:17.359Z,1553711897.359 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-03-27T18:38:27.477Z,1553711907.477 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-03-27T18:38:37.559Z,1553711917.559 [Micromodem](INFO): Nmea out: $CCTMS,2019-03-27T18:38:38Z,0*71

2019-03-27T18:38:54.265Z,1553711934.265 [SBIT](IMPORTANT): SBIT PASSED
2019-03-27T18:38:54.357Z,1553711934.357 [CommandLine](IMPORTANT): got command configSet list
2019-03-27T18:38:54.357Z,1553711934.357 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-03-27T18:38:54.358Z,1553711934.358 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-03-27T18:38:54.359Z,1553711934.359 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-03-27T18:38:54.359Z,1553711934.359 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-03-27T18:38:54.359Z,1553711934.359 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-03-27T18:38:54.646Z,1553711934.646 [MissionManager](IMPORTANT): Started mission Startup
2019-03-27T18:38:54.647Z,1553711934.647 [Startup] Running Loop=1
2019-03-27T18:38:54.647Z,1553711934.647 [Startup](DEBUG): Aggregate::initialize Startup
2019-03-27T18:38:54.647Z,1553711934.647 [Startup:A.GoToSurface] Running Loop=1
2019-03-27T18:38:54.647Z,1553711934.647 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:38:54.648Z,1553711934.648 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:38:54.648Z,1553711934.648 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:38:54.649Z,1553711934.649 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:38:54.649Z,1553711934.649 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:38:54.650Z,1553711934.650 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:38:54.651Z,1553711934.651 [Startup:StartupSatComms] Running Loop=1
2019-03-27T18:38:54.652Z,1553711934.652 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-03-27T18:38:54.652Z,1553711934.652 [Startup:StartupSatComms:A] Running Loop=1
2019-03-27T18:38:55.040Z,1553711935.040 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-03-27T18:39:20.480Z,1553711960.480 [NAL9602](INFO): SBD MO Status=2, MOMSN=2455, MT Status=2, MTMSN=0
2019-03-27T18:39:20.482Z,1553711960.482 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-27T18:39:54.865Z,1553711994.865 [Startup:StartupSatComms:A](INFO): Timed out from 2019-03-27T18:38:54.7Z
2019-03-27T18:39:54.865Z,1553711994.865 [Startup:StartupSatComms:A] Stopped
2019-03-27T18:39:54.865Z,1553711994.865 [Startup:StartupSatComms:B] Running Loop=1
2019-03-27T18:39:55.228Z,1553711995.228 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-27T18:39:58.255Z,1553711998.255 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004961
2019-03-27T18:40:03.572Z,1553712003.572 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190327T171704/Courier0043.lzma
2019-03-27T18:40:03.692Z,1553712003.692 [NAL9602](INFO): SBD MO Status=0, MOMSN=2455, MT Status=0, MTMSN=0
2019-03-27T18:40:03.693Z,1553712003.693 [NAL9602](INFO): No messages in MT queue
2019-03-27T18:40:04.379Z,1553712004.379 [DataOverHttps](INFO): Moved sent file to Logs/20190327T171704/Courier0043.lzma.bak
2019-03-27T18:40:04.379Z,1553712004.379 [DataOverHttps](INFO): SBD MOMSN=10257224
2019-03-27T18:40:04.518Z,1553712004.518 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:07.349Z,1553712007.349 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:10.165Z,1553712010.165 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:13.397Z,1553712013.397 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:16.225Z,1553712016.225 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:16.480Z,1553712016.480 [DataOverHttps](INFO): Sending 176 bytes from file Logs/20190327T171704/Express0044.lzma
2019-03-27T18:40:17.278Z,1553712017.278 [DataOverHttps](INFO): Moved sent file to Logs/20190327T171704/Express0044.lzma.bak
2019-03-27T18:40:17.279Z,1553712017.279 [DataOverHttps](INFO): SBD MOMSN=10257226
2019-03-27T18:40:19.053Z,1553712019.053 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:21.881Z,1553712021.881 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:25.113Z,1553712025.113 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:27.965Z,1553712027.965 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:29.369Z,1553712029.369 [DataOverHttps](INFO): Sending 734 bytes from file Logs/20190327T183721/Express0001.lzma
2019-03-27T18:40:30.174Z,1553712030.174 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Express0001.lzma.bak
2019-03-27T18:40:30.174Z,1553712030.174 [DataOverHttps](INFO): SBD MOMSN=10257228
2019-03-27T18:40:31.177Z,1553712031.177 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:31.631Z,1553712031.631 [Startup:StartupSatComms:B] Stopped
2019-03-27T18:40:31.631Z,1553712031.631 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-03-27T18:40:31.632Z,1553712031.632 [Startup:StartupSatComms] Stopped
2019-03-27T18:40:31.632Z,1553712031.632 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-03-27T18:40:31.632Z,1553712031.632 [Startup](INFO): Completed Startup
2019-03-27T18:40:31.641Z,1553712031.641 [MissionManager](INFO): Startup is completed.
2019-03-27T18:40:31.641Z,1553712031.641 [MissionManager](INFO): Uninitializing Mission Startup
2019-03-27T18:40:31.641Z,1553712031.641 [Startup] Stopped
2019-03-27T18:40:31.641Z,1553712031.641 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-03-27T18:40:31.641Z,1553712031.641 [Startup:A.GoToSurface] Stopped
2019-03-27T18:40:31.641Z,1553712031.641 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:40:32.017Z,1553712032.017 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-03-27T18:40:32.017Z,1553712032.017 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-03-27T18:40:32.018Z,1553712032.018 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-03-27T18:40:32.018Z,1553712032.018 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-03-27T18:40:32.019Z,1553712032.019 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T18:40:32.020Z,1553712032.020 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T18:40:32.025Z,1553712032.025 [MissionManager](IMPORTANT): Started mission Default
2019-03-27T18:40:32.025Z,1553712032.025 [Default] Running Loop=1
2019-03-27T18:40:32.025Z,1553712032.025 [Default](DEBUG): Aggregate::initialize Default
2019-03-27T18:40:32.025Z,1553712032.025 [Default:B.GoToSurface] Running Loop=1
2019-03-27T18:40:32.026Z,1553712032.026 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:40:32.026Z,1553712032.026 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:40:32.026Z,1553712032.026 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:40:32.026Z,1553712032.026 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:40:32.027Z,1553712032.027 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:40:32.027Z,1553712032.027 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:40:32.027Z,1553712032.027 [Default:A.Wait] Running Loop=1
2019-03-27T18:40:32.027Z,1553712032.027 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:40:32.050Z,1553712032.050 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-03-27T18:40:32.050Z,1553712032.050 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-03-27T18:40:32.050Z,1553712032.050 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T18:40:32.437Z,1553712032.437 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-03-27T18:40:32.437Z,1553712032.437 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-03-27T18:40:32.437Z,1553712032.437 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-03-27T18:40:32.437Z,1553712032.437 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-03-27T18:40:32.438Z,1553712032.438 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T18:40:32.438Z,1553712032.438 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T18:40:32.804Z,1553712032.804 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-03-27T18:40:34.001Z,1553712034.001 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:37.237Z,1553712037.237 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:37.427Z,1553712037.427 [CommandLine](IMPORTANT): got command show variable DUSBL_Hy
2019-03-27T18:40:37.514Z,1553712037.514 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-03-27T18:40:37.514Z,1553712037.514 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-03-27T18:40:37.514Z,1553712037.514 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-03-27T18:40:37.515Z,1553712037.515 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-03-27T18:40:37.515Z,1553712037.515 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-03-27T18:40:37.515Z,1553712037.515 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-03-27T18:40:37.516Z,1553712037.516 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-03-27T18:40:37.516Z,1553712037.516 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-03-27T18:40:37.517Z,1553712037.517 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-03-27T18:40:37.517Z,1553712037.517 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-03-27T18:40:37.518Z,1553712037.518 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-03-27T18:40:37.518Z,1553712037.518 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-03-27T18:40:37.531Z,1553712037.531 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-03-27T18:40:37.532Z,1553712037.532 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-03-27T18:40:37.532Z,1553712037.532 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-03-27T18:40:37.536Z,1553712037.536 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-03-27T18:40:37.536Z,1553712037.536 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-03-27T18:40:37.537Z,1553712037.537 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-03-27T18:40:37.537Z,1553712037.537 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-03-27T18:40:37.538Z,1553712037.538 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-03-27T18:40:37.538Z,1553712037.538 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-03-27T18:40:37.538Z,1553712037.538 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-03-27T18:40:37.539Z,1553712037.539 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-03-27T18:40:37.539Z,1553712037.539 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-03-27T18:40:37.540Z,1553712037.540 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-03-27T18:40:40.061Z,1553712040.061 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:41.719Z,1553712041.719 [RDI_Pathfinder](ERROR): Failed to parse:
:  -2.56,        +1.87,       -0.92,   9.33,  0.00
2019-03-27T18:40:43.293Z,1553712043.293 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:45.332Z,1553712045.332 [Default:A.Wait](INFO): Done Waiting.
2019-03-27T18:40:45.332Z,1553712045.332 [Default:A.Wait] Stopped
2019-03-27T18:40:45.332Z,1553712045.332 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:40:45.748Z,1553712045.748 [Default:CheckIn] Running Loop=1
2019-03-27T18:40:45.748Z,1553712045.748 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T18:40:45.748Z,1553712045.748 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T18:40:46.121Z,1553712046.121 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:46.152Z,1553712046.152 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-03-27T18:40:49.357Z,1553712049.357 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:52.181Z,1553712052.181 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:55.413Z,1553712055.413 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:40:58.241Z,1553712058.241 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:01.073Z,1553712061.073 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:03.897Z,1553712063.897 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:07.133Z,1553712067.133 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:09.961Z,1553712069.961 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:13.193Z,1553712073.193 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:16.017Z,1553712076.017 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:19.265Z,1553712079.265 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:20.871Z,1553712080.871 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-03-27T18:41:20.872Z,1553712080.872 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  94.42, 101.91,  73.96
2019-03-27T18:41:22.077Z,1553712082.077 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:25.313Z,1553712085.313 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:28.137Z,1553712088.137 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:31.369Z,1553712091.369 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:34.197Z,1553712094.197 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:37.433Z,1553712097.433 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:39.495Z,1553712099.495 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-03-27T18:41:39.495Z,1553712099.495 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.65 +4.11,        +0.00,   9.28,  0.00
2019-03-27T18:41:40.261Z,1553712100.261 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:43.089Z,1553712103.089 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:41:43.493Z,1553712103.493 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183437.00,A,3648.17641,N,12147.28374,W,0.272,0.00,270319,,,A*78
2019-03-27T18:41:43.496Z,1553712103.496 [NAL9602](INFO): GPS fix at 20190327T183437: (36.802940, -121.788062)
2019-03-27T18:41:43.536Z,1553712103.536 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T18:41:43.536Z,1553712103.536 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-27T18:41:43.944Z,1553712103.944 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-03-27T18:41:53.469Z,1553712113.469 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190327T183721/Courier0004.lzma
2019-03-27T18:41:54.266Z,1553712114.266 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Courier0004.lzma.bak
2019-03-27T18:41:54.266Z,1553712114.266 [DataOverHttps](INFO): SBD MOMSN=10257280
2019-03-27T18:42:09.617Z,1553712129.617 [DataOverHttps](INFO): Sending 643 bytes from file Logs/20190327T183721/Express0005.lzma
2019-03-27T18:42:10.422Z,1553712130.422 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Express0005.lzma.bak
2019-03-27T18:42:10.422Z,1553712130.422 [DataOverHttps](INFO): SBD MOMSN=10257286
2019-03-27T18:42:11.870Z,1553712131.870 [Default:CheckIn:Read_Iridium] Stopped
2019-03-27T18:42:11.870Z,1553712131.870 [Default:CheckIn:C.Wait] Running Loop=1
2019-03-27T18:42:11.871Z,1553712131.871 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:42:16.206Z,1553712136.206 [NAL9602](INFO): Not Powering down - fast GPS
2019-03-27T18:43:39.871Z,1553712219.871 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-03-27T18:43:39.871Z,1553712219.871 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.58,  94.92, 101.91,  76.62
2019-03-27T18:43:39.882Z,1553712219.882 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T18:43:39.882Z,1553712219.882 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T18:43:39.894Z,1553712219.894 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T18:43:40.302Z,1553712220.302 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T18:43:40.303Z,1553712220.303 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T18:44:57.029Z,1553712297.029 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-03-27T18:44:57.032Z,1553712297.032 [BPC1](INFO): Received data from all battery sticks.
2019-03-27T18:46:00.866Z,1553712360.866 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-03-27T18:46:00.866Z,1553712360.866 [RDI_Pathfinder](ERROR): Failed to parse:
:TS1472686,35.0, -0.1,   0.0,1448.9,  0
2019-03-27T18:46:40.865Z,1553712400.865 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T18:46:40.865Z,1553712400.865 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T18:46:40.876Z,1553712400.876 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T18:46:41.271Z,1553712401.271 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T18:46:41.271Z,1553712401.271 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T18:47:12.401Z,1553712432.401 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-03-27T18:47:12.401Z,1553712432.401 [Default:CheckIn:C.Wait] Stopped
2019-03-27T18:47:12.401Z,1553712432.401 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:47:12.401Z,1553712432.401 [Default:CheckIn:D] Running Loop=1
2019-03-27T18:47:12.783Z,1553712432.783 [Default:CheckIn:D] Stopped
2019-03-27T18:47:12.784Z,1553712432.784 [Default:CheckIn:E] Running Loop=1
2019-03-27T18:47:13.184Z,1553712433.184 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.679303 min 
2019-03-27T18:47:13.184Z,1553712433.184 [Default:CheckIn:E] Stopped
2019-03-27T18:47:13.184Z,1553712433.184 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn] Stopped
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn](INFO): Running loop #2
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn] Running Loop=2
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T18:47:13.185Z,1553712433.185 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T18:47:14.777Z,1553712434.777 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:47:15.169Z,1553712435.169 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184008.00,A,3648.16697,N,12147.28277,W,0.233,0.00,270319,,,A*7A
2019-03-27T18:47:15.171Z,1553712435.171 [NAL9602](INFO): GPS fix at 20190327T184008: (36.802783, -121.788046)
2019-03-27T18:47:15.229Z,1553712435.229 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T18:47:15.229Z,1553712435.229 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-27T18:47:21.680Z,1553712441.680 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190327T183721/Courier0007.lzma
2019-03-27T18:47:22.489Z,1553712442.489 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Courier0007.lzma.bak
2019-03-27T18:47:22.490Z,1553712442.490 [DataOverHttps](INFO): SBD MOMSN=10257319
2019-03-27T18:47:34.232Z,1553712454.232 [NAL9602](INFO): SBD MO Status=2, MOMSN=2456, MT Status=2, MTMSN=0
2019-03-27T18:47:34.232Z,1553712454.232 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-27T18:47:35.420Z,1553712455.420 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190327T183721/Express0008.lzma
2019-03-27T18:47:36.226Z,1553712456.226 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Express0008.lzma.bak
2019-03-27T18:47:36.226Z,1553712456.226 [DataOverHttps](INFO): SBD MOMSN=10257325
2019-03-27T18:47:37.896Z,1553712457.896 [Default:CheckIn:Read_Iridium] Stopped
2019-03-27T18:47:37.896Z,1553712457.896 [Default:CheckIn:C.Wait] Running Loop=1
2019-03-27T18:47:37.896Z,1553712457.896 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:48:13.487Z,1553712493.487 [RDI_Pathfinder](ERROR): only read 1 of 5 data items
2019-03-27T18:48:13.487Z,1553712493.487 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,   -1  :BS,   -12,    +7,    -8,A
2019-03-27T18:48:23.136Z,1553712503.136 [NAL9602](INFO): SBD MO Status=2, MOMSN=2456, MT Status=2, MTMSN=0
2019-03-27T18:48:23.136Z,1553712503.136 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-27T18:48:30.699Z,1553712510.699 [CommandLine](IMPORTANT): got command show variable range
2019-03-27T18:48:30.700Z,1553712510.700 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-03-27T18:48:30.906Z,1553712510.906 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-03-27T18:48:30.907Z,1553712510.907 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-03-27T18:48:30.908Z,1553712510.908 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-03-27T18:48:30.915Z,1553712510.915 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-03-27T18:48:30.915Z,1553712510.915 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-03-27T18:48:30.916Z,1553712510.916 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-03-27T18:48:30.916Z,1553712510.916 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-03-27T18:48:37.655Z,1553712517.655 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-03-27T18:48:42.759Z,1553712522.759 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:48:42.759Z,1553712522.759 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:48:42.786Z,1553712522.786 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-03-27T18:48:42.789Z,1553712522.789 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-03-27T18:48:42.793Z,1553712522.793 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-03-27T18:48:42.797Z,1553712522.797 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-03-27T18:48:42.801Z,1553712522.801 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = 1.000000 bool
2019-03-27T18:48:42.802Z,1553712522.802 [DUSBL:A.Pitch](DEBUG): Construct.
2019-03-27T18:48:42.808Z,1553712522.808 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-03-27T18:48:42.850Z,1553712522.850 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-03-27T18:48:42.862Z,1553712522.862 [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>90</Value></DefineArg>

    <DefineArg Name="NumberOfRequests"><Description>
        Number of pings to requst.
    </Description><Units:count/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</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><Science: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>

    <ReadData>
        <While>
            <Arg Name="EnabledDUSBL"/>
        </While>
        <Sensor:DUSBL_Hydroid.acoustic_contact_range/>
        <Sensor:DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame/>
    </ReadData>
    
      <Aggregate Id="RequestRepeater">

        <Sequence Repeat="NumberOfRequests"/>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.transponderCode/><Arg Name="TransponderCode"/></Assign>
        <Assign><Parallel/><Sensor:DUSBL_Hydroid.numberOfPingsRequested/><Arg Name="NumberOfPings"/></Assign>
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:second/><Value>10</Value></Setting>
          </Guidance:Wait>
      </Aggregate>    
</Mission>


2019-03-27T18:48:42.864Z,1553712522.864 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-03-27T18:48:42.960Z,1553712522.960 [Default] Stopped
2019-03-27T18:48:42.965Z,1553712522.965 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-27T18:48:42.965Z,1553712522.965 [Default:B.GoToSurface] Stopped
2019-03-27T18:48:42.965Z,1553712522.965 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:48:42.965Z,1553712522.965 [Default:CheckIn] Stopped
2019-03-27T18:48:42.965Z,1553712522.965 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T18:48:42.965Z,1553712522.965 [Default:CheckIn:C.Wait] Stopped
2019-03-27T18:48:42.965Z,1553712522.965 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:48:42.965Z,1553712522.965 [MissionManager](IMPORTANT): Started mission DUSBL
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL] Running Loop=1
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:48:42.966Z,1553712522.966 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:C] Running Loop=1
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater] Running Loop=1
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:48:42.967Z,1553712522.967 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:48:42.968Z,1553712522.968 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:48:42.968Z,1553712522.968 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:48:42.968Z,1553712522.968 [DUSBL:C] Running Loop=1
2019-03-27T18:48:42.969Z,1553712522.969 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_range
2019-03-27T18:48:42.970Z,1553712522.970 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame
2019-03-27T18:48:42.970Z,1553712522.970 [DUSBL:B.SetSpeed] Running Loop=1
2019-03-27T18:48:42.970Z,1553712522.970 [DUSBL:A.Pitch] Running Loop=1
2019-03-27T18:48:44.558Z,1553712524.558 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:48:44.564Z,1553712524.564 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:48:48.598Z,1553712528.598 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:48:48.602Z,1553712528.602 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:48:52.638Z,1553712532.638 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:48:52.642Z,1553712532.642 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:48:53.076Z,1553712533.076 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:48:53.076Z,1553712533.076 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:48:53.076Z,1553712533.076 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:48:53.077Z,1553712533.077 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater] Running Loop=2
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:48:53.078Z,1553712533.078 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:48:56.674Z,1553712536.674 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:48:56.678Z,1553712536.678 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:00.717Z,1553712540.717 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:00.721Z,1553712540.721 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:03.590Z,1553712543.590 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:03.591Z,1553712543.591 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:03.591Z,1553712543.591 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:03.591Z,1553712543.591 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:03.591Z,1553712543.591 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:03.591Z,1553712543.591 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater] Running Loop=3
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:03.592Z,1553712543.592 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:04.754Z,1553712544.754 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:04.759Z,1553712544.759 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:08.798Z,1553712548.798 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:08.802Z,1553712548.802 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:12.838Z,1553712552.838 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:12.842Z,1553712552.842 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:14.088Z,1553712554.088 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:14.088Z,1553712554.088 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:14.088Z,1553712554.088 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-03-27T18:49:14.089Z,1553712554.089 [DUSBL:RequestRepeater] Running Loop=4
2019-03-27T18:49:14.090Z,1553712554.090 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:14.090Z,1553712554.090 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:14.090Z,1553712554.090 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:14.090Z,1553712554.090 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:14.090Z,1553712554.090 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:16.878Z,1553712556.878 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:16.882Z,1553712556.882 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:20.918Z,1553712560.918 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:20.923Z,1553712560.923 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:24.612Z,1553712564.612 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:24.612Z,1553712564.612 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:24.612Z,1553712564.612 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:24.613Z,1553712564.613 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:24.613Z,1553712564.613 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:24.613Z,1553712564.613 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:24.613Z,1553712564.613 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:24.613Z,1553712564.613 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater] Running Loop=5
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:24.614Z,1553712564.614 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:24.958Z,1553712564.958 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:24.962Z,1553712564.962 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:28.998Z,1553712568.998 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:29.003Z,1553712569.003 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:29.402Z,1553712569.402 [Micromodem](ERROR): Response from modem unexpected: $CADQF,205,1*57

2019-03-27T18:49:29.404Z,1553712569.404 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-03-27T18:49:29.815Z,1553712569.815 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190327184927.899463,06,198,10,0093,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,205,-0.05,-999,9760,4000*70

2019-03-27T18:49:33.038Z,1553712573.038 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:33.043Z,1553712573.043 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:35.088Z,1553712575.088 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:35.088Z,1553712575.088 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:35.088Z,1553712575.088 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:35.088Z,1553712575.088 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-03-27T18:49:35.089Z,1553712575.089 [DUSBL:RequestRepeater] Running Loop=6
2019-03-27T18:49:35.090Z,1553712575.090 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:35.090Z,1553712575.090 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:35.090Z,1553712575.090 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:35.090Z,1553712575.090 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:35.090Z,1553712575.090 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:36.671Z,1553712576.671 [NAL9602](INFO): SBD MO Status=2, MOMSN=2456, MT Status=2, MTMSN=0
2019-03-27T18:49:36.672Z,1553712576.672 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-03-27T18:49:37.073Z,1553712577.073 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:37.074Z,1553712577.074 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:41.118Z,1553712581.118 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:41.123Z,1553712581.123 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:45.158Z,1553712585.158 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:45.162Z,1553712585.162 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:45.278Z,1553712585.278 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-03-27T18:49:45.384Z,1553712585.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-03-27T18:49:45.384Z,1553712585.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-03-27T18:49:45.384Z,1553712585.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-03-27T18:49:45.397Z,1553712585.397 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-03-27T18:49:45.397Z,1553712585.397 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-03-27T18:49:45.398Z,1553712585.398 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-03-27T18:49:45.398Z,1553712585.398 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-03-27T18:49:45.399Z,1553712585.399 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-03-27T18:49:45.399Z,1553712585.399 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-03-27T18:49:45.399Z,1553712585.399 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-03-27T18:49:45.400Z,1553712585.400 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-03-27T18:49:45.400Z,1553712585.400 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-03-27T18:49:45.432Z,1553712585.432 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-03-27T18:49:45.432Z,1553712585.432 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-03-27T18:49:45.437Z,1553712585.437 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-03-27T18:49:45.447Z,1553712585.447 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-03-27T18:49:45.448Z,1553712585.448 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-03-27T18:49:45.454Z,1553712585.454 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-03-27T18:49:45.455Z,1553712585.455 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-03-27T18:49:45.456Z,1553712585.456 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-03-27T18:49:45.462Z,1553712585.462 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-03-27T18:49:45.463Z,1553712585.463 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-03-27T18:49:45.464Z,1553712585.464 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-03-27T18:49:45.470Z,1553712585.470 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-03-27T18:49:45.471Z,1553712585.471 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-03-27T18:49:45.472Z,1553712585.472 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-03-27T18:49:45.596Z,1553712585.596 [CommandLine](IMPORTANT): DUSBL.MissionTimeout (minute)
2019-03-27T18:49:45.596Z,1553712585.596 [CommandLine](IMPORTANT): DUSBL.NumberOfRequests (count)
2019-03-27T18:49:45.610Z,1553712585.610 [CommandLine](IMPORTANT): DUSBL.TransponderCode (count)
2019-03-27T18:49:45.610Z,1553712585.610 [CommandLine](IMPORTANT): DUSBL.NumberOfPings (count)
2019-03-27T18:49:45.610Z,1553712585.610 [CommandLine](IMPORTANT): DUSBL.EnabledDUSBL (bool)
2019-03-27T18:49:45.611Z,1553712585.611 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_voltage (volt)
2019-03-27T18:49:45.611Z,1553712585.611 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgVoltage (volt)
2019-03-27T18:49:45.611Z,1553712585.611 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_current (milliampere)
2019-03-27T18:49:45.612Z,1553712585.612 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgCurrent (milliampere)
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:45.630Z,1553712585.630 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater] Running Loop=7
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:45.631Z,1553712585.631 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:47.179Z,1553712587.179 [NAL9602](INFO): SBD MO Status=0, MOMSN=2456, MT Status=0, MTMSN=0
2019-03-27T18:49:47.179Z,1553712587.179 [NAL9602](INFO): No messages in MT queue
2019-03-27T18:49:49.202Z,1553712589.202 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:49.206Z,1553712589.206 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:53.234Z,1553712593.234 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:53.238Z,1553712593.238 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:49:56.093Z,1553712596.093 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:49:56.093Z,1553712596.093 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:49:56.093Z,1553712596.093 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:49:56.094Z,1553712596.094 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:49:56.094Z,1553712596.094 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:49:56.094Z,1553712596.094 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:49:56.094Z,1553712596.094 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:49:56.094Z,1553712596.094 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater] Running Loop=8
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:49:56.095Z,1553712596.095 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:49:56.179Z,1553712596.179 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-03-27T18:49:57.278Z,1553712597.278 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:49:57.283Z,1553712597.283 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:01.330Z,1553712601.330 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:01.334Z,1553712601.334 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:05.358Z,1553712605.358 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:05.362Z,1553712605.362 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:06.611Z,1553712606.611 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:50:06.611Z,1553712606.611 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:50:06.611Z,1553712606.611 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-03-27T18:50:06.612Z,1553712606.612 [DUSBL:RequestRepeater] Running Loop=9
2019-03-27T18:50:06.613Z,1553712606.613 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:50:06.613Z,1553712606.613 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:50:06.613Z,1553712606.613 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:50:06.613Z,1553712606.613 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:50:06.613Z,1553712606.613 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:50:09.402Z,1553712609.402 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:09.407Z,1553712609.407 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:10.606Z,1553712610.606 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CATRC,RECV,IDEM, 523,Missed start of FSK packet

2019-03-27T18:50:13.433Z,1553712613.433 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:13.434Z,1553712613.434 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:17.104Z,1553712617.104 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:50:17.104Z,1553712617.104 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:50:17.104Z,1553712617.104 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-03-27T18:50:17.105Z,1553712617.105 [DUSBL:RequestRepeater] Running Loop=10
2019-03-27T18:50:17.106Z,1553712617.106 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-03-27T18:50:17.106Z,1553712617.106 [DUSBL:RequestRepeater:A] Running Loop=1
2019-03-27T18:50:17.106Z,1553712617.106 [DUSBL:RequestRepeater:B] Running Loop=1
2019-03-27T18:50:17.106Z,1553712617.106 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-03-27T18:50:17.106Z,1553712617.106 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:50:17.498Z,1553712617.498 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:17.502Z,1553712617.502 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:17.881Z,1553712617.881 [NAL9602](INFO): Not Powering down - fast GPS
2019-03-27T18:50:21.522Z,1553712621.522 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:21.527Z,1553712621.527 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:25.558Z,1553712625.558 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-03-27T18:50:25.562Z,1553712625.562 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-03-27T18:50:27.618Z,1553712627.618 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-03-27T18:50:27.618Z,1553712627.618 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-03-27T18:50:27.618Z,1553712627.618 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:50:27.619Z,1553712627.619 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-03-27T18:50:27.619Z,1553712627.619 [DUSBL:RequestRepeater] Stopped
2019-03-27T18:50:27.619Z,1553712627.619 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-03-27T18:50:27.619Z,1553712627.619 [DUSBL:RequestRepeater:A] Stopped
2019-03-27T18:50:27.619Z,1553712627.619 [DUSBL:RequestRepeater:B] Stopped
2019-03-27T18:50:27.620Z,1553712627.620 [DUSBL](INFO): Completed DUSBL
2019-03-27T18:50:27.620Z,1553712627.620 [MissionManager](INFO): DUSBL is completed.
2019-03-27T18:50:27.620Z,1553712627.620 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-03-27T18:50:27.620Z,1553712627.620 [DUSBL] Stopped
2019-03-27T18:50:27.621Z,1553712627.621 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-03-27T18:50:27.621Z,1553712627.621 [DUSBL:A.Pitch] Stopped
2019-03-27T18:50:27.621Z,1553712627.621 [DUSBL:B.SetSpeed] Stopped
2019-03-27T18:50:27.621Z,1553712627.621 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-03-27T18:50:27.621Z,1553712627.621 [DUSBL:C] Stopped
2019-03-27T18:50:28.008Z,1553712628.008 [MissionManager](IMPORTANT): Started mission Default
2019-03-27T18:50:28.008Z,1553712628.008 [Default] Running Loop=1
2019-03-27T18:50:28.008Z,1553712628.008 [Default](DEBUG): Aggregate::initialize Default
2019-03-27T18:50:28.008Z,1553712628.008 [Default:B.GoToSurface] Running Loop=1
2019-03-27T18:50:28.008Z,1553712628.008 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-03-27T18:50:28.013Z,1553712628.013 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-03-27T18:50:28.013Z,1553712628.013 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-03-27T18:50:28.013Z,1553712628.013 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-03-27T18:50:28.014Z,1553712628.014 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-03-27T18:50:28.014Z,1553712628.014 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-03-27T18:50:28.014Z,1553712628.014 [Default:A.Wait] Running Loop=1
2019-03-27T18:50:28.014Z,1553712628.014 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:50:36.493Z,1553712636.493 [RDI_Pathfinder](ERROR): only read 2 of 5 data items
2019-03-27T18:50:36.494Z,1553712636.494 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,   -11,   +55   -39,A
2019-03-27T18:50:36.504Z,1553712636.504 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1
2019-03-27T18:50:36.504Z,1553712636.504 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault
2019-03-27T18:50:36.515Z,1553712636.515 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor
2019-03-27T18:50:36.890Z,1553712636.890 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor
2019-03-27T18:50:36.891Z,1553712636.891 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1
2019-03-27T18:50:41.339Z,1553712641.339 [Default:A.Wait](INFO): Done Waiting.
2019-03-27T18:50:41.339Z,1553712641.339 [Default:A.Wait] Stopped
2019-03-27T18:50:41.339Z,1553712641.339 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:50:41.756Z,1553712641.756 [Default:CheckIn] Running Loop=1
2019-03-27T18:50:41.756Z,1553712641.756 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-03-27T18:50:41.756Z,1553712641.756 [Default:CheckIn:Read_GPS] Running Loop=1
2019-03-27T18:50:43.333Z,1553712643.333 [NAL9602](DEBUG): Fix Requested
2019-03-27T18:50:43.725Z,1553712643.725 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184337.00,A,3648.16563,N,12147.28253,W,0.058,217.09,270319,,,A*79
2019-03-27T18:50:43.727Z,1553712643.727 [NAL9602](INFO): GPS fix at 20190327T184337: (36.802760, -121.788042)
2019-03-27T18:50:43.764Z,1553712643.764 [Default:CheckIn:Read_GPS] Stopped
2019-03-27T18:50:43.764Z,1553712643.764 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-03-27T18:50:50.496Z,1553712650.496 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190327T183721/Courier0010.lzma
2019-03-27T18:50:51.302Z,1553712651.302 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Courier0010.lzma.bak
2019-03-27T18:50:51.303Z,1553712651.303 [DataOverHttps](INFO): SBD MOMSN=10257369
2019-03-27T18:50:55.864Z,1553712655.864 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-03-27T18:50:55.865Z,1553712655.865 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19032711522186,35.0, -0.1,   .9,  0
2019-03-27T18:51:00.288Z,1553712660.288 [NAL9602](INFO): SBD MO Status=0, MOMSN=2457, MT Status=0, MTMSN=0
2019-03-27T18:51:00.288Z,1553712660.288 [NAL9602](INFO): No messages in MT queue
2019-03-27T18:51:04.378Z,1553712664.378 [DataOverHttps](INFO): Sending 842 bytes from file Logs/20190327T183721/Express0011.lzma
2019-03-27T18:51:05.182Z,1553712665.182 [DataOverHttps](INFO): Moved sent file to Logs/20190327T183721/Express0011.lzma.bak
2019-03-27T18:51:05.182Z,1553712665.182 [DataOverHttps](INFO): SBD MOMSN=10257385
2019-03-27T18:51:06.800Z,1553712666.800 [Default:CheckIn:Read_Iridium] Stopped
2019-03-27T18:51:06.800Z,1553712666.800 [Default:CheckIn:C.Wait] Running Loop=1
2019-03-27T18:51:06.800Z,1553712666.800 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-03-27T18:51:24.123Z,1553712684.123 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,185114,AUV,2.46*48

2019-03-27T18:51:30.991Z,1553712690.991 [NAL9602](INFO): Not Powering down - fast GPS
2019-03-27T18:53:30.162Z,1553712810.162 [CommandLine](IMPORTANT): got command restart application
2019-03-27T18:53:31.169Z,1553712811.169 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-03-27T18:53:31.169Z,1553712811.169 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:31.170Z,1553712811.170 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.257Z,1553712811.257 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-03-27T18:53:31.257Z,1553712811.257 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.258Z,1553712811.258 [CommandLine](INFO): Join timeout helper Thread ID is 8349
2019-03-27T18:53:31.258Z,1553712811.258 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-03-27T18:53:31.258Z,1553712811.258 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.259Z,1553712811.259 [NavChartDb](INFO): Join timeout helper Thread ID is 8350
2019-03-27T18:53:31.617Z,1553712811.617 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:31.617Z,1553712811.617 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.625Z,1553712811.625 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-03-27T18:53:31.625Z,1553712811.625 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.625Z,1553712811.625 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 8351
2019-03-27T18:53:31.945Z,1553712811.945 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:31.945Z,1553712811.945 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-03-27T18:53:31.946Z,1553712811.946 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.957Z,1553712811.957 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-03-27T18:53:31.957Z,1553712811.957 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.957Z,1553712811.957 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 8352
2019-03-27T18:53:31.961Z,1553712811.961 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:31.961Z,1553712811.961 [CTD_NeilBrown](INFO): Powering down
2019-03-27T18:53:31.973Z,1553712811.973 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.977Z,1553712811.977 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-03-27T18:53:31.977Z,1553712811.977 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:31.977Z,1553712811.977 [Radio_Surface](INFO): Join timeout helper Thread ID is 8353
2019-03-27T18:53:32.345Z,1553712812.345 [Radio_Surface](INFO): Powering down
2019-03-27T18:53:32.346Z,1553712812.346 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:32.346Z,1553712812.346 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.366Z,1553712812.366 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-03-27T18:53:32.366Z,1553712812.366 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.366Z,1553712812.366 [DataOverHttps](INFO): Join timeout helper Thread ID is 8354
2019-03-27T18:53:32.413Z,1553712812.413 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:32.413Z,1553712812.413 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.430Z,1553712812.430 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-03-27T18:53:32.430Z,1553712812.430 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.430Z,1553712812.430 [logger](INFO): Join timeout helper Thread ID is 8355
2019-03-27T18:53:32.439Z,1553712812.439 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:32.440Z,1553712812.440 [logger ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.459Z,1553712812.459 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-03-27T18:53:32.459Z,1553712812.459 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.460Z,1553712812.460 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-03-27T18:53:32.460Z,1553712812.460 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.461Z,1553712812.461 [controlThread](INFO): Join timeout helper Thread ID is 8356
2019-03-27T18:53:32.577Z,1553712812.577 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-03-27T18:53:32.577Z,1553712812.577 [controlThread](DEBUG): Uninitializing ControlThread
2019-03-27T18:53:32.578Z,1553712812.578 [AHRS_M2](INFO): Powering down
2019-03-27T18:53:32.650Z,1553712812.650 [DUSBL_Hydroid](INFO): Powering down
2019-03-27T18:53:32.721Z,1553712812.721 [Micromodem](INFO): Powering down
2019-03-27T18:53:32.817Z,1553712812.817 [NAL9602](INFO): Powering down
2019-03-27T18:53:32.889Z,1553712812.889 [RDI_Pathfinder](INFO): Powering down
2019-03-27T18:53:32.890Z,1553712812.890 [RDI_PathfinderUp](INFO): Powering down
2019-03-27T18:53:32.891Z,1553712812.891 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-03-27T18:53:32.892Z,1553712812.892 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-03-27T18:53:32.893Z,1553712812.893 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-03-27T18:53:32.893Z,1553712812.893 [MissionManager](INFO): Uninitializing Mission Default
2019-03-27T18:53:32.893Z,1553712812.893 [Default] Stopped
2019-03-27T18:53:32.893Z,1553712812.893 [Default](DEBUG): Aggregate::uninitialize Default
2019-03-27T18:53:32.894Z,1553712812.894 [Default:B.GoToSurface] Stopped
2019-03-27T18:53:32.894Z,1553712812.894 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-03-27T18:53:32.894Z,1553712812.894 [Default:CheckIn] Stopped
2019-03-27T18:53:32.894Z,1553712812.894 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-03-27T18:53:32.894Z,1553712812.894 [Default:CheckIn:C.Wait] Stopped
2019-03-27T18:53:32.894Z,1553712812.894 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-03-27T18:53:32.896Z,1553712812.896 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-03-27T18:53:32.896Z,1553712812.896 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-03-27T18:53:32.897Z,1553712812.897 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-03-27T18:53:32.897Z,1553712812.897 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-03-27T18:53:32.898Z,1553712812.898 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-03-27T18:53:32.898Z,1553712812.898 [BuoyancyServo](INFO): Powering down
2019-03-27T18:53:32.909Z,1553712812.909 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-03-27T18:53:32.909Z,1553712812.909 [ElevatorServo](INFO): Powering down
2019-03-27T18:53:32.910Z,1553712812.910 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-03-27T18:53:32.910Z,1553712812.910 [MassServo](INFO): Powering down
2019-03-27T18:53:32.911Z,1553712812.911 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-03-27T18:53:32.911Z,1553712812.911 [RudderServo](INFO): Powering down
2019-03-27T18:53:32.912Z,1553712812.912 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-03-27T18:53:32.912Z,1553712812.912 [ThrusterServo](INFO): Powering down
2019-03-27T18:53:32.913Z,1553712812.913 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-03-27T18:53:32.913Z,1553712812.913 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-03-27T18:53:32.913Z,1553712812.913 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-03-27T18:53:32.913Z,1553712812.913 [CBIT](DEBUG): Powering off loads.
2019-03-27T18:53:32.925Z,1553712812.925 [CBIT](DEBUG): Disabling WDT.
2019-03-27T18:53:32.937Z,1553712812.937 [CBIT](DEBUG): Opening all GF detection circuits.
2019-03-27T18:53:32.938Z,1553712812.938 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.983Z,1553712812.983 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:32.993Z,1553712812.993 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:33.040Z,1553712813.040 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:33.043Z,1553712813.043 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:33.098Z,1553712813.098 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-03-27T18:53:33.173Z,1553712813.173 [logger ThreadHandler](INFO): Thread cancelled.