2019-04-09T21:42:40.511Z,1554846160.511 [Supervisor](DEBUG): Initializing supervisor.
2019-04-09T21:42:40.514Z,1554846160.514 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-09T21:42:40.514Z,1554846160.514 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-04-09T21:42:40.515Z,1554846160.515 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-09T21:42:40.516Z,1554846160.516 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-09T21:42:40.516Z,1554846160.516 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-04-09T21:42:40.519Z,1554846160.519 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-09T21:42:40.531Z,1554846160.531 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-09T21:42:40.532Z,1554846160.532 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-09T21:42:40.532Z,1554846160.532 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-04-09T21:42:40.533Z,1554846160.533 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-09T21:42:40.534Z,1554846160.534 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-09T21:42:40.534Z,1554846160.534 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-04-09T21:42:40.536Z,1554846160.536 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-09T21:42:40.537Z,1554846160.537 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-09T21:42:40.541Z,1554846160.541 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-09T21:42:40.967Z,1554846160.967 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-09T21:42:40.967Z,1554846160.967 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-09T21:42:41.067Z,1554846161.067 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-09T21:42:41.069Z,1554846161.069 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-09T21:42:41.397Z,1554846161.397 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-09T21:42:41.399Z,1554846161.399 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-09T21:42:41.542Z,1554846161.542 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-09T21:42:41.544Z,1554846161.544 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-09T21:42:41.738Z,1554846161.738 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-09T21:42:41.740Z,1554846161.740 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-09T21:42:42.201Z,1554846162.201 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-09T21:42:42.203Z,1554846162.203 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-09T21:42:42.416Z,1554846162.416 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-09T21:42:42.416Z,1554846162.416 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-09T21:42:42.563Z,1554846162.563 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-09T21:42:42.565Z,1554846162.565 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-09T21:42:42.761Z,1554846162.761 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-09T21:42:42.761Z,1554846162.761 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-09T21:42:42.858Z,1554846162.858 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-09T21:42:42.859Z,1554846162.859 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-09T21:42:43.200Z,1554846163.200 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-09T21:42:43.202Z,1554846163.202 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-09T21:42:43.283Z,1554846163.283 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-09T21:42:43.387Z,1554846163.387 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-09T21:42:43.387Z,1554846163.387 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-09T21:42:43.896Z,1554846163.896 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-09T21:42:43.897Z,1554846163.897 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-09T21:42:45.017Z,1554846165.017 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-09T21:42:45.019Z,1554846165.019 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-09T21:42:45.021Z,1554846165.021 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-09T21:42:45.231Z,1554846165.231 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-09T21:42:45.333Z,1554846165.333 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-09T21:42:45.433Z,1554846165.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-09T21:42:45.665Z,1554846165.665 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-09T21:42:45.667Z,1554846165.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-09T21:42:45.753Z,1554846165.753 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-09T21:42:45.847Z,1554846165.847 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-09T21:42:45.944Z,1554846165.944 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-09T21:42:46.029Z,1554846166.029 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-09T21:42:46.141Z,1554846166.141 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-09T21:42:46.322Z,1554846166.322 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-09T21:42:46.459Z,1554846166.459 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-09T21:42:46.474Z,1554846166.474 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-09T21:42:47.222Z,1554846167.222 [AHRS_M2] Loaded
2019-04-09T21:42:47.222Z,1554846167.222 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-09T21:42:47.362Z,1554846167.362 [DataOverHttps] Loaded
2019-04-09T21:42:47.362Z,1554846167.362 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-09T21:42:47.363Z,1554846167.363 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-09T21:42:47.363Z,1554846167.363 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889
2019-04-09T21:42:47.377Z,1554846167.377 [Depth_Keller] Loaded
2019-04-09T21:42:47.377Z,1554846167.377 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-09T21:42:47.382Z,1554846167.382 [DropWeight] Loaded
2019-04-09T21:42:47.382Z,1554846167.382 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-09T21:42:47.438Z,1554846167.438 [DUSBL_Hydroid] Loaded
2019-04-09T21:42:47.438Z,1554846167.438 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-09T21:42:47.478Z,1554846167.478 [Micromodem] Loaded
2019-04-09T21:42:47.478Z,1554846167.478 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-09T21:42:47.576Z,1554846167.576 [NAL9602] Loaded
2019-04-09T21:42:47.576Z,1554846167.576 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-09T21:42:47.592Z,1554846167.592 [Onboard] Loaded
2019-04-09T21:42:47.592Z,1554846167.592 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-09T21:42:47.598Z,1554846167.598 [PowerOnly] Loaded
2019-04-09T21:42:47.598Z,1554846167.598 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-09T21:42:47.604Z,1554846167.604 [Radio_Surface] Loaded
2019-04-09T21:42:47.605Z,1554846167.605 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-09T21:42:47.606Z,1554846167.606 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-09T21:42:47.606Z,1554846167.606 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890
2019-04-09T21:42:47.650Z,1554846167.650 [RDI_Pathfinder] Loaded
2019-04-09T21:42:47.651Z,1554846167.651 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-09T21:42:49.133Z,1554846169.133 [BPC1] Loaded
2019-04-09T21:42:49.133Z,1554846169.133 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-09T21:42:49.134Z,1554846169.134 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-09T21:42:49.134Z,1554846169.134 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-09T21:42:49.205Z,1554846169.205 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-09T21:42:49.206Z,1554846169.206 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-09T21:42:49.846Z,1554846169.846 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-09T21:42:49.846Z,1554846169.846 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-09T21:42:49.866Z,1554846169.866 [NavChart] Loaded
2019-04-09T21:42:49.867Z,1554846169.867 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-09T21:42:49.871Z,1554846169.871 [UniversalFixResidualReporter] Loaded
2019-04-09T21:42:49.871Z,1554846169.871 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-09T21:42:49.872Z,1554846169.872 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-09T21:42:49.872Z,1554846169.872 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-09T21:42:49.994Z,1554846169.994 [BuoyancyServo] Loaded
2019-04-09T21:42:49.994Z,1554846169.994 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-09T21:42:50.009Z,1554846170.009 [ElevatorServo] Loaded
2019-04-09T21:42:50.010Z,1554846170.010 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-09T21:42:50.024Z,1554846170.024 [MassServo] Loaded
2019-04-09T21:42:50.025Z,1554846170.025 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-09T21:42:50.040Z,1554846170.040 [RudderServo] Loaded
2019-04-09T21:42:50.040Z,1554846170.040 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-09T21:42:50.055Z,1554846170.055 [ThrusterServo] Loaded
2019-04-09T21:42:50.055Z,1554846170.055 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-09T21:42:50.055Z,1554846170.055 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-09T21:42:50.056Z,1554846170.056 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-09T21:42:50.378Z,1554846170.378 [CTD_NeilBrown] Loaded
2019-04-09T21:42:50.378Z,1554846170.378 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-09T21:42:50.379Z,1554846170.379 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CF4E0
2019-04-09T21:42:50.380Z,1554846170.380 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 891
2019-04-09T21:42:50.424Z,1554846170.424 [WetLabsSeaOWL_UV_A] Loaded
2019-04-09T21:42:50.424Z,1554846170.424 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-09T21:42:50.425Z,1554846170.425 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FF4E0
2019-04-09T21:42:50.426Z,1554846170.426 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 892
2019-04-09T21:42:50.426Z,1554846170.426 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-09T21:42:50.427Z,1554846170.427 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-09T21:42:50.744Z,1554846170.744 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-09T21:42:50.746Z,1554846170.746 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-09T21:42:50.801Z,1554846170.801 [DepthRateCalculator] Loaded
2019-04-09T21:42:50.801Z,1554846170.801 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-09T21:42:50.807Z,1554846170.807 [PitchRateCalculator] Loaded
2019-04-09T21:42:50.807Z,1554846170.807 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-09T21:42:50.819Z,1554846170.819 [SpeedCalculator] Loaded
2019-04-09T21:42:50.820Z,1554846170.820 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-09T21:42:50.840Z,1554846170.840 [TempGradientCalculator] Loaded
2019-04-09T21:42:50.841Z,1554846170.841 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-09T21:42:50.846Z,1554846170.846 [YawRateCalculator] Loaded
2019-04-09T21:42:50.846Z,1554846170.846 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-09T21:42:50.887Z,1554846170.887 [ElevatorOffsetCalculator] Loaded
2019-04-09T21:42:50.887Z,1554846170.887 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-09T21:42:50.887Z,1554846170.887 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-09T21:42:50.889Z,1554846170.889 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-09T21:42:51.048Z,1554846171.048 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-09T21:42:51.070Z,1554846171.070 [SBIT] Loaded
2019-04-09T21:42:51.071Z,1554846171.071 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-09T21:42:51.071Z,1554846171.071 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-09T21:42:51.083Z,1554846171.083 [IBIT] Loaded
2019-04-09T21:42:51.084Z,1554846171.084 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-09T21:42:51.087Z,1554846171.087 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-09T21:42:51.226Z,1554846171.226 [CBIT] Loaded
2019-04-09T21:42:51.226Z,1554846171.226 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-09T21:42:51.226Z,1554846171.226 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-09T21:42:51.227Z,1554846171.227 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-09T21:42:51.338Z,1554846171.338 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-09T21:42:51.338Z,1554846171.338 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-09T21:42:51.465Z,1554846171.465 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-09T21:42:51.465Z,1554846171.465 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-09T21:42:51.551Z,1554846171.551 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-09T21:42:51.635Z,1554846171.635 [VerticalControl] Loaded
2019-04-09T21:42:51.635Z,1554846171.635 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-09T21:42:51.636Z,1554846171.636 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-09T21:42:51.693Z,1554846171.693 [HorizontalControl] Loaded
2019-04-09T21:42:51.693Z,1554846171.693 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-09T21:42:51.694Z,1554846171.694 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-09T21:42:51.695Z,1554846171.695 [SpeedControl] Loaded
2019-04-09T21:42:51.696Z,1554846171.696 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-09T21:42:51.696Z,1554846171.696 [LoopControl](DEBUG): Construct LoopControl.
2019-04-09T21:42:51.697Z,1554846171.697 [LoopControl] Loaded
2019-04-09T21:42:51.697Z,1554846171.697 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-09T21:42:51.698Z,1554846171.698 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-09T21:42:51.698Z,1554846171.698 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-09T21:42:51.740Z,1554846171.740 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-09T21:42:51.744Z,1554846171.744 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-09T21:42:51.744Z,1554846171.744 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-09T21:42:51.751Z,1554846171.751 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-09T21:42:51.752Z,1554846171.752 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-04-09T21:42:51.753Z,1554846171.753 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 893
2019-04-09T21:42:51.757Z,1554846171.757 [Supervisor](INFO): Main Thread ID is 802
2019-04-09T21:42:51.757Z,1554846171.757 [Supervisor](DEBUG): Running supervisor.
2019-04-09T21:42:51.758Z,1554846171.758 [CommandLine ThreadHandler](INFO): Handler Thread ID is 894
2019-04-09T21:42:51.760Z,1554846171.760 [controlThread ThreadHandler](INFO): Handler Thread ID is 895
2019-04-09T21:42:51.761Z,1554846171.761 [controlThread](DEBUG): Initializing ControlThread
2019-04-09T21:42:51.769Z,1554846171.769 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-09T21:42:51.769Z,1554846171.769 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-09T21:42:51.770Z,1554846171.770 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-09T21:42:51.770Z,1554846171.770 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-09T21:42:51.771Z,1554846171.771 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-09T21:42:51.771Z,1554846171.771 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-09T21:42:51.771Z,1554846171.771 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-09T21:42:51.772Z,1554846171.772 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-09T21:42:51.772Z,1554846171.772 [SBIT](INFO): Initialize SBIT Component.
2019-04-09T21:42:51.773Z,1554846171.773 [SBIT](IMPORTANT): git: 2019-03-18-31-ge98d5dc
2019-04-09T21:42:51.773Z,1554846171.773 [SBIT](INFO): git hash: e98d5dc50cbc39e402f19b9946ff4dc0776c8725
2019-04-09T21:42:51.773Z,1554846171.773 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-09T21:42:51.774Z,1554846171.774 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-09T21:42:51.775Z,1554846171.775 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-09T21:42:51.775Z,1554846171.775 [IBIT](INFO): Initialize IBIT Component.
2019-04-09T21:42:51.776Z,1554846171.776 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-09T21:42:51.777Z,1554846171.777 [logger ThreadHandler](INFO): Handler Thread ID is 896
2019-04-09T21:42:51.789Z,1554846171.789 [CBIT](DEBUG): Initialized mux pins.
2019-04-09T21:42:51.789Z,1554846171.789 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-09T21:42:51.797Z,1554846171.797 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 897
2019-04-09T21:42:51.798Z,1554846171.798 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-09T21:42:51.809Z,1554846171.809 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 898
2019-04-09T21:42:51.813Z,1554846171.813 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-09T21:42:51.813Z,1554846171.813 [CBIT](DEBUG): Initializing heartbeat.
2019-04-09T21:42:51.829Z,1554846171.829 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 899
2019-04-09T21:42:51.830Z,1554846171.830 [CTD_NeilBrown](INFO): Powering down
2019-04-09T21:42:51.865Z,1554846171.865 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 900
2019-04-09T21:42:51.866Z,1554846171.866 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T21:42:51.885Z,1554846171.885 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-09T21:42:51.885Z,1554846171.885 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-09T21:42:51.885Z,1554846171.885 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 901
2019-04-09T21:42:51.893Z,1554846171.893 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-09T21:42:51.894Z,1554846171.894 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-09T21:42:51.894Z,1554846171.894 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-09T21:42:51.894Z,1554846171.894 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-09T21:42:51.894Z,1554846171.894 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-09T21:42:51.894Z,1554846171.894 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-09T21:42:51.895Z,1554846171.895 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-09T21:42:51.896Z,1554846171.896 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-09T21:42:51.896Z,1554846171.896 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-09T21:42:51.896Z,1554846171.896 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-09T21:42:51.896Z,1554846171.896 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-09T21:42:51.921Z,1554846171.921 [CBIT](DEBUG): Backplane powered.
2019-04-09T21:42:51.921Z,1554846171.921 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-09T21:42:51.923Z,1554846171.923 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-09T21:42:51.923Z,1554846171.923 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-09T21:42:51.924Z,1554846171.924 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-09T21:42:51.925Z,1554846171.925 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-09T21:42:51.947Z,1554846171.947 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T21:42:51.970Z,1554846171.970 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-04-09T21:42:51.971Z,1554846171.971 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-09T21:42:52.046Z,1554846172.046 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-09T21:42:52.047Z,1554846172.047 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-09T21:42:52.065Z,1554846172.065 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T21:42:52.092Z,1554846172.092 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-09T21:42:52.099Z,1554846172.099 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-09T21:42:52.114Z,1554846172.114 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-09T21:42:52.138Z,1554846172.138 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-04-09T21:42:52.143Z,1554846172.143 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-04-09T21:42:52.156Z,1554846172.156 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-09T21:42:52.213Z,1554846172.213 [Radio_Surface](INFO): Powering up
2019-04-09T21:42:52.250Z,1554846172.250 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-09T21:42:52.250Z,1554846172.250 [DUSBL_Hydroid](INFO): Powering up
2019-04-09T21:42:52.251Z,1554846172.251 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-09T21:42:52.325Z,1554846172.325 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T21:42:52.370Z,1554846172.370 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:52.377Z,1554846172.377 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-09T21:42:52.378Z,1554846172.378 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:52.385Z,1554846172.385 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-09T21:42:52.386Z,1554846172.386 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:52.393Z,1554846172.393 [MassServo](DEBUG): Initializing MassServo.
2019-04-09T21:42:52.394Z,1554846172.394 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:52.401Z,1554846172.401 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T21:42:52.402Z,1554846172.402 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:52.409Z,1554846172.409 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-09T21:42:52.568Z,1554846172.568 [Micromodem](INFO): Powering up
2019-04-09T21:42:52.568Z,1554846172.568 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-09T21:42:52.597Z,1554846172.597 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T21:42:53.289Z,1554846173.289 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-09T21:42:53.289Z,1554846173.289 [RudderServo](FAULT): Rudder failed to initialize
2019-04-09T21:42:53.289Z,1554846173.289 [RudderServo] Communications Fault, FailCount= 1
2019-04-09T21:42:53.289Z,1554846173.289 [RudderServo](ERROR): Communications Fault
2019-04-09T21:42:53.412Z,1554846173.412 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-09T21:42:53.586Z,1554846173.586 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T21:42:53.586Z,1554846173.586 [RudderServo](INFO): Powering down
2019-04-09T21:42:54.267Z,1554846174.267 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T21:42:54.386Z,1554846174.386 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T21:42:54.390Z,1554846174.390 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-09T21:42:54.390Z,1554846174.390 [RudderServo] No Fault, FailCount= 1
2019-04-09T21:43:05.576Z,1554846185.576 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-09T21:43:08.779Z,1554846188.779 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-04-09T21:43:10.391Z,1554846190.391 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-09T21:43:17.664Z,1554846197.664 [NAL9602](INFO): Powering up NAL9602
2019-04-09T21:43:20.087Z,1554846200.087 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-04-09T21:43:22.553Z,1554846202.553 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T21:43:22.553Z,1554846202.553 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   -34,   +10,  :BE,   -34,   +10,   -11,A
2019-04-09T21:43:28.571Z,1554846208.571 [NAL9602](INFO): NAL9602 initialized
2019-04-09T21:43:29.397Z,1554846209.397 [NAL9602](DEBUG): Fix Requested
2019-04-09T21:43:36.295Z,1554846216.295 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-09T21:43:36.300Z,1554846216.300 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-09T21:43:47.326Z,1554846227.326 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.019608
CHAN A1 (24V): -0.025953
CHAN A2 (12V): -0.006693
CHAN A3 (5V): -0.002343
CHAN B0 (3.3V): 0.000091
CHAN B1 (3.15aV): 0.000152
CHAN B2 (3.15bV): 0.000127
CHAN B3 (GND): 0.002050
OPEN: 0.006631
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-09T21:44:29.604Z,1554846269.604 [SBIT](IMPORTANT): SBIT PASSED
2019-04-09T21:44:29.630Z,1554846269.630 [CommandLine](IMPORTANT): got command configSet list
2019-04-09T21:44:29.630Z,1554846269.630 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-09T21:44:29.631Z,1554846269.631 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-09T21:44:29.632Z,1554846269.632 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-09T21:44:29.632Z,1554846269.632 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-09T21:44:29.632Z,1554846269.632 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-09T21:44:29.632Z,1554846269.632 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-09T21:44:29.632Z,1554846269.632 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-09T21:44:29.956Z,1554846269.956 [MissionManager](IMPORTANT): Started mission Startup
2019-04-09T21:44:29.957Z,1554846269.957 [Startup] Running Loop=1
2019-04-09T21:44:29.957Z,1554846269.957 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-09T21:44:29.957Z,1554846269.957 [Startup:A.GoToSurface] Running Loop=1
2019-04-09T21:44:29.957Z,1554846269.957 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T21:44:29.958Z,1554846269.958 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T21:44:29.958Z,1554846269.958 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T21:44:29.958Z,1554846269.958 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T21:44:29.959Z,1554846269.959 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T21:44:29.959Z,1554846269.959 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T21:44:29.961Z,1554846269.961 [Startup:StartupSatComms] Running Loop=1
2019-04-09T21:44:29.961Z,1554846269.961 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-09T21:44:29.961Z,1554846269.961 [Startup:StartupSatComms:A] Running Loop=1
2019-04-09T21:44:30.366Z,1554846270.366 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-09T21:45:18.479Z,1554846318.479 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-04-09T21:45:23.291Z,1554846323.291 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:45:30.173Z,1554846330.173 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-09T21:44:29.0Z
2019-04-09T21:45:30.173Z,1554846330.173 [Startup:StartupSatComms:A] Stopped
2019-04-09T21:45:30.173Z,1554846330.173 [Startup:StartupSatComms:B] Running Loop=1
2019-04-09T21:45:30.596Z,1554846330.596 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T21:45:32.982Z,1554846332.982 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:45:38.959Z,1554846338.959 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005007
2019-04-09T21:45:42.681Z,1554846342.681 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:45:44.618Z,1554846344.618 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T193152/Courier0076.lzma
2019-04-09T21:45:45.423Z,1554846345.423 [DataOverHttps](INFO): Moved sent file to Logs/20190409T193152/Courier0076.lzma.bak
2019-04-09T21:45:45.423Z,1554846345.423 [DataOverHttps](INFO): SBD MOMSN=10519499
2019-04-09T21:45:52.021Z,1554846352.021 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-04-09T21:45:52.021Z,1554846352.021 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-04-09T21:45:52.031Z,1554846352.031 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-04-09T21:45:52.367Z,1554846352.367 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:45:52.394Z,1554846352.394 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-04-09T21:45:52.394Z,1554846352.394 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-04-09T21:45:56.622Z,1554846356.622 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20190409T193152/Express0077.lzma
2019-04-09T21:45:57.426Z,1554846357.426 [DataOverHttps](INFO): Moved sent file to Logs/20190409T193152/Express0077.lzma.bak
2019-04-09T21:45:57.427Z,1554846357.427 [DataOverHttps](INFO): SBD MOMSN=10519501
2019-04-09T21:46:02.066Z,1554846362.066 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:46:08.675Z,1554846368.675 [DataOverHttps](INFO): Sending 1396 bytes from file Logs/20190409T214240/Express0001.lzma
2019-04-09T21:46:09.478Z,1554846369.478 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0001.lzma.bak
2019-04-09T21:46:09.478Z,1554846369.478 [DataOverHttps](INFO): SBD MOMSN=10519504
2019-04-09T21:46:10.174Z,1554846370.174 [Startup:StartupSatComms:B] Stopped
2019-04-09T21:46:10.174Z,1554846370.174 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-09T21:46:10.174Z,1554846370.174 [Startup:StartupSatComms] Stopped
2019-04-09T21:46:10.174Z,1554846370.174 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-09T21:46:10.175Z,1554846370.175 [Startup](INFO): Completed Startup
2019-04-09T21:46:10.175Z,1554846370.175 [MissionManager](INFO): Startup is completed.
2019-04-09T21:46:10.175Z,1554846370.175 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-09T21:46:10.175Z,1554846370.175 [Startup] Stopped
2019-04-09T21:46:10.176Z,1554846370.176 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-09T21:46:10.176Z,1554846370.176 [Startup:A.GoToSurface] Stopped
2019-04-09T21:46:10.176Z,1554846370.176 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T21:46:10.599Z,1554846370.599 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T21:46:10.599Z,1554846370.599 [Default] Running Loop=1
2019-04-09T21:46:10.600Z,1554846370.600 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T21:46:10.600Z,1554846370.600 [Default:B.GoToSurface] Running Loop=1
2019-04-09T21:46:10.600Z,1554846370.600 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T21:46:10.600Z,1554846370.600 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T21:46:10.600Z,1554846370.600 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T21:46:10.601Z,1554846370.601 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T21:46:10.601Z,1554846370.601 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T21:46:10.602Z,1554846370.602 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T21:46:10.602Z,1554846370.602 [Default:A.Wait] Running Loop=1
2019-04-09T21:46:10.602Z,1554846370.602 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:46:12.166Z,1554846372.166 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:46:12.169Z,1554846372.169 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-04-09T21:46:22.281Z,1554846382.281 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:46:23.904Z,1554846383.904 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T21:46:23.904Z,1554846383.904 [Default:A.Wait] Stopped
2019-04-09T21:46:23.904Z,1554846383.904 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:46:24.323Z,1554846384.323 [Default:CheckIn] Running Loop=1
2019-04-09T21:46:24.323Z,1554846384.323 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T21:46:24.323Z,1554846384.323 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T21:46:24.754Z,1554846384.754 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-09T21:46:31.961Z,1554846391.961 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:46:42.058Z,1554846402.058 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:46:52.176Z,1554846412.176 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:47:02.263Z,1554846422.263 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:47:11.973Z,1554846431.973 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:47:21.683Z,1554846441.683 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:47:31.764Z,1554846451.764 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:47:41.873Z,1554846461.873 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:48:38.800Z,1554846518.800 [NAL9602](INFO): SBD MO Status=2, MOMSN=3151, MT Status=2, MTMSN=0
2019-04-09T21:48:38.800Z,1554846518.800 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T21:48:39.207Z,1554846519.207 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T21:48:40.025Z,1554846520.025 [NAL9602](DEBUG): Fix Requested
2019-04-09T21:48:40.422Z,1554846520.422 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214746.00,A,3648.16906,N,12147.28610,W,0.525,161.95,090419,,,A*7E
2019-04-09T21:48:40.425Z,1554846520.425 [NAL9602](INFO): GPS fix at 20190409T214746: (36.802818, -121.788102)
2019-04-09T21:48:40.458Z,1554846520.458 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T21:48:40.458Z,1554846520.458 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T21:48:40.891Z,1554846520.891 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T21:48:49.148Z,1554846529.148 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190409T214240/Courier0004.lzma
2019-04-09T21:48:49.954Z,1554846529.954 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0004.lzma.bak
2019-04-09T21:48:49.954Z,1554846529.954 [DataOverHttps](INFO): SBD MOMSN=10519530
2019-04-09T21:49:09.973Z,1554846549.973 [DataOverHttps](INFO): Sending 804 bytes from file Logs/20190409T214240/Express0005.lzma
2019-04-09T21:49:10.778Z,1554846550.778 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0005.lzma.bak
2019-04-09T21:49:10.778Z,1554846550.778 [DataOverHttps](INFO): SBD MOMSN=10519535
2019-04-09T21:49:11.668Z,1554846551.668 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T21:49:11.668Z,1554846551.668 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T21:49:11.668Z,1554846551.668 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:49:12.443Z,1554846552.443 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T21:50:08.688Z,1554846608.688 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-04-09T21:50:13.466Z,1554846613.466 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:50:23.581Z,1554846623.581 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:50:33.258Z,1554846633.258 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:50:42.954Z,1554846642.954 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:50:52.659Z,1554846652.659 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:02.761Z,1554846662.761 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:12.862Z,1554846672.862 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:14.574Z,1554846674.574 [CommandLine](IMPORTANT): got command show stack
2019-04-09T21:51:14.575Z,1554846674.575 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-09T21:51:14.575Z,1554846674.575 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-09T21:51:14.575Z,1554846674.575 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-04-09T21:51:17.165Z,1554846677.165 [CommandLine](IMPORTANT): got command show variable range
2019-04-09T21:51:17.168Z,1554846677.168 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-09T21:51:17.406Z,1554846677.406 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T21:51:17.407Z,1554846677.407 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-09T21:51:17.408Z,1554846677.408 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-09T21:51:17.415Z,1554846677.415 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-09T21:51:17.415Z,1554846677.415 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-09T21:51:17.416Z,1554846677.416 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-09T21:51:17.416Z,1554846677.416 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-09T21:51:22.651Z,1554846682.651 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:24.217Z,1554846684.217 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-09T21:51:30.431Z,1554846690.431 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T21:51:30.518Z,1554846690.518 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T21:51:30.518Z,1554846690.518 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T21:51:30.519Z,1554846690.519 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T21:51:30.519Z,1554846690.519 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T21:51:30.520Z,1554846690.520 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T21:51:30.520Z,1554846690.520 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T21:51:30.521Z,1554846690.521 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T21:51:30.521Z,1554846690.521 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T21:51:30.521Z,1554846690.521 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T21:51:30.522Z,1554846690.522 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T21:51:30.522Z,1554846690.522 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T21:51:30.523Z,1554846690.523 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T21:51:30.535Z,1554846690.535 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T21:51:30.536Z,1554846690.536 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T21:51:30.536Z,1554846690.536 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T21:51:30.541Z,1554846690.541 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T21:51:30.541Z,1554846690.541 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T21:51:30.541Z,1554846690.541 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T21:51:30.542Z,1554846690.542 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T21:51:30.542Z,1554846690.542 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T21:51:30.543Z,1554846690.543 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T21:51:30.543Z,1554846690.543 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T21:51:30.543Z,1554846690.543 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T21:51:30.544Z,1554846690.544 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T21:51:30.544Z,1554846690.544 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T21:51:30.545Z,1554846690.545 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T21:51:32.242Z,1554846692.242 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:37.524Z,1554846697.524 [RDI_Pathfinder](ERROR): DVL BIT error. See manual. Result code: 68
2019-04-09T21:51:37.525Z,1554846697.525 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32768,V
2019-04-09T21:51:38.359Z,1554846698.359 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-04-09T21:51:42.339Z,1554846702.339 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:51:52.034Z,1554846712.034 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:52:02.143Z,1554846722.143 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:52:11.837Z,1554846731.837 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:52:21.541Z,1554846741.541 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:52:31.243Z,1554846751.243 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:52:55.018Z,1554846775.018 [DataOverHttps](IMPORTANT): SBD MTMSN=20190409T215201
2019-04-09T21:53:00.516Z,1554846780.516 [DataOverHttps](INFO): Received command:run Maintenance/DUSBL.xml
2019-04-09T21:53:00.562Z,1554846780.562 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:53:00.563Z,1554846780.563 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:53:00.617Z,1554846780.617 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T21:53:00.621Z,1554846780.621 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T21:53:00.625Z,1554846780.625 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T21:53:00.628Z,1554846780.628 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T21:53:00.632Z,1554846780.632 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T21:53:00.634Z,1554846780.634 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T21:53:00.640Z,1554846780.640 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T21:53:00.649Z,1554846780.649 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T21:53:00.653Z,1554846780.653 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-09T21:53:00.655Z,1554846780.655 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:53:00.929Z,1554846780.929 [Default] Stopped
2019-04-09T21:53:00.930Z,1554846780.930 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T21:53:00.930Z,1554846780.930 [Default:B.GoToSurface] Stopped
2019-04-09T21:53:00.930Z,1554846780.930 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T21:53:00.930Z,1554846780.930 [Default:CheckIn] Stopped
2019-04-09T21:53:00.930Z,1554846780.930 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T21:53:00.930Z,1554846780.930 [Default:CheckIn:C.Wait] Stopped
2019-04-09T21:53:00.930Z,1554846780.930 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:53:00.930Z,1554846780.930 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL] Running Loop=1
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T21:53:00.931Z,1554846780.931 [DUSBL:C] Running Loop=1
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:53:00.932Z,1554846780.932 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:53:00.935Z,1554846780.935 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:53:00.935Z,1554846780.935 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:53:00.935Z,1554846780.935 [DUSBL:C] Stopped
2019-04-09T21:53:00.936Z,1554846780.936 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T21:53:00.936Z,1554846780.936 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T21:53:11.256Z,1554846791.256 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:53:11.256Z,1554846791.256 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:53:11.256Z,1554846791.256 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:53:11.257Z,1554846791.257 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:53:11.257Z,1554846791.257 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:53:11.257Z,1554846791.257 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:53:11.257Z,1554846791.257 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:53:11.257Z,1554846791.257 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:53:11.258Z,1554846791.258 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:53:21.751Z,1554846801.751 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:53:21.751Z,1554846801.751 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:53:21.751Z,1554846801.751 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:53:21.752Z,1554846801.752 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T21:53:21.753Z,1554846801.753 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T21:53:21.753Z,1554846801.753 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:53:21.753Z,1554846801.753 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:53:21.753Z,1554846801.753 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:53:21.754Z,1554846801.754 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:53:21.754Z,1554846801.754 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:53:23.945Z,1554846803.945 [CommandLine](IMPORTANT): got command stop
2019-04-09T21:53:23.946Z,1554846803.946 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-09T21:53:23.946Z,1554846803.946 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T21:53:24.172Z,1554846804.172 [MissionManager](INFO): MissionManager is completed.
2019-04-09T21:53:24.172Z,1554846804.172 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T21:53:24.172Z,1554846804.172 [DUSBL] Stopped
2019-04-09T21:53:24.172Z,1554846804.172 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T21:53:24.172Z,1554846804.172 [DUSBL:A.Pitch] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:B.SetSpeed] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:53:24.173Z,1554846804.173 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:53:24.584Z,1554846804.584 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T21:53:24.584Z,1554846804.584 [Default] Running Loop=1
2019-04-09T21:53:24.584Z,1554846804.584 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T21:53:24.585Z,1554846804.585 [Default:B.GoToSurface] Running Loop=1
2019-04-09T21:53:24.585Z,1554846804.585 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T21:53:24.585Z,1554846804.585 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T21:53:24.585Z,1554846804.585 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T21:53:24.586Z,1554846804.586 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T21:53:24.586Z,1554846804.586 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T21:53:24.586Z,1554846804.586 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T21:53:24.586Z,1554846804.586 [Default:A.Wait] Running Loop=1
2019-04-09T21:53:24.587Z,1554846804.587 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:53:37.921Z,1554846817.921 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T21:53:37.921Z,1554846817.921 [Default:A.Wait] Stopped
2019-04-09T21:53:37.921Z,1554846817.921 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:53:38.302Z,1554846818.302 [Default:CheckIn] Running Loop=1
2019-04-09T21:53:38.302Z,1554846818.302 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T21:53:38.302Z,1554846818.302 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T21:53:39.905Z,1554846819.905 [NAL9602](DEBUG): Fix Requested
2019-04-09T21:53:40.290Z,1554846820.290 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215246.00,A,3648.15516,N,12147.27542,W,0.136,143.43,090419,,,A*72
2019-04-09T21:53:40.292Z,1554846820.292 [NAL9602](INFO): GPS fix at 20190409T215246: (36.802586, -121.787924)
2019-04-09T21:53:40.316Z,1554846820.316 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T21:53:40.316Z,1554846820.316 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T21:53:46.956Z,1554846826.956 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190409T214240/Courier0007.lzma
2019-04-09T21:53:47.762Z,1554846827.762 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0007.lzma.bak
2019-04-09T21:53:47.762Z,1554846827.762 [DataOverHttps](INFO): SBD MOMSN=10519635
2019-04-09T21:53:59.864Z,1554846839.864 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190409T214240/Courier0010.lzma
2019-04-09T21:54:00.670Z,1554846840.670 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0010.lzma.bak
2019-04-09T21:54:00.670Z,1554846840.670 [DataOverHttps](INFO): SBD MOMSN=10519638
2019-04-09T21:54:00.915Z,1554846840.915 [RDI_Pathfinder](ERROR): Failed to parse:
:8,-32768,-32768,V
2019-04-09T21:54:12.887Z,1554846852.887 [DataOverHttps](INFO): Sending 1620 bytes from file Logs/20190409T214240/Express0008.lzma
2019-04-09T21:54:13.690Z,1554846853.690 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0008.lzma.bak
2019-04-09T21:54:13.690Z,1554846853.690 [DataOverHttps](INFO): SBD MOMSN=10519640
2019-04-09T21:54:26.084Z,1554846866.084 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190409T214240/Express0012.lzma
2019-04-09T21:54:26.890Z,1554846866.890 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0012.lzma.bak
2019-04-09T21:54:26.890Z,1554846866.890 [DataOverHttps](INFO): SBD MOMSN=10519691
2019-04-09T21:54:27.620Z,1554846867.620 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T21:54:27.620Z,1554846867.620 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T21:54:27.620Z,1554846867.620 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:55:06.773Z,1554846906.773 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:55:16.462Z,1554846916.462 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:55:26.172Z,1554846926.172 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:55:36.272Z,1554846936.272 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:55:45.968Z,1554846945.968 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:55:55.658Z,1554846955.658 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:05.764Z,1554846965.764 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:15.442Z,1554846975.442 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:21.378Z,1554846981.378 [DataOverHttps](IMPORTANT): SBD MTMSN=20190409T215527
2019-04-09T21:56:25.581Z,1554846985.581 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:28.444Z,1554846988.444 [DataOverHttps](INFO): Received command:run Maintenance/DUSBL.xml
2019-04-09T21:56:28.463Z,1554846988.463 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:56:28.463Z,1554846988.463 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:56:28.552Z,1554846988.552 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T21:56:28.554Z,1554846988.554 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T21:56:28.556Z,1554846988.556 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T21:56:28.559Z,1554846988.559 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T21:56:28.561Z,1554846988.561 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T21:56:28.562Z,1554846988.562 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T21:56:28.568Z,1554846988.568 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T21:56:28.576Z,1554846988.576 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T21:56:28.581Z,1554846988.581 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-09T21:56:28.583Z,1554846988.583 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T21:56:28.814Z,1554846988.814 [Default] Stopped
2019-04-09T21:56:28.815Z,1554846988.815 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T21:56:28.815Z,1554846988.815 [Default:B.GoToSurface] Stopped
2019-04-09T21:56:28.815Z,1554846988.815 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T21:56:28.815Z,1554846988.815 [Default:CheckIn] Stopped
2019-04-09T21:56:28.815Z,1554846988.815 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T21:56:28.815Z,1554846988.815 [Default:CheckIn:C.Wait] Stopped
2019-04-09T21:56:28.815Z,1554846988.815 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:56:28.815Z,1554846988.815 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL] Running Loop=1
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T21:56:28.816Z,1554846988.816 [DUSBL:C] Running Loop=1
2019-04-09T21:56:28.817Z,1554846988.817 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T21:56:28.817Z,1554846988.817 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:56:28.817Z,1554846988.817 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:56:28.817Z,1554846988.817 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:56:28.818Z,1554846988.818 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:56:28.818Z,1554846988.818 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:56:28.818Z,1554846988.818 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:56:28.818Z,1554846988.818 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:56:28.819Z,1554846988.819 [DUSBL:C] Stopped
2019-04-09T21:56:28.819Z,1554846988.819 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T21:56:28.819Z,1554846988.819 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T21:56:35.258Z,1554846995.258 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:38.925Z,1554846998.925 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:56:38.926Z,1554846998.926 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:56:38.926Z,1554846998.926 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:56:38.926Z,1554846998.926 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:56:38.926Z,1554846998.926 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:56:38.926Z,1554846998.926 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:56:38.927Z,1554846998.927 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:56:44.955Z,1554847004.955 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:49.432Z,1554847009.432 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:56:49.432Z,1554847009.432 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:56:49.432Z,1554847009.432 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T21:56:49.433Z,1554847009.433 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T21:56:49.434Z,1554847009.434 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:56:49.434Z,1554847009.434 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:56:49.434Z,1554847009.434 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:56:49.434Z,1554847009.434 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:56:49.434Z,1554847009.434 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:56:54.659Z,1554847014.659 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:56:59.940Z,1554847019.940 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:56:59.940Z,1554847019.940 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:56:59.940Z,1554847019.940 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:56:59.945Z,1554847019.945 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:56:59.945Z,1554847019.945 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:56:59.945Z,1554847019.945 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:56:59.945Z,1554847019.945 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:56:59.945Z,1554847019.945 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater] Running Loop=4
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:56:59.946Z,1554847019.946 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:57:04.362Z,1554847024.362 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:57:10.414Z,1554847030.414 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:57:10.414Z,1554847030.414 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:57:10.414Z,1554847030.414 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:57:10.415Z,1554847030.415 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:57:10.415Z,1554847030.415 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:57:10.415Z,1554847030.415 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:57:10.415Z,1554847030.415 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:57:10.415Z,1554847030.415 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater] Running Loop=5
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:57:10.416Z,1554847030.416 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:57:14.443Z,1554847034.443 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:57:20.950Z,1554847040.950 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:57:20.951Z,1554847040.951 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:57:20.951Z,1554847040.951 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:57:20.951Z,1554847040.951 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:57:20.951Z,1554847040.951 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater] Running Loop=6
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:57:20.952Z,1554847040.952 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:57:24.542Z,1554847044.542 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T21:57:31.422Z,1554847051.422 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:57:31.422Z,1554847051.422 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:57:31.422Z,1554847051.422 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-09T21:57:31.423Z,1554847051.423 [DUSBL:RequestRepeater] Running Loop=7
2019-04-09T21:57:31.424Z,1554847051.424 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:57:31.424Z,1554847051.424 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:57:31.424Z,1554847051.424 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:57:31.424Z,1554847051.424 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:57:31.424Z,1554847051.424 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:57:40.688Z,1554847060.688 [NAL9602](INFO): SBD MO Status=2, MOMSN=3151, MT Status=2, MTMSN=0
2019-04-09T21:57:40.689Z,1554847060.689 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T21:57:41.953Z,1554847061.953 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:57:41.953Z,1554847061.953 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:57:41.954Z,1554847061.954 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:57:41.954Z,1554847061.954 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater] Running Loop=8
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:57:41.955Z,1554847061.955 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:57:52.440Z,1554847072.440 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:57:52.440Z,1554847072.440 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:57:52.440Z,1554847072.440 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:57:52.441Z,1554847072.441 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:57:52.441Z,1554847072.441 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater] Running Loop=9
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:57:52.442Z,1554847072.442 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:58:02.948Z,1554847082.948 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:58:02.948Z,1554847082.948 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:58:02.948Z,1554847082.948 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:58:02.949Z,1554847082.949 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater] Running Loop=10
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T21:58:02.950Z,1554847082.950 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:58:13.416Z,1554847093.416 [NAL9602](INFO): SBD MO Status=2, MOMSN=3151, MT Status=2, MTMSN=0
2019-04-09T21:58:13.417Z,1554847093.417 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T21:58:13.478Z,1554847093.478 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T21:58:13.478Z,1554847093.478 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T21:58:13.478Z,1554847093.478 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:58:13.478Z,1554847093.478 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T21:58:13.479Z,1554847093.479 [DUSBL:RequestRepeater] Stopped
2019-04-09T21:58:13.479Z,1554847093.479 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T21:58:13.479Z,1554847093.479 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T21:58:13.479Z,1554847093.479 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T21:58:13.479Z,1554847093.479 [DUSBL](INFO): Completed DUSBL
2019-04-09T21:58:13.480Z,1554847093.480 [MissionManager](INFO): DUSBL is completed.
2019-04-09T21:58:13.480Z,1554847093.480 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T21:58:13.480Z,1554847093.480 [DUSBL] Stopped
2019-04-09T21:58:13.480Z,1554847093.480 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T21:58:13.480Z,1554847093.480 [DUSBL:A.Pitch] Stopped
2019-04-09T21:58:13.480Z,1554847093.480 [DUSBL:B.SetSpeed] Stopped
2019-04-09T21:58:13.480Z,1554847093.480 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T21:58:13.876Z,1554847093.876 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T21:58:13.876Z,1554847093.876 [Default] Running Loop=1
2019-04-09T21:58:13.876Z,1554847093.876 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T21:58:13.877Z,1554847093.877 [Default:B.GoToSurface] Running Loop=1
2019-04-09T21:58:13.877Z,1554847093.877 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T21:58:13.877Z,1554847093.877 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T21:58:13.877Z,1554847093.877 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T21:58:13.878Z,1554847093.878 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T21:58:13.878Z,1554847093.878 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T21:58:13.878Z,1554847093.878 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T21:58:13.879Z,1554847093.879 [Default:A.Wait] Running Loop=1
2019-04-09T21:58:13.879Z,1554847093.879 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:58:27.174Z,1554847107.174 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T21:58:27.174Z,1554847107.174 [Default:A.Wait] Stopped
2019-04-09T21:58:27.174Z,1554847107.174 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T21:58:27.589Z,1554847107.589 [Default:CheckIn] Running Loop=1
2019-04-09T21:58:27.590Z,1554847107.590 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T21:58:27.590Z,1554847107.590 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T21:58:34.824Z,1554847114.824 [NAL9602](INFO): SBD MO Status=0, MOMSN=3151, MT Status=0, MTMSN=0
2019-04-09T21:58:34.825Z,1554847114.825 [NAL9602](INFO): No messages in MT queue
2019-04-09T21:58:35.645Z,1554847115.645 [NAL9602](DEBUG): Fix Requested
2019-04-09T21:58:36.051Z,1554847116.051 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215742.00,A,3648.16219,N,12147.28181,W,0.253,143.43,090419,,,A*7C
2019-04-09T21:58:36.053Z,1554847116.053 [NAL9602](INFO): GPS fix at 20190409T215742: (36.802703, -121.788030)
2019-04-09T21:58:36.135Z,1554847116.135 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T21:58:36.136Z,1554847116.136 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T21:58:42.728Z,1554847122.728 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T214240/Courier0011.lzma
2019-04-09T21:58:43.535Z,1554847123.535 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0011.lzma.bak
2019-04-09T21:58:43.535Z,1554847123.535 [DataOverHttps](INFO): SBD MOMSN=10519754
2019-04-09T21:58:55.704Z,1554847135.704 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T214240/Courier0016.lzma
2019-04-09T21:58:56.514Z,1554847136.514 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0016.lzma.bak
2019-04-09T21:58:56.514Z,1554847136.514 [DataOverHttps](INFO): SBD MOMSN=10519756
2019-04-09T21:59:08.656Z,1554847148.656 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T214240/Express0013.lzma
2019-04-09T21:59:08.759Z,1554847148.759 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T21:59:09.462Z,1554847149.462 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0013.lzma.bak
2019-04-09T21:59:09.462Z,1554847149.462 [DataOverHttps](INFO): SBD MOMSN=10519758
2019-04-09T21:59:21.240Z,1554847161.240 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20190409T214240/Express0017.lzma
2019-04-09T21:59:22.046Z,1554847162.046 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0017.lzma.bak
2019-04-09T21:59:22.046Z,1554847162.046 [DataOverHttps](INFO): SBD MOMSN=10519760
2019-04-09T21:59:22.940Z,1554847162.940 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T21:59:22.940Z,1554847162.940 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T21:59:22.940Z,1554847162.940 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T21:59:56.060Z,1554847196.060 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:05.780Z,1554847205.780 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:06.041Z,1554847206.041 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:00:06.042Z,1554847206.042 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:00:06.106Z,1554847206.106 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T22:00:06.108Z,1554847206.108 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T22:00:06.114Z,1554847206.114 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T22:00:06.121Z,1554847206.121 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T22:00:06.123Z,1554847206.123 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T22:00:06.124Z,1554847206.124 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T22:00:06.219Z,1554847206.219 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T22:00:06.248Z,1554847206.248 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T22:00:06.264Z,1554847206.264 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-09T22:00:06.278Z,1554847206.278 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:00:06.624Z,1554847206.624 [Default] Stopped
2019-04-09T22:00:06.624Z,1554847206.624 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T22:00:06.624Z,1554847206.624 [Default:B.GoToSurface] Stopped
2019-04-09T22:00:06.624Z,1554847206.624 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T22:00:06.624Z,1554847206.624 [Default:CheckIn] Stopped
2019-04-09T22:00:06.624Z,1554847206.624 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T22:00:06.624Z,1554847206.624 [Default:CheckIn:C.Wait] Stopped
2019-04-09T22:00:06.624Z,1554847206.624 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:06.633Z,1554847206.633 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL] Running Loop=1
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:00:06.633Z,1554847206.633 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:C] Running Loop=1
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:06.634Z,1554847206.634 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:00:06.635Z,1554847206.635 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:06.635Z,1554847206.635 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:06.635Z,1554847206.635 [DUSBL:C] Stopped
2019-04-09T22:00:06.635Z,1554847206.635 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:00:06.636Z,1554847206.636 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:00:15.874Z,1554847215.874 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:16.716Z,1554847216.716 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:00:16.716Z,1554847216.716 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:00:16.716Z,1554847216.716 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:16.717Z,1554847216.717 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:00:16.717Z,1554847216.717 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T22:00:16.718Z,1554847216.718 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:16.719Z,1554847216.718 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:16.719Z,1554847216.719 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:16.719Z,1554847216.719 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:16.719Z,1554847216.719 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:00:25.967Z,1554847225.967 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:27.200Z,1554847227.200 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:00:27.200Z,1554847227.200 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:00:27.200Z,1554847227.200 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:27.201Z,1554847227.201 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:00:27.201Z,1554847227.201 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:00:27.201Z,1554847227.201 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:00:27.201Z,1554847227.201 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:00:27.201Z,1554847227.201 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:27.202Z,1554847227.202 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:00:35.667Z,1554847235.667 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:37.703Z,1554847237.703 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:00:37.703Z,1554847237.703 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:00:37.703Z,1554847237.703 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:00:37.704Z,1554847237.704 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater] Running Loop=4
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:37.705Z,1554847237.705 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:00:45.793Z,1554847245.793 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:48.188Z,1554847248.188 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:00:48.188Z,1554847248.188 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:00:48.188Z,1554847248.188 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:00:48.189Z,1554847248.189 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater] Running Loop=5
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:48.190Z,1554847248.190 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:00:55.897Z,1554847255.897 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:00:58.708Z,1554847258.708 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:00:58.708Z,1554847258.708 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:00:58.708Z,1554847258.708 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:00:58.708Z,1554847258.708 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater] Running Loop=6
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:00:58.709Z,1554847258.709 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:00:58.710Z,1554847258.710 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:00:58.710Z,1554847258.710 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:05.546Z,1554847265.546 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:09.224Z,1554847269.224 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:01:09.224Z,1554847269.224 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:01:09.224Z,1554847269.224 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:01:09.224Z,1554847269.224 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater] Running Loop=7
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:01:09.229Z,1554847269.229 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:01:09.230Z,1554847269.230 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:15.255Z,1554847275.255 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:19.741Z,1554847279.741 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:01:19.741Z,1554847279.741 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:01:19.741Z,1554847279.741 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:01:19.744Z,1554847279.744 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater] Running Loop=8
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:01:19.753Z,1554847279.753 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:01:19.754Z,1554847279.754 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:01:19.754Z,1554847279.754 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:25.342Z,1554847285.342 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:30.204Z,1554847290.204 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:01:30.204Z,1554847290.204 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:01:30.204Z,1554847290.204 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-04-09T22:01:30.205Z,1554847290.205 [DUSBL:RequestRepeater] Running Loop=9
2019-04-09T22:01:30.206Z,1554847290.206 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:01:30.206Z,1554847290.206 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:01:30.206Z,1554847290.206 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:01:30.206Z,1554847290.206 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:01:30.206Z,1554847290.206 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:35.442Z,1554847295.442 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:40.720Z,1554847300.720 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:01:40.720Z,1554847300.720 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:01:40.720Z,1554847300.720 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:01:40.721Z,1554847300.721 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:01:40.721Z,1554847300.721 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater] Running Loop=10
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:01:40.722Z,1554847300.722 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:45.138Z,1554847305.138 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:51.216Z,1554847311.216 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:01:51.216Z,1554847311.216 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:01:51.216Z,1554847311.216 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:01:51.221Z,1554847311.221 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:01:51.221Z,1554847311.221 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:01:51.221Z,1554847311.221 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:01:51.221Z,1554847311.221 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:01:51.221Z,1554847311.221 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL](INFO): Completed DUSBL
2019-04-09T22:01:51.222Z,1554847311.222 [MissionManager](INFO): DUSBL is completed.
2019-04-09T22:01:51.222Z,1554847311.222 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL] Stopped
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL:A.Pitch] Stopped
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL:B.SetSpeed] Stopped
2019-04-09T22:01:51.222Z,1554847311.222 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T22:01:51.472Z,1554847311.472 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T22:01:51.640Z,1554847311.640 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T22:01:51.640Z,1554847311.640 [Default] Running Loop=1
2019-04-09T22:01:51.649Z,1554847311.649 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T22:01:51.649Z,1554847311.649 [Default:B.GoToSurface] Running Loop=1
2019-04-09T22:01:51.649Z,1554847311.649 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T22:01:51.649Z,1554847311.649 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T22:01:51.649Z,1554847311.649 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T22:01:51.650Z,1554847311.650 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T22:01:51.650Z,1554847311.650 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T22:01:51.650Z,1554847311.650 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T22:01:51.651Z,1554847311.651 [Default:A.Wait] Running Loop=1
2019-04-09T22:01:51.651Z,1554847311.651 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:01:51.681Z,1554847311.681 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T22:01:51.681Z,1554847311.681 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T22:01:51.682Z,1554847311.682 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T22:01:51.682Z,1554847311.682 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T22:01:51.683Z,1554847311.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T22:01:51.683Z,1554847311.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T22:01:51.683Z,1554847311.683 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T22:01:51.684Z,1554847311.684 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T22:01:51.684Z,1554847311.684 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T22:01:51.689Z,1554847311.689 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T22:01:51.689Z,1554847311.689 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T22:01:51.689Z,1554847311.689 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T22:01:51.731Z,1554847311.731 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T22:01:51.731Z,1554847311.731 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T22:01:51.732Z,1554847311.732 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T22:01:51.753Z,1554847311.753 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T22:01:51.754Z,1554847311.754 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T22:01:51.754Z,1554847311.754 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T22:01:51.754Z,1554847311.754 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T22:01:51.755Z,1554847311.755 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T22:01:51.755Z,1554847311.755 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T22:01:51.755Z,1554847311.755 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T22:01:51.756Z,1554847311.756 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T22:01:51.756Z,1554847311.756 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T22:01:51.765Z,1554847311.765 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T22:01:51.765Z,1554847311.765 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T22:01:54.844Z,1554847314.844 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:01:55.590Z,1554847315.590 [CommandLine](IMPORTANT): got command report
2019-04-09T22:01:55.591Z,1554847315.591 [Reporter](INFO): acoustic_contact_range reporting when touched
2019-04-09T22:01:55.591Z,1554847315.591 [Reporter](INFO): DUSBL_Hydroid.xAngle reporting when touched
2019-04-09T22:02:04.944Z,1554847324.944 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:02:04.989Z,1554847324.989 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T22:02:04.989Z,1554847324.989 [Default:A.Wait] Stopped
2019-04-09T22:02:04.989Z,1554847324.989 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:02:05.373Z,1554847325.373 [Default:CheckIn] Running Loop=1
2019-04-09T22:02:05.373Z,1554847325.373 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T22:02:05.373Z,1554847325.373 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T22:02:06.957Z,1554847326.957 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:02:07.349Z,1554847327.349 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220113.00,A,3648.16490,N,12147.28086,W,0.019,143.43,090419,,,A*75
2019-04-09T22:02:07.351Z,1554847327.351 [NAL9602](INFO): GPS fix at 20190409T220113: (36.802748, -121.788014)
2019-04-09T22:02:07.390Z,1554847327.390 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T22:02:07.390Z,1554847327.390 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T22:02:12.846Z,1554847332.846 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190409T214240/Courier0019.lzma
2019-04-09T22:02:13.650Z,1554847333.650 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Courier0019.lzma.bak
2019-04-09T22:02:13.651Z,1554847333.651 [DataOverHttps](INFO): SBD MOMSN=10519779
2019-04-09T22:02:15.095Z,1554847335.095 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:02:25.918Z,1554847345.918 [DataOverHttps](INFO): Sending 1095 bytes from file Logs/20190409T214240/Express0020.lzma
2019-04-09T22:02:26.722Z,1554847346.722 [DataOverHttps](INFO): Moved sent file to Logs/20190409T214240/Express0020.lzma.bak
2019-04-09T22:02:26.722Z,1554847346.722 [DataOverHttps](INFO): SBD MOMSN=10519782
2019-04-09T22:02:27.636Z,1554847347.636 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T22:02:27.636Z,1554847347.636 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T22:02:27.636Z,1554847347.636 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:02:29.612Z,1554847349.612 [NAL9602](INFO): SBD MO Status=2, MOMSN=3152, MT Status=2, MTMSN=0
2019-04-09T22:02:29.612Z,1554847349.612 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:02:40.666Z,1554847360.666 [CommandLine](IMPORTANT): got command get DUSBL_Hydroid.loadAtStartup
2019-04-09T22:02:40.667Z,1554847360.667 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup 1 bool
2019-04-09T22:02:48.294Z,1554847368.294 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:02:48.295Z,1554847368.295 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:02:48.341Z,1554847368.341 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T22:02:48.343Z,1554847368.343 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T22:02:48.353Z,1554847368.353 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T22:02:48.355Z,1554847368.355 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T22:02:48.366Z,1554847368.366 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T22:02:48.367Z,1554847368.367 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T22:02:48.376Z,1554847368.376 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T22:02:48.409Z,1554847368.409 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T22:02:48.433Z,1554847368.433 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

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

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

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

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>   

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>      
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

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

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

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

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


2019-04-09T22:02:48.435Z,1554847368.435 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:02:48.726Z,1554847368.726 [Default] Stopped
2019-04-09T22:02:48.726Z,1554847368.726 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T22:02:48.726Z,1554847368.726 [Default:B.GoToSurface] Stopped
2019-04-09T22:02:48.726Z,1554847368.726 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T22:02:48.727Z,1554847368.727 [Default:CheckIn] Stopped
2019-04-09T22:02:48.727Z,1554847368.727 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T22:02:48.727Z,1554847368.727 [Default:CheckIn:C.Wait] Stopped
2019-04-09T22:02:48.727Z,1554847368.727 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:02:48.727Z,1554847368.727 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T22:02:48.727Z,1554847368.727 [DUSBL] Running Loop=1
2019-04-09T22:02:48.727Z,1554847368.727 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T22:02:48.727Z,1554847368.727 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:02:48.728Z,1554847368.728 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T22:02:48.728Z,1554847368.728 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:02:48.728Z,1554847368.728 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T22:02:48.728Z,1554847368.728 [DUSBL:C] Running Loop=1
2019-04-09T22:02:48.728Z,1554847368.728 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:02:48.733Z,1554847368.733 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:02:48.734Z,1554847368.734 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:02:48.734Z,1554847368.734 [DUSBL:C] Stopped
2019-04-09T22:02:48.734Z,1554847368.734 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:02:48.734Z,1554847368.734 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:02:58.772Z,1554847378.772 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:02:58.772Z,1554847378.772 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:02:58.772Z,1554847378.772 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:02:58.777Z,1554847378.777 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:02:58.778Z,1554847378.778 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:03:09.238Z,1554847389.238 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:03:09.238Z,1554847389.238 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:03:09.238Z,1554847389.238 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:03:09.239Z,1554847389.239 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:03:09.239Z,1554847389.239 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:03:09.239Z,1554847389.239 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:03:09.239Z,1554847389.239 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:03:09.239Z,1554847389.239 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:03:09.240Z,1554847389.240 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:03:19.756Z,1554847399.756 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:03:19.756Z,1554847399.756 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:03:19.756Z,1554847399.756 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:03:19.757Z,1554847399.757 [DUSBL:RequestRepeater](INFO): Running loop #4
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater] Running Loop=4
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:03:19.758Z,1554847399.758 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:03:30.283Z,1554847410.283 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:03:30.284Z,1554847410.284 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:03:30.284Z,1554847410.284 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:03:30.284Z,1554847410.284 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:03:30.284Z,1554847410.284 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater](INFO): Running loop #5
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater] Running Loop=5
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:03:30.285Z,1554847410.285 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:03:30.286Z,1554847410.286 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:03:40.788Z,1554847420.788 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:03:40.788Z,1554847420.788 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:03:40.788Z,1554847420.788 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater](INFO): Running loop #6
2019-04-09T22:03:40.789Z,1554847420.789 [DUSBL:RequestRepeater] Running Loop=6
2019-04-09T22:03:40.790Z,1554847420.790 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:03:40.790Z,1554847420.790 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:03:40.790Z,1554847420.790 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:03:40.790Z,1554847420.790 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:03:40.790Z,1554847420.790 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:03:51.332Z,1554847431.332 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:03:51.332Z,1554847431.332 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:03:51.333Z,1554847431.333 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:03:51.333Z,1554847431.333 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:03:51.333Z,1554847431.333 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:03:51.333Z,1554847431.333 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater](INFO): Running loop #7
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater] Running Loop=7
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:03:51.334Z,1554847431.334 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:04:01.779Z,1554847441.779 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:04:01.779Z,1554847441.779 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:04:01.779Z,1554847441.779 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:04:01.780Z,1554847441.780 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:04:01.780Z,1554847441.780 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater](INFO): Running loop #8
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater] Running Loop=8
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:04:01.781Z,1554847441.781 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:04:01.781Z,1554847441.782 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:04:12.284Z,1554847452.284 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:04:12.284Z,1554847452.284 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:04:12.284Z,1554847452.284 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater](INFO): Running loop #9
2019-04-09T22:04:12.285Z,1554847452.285 [DUSBL:RequestRepeater] Running Loop=9
2019-04-09T22:04:12.286Z,1554847452.286 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:04:12.286Z,1554847452.286 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:04:12.286Z,1554847452.286 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:04:12.286Z,1554847452.286 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:04:12.286Z,1554847452.286 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:04:13.867Z,1554847453.867 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T22:04:13.868Z,1554847453.868 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040915120393,35.0  0.0,1448.9,  0
2019-04-09T22:04:22.804Z,1554847462.804 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:04:22.804Z,1554847462.804 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:04:22.804Z,1554847462.804 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:04:22.809Z,1554847462.809 [DUSBL:RequestRepeater](INFO): Running loop #10
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater] Running Loop=10
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:04:22.810Z,1554847462.810 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:04:29.235Z,1554847469.235 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T22:04:29.236Z,1554847469.236 [RDI_Pathfinder](ERROR): Failed to parse:
:TS5121893,35.0, -0.1,   0.0,1448.9,  0
2019-04-09T22:04:32.877Z,1554847472.877 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T22:04:32.878Z,1554847472.878 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,1904091512229-0.1,   0.0,1448.9,  0
2019-04-09T22:04:33.304Z,1554847473.304 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:04:33.304Z,1554847473.304 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:04:33.304Z,1554847473.304 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:04:33.305Z,1554847473.305 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:04:33.305Z,1554847473.305 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:04:33.305Z,1554847473.305 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:04:33.305Z,1554847473.305 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:04:33.305Z,1554847473.305 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL](INFO): Completed DUSBL
2019-04-09T22:04:33.306Z,1554847473.306 [MissionManager](INFO): DUSBL is completed.
2019-04-09T22:04:33.306Z,1554847473.306 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL] Stopped
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL:A.Pitch] Stopped
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL:B.SetSpeed] Stopped
2019-04-09T22:04:33.306Z,1554847473.306 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T22:04:33.684Z,1554847473.684 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T22:04:33.684Z,1554847473.684 [Default] Running Loop=1
2019-04-09T22:04:33.684Z,1554847473.684 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T22:04:33.685Z,1554847473.685 [Default:B.GoToSurface] Running Loop=1
2019-04-09T22:04:33.685Z,1554847473.685 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T22:04:33.685Z,1554847473.685 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T22:04:33.685Z,1554847473.685 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T22:04:33.686Z,1554847473.686 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T22:04:33.686Z,1554847473.686 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T22:04:33.686Z,1554847473.686 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T22:04:33.687Z,1554847473.687 [Default:A.Wait] Running Loop=1
2019-04-09T22:04:33.687Z,1554847473.687 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:04:47.068Z,1554847487.068 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T22:04:47.068Z,1554847487.068 [Default:A.Wait] Stopped
2019-04-09T22:04:47.068Z,1554847487.068 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:04:47.402Z,1554847487.402 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:04:47.415Z,1554847487.415 [Default:CheckIn] Running Loop=1
2019-04-09T22:04:47.415Z,1554847487.415 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T22:04:47.415Z,1554847487.415 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T22:04:57.503Z,1554847497.503 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:07.197Z,1554847507.197 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:16.905Z,1554847516.905 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:21.324Z,1554847521.324 [NAL9602](INFO): SBD MO Status=2, MOMSN=3152, MT Status=2, MTMSN=0
2019-04-09T22:05:21.324Z,1554847521.324 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:05:26.591Z,1554847526.591 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:36.713Z,1554847536.713 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:38.288Z,1554847538.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=3152, MT Status=2, MTMSN=0
2019-04-09T22:05:38.288Z,1554847538.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:05:46.383Z,1554847546.383 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:05:56.078Z,1554847556.078 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:05.788Z,1554847565.788 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:15.474Z,1554847575.474 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:25.168Z,1554847585.168 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:25.556Z,1554847585.556 [NAL9602](INFO): SBD MO Status=2, MOMSN=3152, MT Status=2, MTMSN=0
2019-04-09T22:06:25.556Z,1554847585.556 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:06:31.994Z,1554847591.994 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T22:06:32.132Z,1554847592.132 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T22:06:32.132Z,1554847592.132 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T22:06:32.141Z,1554847592.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T22:06:32.141Z,1554847592.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T22:06:32.141Z,1554847592.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T22:06:32.142Z,1554847592.142 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T22:06:32.142Z,1554847592.142 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T22:06:32.143Z,1554847592.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T22:06:32.143Z,1554847592.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T22:06:32.143Z,1554847592.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T22:06:32.144Z,1554847592.144 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T22:06:32.144Z,1554847592.144 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T22:06:32.240Z,1554847592.240 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T22:06:32.257Z,1554847592.257 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T22:06:32.257Z,1554847592.257 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T22:06:32.278Z,1554847592.278 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T22:06:32.278Z,1554847592.278 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T22:06:32.279Z,1554847592.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T22:06:32.279Z,1554847592.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T22:06:32.280Z,1554847592.280 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T22:06:32.280Z,1554847592.280 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T22:06:32.280Z,1554847592.280 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T22:06:32.297Z,1554847592.297 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T22:06:32.297Z,1554847592.297 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T22:06:32.298Z,1554847592.298 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T22:06:32.298Z,1554847592.298 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T22:06:34.880Z,1554847594.880 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:38.527Z,1554847598.527 [NAL9602](INFO): SBD MO Status=2, MOMSN=3152, MT Status=2, MTMSN=0
2019-04-09T22:06:38.527Z,1554847598.527 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:06:44.967Z,1554847604.967 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:53.291Z,1554847613.291 [CommandLine](IMPORTANT): got command configSet DUSBL_Hydroid.verbosity 3.000000 enum persist
2019-04-09T22:06:54.688Z,1554847614.688 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:06:56.194Z,1554847616.194 [CommandLine](IMPORTANT): got command restart application
2019-04-09T22:06:57.068Z,1554847617.068 [NAL9602](INFO): SBD MO Status=0, MOMSN=3152, MT Status=0, MTMSN=0
2019-04-09T22:06:57.068Z,1554847617.068 [NAL9602](INFO): No messages in MT queue
2019-04-09T22:06:57.201Z,1554847617.201 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-04-09T22:06:57.201Z,1554847617.201 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:57.201Z,1554847617.201 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.349Z,1554847617.349 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-09T22:06:57.349Z,1554847617.349 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.349Z,1554847617.349 [CommandLine](INFO): Join timeout helper Thread ID is 971
2019-04-09T22:06:57.350Z,1554847617.350 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-09T22:06:57.350Z,1554847617.350 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.351Z,1554847617.351 [NavChartDb](INFO): Join timeout helper Thread ID is 972
2019-04-09T22:06:57.689Z,1554847617.689 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:57.689Z,1554847617.689 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.693Z,1554847617.693 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-09T22:06:57.693Z,1554847617.693 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.693Z,1554847617.693 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 973
2019-04-09T22:06:57.869Z,1554847617.869 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:57.869Z,1554847617.869 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T22:06:57.870Z,1554847617.870 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.873Z,1554847617.873 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-09T22:06:57.873Z,1554847617.873 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.873Z,1554847617.873 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 974
2019-04-09T22:06:57.889Z,1554847617.889 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:57.889Z,1554847617.889 [CTD_NeilBrown](INFO): Powering down
2019-04-09T22:06:57.890Z,1554847617.890 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:06:57.901Z,1554847617.901 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.913Z,1554847617.913 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-09T22:06:57.913Z,1554847617.913 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:57.913Z,1554847617.913 [Radio_Surface](INFO): Join timeout helper Thread ID is 975
2019-04-09T22:06:58.045Z,1554847618.045 [Radio_Surface](INFO): Powering down
2019-04-09T22:06:58.046Z,1554847618.046 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:58.046Z,1554847618.046 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.050Z,1554847618.050 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-09T22:06:58.050Z,1554847618.050 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.050Z,1554847618.050 [DataOverHttps](INFO): Join timeout helper Thread ID is 976
2019-04-09T22:06:58.233Z,1554847618.233 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:58.233Z,1554847618.233 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.253Z,1554847618.253 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-09T22:06:58.254Z,1554847618.254 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.254Z,1554847618.254 [logger](INFO): Join timeout helper Thread ID is 977
2019-04-09T22:06:58.281Z,1554847618.281 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220604.00,A,3648.16768,N,12147.28092,W,0.311,135.69,090419,,,A*77
2019-04-09T22:06:58.283Z,1554847618.283 [NAL9602](INFO): GPS fix at 20190409T220604: (36.802795, -121.788015)
2019-04-09T22:06:58.293Z,1554847618.293 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:58.294Z,1554847618.294 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.306Z,1554847618.306 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-09T22:06:58.306Z,1554847618.306 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.306Z,1554847618.306 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-09T22:06:58.306Z,1554847618.306 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.306Z,1554847618.306 [controlThread](INFO): Join timeout helper Thread ID is 978
2019-04-09T22:06:58.314Z,1554847618.314 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T22:06:58.315Z,1554847618.315 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T22:06:58.351Z,1554847618.351 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T22:06:58.352Z,1554847618.352 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-09T22:06:58.352Z,1554847618.352 [AHRS_M2](INFO): Powering down
2019-04-09T22:06:58.441Z,1554847618.441 [DUSBL_Hydroid](INFO): Powering down
2019-04-09T22:06:58.534Z,1554847618.534 [Micromodem](INFO): Powering down
2019-04-09T22:06:58.629Z,1554847618.629 [NAL9602](INFO): Powering down
2019-04-09T22:06:58.701Z,1554847618.701 [RDI_Pathfinder](INFO): Powering down
2019-04-09T22:06:58.702Z,1554847618.702 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-09T22:06:58.703Z,1554847618.703 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-09T22:06:58.704Z,1554847618.704 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-09T22:06:58.704Z,1554847618.704 [MissionManager](INFO): Uninitializing Mission Default
2019-04-09T22:06:58.704Z,1554847618.704 [Default] Stopped
2019-04-09T22:06:58.705Z,1554847618.705 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T22:06:58.705Z,1554847618.705 [Default:B.GoToSurface] Stopped
2019-04-09T22:06:58.705Z,1554847618.705 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T22:06:58.705Z,1554847618.705 [Default:CheckIn] Stopped
2019-04-09T22:06:58.705Z,1554847618.705 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T22:06:58.705Z,1554847618.705 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T22:06:58.708Z,1554847618.708 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-09T22:06:58.708Z,1554847618.708 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-09T22:06:58.708Z,1554847618.708 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-09T22:06:58.708Z,1554847618.708 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-09T22:06:58.709Z,1554847618.709 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-09T22:06:58.709Z,1554847618.709 [BuoyancyServo](INFO): Powering down
2019-04-09T22:06:58.721Z,1554847618.721 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-09T22:06:58.721Z,1554847618.721 [ElevatorServo](INFO): Powering down
2019-04-09T22:06:58.722Z,1554847618.722 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-09T22:06:58.722Z,1554847618.722 [MassServo](INFO): Powering down
2019-04-09T22:06:58.723Z,1554847618.723 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T22:06:58.723Z,1554847618.723 [RudderServo](INFO): Powering down
2019-04-09T22:06:58.723Z,1554847618.723 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-09T22:06:58.723Z,1554847618.723 [ThrusterServo](INFO): Powering down
2019-04-09T22:06:58.724Z,1554847618.724 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-09T22:06:58.725Z,1554847618.725 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-09T22:06:58.725Z,1554847618.725 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-09T22:06:58.725Z,1554847618.725 [CBIT](DEBUG): Powering off loads.
2019-04-09T22:06:58.737Z,1554847618.737 [CBIT](DEBUG): Disabling WDT.
2019-04-09T22:06:58.748Z,1554847618.748 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-09T22:06:58.749Z,1554847618.749 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.796Z,1554847618.796 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.805Z,1554847618.805 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.845Z,1554847618.845 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.847Z,1554847618.847 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.901Z,1554847618.901 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T22:06:58.972Z,1554847618.972 [logger ThreadHandler](INFO): Thread cancelled.