2022-11-09T18:30:56.730Z,1668018656.730 [Supervisor](DEBUG): Initializing supervisor.
2022-11-09T18:30:56.736Z,1668018656.736 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-11-09T18:30:56.736Z,1668018656.736 [SyncHandler](INFO): Protected caller Thread ID is 5554
2022-11-09T18:30:56.737Z,1668018656.737 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-11-09T18:30:56.738Z,1668018656.738 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-11-09T18:30:56.738Z,1668018656.738 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5555
2022-11-09T18:30:56.743Z,1668018656.743 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-11-09T18:30:56.760Z,1668018656.760 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-11-09T18:30:56.761Z,1668018656.761 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-11-09T18:30:56.761Z,1668018656.761 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 5556
2022-11-09T18:30:56.766Z,1668018656.766 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-11-09T18:30:56.767Z,1668018656.767 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-11-09T18:30:56.767Z,1668018656.767 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5557
2022-11-09T18:30:56.769Z,1668018656.769 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-11-09T18:30:56.770Z,1668018656.770 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-11-09T18:30:56.771Z,1668018656.770 [logger ThreadHandler](INFO): Protected caller Thread ID is 5558
2022-11-09T18:30:56.774Z,1668018656.774 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-11-09T18:30:56.775Z,1668018656.775 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-11-09T18:30:56.776Z,1668018656.776 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-11-09T18:30:57.190Z,1668018657.190 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-11-09T18:30:57.191Z,1668018657.191 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-11-09T18:30:57.398Z,1668018657.398 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-11-09T18:30:57.399Z,1668018657.399 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-11-09T18:30:57.574Z,1668018657.574 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-11-09T18:30:57.575Z,1668018657.575 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-11-09T18:30:57.679Z,1668018657.679 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-11-09T18:30:57.679Z,1668018657.679 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-11-09T18:30:58.075Z,1668018658.075 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-11-09T18:30:58.075Z,1668018658.075 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-11-09T18:30:58.481Z,1668018658.481 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-11-09T18:30:58.481Z,1668018658.481 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-11-09T18:30:58.576Z,1668018658.576 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-11-09T18:30:58.576Z,1668018658.576 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-11-09T18:30:58.798Z,1668018658.798 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-11-09T18:30:58.798Z,1668018658.798 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-11-09T18:30:59.290Z,1668018659.290 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-11-09T18:30:59.291Z,1668018659.291 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-11-09T18:30:59.633Z,1668018659.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-11-09T18:30:59.634Z,1668018659.634 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-11-09T18:30:59.714Z,1668018659.714 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-11-09T18:30:59.917Z,1668018659.917 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-11-09T18:30:59.918Z,1668018659.918 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-11-09T18:31:00.051Z,1668018660.051 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-11-09T18:31:00.052Z,1668018660.052 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-11-09T18:31:00.759Z,1668018660.759 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-11-09T18:31:00.760Z,1668018660.760 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-11-09T18:31:00.838Z,1668018660.838 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-11-09T18:31:01.118Z,1668018661.118 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-11-09T18:31:01.120Z,1668018661.120 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/
2022-11-09T18:31:01.121Z,1668018661.121 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/vehicle.cfg
2022-11-09T18:31:01.293Z,1668018661.293 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/logger.cfg
2022-11-09T18:31:01.384Z,1668018661.384 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Servo.cfg
2022-11-09T18:31:01.493Z,1668018661.493 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Control.cfg
2022-11-09T18:31:01.591Z,1668018661.591 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/secure.cfg
2022-11-09T18:31:01.674Z,1668018661.674 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Simulator.cfg
2022-11-09T18:31:01.757Z,1668018661.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Science.cfg
2022-11-09T18:31:01.869Z,1668018661.869 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/BIT.cfg
2022-11-09T18:31:01.965Z,1668018661.965 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Sensor.cfg
2022-11-09T18:31:02.116Z,1668018662.116 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Battery.cfg
2022-11-09T18:31:02.376Z,1668018662.376 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-11-09T18:31:02.376Z,1668018662.376 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Navigation.cfg
2022-11-09T18:31:02.469Z,1668018662.469 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/root/
2022-11-09T18:31:02.470Z,1668018662.470 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2022-11-09T18:31:02.482Z,1668018662.482 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-11-09T18:31:02.790Z,1668018662.790 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-11-09T18:31:02.790Z,1668018662.790 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-11-09T18:31:02.902Z,1668018662.902 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-11-09T18:31:02.903Z,1668018662.903 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-11-09T18:31:02.942Z,1668018662.942 [DeadReckonUsingSpeedCalculator] Loaded
2022-11-09T18:31:02.942Z,1668018662.942 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2022-11-09T18:31:02.955Z,1668018662.955 [NavChart] Loaded
2022-11-09T18:31:02.955Z,1668018662.955 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-11-09T18:31:02.961Z,1668018662.961 [UniversalFixResidualReporter] Loaded
2022-11-09T18:31:02.961Z,1668018662.961 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-11-09T18:31:02.961Z,1668018662.961 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-11-09T18:31:02.962Z,1668018662.962 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-11-09T18:31:02.972Z,1668018662.972 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-11-09T18:31:02.973Z,1668018662.973 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-11-09T18:31:03.229Z,1668018663.229 [PAR_Licor] Loaded
2022-11-09T18:31:03.229Z,1668018663.229 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-11-09T18:31:03.351Z,1668018663.351 [WetLabsBB2FL] Loaded
2022-11-09T18:31:03.351Z,1668018663.351 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-11-09T18:31:03.353Z,1668018663.353 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4065A4E0
2022-11-09T18:31:03.353Z,1668018663.353 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5640
2022-11-09T18:31:03.364Z,1668018663.364 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-11-09T18:31:03.365Z,1668018663.365 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-11-09T18:31:03.458Z,1668018663.458 [VerticalControl](DEBUG): Construct VerticalControl.
2022-11-09T18:31:03.583Z,1668018663.583 [VerticalControl] Loaded
2022-11-09T18:31:03.584Z,1668018663.584 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-11-09T18:31:03.587Z,1668018663.587 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-11-09T18:31:03.668Z,1668018663.668 [HorizontalControl] Loaded
2022-11-09T18:31:03.668Z,1668018663.668 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-11-09T18:31:03.670Z,1668018663.670 [SpeedControl](DEBUG): Construct SpeedControl.
2022-11-09T18:31:03.673Z,1668018663.673 [SpeedControl] Loaded
2022-11-09T18:31:03.674Z,1668018663.674 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-11-09T18:31:03.676Z,1668018663.676 [LoopControl](DEBUG): Construct LoopControl.
2022-11-09T18:31:03.677Z,1668018663.677 [LoopControl] Loaded
2022-11-09T18:31:03.677Z,1668018663.677 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-11-09T18:31:03.678Z,1668018663.678 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-11-09T18:31:03.678Z,1668018663.678 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-11-09T18:31:03.779Z,1668018663.779 [DepthRateCalculator] Loaded
2022-11-09T18:31:03.779Z,1668018663.779 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-11-09T18:31:03.804Z,1668018663.804 [PitchRateCalculator] Loaded
2022-11-09T18:31:03.804Z,1668018663.804 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-11-09T18:31:03.846Z,1668018663.846 [SpeedCalculator] Loaded
2022-11-09T18:31:03.846Z,1668018663.846 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-11-09T18:31:03.870Z,1668018663.870 [YawRateCalculator] Loaded
2022-11-09T18:31:03.870Z,1668018663.870 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-11-09T18:31:03.921Z,1668018663.921 [ElevatorOffsetCalculator] Loaded
2022-11-09T18:31:03.921Z,1668018663.921 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-11-09T18:31:03.921Z,1668018663.921 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-11-09T18:31:03.922Z,1668018663.922 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-11-09T18:31:04.072Z,1668018664.072 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-11-09T18:31:04.072Z,1668018664.072 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-11-09T18:31:04.131Z,1668018664.131 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-11-09T18:31:04.132Z,1668018664.132 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-11-09T18:31:04.256Z,1668018664.256 [BuoyancyServo] Loaded
2022-11-09T18:31:04.257Z,1668018664.257 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-11-09T18:31:04.277Z,1668018664.277 [ElevatorServo] Loaded
2022-11-09T18:31:04.277Z,1668018664.277 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-11-09T18:31:04.296Z,1668018664.296 [MassServo] Loaded
2022-11-09T18:31:04.296Z,1668018664.296 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-11-09T18:31:04.315Z,1668018664.315 [RudderServo] Loaded
2022-11-09T18:31:04.315Z,1668018664.315 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-11-09T18:31:04.330Z,1668018664.330 [ThrusterHE] Loaded
2022-11-09T18:31:04.330Z,1668018664.330 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-11-09T18:31:04.331Z,1668018664.331 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-11-09T18:31:04.331Z,1668018664.331 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-11-09T18:31:04.485Z,1668018664.485 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-11-09T18:31:04.485Z,1668018664.485 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-11-09T18:31:04.905Z,1668018664.905 [AHRS_M2] Loaded
2022-11-09T18:31:04.905Z,1668018664.905 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-11-09T18:31:04.940Z,1668018664.940 [BackseatComponent] Loaded
2022-11-09T18:31:04.941Z,1668018664.941 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-11-09T18:31:04.942Z,1668018664.942 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A554E0
2022-11-09T18:31:04.942Z,1668018664.942 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 5641
2022-11-09T18:31:04.945Z,1668018664.945 [LcmUniversalReporter] Loaded
2022-11-09T18:31:04.945Z,1668018664.945 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-11-09T18:31:05.768Z,1668018665.768 [BPC1] Loaded
2022-11-09T18:31:05.769Z,1668018665.769 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2022-11-09T18:31:05.842Z,1668018665.842 [DataOverHttps] Loaded
2022-11-09T18:31:05.842Z,1668018665.842 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-11-09T18:31:05.843Z,1668018665.843 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A854E0
2022-11-09T18:31:05.843Z,1668018665.843 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5642
2022-11-09T18:31:05.864Z,1668018665.864 [Depth_Keller] Loaded
2022-11-09T18:31:05.864Z,1668018665.864 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-11-09T18:31:05.869Z,1668018665.869 [DropWeight] Loaded
2022-11-09T18:31:05.870Z,1668018665.870 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2022-11-09T18:31:05.889Z,1668018665.889 [MultiRay] Loaded
2022-11-09T18:31:05.889Z,1668018665.889 [ComponentRegistry](DEBUG): SyncComponent "MultiRay" handled in the control thread.
2022-11-09T18:31:05.951Z,1668018665.951 [NAL9602] Loaded
2022-11-09T18:31:05.951Z,1668018665.951 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-11-09T18:31:05.982Z,1668018665.982 [Onboard] Loaded
2022-11-09T18:31:05.982Z,1668018665.982 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-11-09T18:31:05.983Z,1668018665.983 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40AB54E0
2022-11-09T18:31:05.984Z,1668018665.984 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 5643
2022-11-09T18:31:05.990Z,1668018665.990 [PowerOnly](INFO): Adding load control power supply at /dev/loadC3
2022-11-09T18:31:06.001Z,1668018666.001 [PowerOnly] Loaded
2022-11-09T18:31:06.001Z,1668018666.001 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2022-11-09T18:31:06.013Z,1668018666.013 [Power24vConverter] Loaded
2022-11-09T18:31:06.014Z,1668018666.014 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-11-09T18:31:06.027Z,1668018666.027 [Radio_Surface] Loaded
2022-11-09T18:31:06.027Z,1668018666.027 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-11-09T18:31:06.028Z,1668018666.028 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40AE54E0
2022-11-09T18:31:06.029Z,1668018666.029 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5644
2022-11-09T18:31:06.122Z,1668018666.122 [DAT] Loaded
2022-11-09T18:31:06.123Z,1668018666.123 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-11-09T18:31:06.124Z,1668018666.124 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40B154E0
2022-11-09T18:31:06.124Z,1668018666.124 [DAT ThreadHandler](INFO): Protected caller Thread ID is 5645
2022-11-09T18:31:06.124Z,1668018666.124 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-11-09T18:31:06.125Z,1668018666.125 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-11-09T18:31:06.268Z,1668018666.268 [SBIT](DEBUG): Construct Startup Built In Test.
2022-11-09T18:31:06.277Z,1668018666.277 [SBIT] Loaded
2022-11-09T18:31:06.277Z,1668018666.277 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-11-09T18:31:06.280Z,1668018666.280 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-11-09T18:31:06.294Z,1668018666.294 [IBIT] Loaded
2022-11-09T18:31:06.294Z,1668018666.294 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-11-09T18:31:06.300Z,1668018666.300 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-11-09T18:31:06.402Z,1668018666.402 [CBIT] Loaded
2022-11-09T18:31:06.403Z,1668018666.403 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-11-09T18:31:06.403Z,1668018666.403 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-11-09T18:31:06.404Z,1668018666.404 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-11-09T18:31:06.431Z,1668018666.431 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-11-09T18:31:06.437Z,1668018666.437 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-11-09T18:31:06.440Z,1668018666.440 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-11-09T18:31:06.451Z,1668018666.451 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-11-09T18:31:06.452Z,1668018666.452 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BA34E0
2022-11-09T18:31:06.453Z,1668018666.453 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5646
2022-11-09T18:31:06.457Z,1668018666.457 [Supervisor](INFO): Main Thread ID is 5393
2022-11-09T18:31:06.457Z,1668018666.457 [Supervisor](DEBUG): Running supervisor.
2022-11-09T18:31:06.458Z,1668018666.458 [CommandExec ThreadHandler](INFO): Handler Thread ID is 5647
2022-11-09T18:31:06.458Z,1668018666.458 [CommandExec](INFO): Initializing the command executive.
2022-11-09T18:31:06.460Z,1668018666.460 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5648
2022-11-09T18:31:06.462Z,1668018666.462 [controlThread ThreadHandler](INFO): Handler Thread ID is 5649
2022-11-09T18:31:06.463Z,1668018666.463 [controlThread](DEBUG): Initializing ControlThread
2022-11-09T18:31:06.464Z,1668018666.464 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-11-09T18:31:06.465Z,1668018666.465 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-11-09T18:31:06.465Z,1668018666.465 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-11-09T18:31:06.469Z,1668018666.469 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-11-09T18:31:06.470Z,1668018666.470 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-11-09T18:31:06.471Z,1668018666.471 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-11-09T18:31:06.471Z,1668018666.471 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-11-09T18:31:06.472Z,1668018666.472 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-11-09T18:31:06.472Z,1668018666.472 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-11-09T18:31:06.472Z,1668018666.472 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-11-09T18:31:06.473Z,1668018666.473 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-11-09T18:31:06.473Z,1668018666.473 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-11-09T18:31:06.479Z,1668018666.479 [SBIT](INFO): Initialize SBIT Component.
2022-11-09T18:31:06.479Z,1668018666.479 [SBIT](IMPORTANT): git: 2022-10-11-49-gb44faf3dc
2022-11-09T18:31:06.479Z,1668018666.479 [SBIT](INFO): git hash: b44faf3dc92774180e7da8d3246e288394a00694
2022-11-09T18:31:06.480Z,1668018666.480 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-11-09T18:31:06.481Z,1668018666.481 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2022-11-09T18:31:06.482Z,1668018666.482 [SBIT](INFO): Beginning SBIT in 109.000000 seconds.
2022-11-09T18:31:06.483Z,1668018666.483 [IBIT](INFO): Initialize IBIT Component.
2022-11-09T18:31:06.484Z,1668018666.484 [CBIT](DEBUG): Initialize CBIT Component.
2022-11-09T18:31:06.485Z,1668018666.485 [logger ThreadHandler](INFO): Handler Thread ID is 5650
2022-11-09T18:31:06.496Z,1668018666.496 [CBIT](DEBUG): Initialized mux pins.
2022-11-09T18:31:06.496Z,1668018666.496 [CBIT](DEBUG): Initializing the watchdog timer.
2022-11-09T18:31:06.505Z,1668018666.505 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5651
2022-11-09T18:31:06.509Z,1668018666.509 [WetLabsBB2FL](INFO): Powering up
2022-11-09T18:31:06.510Z,1668018666.510 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 5653
2022-11-09T18:31:06.517Z,1668018666.517 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5654
2022-11-09T18:31:06.518Z,1668018666.518 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-11-09T18:31:06.520Z,1668018666.520 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-11-09T18:31:06.521Z,1668018666.521 [CBIT](DEBUG): Initializing heartbeat.
2022-11-09T18:31:06.529Z,1668018666.529 [Onboard ThreadHandler](INFO): Handler Thread ID is 5655
2022-11-09T18:31:06.559Z,1668018666.559 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5656
2022-11-09T18:31:06.569Z,1668018666.569 [DAT ThreadHandler](INFO): Handler Thread ID is 5657
2022-11-09T18:31:06.569Z,1668018666.569 [DAT](INFO): Powering up
2022-11-09T18:31:06.570Z,1668018666.570 [DAT](DEBUG): Initializing DAT.
2022-11-09T18:31:06.573Z,1668018666.573 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5659
2022-11-09T18:31:06.576Z,1668018666.576 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2022-11-09T18:31:06.576Z,1668018666.576 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2022-11-09T18:31:06.577Z,1668018666.577 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2022-11-09T18:31:06.592Z,1668018666.592 [CBIT](DEBUG): Deactivating GF circuits.
2022-11-09T18:31:06.592Z,1668018666.592 [CBIT](DEBUG): Deactivating emergency mode.
2022-11-09T18:31:06.628Z,1668018666.628 [CBIT](DEBUG): Backplane powered.
2022-11-09T18:31:06.629Z,1668018666.629 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2022-11-09T18:31:06.642Z,1668018666.642 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-11-09T18:31:06.665Z,1668018666.665 [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>


2022-11-09T18:31:06.666Z,1668018666.666 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-11-09T18:31:06.740Z,1668018666.740 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-11-09T18:31:06.741Z,1668018666.741 [Default:A.Wait](DEBUG): Construct Wait.
2022-11-09T18:31:06.743Z,1668018666.743 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-11-09T18:31:06.795Z,1668018666.795 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-11-09T18:31:06.798Z,1668018666.798 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-11-09T18:31:06.837Z,1668018666.837 [Default:E.Execute](DEBUG): Construct Execute.
2022-11-09T18:31:06.841Z,1668018666.841 [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="P4H">
                <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>


2022-11-09T18:31:06.853Z,1668018666.853 [controlThread](DEBUG): Component order: CycleStarter,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,DropWeight,MultiRay,NAL9602,PowerOnly,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2022-11-09T18:31:06.862Z,1668018666.862 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-11-09T18:31:06.932Z,1668018666.932 [MultiRay](INFO): Powering up MultiRay Lights
2022-11-09T18:31:06.960Z,1668018666.960 [Radio_Surface](INFO): Powering up
2022-11-09T18:31:06.973Z,1668018666.973 [Power24vConverter](INFO): Powering up.
2022-11-09T18:31:07.009Z,1668018667.009 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:07.017Z,1668018667.017 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-11-09T18:31:07.018Z,1668018667.018 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:07.033Z,1668018667.033 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-11-09T18:31:07.034Z,1668018667.034 [MassServo](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:07.041Z,1668018667.041 [MassServo](DEBUG): Initializing MassServo.
2022-11-09T18:31:07.041Z,1668018667.041 [RudderServo](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:07.049Z,1668018667.049 [RudderServo](DEBUG): Initializing RudderServo.
2022-11-09T18:31:07.049Z,1668018667.049 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:07.057Z,1668018667.057 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-11-09T18:31:07.326Z,1668018667.326 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2022-11-09T18:31:07.327Z,1668018667.327 [DropWeight] Hardware Fault, FailCount= 1
2022-11-09T18:31:07.327Z,1668018667.327 [DropWeight](ERROR): Hardware Fault
2022-11-09T18:31:07.353Z,1668018667.353 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:31:07.405Z,1668018667.405 [CommandExec](FAULT): Scheduling is paused
2022-11-09T18:31:07.406Z,1668018667.406 [CBIT](INFO): Critical error at 20221109T183107
2022-11-09T18:31:07.406Z,1668018667.406 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2022-11-09T18:31:07.416Z,1668018667.416 [CBIT](ERROR): Hardware Fault in component: DropWeight
2022-11-09T18:31:07.417Z,1668018667.417 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2022-11-09T18:31:08.024Z,1668018668.024 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2022-11-09T18:31:08.024Z,1668018668.024 [RudderServo](FAULT): Rudder failed to initialize
2022-11-09T18:31:08.024Z,1668018668.024 [RudderServo] Communications Fault, FailCount= 1
2022-11-09T18:31:08.025Z,1668018668.025 [RudderServo](ERROR): Communications Fault
2022-11-09T18:31:08.026Z,1668018668.026 [CBIT](INFO): Critical error at 20221109T183107
2022-11-09T18:31:08.029Z,1668018668.029 [CBIT](ERROR): Communications Fault in component: RudderServo
2022-11-09T18:31:08.469Z,1668018668.469 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-11-09T18:31:08.469Z,1668018668.469 [RudderServo](INFO): Powering down
2022-11-09T18:31:08.913Z,1668018668.913 [RudderServo](DEBUG): Initializing EZServoServo.
2022-11-09T18:31:09.033Z,1668018669.033 [RudderServo](DEBUG): Initializing RudderServo.
2022-11-09T18:31:09.037Z,1668018669.037 [CBIT](INFO): Clearing failed state for component RudderServo
2022-11-09T18:31:09.037Z,1668018669.037 [RudderServo] No Fault, FailCount= 1
2022-11-09T18:31:09.120Z,1668018669.120 [WetLabsBB2FL](INFO): Powering down
2022-11-09T18:31:12.721Z,1668018672.721 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-11-09T18:31:21.695Z,1668018681.695 [DAT](INFO): commRate: 800
2022-11-09T18:31:23.760Z,1668018683.760 [DAT](INFO): entering command mode
2022-11-09T18:31:23.961Z,1668018683.961 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:24.213Z,1668018684.213 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:24.465Z,1668018684.465 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:24.717Z,1668018684.717 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:24.969Z,1668018684.969 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:25.221Z,1668018685.221 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:25.473Z,1668018685.473 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:25.725Z,1668018685.725 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:25.977Z,1668018685.977 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:26.229Z,1668018686.229 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:26.481Z,1668018686.481 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:26.733Z,1668018686.733 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:26.985Z,1668018686.985 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:27.237Z,1668018687.237 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:27.489Z,1668018687.489 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:27.741Z,1668018687.741 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:27.993Z,1668018687.993 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:28.245Z,1668018688.245 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:28.499Z,1668018688.499 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:28.753Z,1668018688.753 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:29.005Z,1668018689.005 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:29.257Z,1668018689.257 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:29.509Z,1668018689.509 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:29.761Z,1668018689.761 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:30.013Z,1668018690.013 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:30.265Z,1668018690.265 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:30.517Z,1668018690.517 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:30.769Z,1668018690.769 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:31.021Z,1668018691.021 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:31.273Z,1668018691.273 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:31.525Z,1668018691.525 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:31.777Z,1668018691.777 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:32.029Z,1668018692.029 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:32.281Z,1668018692.281 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:32.533Z,1668018692.533 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:32.785Z,1668018692.785 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:33.037Z,1668018693.037 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:33.289Z,1668018693.289 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:33.541Z,1668018693.541 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:33.793Z,1668018693.793 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:34.045Z,1668018694.045 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:34.297Z,1668018694.297 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:34.549Z,1668018694.549 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:34.801Z,1668018694.801 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:35.053Z,1668018695.053 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:35.305Z,1668018695.305 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:35.557Z,1668018695.557 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:35.809Z,1668018695.809 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:36.058Z,1668018696.058 [NAL9602](INFO): Powering up NAL9602
2022-11-09T18:31:36.061Z,1668018696.061 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:36.313Z,1668018696.313 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:36.565Z,1668018696.565 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:36.817Z,1668018696.817 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:37.069Z,1668018697.069 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:37.321Z,1668018697.321 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:37.573Z,1668018697.573 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:37.825Z,1668018697.825 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:38.077Z,1668018698.077 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:38.329Z,1668018698.329 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:38.582Z,1668018698.582 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:38.833Z,1668018698.833 [DAT](DEBUG): checking for command mode acknowledgment
2022-11-09T18:31:38.833Z,1668018698.833 [DAT](FAULT): failed to enter command mode
2022-11-09T18:31:39.136Z,1668018699.136 [DAT](INFO): entering command mode
2022-11-09T18:31:39.338Z,1668018699.338 [DAT](INFO): setting verbose to 3
2022-11-09T18:31:39.590Z,1668018699.590 [DAT](INFO): set verbose to 3
2022-11-09T18:31:39.590Z,1668018699.590 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:31:39.842Z,1668018699.842 [DAT](INFO): set DatVerbose to 27440
2022-11-09T18:31:39.842Z,1668018699.842 [DAT](INFO): setting transmit power to 8
2022-11-09T18:31:40.094Z,1668018700.094 [DAT](INFO): set transmit power to 8
2022-11-09T18:31:40.095Z,1668018700.095 [DAT](INFO): setting local address to 10
2022-11-09T18:31:40.346Z,1668018700.346 [DAT](INFO): set local address to 10
2022-11-09T18:31:40.347Z,1668018700.347 [DAT](INFO): Setting time to: 18:31:40 And date to:11/9/2022
2022-11-09T18:31:40.598Z,1668018700.598 [DAT](INFO): Local DAT time set to Wed Nov 9, 2022  18:31:40  

2022-11-09T18:31:46.998Z,1668018706.998 [NAL9602](INFO): NAL9602 initialized
2022-11-09T18:32:56.087Z,1668018776.087 [SBIT](IMPORTANT): Beginning Startup BIT
2022-11-09T18:32:56.091Z,1668018776.091 [CBIT](IMPORTANT): Beginning ground fault scan
2022-11-09T18:33:07.072Z,1668018787.072 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.012712
CHAN A1 (24V): 0.000586
CHAN A2 (12V): -0.005603
CHAN A3 (5V): -0.003002
CHAN B0 (3.3V): -0.001781
CHAN B1 (3.15aV): -0.000893
CHAN B2 (3.15bV): -0.000632
CHAN B3 (GND): -0.000469
OPEN: 0.004986
Full Scale: +/- 1 mA
2022-11-09T18:33:21.519Z,1668018801.519 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2022-11-09T18:33:34.423Z,1668018814.423 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004884
2022-11-09T18:33:50.247Z,1668018830.247 [SBIT](IMPORTANT): SBIT PASSED
2022-11-09T18:33:50.248Z,1668018830.248 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): BackseatComponent.needs24v=1 bool;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): BuoyancyServo.fastPumpCoefficient=6 none;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): CBIT.gf24Offset=149 microampere;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): CBIT.gfScanTimeout=2 hour;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): DAT.surfaceThreshold=-1 meter;

2022-11-09T18:33:50.249Z,1668018830.249 [SBIT](IMPORTANT): Express none _.ayeris_disk_space;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): Express linearApproximation _.ayeris_particle_counts 250.000000 count;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): Express none _.ayeris_particle_size;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): IBIT.batteryCapacityThreshold=5 ampere_hour;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=11 volt;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=210.367112 cubic_centimeter;

2022-11-09T18:33:50.250Z,1668018830.250 [SBIT](IMPORTANT): VerticalControl.massDefault=22.333859 millimeter;

2022-11-09T18:33:50.666Z,1668018830.666 [MissionManager](IMPORTANT): Started mission Startup
2022-11-09T18:33:50.667Z,1668018830.667 [Startup] Running Loop=1
2022-11-09T18:33:50.667Z,1668018830.667 [Startup](DEBUG): Aggregate::initialize Startup
2022-11-09T18:33:50.667Z,1668018830.667 [Startup:A.GoToSurface] Running Loop=1
2022-11-09T18:33:50.667Z,1668018830.667 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-11-09T18:33:50.668Z,1668018830.668 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-11-09T18:33:50.668Z,1668018830.668 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-11-09T18:33:50.668Z,1668018830.668 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-11-09T18:33:50.669Z,1668018830.669 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-11-09T18:33:50.669Z,1668018830.669 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-11-09T18:33:50.671Z,1668018830.671 [Startup:StartupSatComms] Running Loop=1
2022-11-09T18:33:50.671Z,1668018830.671 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2022-11-09T18:33:50.671Z,1668018830.671 [Startup:StartupSatComms:A] Running Loop=1
2022-11-09T18:33:51.060Z,1668018831.060 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2022-11-09T18:34:06.801Z,1668018846.801 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2022-11-09T18:34:06.801Z,1668018846.801 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-11-09T18:34:06.802Z,1668018846.802 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2022-11-09T18:34:06.802Z,1668018846.802 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-11-09T18:34:06.821Z,1668018846.821 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-11-09T18:34:06.821Z,1668018846.821 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-11-09T18:34:07.218Z,1668018847.218 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-11-09T18:34:07.218Z,1668018847.218 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2022-11-09T18:34:07.219Z,1668018847.219 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-11-09T18:34:07.219Z,1668018847.219 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2022-11-09T18:34:07.596Z,1668018847.596 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-11-09T18:34:50.825Z,1668018890.825 [Startup:StartupSatComms:A](INFO): Timed out from 2022-11-09T18:33:50.7Z
2022-11-09T18:34:50.825Z,1668018890.825 [Startup:StartupSatComms:A] Stopped
2022-11-09T18:34:50.825Z,1668018890.825 [Startup:StartupSatComms:B] Running Loop=1
2022-11-09T18:34:51.219Z,1668018891.219 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-11-09T18:34:52.713Z,1668018892.713 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:34:52.729Z,1668018892.729 [DAT](INFO): setting remote address to 1
2022-11-09T18:34:52.982Z,1668018892.982 [DAT](INFO): set remote address to 1
2022-11-09T18:34:52.982Z,1668018892.982 [DAT](INFO): entering online mode
2022-11-09T18:34:53.235Z,1668018893.235 [DAT](INFO): commRate: 800
2022-11-09T18:34:53.235Z,1668018893.235 [DAT](INFO): online mode acknowledged
2022-11-09T18:34:53.235Z,1668018893.235 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:34:56.510Z,1668018896.510 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2022-11-09T18:34:59.260Z,1668018899.260 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20221109T182219/Courier0004.lzma
2022-11-09T18:35:00.262Z,1668018900.262 [DataOverHttps](INFO): Moved sent file to Logs/20221109T182219/Courier0004.lzma.bak
2022-11-09T18:35:00.262Z,1668018900.262 [DataOverHttps](INFO): SBD MOMSN=17277735
2022-11-09T18:35:11.641Z,1668018911.641 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:35:13.262Z,1668018913.262 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:35:13.291Z,1668018913.291 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:35:16.546Z,1668018916.546 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2022-11-09T18:35:16.624Z,1668018916.624 [DataOverHttps](INFO): Sending 245 bytes from file Logs/20221109T183056/Courier0000.lzma
2022-11-09T18:35:17.626Z,1668018917.626 [DataOverHttps](INFO): Moved sent file to Logs/20221109T183056/Courier0000.lzma.bak
2022-11-09T18:35:17.626Z,1668018917.626 [DataOverHttps](INFO): SBD MOMSN=17277737
2022-11-09T18:35:33.685Z,1668018933.685 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:35:35.289Z,1668018935.289 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:35:35.316Z,1668018935.316 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:35:35.397Z,1668018935.397 [DataOverHttps](INFO): Sending 677 bytes from file Logs/20221109T002546/Express0005.lzma
2022-11-09T18:35:35.458Z,1668018935.458 [Startup:StartupSatComms:B] Stopped
2022-11-09T18:35:35.458Z,1668018935.458 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2022-11-09T18:35:35.458Z,1668018935.458 [Startup:StartupSatComms] Stopped
2022-11-09T18:35:35.458Z,1668018935.458 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2022-11-09T18:35:35.459Z,1668018935.459 [Startup](INFO): Completed Startup
2022-11-09T18:35:35.459Z,1668018935.459 [MissionManager](INFO): Startup is completed.
2022-11-09T18:35:35.459Z,1668018935.459 [MissionManager](INFO): Uninitializing Mission Startup
2022-11-09T18:35:35.459Z,1668018935.459 [Startup] Stopped
2022-11-09T18:35:35.459Z,1668018935.459 [Startup](DEBUG): Aggregate::uninitialize Startup
2022-11-09T18:35:35.459Z,1668018935.459 [Startup:A.GoToSurface] Stopped
2022-11-09T18:35:35.459Z,1668018935.459 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-11-09T18:35:35.810Z,1668018935.810 [MissionManager](IMPORTANT): Started mission Default
2022-11-09T18:35:35.810Z,1668018935.810 [Default] Running Loop=1
2022-11-09T18:35:35.810Z,1668018935.810 [Default](DEBUG): Aggregate::initialize Default
2022-11-09T18:35:35.810Z,1668018935.810 [Default:B.GoToSurface] Running Loop=1
2022-11-09T18:35:35.810Z,1668018935.810 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-11-09T18:35:35.811Z,1668018935.811 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-11-09T18:35:35.811Z,1668018935.811 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-11-09T18:35:35.811Z,1668018935.811 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-11-09T18:35:35.812Z,1668018935.812 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-11-09T18:35:35.812Z,1668018935.812 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-11-09T18:35:35.832Z,1668018935.832 [Default:A.Wait] Running Loop=1
2022-11-09T18:35:35.832Z,1668018935.832 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:35:36.346Z,1668018936.346 [DataOverHttps](INFO): Moved sent file to Logs/20221109T002546/Express0005.lzma.bak
2022-11-09T18:35:36.346Z,1668018936.346 [DataOverHttps](INFO): SBD MOMSN=17277743
2022-11-09T18:35:38.566Z,1668018938.566 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2022-11-09T18:35:49.114Z,1668018949.114 [Default:A.Wait](INFO): Done Waiting.
2022-11-09T18:35:49.114Z,1668018949.114 [Default:A.Wait] Stopped
2022-11-09T18:35:49.114Z,1668018949.114 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:35:49.526Z,1668018949.526 [Default:CheckIn] Running Loop=1
2022-11-09T18:35:49.526Z,1668018949.526 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-11-09T18:35:49.526Z,1668018949.526 [Default:CheckIn:Read_GPS] Running Loop=1
2022-11-09T18:35:49.931Z,1668018949.931 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-11-09T18:35:55.721Z,1668018955.721 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:35:55.973Z,1668018955.973 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:35:56.225Z,1668018956.225 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:35:59.502Z,1668018959.502 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2022-11-09T18:36:14.345Z,1668018974.345 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:36:14.346Z,1668018974.346 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:36:14.408Z,1668018974.408 [MissionManager](INFO): DefineArg multiray_test.MissionTimeout = 5.000000 min
2022-11-09T18:36:14.411Z,1668018974.411 [MissionManager](INFO): DefineArg multiray_test.LightDuration = 5.000000 s
2022-11-09T18:36:14.414Z,1668018974.414 [MissionManager](INFO): DefineArg multiray_test.LightMode0 = 0.000000 count
2022-11-09T18:36:14.417Z,1668018974.417 [MissionManager](INFO): DefineArg multiray_test.LightMode1 = 1.000000 count
2022-11-09T18:36:14.419Z,1668018974.419 [MissionManager](INFO): DefineArg multiray_test.LightMode2 = 2.000000 count
2022-11-09T18:36:14.443Z,1668018974.443 [MissionManager](INFO): DefineArg multiray_test.EnabledMultiray = 1 bool
2022-11-09T18:36:14.451Z,1668018974.451 [multiray_test:C.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.459Z,1668018974.459 [multiray_test:E.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.481Z,1668018974.481 [multiray_test:G.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.488Z,1668018974.488 [multiray_test:I.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.491Z,1668018974.491 [multiray_test:K.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.498Z,1668018974.498 [multiray_test:M.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.502Z,1668018974.502 [multiray_test:O.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.513Z,1668018974.513 [multiray_test:Q.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.518Z,1668018974.518 [multiray_test:R.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.521Z,1668018974.521 [multiray_test:T.Wait](DEBUG): Construct Wait.
2022-11-09T18:36:14.530Z,1668018974.530 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>

<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Sensor="Tethys/Sensor"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd"
       Id="multiray_test">

    <Description>
        This mission is designed to run in the lab only. Cycles through MultiRay light modes
    </Description>

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

    <DefineArg Name="LightDuration"><Description>
        How long to wait before changing light modes
    </Description><Units:second/><Value>5</Value></DefineArg>

    <DefineArg Name="LightMode0"><Description>
        Light mode = 0
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="LightMode1"><Description>
        Light mode = 1
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="LightMode2"><Description>
        Light mode = 2
    </Description><Units:count/><Value>2</Value></DefineArg>

    <DefineArg Name="EnabledMultiray"><Description>
        Automatically set to true if the Multiray is enabled.
    </Description><Science:MultiRay.loadAtStartup/></DefineArg>

    <Timeout Duration="MissionTimeout"/>



    <ReadData Strategy="MinError">
        <While>
            <Arg Name="EnabledMultiray"/>
        </While>
    <Sensor:MultiRay.lightModeLog/>
    </ReadData>


    <!-- <ReadDatum>
            <Sensor:MultiRay.lightModeLog/>
    </ReadDatum> -->

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>
    
    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

</Mission>


2022-11-09T18:36:14.577Z,1668018974.577 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:36:14.589Z,1668018974.589 [Default] Stopped
2022-11-09T18:36:14.589Z,1668018974.589 [Default](DEBUG): Aggregate::uninitialize Default
2022-11-09T18:36:14.589Z,1668018974.589 [Default:B.GoToSurface] Stopped
2022-11-09T18:36:14.589Z,1668018974.589 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-11-09T18:36:14.589Z,1668018974.589 [Default:CheckIn] Stopped
2022-11-09T18:36:14.589Z,1668018974.589 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-11-09T18:36:14.589Z,1668018974.589 [Default:CheckIn:Read_GPS] Stopped
2022-11-09T18:36:14.590Z,1668018974.590 [MissionManager](IMPORTANT): Started mission multiray_test
2022-11-09T18:36:14.590Z,1668018974.590 [multiray_test] Running Loop=1
2022-11-09T18:36:14.590Z,1668018974.590 [multiray_test](DEBUG): Aggregate::initialize multiray_test
2022-11-09T18:36:14.590Z,1668018974.590 [multiray_test:A] Running Loop=1
2022-11-09T18:36:14.590Z,1668018974.590 [multiray_test:B] Running Loop=1
2022-11-09T18:36:14.591Z,1668018974.591 [multiray_test:B] Stopped
2022-11-09T18:36:14.591Z,1668018974.591 [multiray_test:C.Wait] Running Loop=1
2022-11-09T18:36:14.591Z,1668018974.591 [multiray_test:C.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:14.591Z,1668018974.591 [multiray_test:A] Running Loop=1
2022-11-09T18:36:14.592Z,1668018974.592 [multiray_test:A](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog
2022-11-09T18:36:15.990Z,1668018975.990 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:36:16.657Z,1668018976.657 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED
2022-11-09T18:36:16.657Z,1668018976.657 [DAT](ERROR): Ack receipt timeout failure.
2022-11-09T18:36:16.909Z,1668018976.909 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:36:17.161Z,1668018977.161 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:36:17.413Z,1668018977.413 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:36:20.211Z,1668018980.211 [multiray_test:C.Wait](INFO): Done Waiting.
2022-11-09T18:36:20.211Z,1668018980.211 [multiray_test:C.Wait] Stopped
2022-11-09T18:36:20.211Z,1668018980.211 [multiray_test:C.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:20.211Z,1668018980.211 [multiray_test:D] Running Loop=1
2022-11-09T18:36:20.619Z,1668018980.619 [multiray_test:D] Stopped
2022-11-09T18:36:20.619Z,1668018980.619 [multiray_test:E.Wait] Running Loop=1
2022-11-09T18:36:20.619Z,1668018980.619 [multiray_test:E.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:21.866Z,1668018981.866 [MultiRay](INFO): White lights on
2022-11-09T18:36:26.285Z,1668018986.285 [multiray_test:E.Wait](INFO): Done Waiting.
2022-11-09T18:36:26.285Z,1668018986.285 [multiray_test:E.Wait] Stopped
2022-11-09T18:36:26.285Z,1668018986.285 [multiray_test:E.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:26.285Z,1668018986.285 [multiray_test:F] Running Loop=1
2022-11-09T18:36:26.710Z,1668018986.710 [multiray_test:F] Stopped
2022-11-09T18:36:26.710Z,1668018986.710 [multiray_test:G.Wait] Running Loop=1
2022-11-09T18:36:26.710Z,1668018986.710 [multiray_test:G.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:27.157Z,1668018987.157 [MultiRay](INFO): White lights on
2022-11-09T18:36:27.497Z,1668018987.497 [DAT](FAULT): Buffer send receipt timeout failure.
2022-11-09T18:36:27.497Z,1668018987.497 [DAT](DEBUG): In sendingTransmitVerify, timeout so go online and set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:36:27.749Z,1668018987.749 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:36:28.001Z,1668018988.001 [DAT](INFO): entering online mode
2022-11-09T18:36:28.253Z,1668018988.253 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:28.505Z,1668018988.505 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:28.757Z,1668018988.757 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:29.009Z,1668018989.009 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:29.261Z,1668018989.261 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:29.513Z,1668018989.513 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:29.765Z,1668018989.765 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:30.017Z,1668018990.017 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:30.269Z,1668018990.269 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:30.521Z,1668018990.521 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:30.773Z,1668018990.773 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:31.025Z,1668018991.025 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:31.277Z,1668018991.277 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:31.529Z,1668018991.529 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:31.781Z,1668018991.781 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:32.033Z,1668018992.033 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:32.285Z,1668018992.285 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:32.366Z,1668018992.366 [multiray_test:G.Wait](INFO): Done Waiting.
2022-11-09T18:36:32.366Z,1668018992.366 [multiray_test:G.Wait] Stopped
2022-11-09T18:36:32.367Z,1668018992.367 [multiray_test:G.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:32.367Z,1668018992.367 [multiray_test:H] Running Loop=1
2022-11-09T18:36:32.537Z,1668018992.537 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:32.770Z,1668018992.770 [multiray_test:H] Stopped
2022-11-09T18:36:32.770Z,1668018992.770 [multiray_test:I.Wait] Running Loop=1
2022-11-09T18:36:32.770Z,1668018992.770 [multiray_test:I.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:32.789Z,1668018992.789 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:33.041Z,1668018993.041 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:33.241Z,1668018993.241 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:36:33.293Z,1668018993.293 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:33.545Z,1668018993.545 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:33.797Z,1668018993.797 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:34.049Z,1668018994.049 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:34.301Z,1668018994.301 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:34.553Z,1668018994.553 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:34.809Z,1668018994.809 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:35.061Z,1668018995.061 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:35.313Z,1668018995.313 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:35.567Z,1668018995.567 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:35.821Z,1668018995.821 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:36.073Z,1668018996.073 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:36.325Z,1668018996.325 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:36.577Z,1668018996.577 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:36.829Z,1668018996.829 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:37.081Z,1668018997.081 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:37.333Z,1668018997.333 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:37.585Z,1668018997.585 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:37.837Z,1668018997.837 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:38.089Z,1668018998.089 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:38.341Z,1668018998.341 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:38.447Z,1668018998.447 [multiray_test:I.Wait](INFO): Done Waiting.
2022-11-09T18:36:38.448Z,1668018998.448 [multiray_test:I.Wait] Stopped
2022-11-09T18:36:38.448Z,1668018998.448 [multiray_test:I.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:38.448Z,1668018998.448 [multiray_test:J] Running Loop=1
2022-11-09T18:36:38.593Z,1668018998.593 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:38.810Z,1668018998.810 [multiray_test:J] Stopped
2022-11-09T18:36:38.810Z,1668018998.810 [multiray_test:K.Wait] Running Loop=1
2022-11-09T18:36:38.810Z,1668018998.810 [multiray_test:K.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:38.845Z,1668018998.845 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:39.097Z,1668018999.097 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:39.349Z,1668018999.349 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:39.601Z,1668018999.601 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:39.853Z,1668018999.853 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:40.059Z,1668019000.059 [MultiRay](INFO): White lights on
2022-11-09T18:36:40.105Z,1668019000.105 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:40.357Z,1668019000.357 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:40.609Z,1668019000.609 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:40.861Z,1668019000.861 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:41.113Z,1668019001.113 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:41.365Z,1668019001.365 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:41.617Z,1668019001.617 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:41.869Z,1668019001.869 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:42.121Z,1668019002.121 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:42.373Z,1668019002.373 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:42.625Z,1668019002.625 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:42.877Z,1668019002.877 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:43.129Z,1668019003.129 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:36:43.129Z,1668019003.129 [DAT](FAULT): failed to enter online mode
2022-11-09T18:36:43.129Z,1668019003.129 [DAT](FAULT): Failure returning to online mode
2022-11-09T18:36:43.129Z,1668019003.129 [DAT] Communications Fault, FailCount= 1
2022-11-09T18:36:43.129Z,1668019003.129 [DAT](ERROR): Communications Fault
2022-11-09T18:36:43.299Z,1668019003.299 [CBIT](ERROR): Communications Fault in component: DAT
2022-11-09T18:36:43.533Z,1668019003.533 [DAT](INFO): Powering down
2022-11-09T18:36:44.009Z,1668019004.009 [DAT](FAULT): LCB fault: LCB Watchdog Reset. Invalid Command. Hardware Overcurrent Shutdown. Current Limiter Activated.
2022-11-09T18:36:44.009Z,1668019004.009 [DAT] Hardware Fault, FailCount= 1
2022-11-09T18:36:44.009Z,1668019004.009 [DAT](ERROR): Hardware Fault
2022-11-09T18:36:44.454Z,1668019004.454 [multiray_test:K.Wait](INFO): Done Waiting.
2022-11-09T18:36:44.454Z,1668019004.454 [multiray_test:K.Wait] Stopped
2022-11-09T18:36:44.454Z,1668019004.454 [multiray_test:K.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:44.454Z,1668019004.454 [multiray_test:L] Running Loop=1
2022-11-09T18:36:44.463Z,1668019004.463 [CBIT](INFO): Clearing failed state for component DAT
2022-11-09T18:36:44.463Z,1668019004.463 [DAT] No Fault, FailCount= 1
2022-11-09T18:36:44.861Z,1668019004.861 [multiray_test:L] Stopped
2022-11-09T18:36:44.861Z,1668019004.861 [multiray_test:M.Wait] Running Loop=1
2022-11-09T18:36:44.861Z,1668019004.861 [multiray_test:M.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:45.304Z,1668019005.304 [MultiRay](INFO): White lights on
2022-11-09T18:36:46.580Z,1668019006.580 [DAT](INFO): Powering up
2022-11-09T18:36:46.581Z,1668019006.581 [DAT](DEBUG): Initializing DAT.
2022-11-09T18:36:50.114Z,1668019010.114 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-11-09T18:36:50.515Z,1668019010.515 [multiray_test:M.Wait](INFO): Done Waiting.
2022-11-09T18:36:50.515Z,1668019010.515 [multiray_test:M.Wait] Stopped
2022-11-09T18:36:50.515Z,1668019010.515 [multiray_test:M.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:50.515Z,1668019010.515 [multiray_test:N] Running Loop=1
2022-11-09T18:36:50.956Z,1668019010.956 [multiray_test:N] Stopped
2022-11-09T18:36:50.956Z,1668019010.956 [multiray_test:O.Wait] Running Loop=1
2022-11-09T18:36:50.960Z,1668019010.960 [multiray_test:O.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:51.404Z,1668019011.404 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:36:56.585Z,1668019016.585 [multiray_test:O.Wait](INFO): Done Waiting.
2022-11-09T18:36:56.585Z,1668019016.585 [multiray_test:O.Wait] Stopped
2022-11-09T18:36:56.585Z,1668019016.585 [multiray_test:O.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:36:56.586Z,1668019016.586 [multiray_test:P] Running Loop=1
2022-11-09T18:36:56.998Z,1668019016.998 [multiray_test:P] Stopped
2022-11-09T18:36:56.998Z,1668019016.998 [multiray_test:Q.Wait] Running Loop=1
2022-11-09T18:36:56.998Z,1668019016.998 [multiray_test:Q.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:36:58.254Z,1668019018.254 [MultiRay](INFO): White lights on
2022-11-09T18:37:01.719Z,1668019021.719 [DAT](INFO): commRate: 800
2022-11-09T18:37:02.654Z,1668019022.654 [multiray_test:Q.Wait](INFO): Done Waiting.
2022-11-09T18:37:02.655Z,1668019022.655 [multiray_test:Q.Wait] Stopped
2022-11-09T18:37:02.655Z,1668019022.655 [multiray_test:Q.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:02.655Z,1668019022.655 [multiray_test:U] Running Loop=1
2022-11-09T18:37:03.059Z,1668019023.059 [multiray_test:U] Stopped
2022-11-09T18:37:03.059Z,1668019023.059 [multiray_test:R.Wait] Running Loop=1
2022-11-09T18:37:03.059Z,1668019023.059 [multiray_test:R.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:03.525Z,1668019023.525 [MultiRay](INFO): White lights on
2022-11-09T18:37:03.788Z,1668019023.788 [DAT](INFO): entering command mode
2022-11-09T18:37:03.989Z,1668019023.989 [DAT](INFO): setting verbose to 3
2022-11-09T18:37:04.242Z,1668019024.242 [DAT](INFO): set verbose to 3
2022-11-09T18:37:04.242Z,1668019024.242 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:37:04.494Z,1668019024.494 [DAT](INFO): set DatVerbose to 27440
2022-11-09T18:37:04.494Z,1668019024.494 [DAT](INFO): setting transmit power to 8
2022-11-09T18:37:04.746Z,1668019024.746 [DAT](INFO): set transmit power to 8
2022-11-09T18:37:04.746Z,1668019024.746 [DAT](INFO): setting local address to 10
2022-11-09T18:37:04.998Z,1668019024.998 [DAT](INFO): set local address to 10
2022-11-09T18:37:04.999Z,1668019024.999 [DAT](INFO): Setting time to: 18:37:4 And date to:11/9/2022
2022-11-09T18:37:05.250Z,1668019025.250 [DAT](INFO): Local DAT time set to Wed Nov 9, 2022  18:37:04  

2022-11-09T18:37:05.250Z,1668019025.250 [DAT](INFO): setting remote address to 1
2022-11-09T18:37:05.507Z,1668019025.507 [DAT](INFO): set remote address to 1
2022-11-09T18:37:05.509Z,1668019025.509 [DAT](INFO): entering online mode
2022-11-09T18:37:05.755Z,1668019025.755 [DAT](INFO): commRate: 800
2022-11-09T18:37:05.755Z,1668019025.755 [DAT](INFO): online mode acknowledged
2022-11-09T18:37:05.755Z,1668019025.755 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:37:07.925Z,1668019027.925 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2022-11-09T18:37:07.926Z,1668019027.926 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-11-09T18:37:07.927Z,1668019027.927 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2022-11-09T18:37:07.927Z,1668019027.927 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-11-09T18:37:07.961Z,1668019027.961 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-11-09T18:37:07.961Z,1668019027.961 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-11-09T18:37:08.334Z,1668019028.334 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-11-09T18:37:08.335Z,1668019028.335 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2022-11-09T18:37:08.335Z,1668019028.335 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-11-09T18:37:08.335Z,1668019028.335 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2022-11-09T18:37:08.742Z,1668019028.742 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-11-09T18:37:08.743Z,1668019028.743 [multiray_test:R.Wait](INFO): Done Waiting.
2022-11-09T18:37:08.743Z,1668019028.743 [multiray_test:R.Wait] Stopped
2022-11-09T18:37:08.743Z,1668019028.743 [multiray_test:R.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:08.743Z,1668019028.743 [multiray_test:S] Running Loop=1
2022-11-09T18:37:09.131Z,1668019029.131 [multiray_test:S] Stopped
2022-11-09T18:37:09.131Z,1668019029.131 [multiray_test:T.Wait] Running Loop=1
2022-11-09T18:37:09.131Z,1668019029.131 [multiray_test:T.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:09.669Z,1668019029.669 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:37:14.766Z,1668019034.766 [multiray_test:T.Wait](INFO): Done Waiting.
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test:T.Wait] Stopped
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test:T.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test](INFO): Completed multiray_test
2022-11-09T18:37:14.767Z,1668019034.767 [MissionManager](INFO): multiray_test is completed.
2022-11-09T18:37:14.767Z,1668019034.767 [MissionManager](INFO): Uninitializing Mission multiray_test
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test] Stopped
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test](DEBUG): Aggregate::uninitialize multiray_test
2022-11-09T18:37:14.767Z,1668019034.767 [multiray_test:A] Stopped
2022-11-09T18:37:15.170Z,1668019035.170 [MissionManager](IMPORTANT): Started mission Default
2022-11-09T18:37:15.171Z,1668019035.171 [Default] Running Loop=1
2022-11-09T18:37:15.171Z,1668019035.171 [Default](DEBUG): Aggregate::initialize Default
2022-11-09T18:37:15.171Z,1668019035.171 [Default:B.GoToSurface] Running Loop=1
2022-11-09T18:37:15.171Z,1668019035.171 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-11-09T18:37:15.171Z,1668019035.171 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-11-09T18:37:15.171Z,1668019035.171 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-11-09T18:37:15.172Z,1668019035.172 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-11-09T18:37:15.172Z,1668019035.172 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-11-09T18:37:15.173Z,1668019035.173 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-11-09T18:37:15.173Z,1668019035.173 [Default:A.Wait] Running Loop=1
2022-11-09T18:37:15.173Z,1668019035.173 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:15.845Z,1668019035.845 [DAT](FAULT): Buffer send receipt timeout failure.
2022-11-09T18:37:15.845Z,1668019035.845 [DAT](DEBUG): In sendingTransmitVerify, timeout so go online and set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:37:16.097Z,1668019036.097 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:37:16.351Z,1668019036.351 [DAT](INFO): entering online mode
2022-11-09T18:37:16.605Z,1668019036.605 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:16.858Z,1668019036.858 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:17.109Z,1668019037.109 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:17.361Z,1668019037.361 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:17.617Z,1668019037.617 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:17.869Z,1668019037.869 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:18.121Z,1668019038.121 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:18.373Z,1668019038.373 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:18.625Z,1668019038.625 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:18.877Z,1668019038.877 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:19.129Z,1668019039.129 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:19.381Z,1668019039.381 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:19.633Z,1668019039.633 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:19.885Z,1668019039.885 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:20.137Z,1668019040.137 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:20.389Z,1668019040.389 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:20.641Z,1668019040.641 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:20.893Z,1668019040.893 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:21.145Z,1668019041.145 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:21.397Z,1668019041.397 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:21.649Z,1668019041.649 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:21.901Z,1668019041.901 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:22.153Z,1668019042.153 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:22.405Z,1668019042.405 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:22.657Z,1668019042.657 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:22.909Z,1668019042.909 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:23.161Z,1668019043.161 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:23.413Z,1668019043.413 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:23.665Z,1668019043.665 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:23.917Z,1668019043.917 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:24.169Z,1668019044.169 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:24.421Z,1668019044.421 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:24.673Z,1668019044.673 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:24.925Z,1668019044.925 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:25.177Z,1668019045.177 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:25.429Z,1668019045.429 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:25.681Z,1668019045.681 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:25.933Z,1668019045.933 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:26.185Z,1668019046.185 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:26.437Z,1668019046.437 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:26.689Z,1668019046.689 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:26.941Z,1668019046.941 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:27.193Z,1668019047.193 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:27.445Z,1668019047.445 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:27.697Z,1668019047.697 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:27.949Z,1668019047.949 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:28.201Z,1668019048.201 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:28.453Z,1668019048.453 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:28.506Z,1668019048.506 [Default:A.Wait](INFO): Done Waiting.
2022-11-09T18:37:28.506Z,1668019048.506 [Default:A.Wait] Stopped
2022-11-09T18:37:28.506Z,1668019048.506 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:28.705Z,1668019048.705 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:28.911Z,1668019048.911 [Default:CheckIn] Running Loop=1
2022-11-09T18:37:28.911Z,1668019048.911 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-11-09T18:37:28.911Z,1668019048.911 [Default:CheckIn:Read_GPS] Running Loop=1
2022-11-09T18:37:28.957Z,1668019048.957 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:29.209Z,1668019049.209 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:29.461Z,1668019049.461 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:29.713Z,1668019049.713 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:29.965Z,1668019049.965 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:30.217Z,1668019050.217 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:30.472Z,1668019050.472 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:30.725Z,1668019050.725 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:30.978Z,1668019050.978 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:31.229Z,1668019051.229 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:31.481Z,1668019051.481 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:37:31.481Z,1668019051.481 [DAT](FAULT): failed to enter online mode
2022-11-09T18:37:31.481Z,1668019051.481 [DAT](FAULT): Failure returning to online mode
2022-11-09T18:37:31.481Z,1668019051.481 [DAT] Communications Fault, FailCount= 2
2022-11-09T18:37:31.481Z,1668019051.481 [DAT](ERROR): Communications Fault
2022-11-09T18:37:31.734Z,1668019051.734 [CBIT](ERROR): Communications Fault in component: DAT
2022-11-09T18:37:31.885Z,1668019051.885 [DAT](INFO): Powering down
2022-11-09T18:37:32.980Z,1668019052.980 [CBIT](INFO): Clearing failed state for component DAT
2022-11-09T18:37:32.980Z,1668019052.980 [DAT] No Fault, FailCount= 2
2022-11-09T18:37:34.933Z,1668019054.933 [DAT](INFO): Powering up
2022-11-09T18:37:34.933Z,1668019054.933 [DAT](DEBUG): Initializing DAT.
2022-11-09T18:37:44.302Z,1668019064.302 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:37:44.303Z,1668019064.303 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:37:44.380Z,1668019064.380 [MissionManager](INFO): DefineArg multiray_test.MissionTimeout = 5.000000 min
2022-11-09T18:37:44.382Z,1668019064.382 [MissionManager](INFO): DefineArg multiray_test.LightDuration = 5.000000 s
2022-11-09T18:37:44.385Z,1668019064.385 [MissionManager](INFO): DefineArg multiray_test.LightMode0 = 0.000000 count
2022-11-09T18:37:44.387Z,1668019064.387 [MissionManager](INFO): DefineArg multiray_test.LightMode1 = 1.000000 count
2022-11-09T18:37:44.389Z,1668019064.389 [MissionManager](INFO): DefineArg multiray_test.LightMode2 = 2.000000 count
2022-11-09T18:37:44.391Z,1668019064.391 [MissionManager](INFO): DefineArg multiray_test.EnabledMultiray = 1 bool
2022-11-09T18:37:44.395Z,1668019064.395 [multiray_test:C.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.398Z,1668019064.398 [multiray_test:E.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.401Z,1668019064.401 [multiray_test:G.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.403Z,1668019064.403 [multiray_test:I.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.406Z,1668019064.406 [multiray_test:K.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.409Z,1668019064.409 [multiray_test:M.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.411Z,1668019064.411 [multiray_test:O.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.451Z,1668019064.451 [multiray_test:Q.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.458Z,1668019064.458 [multiray_test:R.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.465Z,1668019064.465 [multiray_test:T.Wait](DEBUG): Construct Wait.
2022-11-09T18:37:44.474Z,1668019064.474 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>

<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Sensor="Tethys/Sensor"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd"
       Id="multiray_test">

    <Description>
        This mission is designed to run in the lab only. Cycles through MultiRay light modes
    </Description>

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

    <DefineArg Name="LightDuration"><Description>
        How long to wait before changing light modes
    </Description><Units:second/><Value>5</Value></DefineArg>

    <DefineArg Name="LightMode0"><Description>
        Light mode = 0
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="LightMode1"><Description>
        Light mode = 1
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="LightMode2"><Description>
        Light mode = 2
    </Description><Units:count/><Value>2</Value></DefineArg>

    <DefineArg Name="EnabledMultiray"><Description>
        Automatically set to true if the Multiray is enabled.
    </Description><Science:MultiRay.loadAtStartup/></DefineArg>

    <Timeout Duration="MissionTimeout"/>



    <ReadData Strategy="MinError">
        <While>
            <Arg Name="EnabledMultiray"/>
        </While>
    <Sensor:MultiRay.lightModeLog/>
    </ReadData>


    <!-- <ReadDatum>
            <Sensor:MultiRay.lightModeLog/>
    </ReadDatum> -->

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>
    
    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

</Mission>


2022-11-09T18:37:44.481Z,1668019064.481 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:37:44.657Z,1668019064.657 [Default] Stopped
2022-11-09T18:37:44.658Z,1668019064.658 [Default](DEBUG): Aggregate::uninitialize Default
2022-11-09T18:37:44.658Z,1668019064.658 [Default:B.GoToSurface] Stopped
2022-11-09T18:37:44.658Z,1668019064.658 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-11-09T18:37:44.658Z,1668019064.658 [Default:CheckIn] Stopped
2022-11-09T18:37:44.658Z,1668019064.658 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-11-09T18:37:44.658Z,1668019064.658 [Default:CheckIn:Read_GPS] Stopped
2022-11-09T18:37:44.658Z,1668019064.658 [MissionManager](IMPORTANT): Started mission multiray_test
2022-11-09T18:37:44.658Z,1668019064.658 [multiray_test] Running Loop=1
2022-11-09T18:37:44.659Z,1668019064.659 [multiray_test](DEBUG): Aggregate::initialize multiray_test
2022-11-09T18:37:44.659Z,1668019064.659 [multiray_test:A] Running Loop=1
2022-11-09T18:37:44.659Z,1668019064.659 [multiray_test:B] Running Loop=1
2022-11-09T18:37:44.659Z,1668019064.659 [multiray_test:B] Stopped
2022-11-09T18:37:44.660Z,1668019064.660 [multiray_test:C.Wait] Running Loop=1
2022-11-09T18:37:44.660Z,1668019064.660 [multiray_test:C.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:44.660Z,1668019064.660 [multiray_test:A] Running Loop=1
2022-11-09T18:37:44.660Z,1668019064.660 [multiray_test:A](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog
2022-11-09T18:37:45.950Z,1668019065.950 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:37:49.855Z,1668019069.855 [DAT](INFO): commRate: 800
2022-11-09T18:37:50.325Z,1668019070.325 [multiray_test:C.Wait](INFO): Done Waiting.
2022-11-09T18:37:50.325Z,1668019070.325 [multiray_test:C.Wait] Stopped
2022-11-09T18:37:50.325Z,1668019070.325 [multiray_test:C.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:50.325Z,1668019070.325 [multiray_test:D] Running Loop=1
2022-11-09T18:37:50.737Z,1668019070.737 [multiray_test:D] Stopped
2022-11-09T18:37:50.737Z,1668019070.737 [multiray_test:E.Wait] Running Loop=1
2022-11-09T18:37:50.737Z,1668019070.737 [multiray_test:E.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:51.924Z,1668019071.924 [DAT](INFO): entering command mode
2022-11-09T18:37:51.967Z,1668019071.967 [MultiRay](INFO): White lights on
2022-11-09T18:37:52.122Z,1668019072.122 [DAT](INFO): setting verbose to 3
2022-11-09T18:37:52.374Z,1668019072.374 [DAT](INFO): set verbose to 3
2022-11-09T18:37:52.374Z,1668019072.374 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:37:52.626Z,1668019072.626 [DAT](INFO): set DatVerbose to 27440
2022-11-09T18:37:52.626Z,1668019072.626 [DAT](INFO): setting transmit power to 8
2022-11-09T18:37:52.878Z,1668019072.878 [DAT](INFO): set transmit power to 8
2022-11-09T18:37:52.878Z,1668019072.878 [DAT](INFO): setting local address to 10
2022-11-09T18:37:53.130Z,1668019073.130 [DAT](INFO): set local address to 10
2022-11-09T18:37:53.131Z,1668019073.131 [DAT](INFO): Setting time to: 18:37:53 And date to:11/9/2022
2022-11-09T18:37:53.382Z,1668019073.382 [DAT](INFO): Local DAT time set to Wed Nov 9, 2022  18:37:53  

2022-11-09T18:37:53.382Z,1668019073.382 [DAT](INFO): setting remote address to 1
2022-11-09T18:37:53.634Z,1668019073.634 [DAT](INFO): set remote address to 1
2022-11-09T18:37:53.634Z,1668019073.634 [DAT](INFO): entering online mode
2022-11-09T18:37:53.887Z,1668019073.887 [DAT](INFO): commRate: 800
2022-11-09T18:37:53.887Z,1668019073.887 [DAT](INFO): online mode acknowledged
2022-11-09T18:37:53.887Z,1668019073.887 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:37:56.401Z,1668019076.401 [multiray_test:E.Wait](INFO): Done Waiting.
2022-11-09T18:37:56.401Z,1668019076.401 [multiray_test:E.Wait] Stopped
2022-11-09T18:37:56.401Z,1668019076.401 [multiray_test:E.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:37:56.401Z,1668019076.401 [multiray_test:F] Running Loop=1
2022-11-09T18:37:56.821Z,1668019076.821 [multiray_test:F] Stopped
2022-11-09T18:37:56.821Z,1668019076.821 [multiray_test:G.Wait] Running Loop=1
2022-11-09T18:37:56.821Z,1668019076.821 [multiray_test:G.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:37:57.269Z,1668019077.269 [MultiRay](INFO): White lights on
2022-11-09T18:38:02.471Z,1668019082.471 [multiray_test:G.Wait](INFO): Done Waiting.
2022-11-09T18:38:02.471Z,1668019082.471 [multiray_test:G.Wait] Stopped
2022-11-09T18:38:02.471Z,1668019082.471 [multiray_test:G.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:02.471Z,1668019082.471 [multiray_test:H] Running Loop=1
2022-11-09T18:38:02.875Z,1668019082.875 [multiray_test:H] Stopped
2022-11-09T18:38:02.875Z,1668019082.875 [multiray_test:I.Wait] Running Loop=1
2022-11-09T18:38:02.875Z,1668019082.875 [multiray_test:I.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:03.452Z,1668019083.452 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:38:03.989Z,1668019083.989 [DAT](FAULT): Buffer send receipt timeout failure.
2022-11-09T18:38:03.989Z,1668019083.989 [DAT](DEBUG): In sendingTransmitVerify, timeout so go online and set commsState_ = SENDING_FILL_BUFFER
2022-11-09T18:38:04.241Z,1668019084.241 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2022-11-09T18:38:04.493Z,1668019084.493 [DAT](INFO): entering online mode
2022-11-09T18:38:04.745Z,1668019084.745 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:04.997Z,1668019084.997 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:05.249Z,1668019085.249 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:05.501Z,1668019085.501 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:05.753Z,1668019085.753 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:06.005Z,1668019086.005 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:06.257Z,1668019086.257 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:06.509Z,1668019086.509 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:06.761Z,1668019086.761 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:07.013Z,1668019087.013 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:07.265Z,1668019087.265 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:07.517Z,1668019087.517 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:07.769Z,1668019087.769 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:08.021Z,1668019088.021 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:08.273Z,1668019088.273 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:08.514Z,1668019088.514 [multiray_test:I.Wait](INFO): Done Waiting.
2022-11-09T18:38:08.514Z,1668019088.514 [multiray_test:I.Wait] Stopped
2022-11-09T18:38:08.514Z,1668019088.514 [multiray_test:I.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:08.515Z,1668019088.515 [multiray_test:J] Running Loop=1
2022-11-09T18:38:08.525Z,1668019088.525 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:08.777Z,1668019088.777 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:08.922Z,1668019088.922 [multiray_test:J] Stopped
2022-11-09T18:38:08.922Z,1668019088.922 [multiray_test:K.Wait] Running Loop=1
2022-11-09T18:38:08.922Z,1668019088.922 [multiray_test:K.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:09.029Z,1668019089.029 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:09.281Z,1668019089.281 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:09.533Z,1668019089.533 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:09.785Z,1668019089.785 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:10.037Z,1668019090.037 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:10.197Z,1668019090.197 [MultiRay](INFO): White lights on
2022-11-09T18:38:10.289Z,1668019090.289 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:10.541Z,1668019090.541 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:10.793Z,1668019090.793 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:11.045Z,1668019091.045 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:11.297Z,1668019091.297 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:11.549Z,1668019091.549 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:11.801Z,1668019091.801 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:12.053Z,1668019092.053 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:12.305Z,1668019092.305 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:12.557Z,1668019092.557 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:12.809Z,1668019092.809 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:13.061Z,1668019093.061 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:13.313Z,1668019093.313 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:13.565Z,1668019093.565 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:13.817Z,1668019093.817 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:14.069Z,1668019094.069 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:14.321Z,1668019094.321 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:14.568Z,1668019094.568 [multiray_test:K.Wait](INFO): Done Waiting.
2022-11-09T18:38:14.568Z,1668019094.568 [multiray_test:K.Wait] Stopped
2022-11-09T18:38:14.568Z,1668019094.568 [multiray_test:K.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:14.568Z,1668019094.568 [multiray_test:L] Running Loop=1
2022-11-09T18:38:14.573Z,1668019094.573 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:14.825Z,1668019094.825 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:15.032Z,1668019095.032 [multiray_test:L] Stopped
2022-11-09T18:38:15.033Z,1668019095.033 [multiray_test:M.Wait] Running Loop=1
2022-11-09T18:38:15.033Z,1668019095.033 [multiray_test:M.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:15.077Z,1668019095.077 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:15.329Z,1668019095.329 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:15.428Z,1668019095.428 [MultiRay](INFO): White lights on
2022-11-09T18:38:15.581Z,1668019095.581 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:15.833Z,1668019095.833 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:16.085Z,1668019096.085 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:16.337Z,1668019096.337 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:16.589Z,1668019096.589 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:16.841Z,1668019096.841 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:17.093Z,1668019097.093 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:17.345Z,1668019097.345 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:17.597Z,1668019097.597 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:17.849Z,1668019097.849 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:18.101Z,1668019098.101 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:18.353Z,1668019098.353 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:18.605Z,1668019098.605 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:18.857Z,1668019098.857 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:19.109Z,1668019099.109 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:19.361Z,1668019099.361 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:19.613Z,1668019099.613 [DAT](DEBUG): checking for online mode acknowledgment
2022-11-09T18:38:19.613Z,1668019099.613 [DAT](FAULT): failed to enter online mode
2022-11-09T18:38:19.613Z,1668019099.613 [DAT](FAULT): Failure returning to online mode
2022-11-09T18:38:19.613Z,1668019099.613 [DAT] Communications Fault, FailCount= 3
2022-11-09T18:38:19.613Z,1668019099.613 [DAT](ERROR): Communications Fault
2022-11-09T18:38:19.833Z,1668019099.833 [CBIT](ERROR): Communications Fault in component: DAT
2022-11-09T18:38:20.017Z,1668019100.017 [DAT](INFO): Powering down
2022-11-09T18:38:20.651Z,1668019100.651 [multiray_test:M.Wait](INFO): Done Waiting.
2022-11-09T18:38:20.651Z,1668019100.651 [multiray_test:M.Wait] Stopped
2022-11-09T18:38:20.651Z,1668019100.651 [multiray_test:M.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:20.651Z,1668019100.651 [multiray_test:N] Running Loop=1
2022-11-09T18:38:21.061Z,1668019101.061 [multiray_test:N] Stopped
2022-11-09T18:38:21.061Z,1668019101.061 [multiray_test:O.Wait] Running Loop=1
2022-11-09T18:38:21.061Z,1668019101.061 [multiray_test:O.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:21.070Z,1668019101.070 [CBIT](INFO): Clearing failed state for component DAT
2022-11-09T18:38:21.070Z,1668019101.070 [DAT] No Fault, FailCount= 3
2022-11-09T18:38:21.521Z,1668019101.521 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:38:23.060Z,1668019103.060 [DAT](INFO): Powering up
2022-11-09T18:38:23.061Z,1668019103.061 [DAT](DEBUG): Initializing DAT.
2022-11-09T18:38:26.685Z,1668019106.685 [multiray_test:O.Wait](INFO): Done Waiting.
2022-11-09T18:38:26.685Z,1668019106.685 [multiray_test:O.Wait] Stopped
2022-11-09T18:38:26.685Z,1668019106.685 [multiray_test:O.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:26.685Z,1668019106.685 [multiray_test:P] Running Loop=1
2022-11-09T18:38:27.104Z,1668019107.104 [multiray_test:P] Stopped
2022-11-09T18:38:27.104Z,1668019107.104 [multiray_test:Q.Wait] Running Loop=1
2022-11-09T18:38:27.104Z,1668019107.104 [multiray_test:Q.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:28.414Z,1668019108.414 [MultiRay](INFO): White lights on
2022-11-09T18:38:32.747Z,1668019112.747 [multiray_test:Q.Wait](INFO): Done Waiting.
2022-11-09T18:38:32.747Z,1668019112.747 [multiray_test:Q.Wait] Stopped
2022-11-09T18:38:32.747Z,1668019112.747 [multiray_test:Q.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:32.747Z,1668019112.747 [multiray_test:U] Running Loop=1
2022-11-09T18:38:33.153Z,1668019113.153 [multiray_test:U] Stopped
2022-11-09T18:38:33.154Z,1668019113.154 [multiray_test:R.Wait] Running Loop=1
2022-11-09T18:38:33.154Z,1668019113.154 [multiray_test:R.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:33.618Z,1668019113.618 [MultiRay](INFO): White lights on
2022-11-09T18:38:38.191Z,1668019118.191 [DAT](INFO): commRate: 800
2022-11-09T18:38:38.906Z,1668019118.906 [multiray_test:R.Wait](INFO): Done Waiting.
2022-11-09T18:38:38.907Z,1668019118.907 [multiray_test:R.Wait] Stopped
2022-11-09T18:38:38.907Z,1668019118.907 [multiray_test:R.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:38.907Z,1668019118.907 [multiray_test:S] Running Loop=1
2022-11-09T18:38:39.287Z,1668019119.287 [multiray_test:S] Stopped
2022-11-09T18:38:39.288Z,1668019119.288 [multiray_test:T.Wait] Running Loop=1
2022-11-09T18:38:39.288Z,1668019119.288 [multiray_test:T.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:39.740Z,1668019119.740 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:38:40.269Z,1668019120.269 [DAT](INFO): entering command mode
2022-11-09T18:38:40.466Z,1668019120.466 [DAT](INFO): setting verbose to 3
2022-11-09T18:38:40.727Z,1668019120.727 [DAT](INFO): set verbose to 3
2022-11-09T18:38:40.727Z,1668019120.727 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:38:40.977Z,1668019120.977 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:41.233Z,1668019121.233 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:41.493Z,1668019121.493 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:41.745Z,1668019121.745 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:41.997Z,1668019121.997 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:42.249Z,1668019122.249 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:42.501Z,1668019122.501 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:42.753Z,1668019122.753 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:43.005Z,1668019123.005 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:43.257Z,1668019123.257 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:43.509Z,1668019123.509 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:43.761Z,1668019123.761 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:44.013Z,1668019124.013 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:44.265Z,1668019124.265 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:44.517Z,1668019124.517 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:44.769Z,1668019124.769 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:44.937Z,1668019124.937 [multiray_test:T.Wait](INFO): Done Waiting.
2022-11-09T18:38:44.937Z,1668019124.937 [multiray_test:T.Wait] Stopped
2022-11-09T18:38:44.937Z,1668019124.937 [multiray_test:T.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:44.938Z,1668019124.938 [multiray_test](INFO): Completed multiray_test
2022-11-09T18:38:44.938Z,1668019124.938 [MissionManager](INFO): multiray_test is completed.
2022-11-09T18:38:44.938Z,1668019124.938 [MissionManager](INFO): Uninitializing Mission multiray_test
2022-11-09T18:38:44.938Z,1668019124.938 [multiray_test] Stopped
2022-11-09T18:38:44.938Z,1668019124.938 [multiray_test](DEBUG): Aggregate::uninitialize multiray_test
2022-11-09T18:38:44.938Z,1668019124.938 [multiray_test:A] Stopped
2022-11-09T18:38:45.021Z,1668019125.021 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:45.273Z,1668019125.273 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:45.351Z,1668019125.351 [MissionManager](IMPORTANT): Started mission Default
2022-11-09T18:38:45.351Z,1668019125.351 [Default] Running Loop=1
2022-11-09T18:38:45.351Z,1668019125.351 [Default](DEBUG): Aggregate::initialize Default
2022-11-09T18:38:45.352Z,1668019125.352 [Default:B.GoToSurface] Running Loop=1
2022-11-09T18:38:45.352Z,1668019125.352 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-11-09T18:38:45.352Z,1668019125.352 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-11-09T18:38:45.361Z,1668019125.361 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-11-09T18:38:45.361Z,1668019125.361 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-11-09T18:38:45.361Z,1668019125.361 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-11-09T18:38:45.361Z,1668019125.361 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-11-09T18:38:45.362Z,1668019125.362 [Default:A.Wait] Running Loop=1
2022-11-09T18:38:45.362Z,1668019125.362 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:38:45.525Z,1668019125.525 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:45.785Z,1668019125.785 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:46.037Z,1668019126.037 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:46.289Z,1668019126.289 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:46.545Z,1668019126.545 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:46.797Z,1668019126.797 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:47.049Z,1668019127.049 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:47.301Z,1668019127.301 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:47.553Z,1668019127.553 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:47.807Z,1668019127.807 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:48.061Z,1668019128.061 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:48.313Z,1668019128.313 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:48.565Z,1668019128.565 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:48.817Z,1668019128.817 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:49.069Z,1668019129.069 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:49.321Z,1668019129.321 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:49.573Z,1668019129.573 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:49.825Z,1668019129.825 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:50.077Z,1668019130.077 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:50.329Z,1668019130.329 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:50.581Z,1668019130.581 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:50.834Z,1668019130.834 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:51.085Z,1668019131.085 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:51.337Z,1668019131.337 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:51.592Z,1668019131.592 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:51.841Z,1668019131.841 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:52.093Z,1668019132.093 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:52.345Z,1668019132.345 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:52.597Z,1668019132.597 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:52.849Z,1668019132.849 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:53.101Z,1668019133.101 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:53.353Z,1668019133.353 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:53.605Z,1668019133.605 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:53.857Z,1668019133.857 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:54.109Z,1668019134.109 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:54.361Z,1668019134.361 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:54.613Z,1668019134.613 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:54.865Z,1668019134.865 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:55.117Z,1668019135.117 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:55.369Z,1668019135.369 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:55.621Z,1668019135.621 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:55.873Z,1668019135.873 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:55.873Z,1668019135.873 [DAT](FAULT): failed to set DatVerbose
2022-11-09T18:38:56.125Z,1668019136.125 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:38:56.377Z,1668019136.377 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:56.629Z,1668019136.629 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:56.881Z,1668019136.881 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:57.133Z,1668019137.133 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:57.385Z,1668019137.385 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:57.637Z,1668019137.637 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:57.889Z,1668019137.889 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:58.141Z,1668019138.141 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:58.393Z,1668019138.393 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:58.645Z,1668019138.645 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:58.655Z,1668019138.655 [Default:A.Wait](INFO): Done Waiting.
2022-11-09T18:38:58.655Z,1668019138.655 [Default:A.Wait] Stopped
2022-11-09T18:38:58.655Z,1668019138.655 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:38:58.897Z,1668019138.897 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:59.068Z,1668019139.068 [Default:CheckIn] Running Loop=1
2022-11-09T18:38:59.069Z,1668019139.069 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-11-09T18:38:59.069Z,1668019139.069 [Default:CheckIn:Read_GPS] Running Loop=1
2022-11-09T18:38:59.149Z,1668019139.149 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:59.401Z,1668019139.401 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:59.653Z,1668019139.653 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:38:59.905Z,1668019139.905 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:00.157Z,1668019140.157 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:00.409Z,1668019140.409 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:00.661Z,1668019140.661 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:00.913Z,1668019140.913 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:01.165Z,1668019141.165 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:01.417Z,1668019141.417 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:01.669Z,1668019141.669 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:01.923Z,1668019141.923 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:02.177Z,1668019142.177 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:02.429Z,1668019142.429 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:02.681Z,1668019142.681 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:02.933Z,1668019142.933 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:03.185Z,1668019143.185 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:03.437Z,1668019143.437 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:03.689Z,1668019143.689 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:03.941Z,1668019143.941 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:04.193Z,1668019144.193 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:04.445Z,1668019144.445 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:04.697Z,1668019144.697 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:04.949Z,1668019144.949 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:05.201Z,1668019145.201 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:05.453Z,1668019145.453 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:05.705Z,1668019145.705 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:05.957Z,1668019145.957 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:06.209Z,1668019146.209 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:06.461Z,1668019146.461 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:06.713Z,1668019146.713 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:06.965Z,1668019146.965 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:07.217Z,1668019147.217 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:07.469Z,1668019147.469 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:07.721Z,1668019147.721 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:07.973Z,1668019147.973 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:08.225Z,1668019148.225 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:08.479Z,1668019148.479 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:08.733Z,1668019148.733 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:08.985Z,1668019148.985 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:09.237Z,1668019149.237 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:09.489Z,1668019149.489 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:09.741Z,1668019149.741 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:09.993Z,1668019149.993 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:10.245Z,1668019150.245 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:10.497Z,1668019150.497 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:10.749Z,1668019150.749 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:11.001Z,1668019151.001 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:11.253Z,1668019151.253 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:11.253Z,1668019151.253 [DAT](FAULT): failed to set DatVerbose
2022-11-09T18:39:11.505Z,1668019151.505 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:39:11.757Z,1668019151.757 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:12.009Z,1668019152.009 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:12.261Z,1668019152.261 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:12.513Z,1668019152.513 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:12.765Z,1668019152.765 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:13.017Z,1668019153.017 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:13.269Z,1668019153.269 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:13.521Z,1668019153.521 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:13.773Z,1668019153.773 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:14.025Z,1668019154.025 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:14.277Z,1668019154.277 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:14.529Z,1668019154.529 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:14.781Z,1668019154.781 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:15.033Z,1668019155.033 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:15.285Z,1668019155.285 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:15.537Z,1668019155.537 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:15.789Z,1668019155.789 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:16.041Z,1668019156.041 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:16.293Z,1668019156.293 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:16.545Z,1668019156.545 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:16.797Z,1668019156.797 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:17.049Z,1668019157.049 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:17.301Z,1668019157.301 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:17.553Z,1668019157.553 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:17.805Z,1668019157.805 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:18.057Z,1668019158.057 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:18.309Z,1668019158.309 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:18.561Z,1668019158.561 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:18.813Z,1668019158.813 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:19.068Z,1668019159.068 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:19.321Z,1668019159.321 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:19.573Z,1668019159.573 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:19.825Z,1668019159.825 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:20.077Z,1668019160.077 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:20.329Z,1668019160.329 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:20.581Z,1668019160.581 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:20.833Z,1668019160.833 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:21.085Z,1668019161.085 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:21.337Z,1668019161.337 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:21.589Z,1668019161.589 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:21.841Z,1668019161.841 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:22.093Z,1668019162.093 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:22.345Z,1668019162.345 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:22.597Z,1668019162.597 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:22.849Z,1668019162.849 [DAT](DEBUG): checking for DatVerbose setting acknowledgment
2022-11-09T18:39:23.101Z,1668019163.101 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: Verbose         | 3           
, available: user:2>
2022-11-09T18:39:23.101Z,1668019163.101 [DAT] Communications Fault, FailCount= 4
2022-11-09T18:39:23.101Z,1668019163.101 [DAT](ERROR): Communications Fault
2022-11-09T18:39:23.391Z,1668019163.391 [CBIT](ERROR): Communications Fault in component: DAT
2022-11-09T18:39:23.504Z,1668019163.504 [DAT](INFO): Powering down
2022-11-09T18:39:23.698Z,1668019163.698 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2022-11-09T18:39:23.701Z,1668019163.701 [BPC1](INFO): Received data from all battery sticks.
2022-11-09T18:39:24.515Z,1668019164.515 [CBIT](INFO): Clearing failed state for component DAT
2022-11-09T18:39:24.515Z,1668019164.515 [DAT] No Fault, FailCount= 4
2022-11-09T18:39:26.553Z,1668019166.553 [DAT](INFO): Powering up
2022-11-09T18:39:26.553Z,1668019166.553 [DAT](DEBUG): Initializing DAT.
2022-11-09T18:39:41.675Z,1668019181.675 [DAT](INFO): commRate: 800
2022-11-09T18:39:43.741Z,1668019183.741 [DAT](INFO): entering command mode
2022-11-09T18:39:43.941Z,1668019183.941 [DAT](INFO): setting verbose to 3
2022-11-09T18:39:44.194Z,1668019184.194 [DAT](INFO): set verbose to 3
2022-11-09T18:39:44.194Z,1668019184.194 [DAT](INFO): setting DatVerbose to 27440
2022-11-09T18:39:44.446Z,1668019184.446 [DAT](INFO): set DatVerbose to 27440
2022-11-09T18:39:44.446Z,1668019184.446 [DAT](INFO): setting transmit power to 8
2022-11-09T18:39:44.698Z,1668019184.698 [DAT](INFO): set transmit power to 8
2022-11-09T18:39:44.698Z,1668019184.698 [DAT](INFO): setting local address to 10
2022-11-09T18:39:44.950Z,1668019184.950 [DAT](INFO): set local address to 10
2022-11-09T18:39:44.951Z,1668019184.951 [DAT](INFO): Setting time to: 18:39:44 And date to:11/9/2022
2022-11-09T18:39:45.202Z,1668019185.202 [DAT](INFO): Local DAT time set to Wed Nov 9, 2022  18:39:44  

2022-11-09T18:39:45.202Z,1668019185.202 [DAT](INFO): setting remote address to 1
2022-11-09T18:39:45.454Z,1668019185.454 [DAT](INFO): set remote address to 1
2022-11-09T18:39:45.454Z,1668019185.454 [DAT](INFO): entering online mode
2022-11-09T18:39:45.707Z,1668019185.707 [DAT](INFO): commRate: 800
2022-11-09T18:39:45.708Z,1668019185.708 [DAT](INFO): online mode acknowledged
2022-11-09T18:39:45.708Z,1668019185.708 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2022-11-09T18:39:48.986Z,1668019188.986 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2022-11-09T18:39:49.566Z,1668019189.566 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:39:49.566Z,1668019189.566 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:39:49.703Z,1668019189.703 [MissionManager](INFO): DefineArg multiray_test.MissionTimeout = 5.000000 min
2022-11-09T18:39:49.718Z,1668019189.718 [MissionManager](INFO): DefineArg multiray_test.LightDuration = 5.000000 s
2022-11-09T18:39:49.720Z,1668019189.720 [MissionManager](INFO): DefineArg multiray_test.LightMode0 = 0.000000 count
2022-11-09T18:39:49.726Z,1668019189.726 [MissionManager](INFO): DefineArg multiray_test.LightMode1 = 1.000000 count
2022-11-09T18:39:49.728Z,1668019189.728 [MissionManager](INFO): DefineArg multiray_test.LightMode2 = 2.000000 count
2022-11-09T18:39:49.730Z,1668019189.730 [MissionManager](INFO): DefineArg multiray_test.EnabledMultiray = 1 bool
2022-11-09T18:39:49.734Z,1668019189.734 [multiray_test:C.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.752Z,1668019189.752 [multiray_test:E.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.755Z,1668019189.755 [multiray_test:G.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.798Z,1668019189.798 [multiray_test:I.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.801Z,1668019189.801 [multiray_test:K.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.803Z,1668019189.803 [multiray_test:M.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.820Z,1668019189.820 [multiray_test:O.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.835Z,1668019189.835 [multiray_test:Q.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.838Z,1668019189.838 [multiray_test:R.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.840Z,1668019189.840 [multiray_test:T.Wait](DEBUG): Construct Wait.
2022-11-09T18:39:49.848Z,1668019189.848 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>

<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Sensor="Tethys/Sensor"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd"
       Id="multiray_test">

    <Description>
        This mission is designed to run in the lab only. Cycles through MultiRay light modes
    </Description>

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

    <DefineArg Name="LightDuration"><Description>
        How long to wait before changing light modes
    </Description><Units:second/><Value>5</Value></DefineArg>

    <DefineArg Name="LightMode0"><Description>
        Light mode = 0
    </Description><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="LightMode1"><Description>
        Light mode = 1
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="LightMode2"><Description>
        Light mode = 2
    </Description><Units:count/><Value>2</Value></DefineArg>

    <DefineArg Name="EnabledMultiray"><Description>
        Automatically set to true if the Multiray is enabled.
    </Description><Science:MultiRay.loadAtStartup/></DefineArg>

    <Timeout Duration="MissionTimeout"/>



    <ReadData Strategy="MinError">
        <While>
            <Arg Name="EnabledMultiray"/>
        </While>
    <Sensor:MultiRay.lightModeLog/>
    </ReadData>


    <!-- <ReadDatum>
            <Sensor:MultiRay.lightModeLog/>
    </ReadDatum> -->

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>
    
    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode1"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode2"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

    <Assign><Sequence/><Sensor:MultiRay.lightModeCommand/><Arg Name="LightMode0"/></Assign>    
    <Guidance:Wait>
                <Sequence/>
                <Setting><Guidance:Wait.duration/><Arg Name="LightDuration"/></Setting>
            </Guidance:Wait>

</Mission>


2022-11-09T18:39:49.850Z,1668019189.850 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/multiray_test.xml
2022-11-09T18:39:49.965Z,1668019189.965 [Default] Stopped
2022-11-09T18:39:49.965Z,1668019189.965 [Default](DEBUG): Aggregate::uninitialize Default
2022-11-09T18:39:49.965Z,1668019189.965 [Default:B.GoToSurface] Stopped
2022-11-09T18:39:49.966Z,1668019189.966 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-11-09T18:39:49.966Z,1668019189.966 [Default:CheckIn] Stopped
2022-11-09T18:39:49.966Z,1668019189.966 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-11-09T18:39:49.966Z,1668019189.966 [Default:CheckIn:Read_GPS] Stopped
2022-11-09T18:39:49.966Z,1668019189.966 [MissionManager](IMPORTANT): Started mission multiray_test
2022-11-09T18:39:49.966Z,1668019189.966 [multiray_test] Running Loop=1
2022-11-09T18:39:49.966Z,1668019189.966 [multiray_test](DEBUG): Aggregate::initialize multiray_test
2022-11-09T18:39:49.966Z,1668019189.966 [multiray_test:A] Running Loop=1
2022-11-09T18:39:49.967Z,1668019189.967 [multiray_test:B] Running Loop=1
2022-11-09T18:39:49.967Z,1668019189.967 [multiray_test:B] Stopped
2022-11-09T18:39:49.967Z,1668019189.967 [multiray_test:C.Wait] Running Loop=1
2022-11-09T18:39:49.967Z,1668019189.967 [multiray_test:C.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:39:49.967Z,1668019189.967 [multiray_test:A] Running Loop=1
2022-11-09T18:39:49.993Z,1668019189.993 [multiray_test:A](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog
2022-11-09T18:39:51.233Z,1668019191.233 [MultiRay](IMPORTANT): All lights off
2022-11-09T18:39:55.638Z,1668019195.638 [multiray_test:C.Wait](INFO): Done Waiting.
2022-11-09T18:39:55.638Z,1668019195.638 [multiray_test:C.Wait] Stopped
2022-11-09T18:39:55.638Z,1668019195.638 [multiray_test:C.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:39:55.638Z,1668019195.638 [multiray_test:D] Running Loop=1
2022-11-09T18:39:56.035Z,1668019196.035 [multiray_test:D] Stopped
2022-11-09T18:39:56.035Z,1668019196.035 [multiray_test:E.Wait] Running Loop=1
2022-11-09T18:39:56.035Z,1668019196.035 [multiray_test:E.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:39:57.307Z,1668019197.307 [MultiRay](INFO): White lights on
2022-11-09T18:39:57.586Z,1668019197.586 [CommandExec](IMPORTANT): got command stop
2022-11-09T18:39:57.586Z,1668019197.586 [CommandExec](IMPORTANT): Scheduling is paused
2022-11-09T18:39:57.586Z,1668019197.586 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2022-11-09T18:39:57.667Z,1668019197.667 [MissionManager](INFO): MissionManager is completed.
2022-11-09T18:39:57.667Z,1668019197.667 [MissionManager](INFO): Uninitializing Mission multiray_test
2022-11-09T18:39:57.667Z,1668019197.667 [multiray_test] Stopped
2022-11-09T18:39:57.667Z,1668019197.667 [multiray_test](DEBUG): Aggregate::uninitialize multiray_test
2022-11-09T18:39:57.667Z,1668019197.667 [multiray_test:A] Stopped
2022-11-09T18:39:57.667Z,1668019197.667 [multiray_test:E.Wait] Stopped
2022-11-09T18:39:57.667Z,1668019197.667 [multiray_test:E.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:39:58.067Z,1668019198.067 [MissionManager](IMPORTANT): Started mission Default
2022-11-09T18:39:58.067Z,1668019198.067 [Default] Running Loop=1
2022-11-09T18:39:58.067Z,1668019198.067 [Default](DEBUG): Aggregate::initialize Default
2022-11-09T18:39:58.067Z,1668019198.067 [Default:B.GoToSurface] Running Loop=1
2022-11-09T18:39:58.067Z,1668019198.067 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-11-09T18:39:58.067Z,1668019198.067 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-11-09T18:39:58.068Z,1668019198.068 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-11-09T18:39:58.068Z,1668019198.068 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-11-09T18:39:58.068Z,1668019198.068 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-11-09T18:39:58.069Z,1668019198.069 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-11-09T18:39:58.069Z,1668019198.069 [Default:A.Wait] Running Loop=1
2022-11-09T18:39:58.069Z,1668019198.069 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-11-09T18:40:01.141Z,1668019201.141 [CommandExec](IMPORTANT): got command restart application
2022-11-09T18:40:02.144Z,1668019202.144 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:02.145Z,1668019202.145 [CommandExec](INFO): Uninitializing the command executive.
2022-11-09T18:40:02.145Z,1668019202.145 [CommandExec](INFO): Uninitializing the command scheduler.
2022-11-09T18:40:02.145Z,1668019202.145 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.228Z,1668019202.228 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2022-11-09T18:40:02.228Z,1668019202.228 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2022-11-09T18:40:02.229Z,1668019202.229 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.229Z,1668019202.229 [NavChartDb](INFO): Join timeout helper Thread ID is 5716
2022-11-09T18:40:02.628Z,1668019202.628 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:02.629Z,1668019202.629 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.645Z,1668019202.645 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2022-11-09T18:40:02.646Z,1668019202.646 [DAT ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.646Z,1668019202.646 [DAT](INFO): Join timeout helper Thread ID is 5717
2022-11-09T18:40:02.848Z,1668019202.848 [DAT](INFO): Powering down
2022-11-09T18:40:02.923Z,1668019202.923 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:02.924Z,1668019202.924 [DAT](INFO): Powering down
2022-11-09T18:40:02.925Z,1668019202.925 [DAT ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.936Z,1668019202.936 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2022-11-09T18:40:02.936Z,1668019202.936 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:02.937Z,1668019202.937 [Radio_Surface](INFO): Join timeout helper Thread ID is 5718
2022-11-09T18:40:03.176Z,1668019203.176 [Radio_Surface](INFO): Powering down
2022-11-09T18:40:03.177Z,1668019203.177 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:03.177Z,1668019203.177 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:03.180Z,1668019203.180 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2022-11-09T18:40:03.180Z,1668019203.180 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:03.181Z,1668019203.181 [Onboard](INFO): Join timeout helper Thread ID is 5719
2022-11-09T18:40:03.601Z,1668019203.601 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2022-11-09T18:40:06.984Z,1668019206.984 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:06.985Z,1668019206.985 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:06.996Z,1668019206.996 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2022-11-09T18:40:06.996Z,1668019206.996 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:06.997Z,1668019206.997 [DataOverHttps](INFO): Join timeout helper Thread ID is 5720
2022-11-09T18:40:07.616Z,1668019207.616 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:07.617Z,1668019207.617 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:07.621Z,1668019207.621 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2022-11-09T18:40:07.621Z,1668019207.621 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:07.622Z,1668019207.622 [BackseatComponent](INFO): Join timeout helper Thread ID is 5721
2022-11-09T18:40:07.789Z,1668019207.789 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:07.789Z,1668019207.789 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:07.805Z,1668019207.805 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2022-11-09T18:40:07.805Z,1668019207.805 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:07.806Z,1668019207.806 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 5722
2022-11-09T18:40:08.200Z,1668019208.200 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:08.201Z,1668019208.201 [WetLabsBB2FL](INFO): Powering down
2022-11-09T18:40:08.201Z,1668019208.201 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.205Z,1668019208.205 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2022-11-09T18:40:08.205Z,1668019208.205 [logger ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.206Z,1668019208.206 [logger](INFO): Join timeout helper Thread ID is 5723
2022-11-09T18:40:08.208Z,1668019208.208 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:08.209Z,1668019208.209 [logger ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.225Z,1668019208.225 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2022-11-09T18:40:08.225Z,1668019208.225 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.225Z,1668019208.225 [CommandLine](INFO): Join timeout helper Thread ID is 5724
2022-11-09T18:40:08.280Z,1668019208.280 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:08.281Z,1668019208.281 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.285Z,1668019208.285 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2022-11-09T18:40:08.285Z,1668019208.285 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.285Z,1668019208.285 [CommandExec](INFO): Join timeout helper Thread ID is 5725
2022-11-09T18:40:08.287Z,1668019208.287 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2022-11-09T18:40:08.287Z,1668019208.287 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.287Z,1668019208.287 [controlThread](INFO): Join timeout helper Thread ID is 5726
2022-11-09T18:40:08.520Z,1668019208.520 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2022-11-09T18:40:08.521Z,1668019208.521 [controlThread](DEBUG): Uninitializing ControlThread
2022-11-09T18:40:08.521Z,1668019208.521 [AHRS_M2](INFO): Powering down
2022-11-09T18:40:08.593Z,1668019208.593 [MultiRay](INFO): Powering down.
2022-11-09T18:40:08.594Z,1668019208.594 [NAL9602](INFO): Powering down
2022-11-09T18:40:08.596Z,1668019208.596 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2022-11-09T18:40:08.597Z,1668019208.597 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2022-11-09T18:40:08.597Z,1668019208.597 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2022-11-09T18:40:08.598Z,1668019208.598 [MissionManager](INFO): Uninitializing Mission Default
2022-11-09T18:40:08.598Z,1668019208.598 [Default] Stopped
2022-11-09T18:40:08.598Z,1668019208.598 [Default](DEBUG): Aggregate::uninitialize Default
2022-11-09T18:40:08.598Z,1668019208.598 [Default:A.Wait] Stopped
2022-11-09T18:40:08.598Z,1668019208.598 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-11-09T18:40:08.598Z,1668019208.598 [Default:B.GoToSurface] Stopped
2022-11-09T18:40:08.598Z,1668019208.598 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-11-09T18:40:08.601Z,1668019208.601 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2022-11-09T18:40:08.601Z,1668019208.601 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2022-11-09T18:40:08.602Z,1668019208.602 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2022-11-09T18:40:08.602Z,1668019208.602 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2022-11-09T18:40:08.602Z,1668019208.602 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2022-11-09T18:40:08.602Z,1668019208.602 [BuoyancyServo](INFO): Powering down
2022-11-09T18:40:08.616Z,1668019208.616 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2022-11-09T18:40:08.616Z,1668019208.616 [ElevatorServo](INFO): Powering down
2022-11-09T18:40:08.617Z,1668019208.617 [MassServo](DEBUG): Uninitialize Mass Servo.
2022-11-09T18:40:08.617Z,1668019208.617 [MassServo](INFO): Powering down
2022-11-09T18:40:08.618Z,1668019208.618 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-11-09T18:40:08.618Z,1668019208.618 [RudderServo](INFO): Powering down
2022-11-09T18:40:08.619Z,1668019208.619 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2022-11-09T18:40:08.619Z,1668019208.619 [ThrusterHE](INFO): Powering down
2022-11-09T18:40:08.620Z,1668019208.620 [SBIT](DEBUG): Uninitialize SBIT Component.
2022-11-09T18:40:08.621Z,1668019208.621 [IBIT](DEBUG): Uninitialize IBIT Component.
2022-11-09T18:40:08.621Z,1668019208.621 [CBIT](DEBUG): Uninitialize CBIT Component.
2022-11-09T18:40:08.621Z,1668019208.621 [CBIT](DEBUG): Powering off loads.
2022-11-09T18:40:08.632Z,1668019208.632 [CBIT](DEBUG): Disabling WDT.
2022-11-09T18:40:08.644Z,1668019208.644 [CBIT](DEBUG): Opening all GF detection circuits.
2022-11-09T18:40:08.645Z,1668019208.645 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.668Z,1668019208.668 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.715Z,1668019208.715 [DAT ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.719Z,1668019208.719 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.722Z,1668019208.722 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.729Z,1668019208.729 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.773Z,1668019208.773 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.820Z,1668019208.820 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-11-09T18:40:08.878Z,1668019208.878 [logger ThreadHandler](INFO): Thread cancelled.