2019-04-09T23:11:08.958Z,1554851468.958 [Supervisor](DEBUG): Initializing supervisor.
2019-04-09T23:11:08.961Z,1554851468.961 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-09T23:11:08.961Z,1554851468.961 [SyncHandler](INFO): Protected caller Thread ID is 1439
2019-04-09T23:11:08.962Z,1554851468.962 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-09T23:11:08.963Z,1554851468.963 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-09T23:11:08.963Z,1554851468.963 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1440
2019-04-09T23:11:08.967Z,1554851468.967 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-09T23:11:08.979Z,1554851468.979 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-09T23:11:08.980Z,1554851468.980 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-09T23:11:08.980Z,1554851468.980 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1441
2019-04-09T23:11:08.981Z,1554851468.981 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-09T23:11:08.982Z,1554851468.982 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-09T23:11:08.982Z,1554851468.982 [logger ThreadHandler](INFO): Protected caller Thread ID is 1442
2019-04-09T23:11:08.984Z,1554851468.984 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-09T23:11:08.985Z,1554851468.985 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-09T23:11:08.986Z,1554851468.986 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-09T23:11:09.513Z,1554851469.513 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-09T23:11:09.514Z,1554851469.514 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-09T23:11:09.615Z,1554851469.615 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-09T23:11:09.615Z,1554851469.615 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-09T23:11:09.970Z,1554851469.970 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-09T23:11:09.971Z,1554851469.971 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-09T23:11:10.120Z,1554851470.120 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-09T23:11:10.121Z,1554851470.121 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-09T23:11:10.327Z,1554851470.327 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-09T23:11:10.327Z,1554851470.327 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-09T23:11:10.821Z,1554851470.821 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-09T23:11:10.822Z,1554851470.822 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-09T23:11:11.047Z,1554851471.047 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-09T23:11:11.048Z,1554851471.048 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-09T23:11:11.202Z,1554851471.202 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-09T23:11:11.203Z,1554851471.203 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-09T23:11:11.413Z,1554851471.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-09T23:11:11.414Z,1554851471.414 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-09T23:11:11.513Z,1554851471.513 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-09T23:11:11.514Z,1554851471.514 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-09T23:11:11.868Z,1554851471.868 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-09T23:11:11.869Z,1554851471.869 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-09T23:11:11.951Z,1554851471.951 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-09T23:11:12.059Z,1554851472.059 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-09T23:11:12.059Z,1554851472.059 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-09T23:11:12.601Z,1554851472.601 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-09T23:11:12.602Z,1554851472.602 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-09T23:11:13.028Z,1554851473.028 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-09T23:11:13.031Z,1554851473.031 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-09T23:11:13.031Z,1554851473.031 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-09T23:11:13.477Z,1554851473.477 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-09T23:11:13.793Z,1554851473.793 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-09T23:11:13.929Z,1554851473.929 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-09T23:11:14.258Z,1554851474.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-09T23:11:14.258Z,1554851474.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-09T23:11:14.345Z,1554851474.345 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-09T23:11:14.442Z,1554851474.442 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-09T23:11:14.543Z,1554851474.543 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-09T23:11:14.627Z,1554851474.627 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-09T23:11:14.742Z,1554851474.742 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-09T23:11:14.929Z,1554851474.929 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-09T23:11:15.071Z,1554851475.071 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-04-09T23:11:15.072Z,1554851475.072 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-09T23:11:15.084Z,1554851475.084 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-09T23:11:15.477Z,1554851475.477 [AHRS_M2] Loaded
2019-04-09T23:11:15.477Z,1554851475.477 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-09T23:11:15.561Z,1554851475.561 [DataOverHttps] Loaded
2019-04-09T23:11:15.561Z,1554851475.561 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-09T23:11:15.562Z,1554851475.562 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-09T23:11:15.562Z,1554851475.562 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1521
2019-04-09T23:11:15.576Z,1554851475.576 [Depth_Keller] Loaded
2019-04-09T23:11:15.576Z,1554851475.576 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-09T23:11:15.581Z,1554851475.581 [DropWeight] Loaded
2019-04-09T23:11:15.582Z,1554851475.582 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-09T23:11:15.640Z,1554851475.640 [DUSBL_Hydroid] Loaded
2019-04-09T23:11:15.640Z,1554851475.640 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-09T23:11:15.681Z,1554851475.681 [Micromodem] Loaded
2019-04-09T23:11:15.682Z,1554851475.682 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-09T23:11:15.783Z,1554851475.783 [NAL9602] Loaded
2019-04-09T23:11:15.784Z,1554851475.784 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-09T23:11:15.800Z,1554851475.800 [Onboard] Loaded
2019-04-09T23:11:15.800Z,1554851475.800 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-09T23:11:15.806Z,1554851475.806 [PowerOnly] Loaded
2019-04-09T23:11:15.806Z,1554851475.806 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-09T23:11:15.813Z,1554851475.813 [Radio_Surface] Loaded
2019-04-09T23:11:15.813Z,1554851475.813 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-09T23:11:15.814Z,1554851475.814 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-09T23:11:15.815Z,1554851475.815 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1522
2019-04-09T23:11:15.861Z,1554851475.861 [RDI_Pathfinder] Loaded
2019-04-09T23:11:15.861Z,1554851475.861 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-09T23:11:17.404Z,1554851477.404 [BPC1] Loaded
2019-04-09T23:11:17.405Z,1554851477.405 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-09T23:11:17.405Z,1554851477.405 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-09T23:11:17.406Z,1554851477.406 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-09T23:11:17.419Z,1554851477.419 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-09T23:11:17.419Z,1554851477.419 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-09T23:11:17.528Z,1554851477.528 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-09T23:11:17.528Z,1554851477.528 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-09T23:11:17.550Z,1554851477.550 [NavChart] Loaded
2019-04-09T23:11:17.550Z,1554851477.550 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-09T23:11:17.554Z,1554851477.554 [UniversalFixResidualReporter] Loaded
2019-04-09T23:11:17.554Z,1554851477.554 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-09T23:11:17.555Z,1554851477.555 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-09T23:11:17.555Z,1554851477.555 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-09T23:11:17.659Z,1554851477.659 [BuoyancyServo] Loaded
2019-04-09T23:11:17.659Z,1554851477.659 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-09T23:11:17.675Z,1554851477.675 [ElevatorServo] Loaded
2019-04-09T23:11:17.675Z,1554851477.675 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-09T23:11:17.690Z,1554851477.690 [MassServo] Loaded
2019-04-09T23:11:17.691Z,1554851477.691 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-09T23:11:17.706Z,1554851477.706 [RudderServo] Loaded
2019-04-09T23:11:17.707Z,1554851477.707 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-09T23:11:17.722Z,1554851477.722 [ThrusterServo] Loaded
2019-04-09T23:11:17.722Z,1554851477.722 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-09T23:11:17.722Z,1554851477.722 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-09T23:11:17.723Z,1554851477.723 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-09T23:11:17.979Z,1554851477.979 [CTD_NeilBrown] Loaded
2019-04-09T23:11:17.979Z,1554851477.979 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-09T23:11:17.980Z,1554851477.980 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CF4E0
2019-04-09T23:11:17.981Z,1554851477.981 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1523
2019-04-09T23:11:18.027Z,1554851478.027 [WetLabsSeaOWL_UV_A] Loaded
2019-04-09T23:11:18.027Z,1554851478.027 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-09T23:11:18.028Z,1554851478.028 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FF4E0
2019-04-09T23:11:18.028Z,1554851478.028 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1524
2019-04-09T23:11:18.029Z,1554851478.029 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-09T23:11:18.030Z,1554851478.030 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-09T23:11:18.551Z,1554851478.551 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-09T23:11:18.552Z,1554851478.552 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-09T23:11:18.593Z,1554851478.593 [DepthRateCalculator] Loaded
2019-04-09T23:11:18.594Z,1554851478.594 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-09T23:11:18.599Z,1554851478.599 [PitchRateCalculator] Loaded
2019-04-09T23:11:18.600Z,1554851478.600 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-09T23:11:18.612Z,1554851478.612 [SpeedCalculator] Loaded
2019-04-09T23:11:18.613Z,1554851478.613 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-09T23:11:18.634Z,1554851478.634 [TempGradientCalculator] Loaded
2019-04-09T23:11:18.634Z,1554851478.634 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-09T23:11:18.640Z,1554851478.640 [YawRateCalculator] Loaded
2019-04-09T23:11:18.640Z,1554851478.640 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-09T23:11:18.682Z,1554851478.682 [ElevatorOffsetCalculator] Loaded
2019-04-09T23:11:18.682Z,1554851478.682 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-09T23:11:18.683Z,1554851478.683 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-09T23:11:18.683Z,1554851478.683 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-09T23:11:18.822Z,1554851478.822 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-09T23:11:18.846Z,1554851478.846 [SBIT] Loaded
2019-04-09T23:11:18.846Z,1554851478.846 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-09T23:11:18.847Z,1554851478.847 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-09T23:11:18.859Z,1554851478.859 [IBIT] Loaded
2019-04-09T23:11:18.859Z,1554851478.859 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-09T23:11:18.862Z,1554851478.862 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-09T23:11:19.005Z,1554851479.005 [CBIT] Loaded
2019-04-09T23:11:19.006Z,1554851479.006 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-09T23:11:19.006Z,1554851479.006 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-09T23:11:19.007Z,1554851479.007 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-09T23:11:19.077Z,1554851479.077 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-09T23:11:19.078Z,1554851479.078 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-09T23:11:19.181Z,1554851479.181 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-09T23:11:19.182Z,1554851479.182 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-09T23:11:19.249Z,1554851479.249 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-09T23:11:19.337Z,1554851479.337 [VerticalControl] Loaded
2019-04-09T23:11:19.337Z,1554851479.337 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-09T23:11:19.338Z,1554851479.338 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-09T23:11:19.396Z,1554851479.396 [HorizontalControl] Loaded
2019-04-09T23:11:19.397Z,1554851479.397 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-09T23:11:19.397Z,1554851479.397 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-09T23:11:19.399Z,1554851479.399 [SpeedControl] Loaded
2019-04-09T23:11:19.399Z,1554851479.399 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-09T23:11:19.400Z,1554851479.400 [LoopControl](DEBUG): Construct LoopControl.
2019-04-09T23:11:19.401Z,1554851479.401 [LoopControl] Loaded
2019-04-09T23:11:19.401Z,1554851479.401 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-09T23:11:19.401Z,1554851479.401 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-09T23:11:19.402Z,1554851479.402 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-09T23:11:19.429Z,1554851479.429 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-09T23:11:19.433Z,1554851479.433 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-09T23:11:19.434Z,1554851479.434 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-09T23:11:19.441Z,1554851479.441 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-09T23:11:19.442Z,1554851479.442 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-04-09T23:11:19.442Z,1554851479.442 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1525
2019-04-09T23:11:19.447Z,1554851479.447 [Supervisor](INFO): Main Thread ID is 802
2019-04-09T23:11:19.447Z,1554851479.447 [Supervisor](DEBUG): Running supervisor.
2019-04-09T23:11:19.448Z,1554851479.448 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1526
2019-04-09T23:11:19.450Z,1554851479.450 [controlThread ThreadHandler](INFO): Handler Thread ID is 1527
2019-04-09T23:11:19.450Z,1554851479.450 [controlThread](DEBUG): Initializing ControlThread
2019-04-09T23:11:19.456Z,1554851479.456 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-09T23:11:19.456Z,1554851479.456 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-09T23:11:19.457Z,1554851479.457 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-09T23:11:19.458Z,1554851479.458 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-09T23:11:19.458Z,1554851479.458 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-09T23:11:19.458Z,1554851479.458 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-09T23:11:19.459Z,1554851479.459 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-09T23:11:19.459Z,1554851479.459 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-09T23:11:19.460Z,1554851479.460 [SBIT](INFO): Initialize SBIT Component.
2019-04-09T23:11:19.460Z,1554851479.460 [SBIT](IMPORTANT): git: 2019-03-18-31-ge98d5dc
2019-04-09T23:11:19.460Z,1554851479.460 [SBIT](INFO): git hash: e98d5dc50cbc39e402f19b9946ff4dc0776c8725
2019-04-09T23:11:19.461Z,1554851479.461 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-09T23:11:19.461Z,1554851479.461 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-09T23:11:19.462Z,1554851479.462 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-09T23:11:19.463Z,1554851479.463 [IBIT](INFO): Initialize IBIT Component.
2019-04-09T23:11:19.463Z,1554851479.463 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-09T23:11:19.464Z,1554851479.464 [logger ThreadHandler](INFO): Handler Thread ID is 1528
2019-04-09T23:11:19.477Z,1554851479.477 [CBIT](DEBUG): Initialized mux pins.
2019-04-09T23:11:19.477Z,1554851479.477 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-09T23:11:19.481Z,1554851479.481 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1529
2019-04-09T23:11:19.482Z,1554851479.482 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-09T23:11:19.489Z,1554851479.489 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1530
2019-04-09T23:11:19.497Z,1554851479.497 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1531
2019-04-09T23:11:19.498Z,1554851479.498 [CTD_NeilBrown](INFO): Powering down
2019-04-09T23:11:19.501Z,1554851479.501 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-09T23:11:19.501Z,1554851479.501 [CBIT](DEBUG): Initializing heartbeat.
2019-04-09T23:11:19.529Z,1554851479.529 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1532
2019-04-09T23:11:19.530Z,1554851479.530 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T23:11:19.561Z,1554851479.561 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1533
2019-04-09T23:11:19.564Z,1554851479.564 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-09T23:11:19.564Z,1554851479.564 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-09T23:11:19.564Z,1554851479.564 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-09T23:11:19.565Z,1554851479.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-09T23:11:19.565Z,1554851479.565 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-09T23:11:19.565Z,1554851479.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-09T23:11:19.565Z,1554851479.565 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-09T23:11:19.565Z,1554851479.565 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-09T23:11:19.566Z,1554851479.566 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-09T23:11:19.567Z,1554851479.567 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-09T23:11:19.567Z,1554851479.567 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-09T23:11:19.573Z,1554851479.573 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-09T23:11:19.573Z,1554851479.573 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-09T23:11:19.609Z,1554851479.609 [CBIT](DEBUG): Backplane powered.
2019-04-09T23:11:19.609Z,1554851479.609 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-09T23:11:19.611Z,1554851479.611 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-09T23:11:19.611Z,1554851479.611 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-09T23:11:19.612Z,1554851479.612 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-09T23:11:19.613Z,1554851479.613 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-09T23:11:19.623Z,1554851479.623 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T23:11:19.650Z,1554851479.650 [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-09T23:11:19.651Z,1554851479.651 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-09T23:11:19.713Z,1554851479.713 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-09T23:11:19.715Z,1554851479.715 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-09T23:11:19.716Z,1554851479.716 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T23:11:19.744Z,1554851479.744 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-09T23:11:19.766Z,1554851479.766 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:11:19.772Z,1554851479.772 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-09T23:11:19.791Z,1554851479.791 [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-09T23:11:19.796Z,1554851479.796 [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-09T23:11:19.821Z,1554851479.821 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-09T23:11:19.855Z,1554851479.855 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-09T23:11:19.855Z,1554851479.855 [DUSBL_Hydroid](INFO): Powering up
2019-04-09T23:11:19.856Z,1554851479.856 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-09T23:11:19.893Z,1554851479.893 [Radio_Surface](INFO): Powering up
2019-04-09T23:11:19.937Z,1554851479.937 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T23:11:19.951Z,1554851479.951 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:19.957Z,1554851479.957 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-09T23:11:19.958Z,1554851479.958 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:19.965Z,1554851479.965 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-09T23:11:19.966Z,1554851479.966 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:19.973Z,1554851479.973 [MassServo](DEBUG): Initializing MassServo.
2019-04-09T23:11:19.974Z,1554851479.974 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:19.981Z,1554851479.981 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T23:11:19.982Z,1554851479.982 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:19.993Z,1554851479.993 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-09T23:11:20.222Z,1554851480.222 [Micromodem](INFO): Powering up
2019-04-09T23:11:20.222Z,1554851480.222 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-09T23:11:20.261Z,1554851480.261 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T23:11:20.937Z,1554851480.937 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-09T23:11:20.937Z,1554851480.937 [RudderServo](FAULT): Rudder failed to initialize
2019-04-09T23:11:20.937Z,1554851480.937 [RudderServo] Communications Fault, FailCount= 1
2019-04-09T23:11:20.937Z,1554851480.937 [RudderServo](ERROR): Communications Fault
2019-04-09T23:11:21.048Z,1554851481.048 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-09T23:11:21.206Z,1554851481.206 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T23:11:21.206Z,1554851481.206 [RudderServo](INFO): Powering down
2019-04-09T23:11:21.892Z,1554851481.892 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T23:11:22.014Z,1554851482.014 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T23:11:22.018Z,1554851482.018 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-09T23:11:22.018Z,1554851482.018 [RudderServo] No Fault, FailCount= 1
2019-04-09T23:11:33.241Z,1554851493.241 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-09T23:11:36.446Z,1554851496.446 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-04-09T23:11:38.079Z,1554851498.079 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-09T23:11:46.143Z,1554851506.143 [NAL9602](INFO): Powering up NAL9602
2019-04-09T23:11:57.059Z,1554851517.059 [NAL9602](INFO): NAL9602 initialized
2019-04-09T23:11:57.878Z,1554851517.878 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:12:02.719Z,1554851522.719 [Micromodem](ERROR): Response from modem unexpected: $CADQF,199,1*51

2019-04-09T23:12:03.123Z,1554851523.123 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21

2019-04-09T23:12:03.536Z,1554851523.536 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190409231201.477408,05,392,13,0098,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,199,-0.05,-999,9760,4000*7D

2019-04-09T23:12:03.959Z,1554851523.959 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-09T23:12:03.967Z,1554851523.967 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-09T23:12:15.013Z,1554851535.013 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.020057
CHAN A1 (24V): -0.025719
CHAN A2 (12V): -0.006936
CHAN A3 (5V): -0.002040
CHAN B0 (3.3V): 0.000396
CHAN B1 (3.15aV): 0.000358
CHAN B2 (3.15bV): 0.000055
CHAN B3 (GND): 0.001997
OPEN: 0.006244
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-09T23:12:25.267Z,1554851545.267 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:12:35.365Z,1554851555.365 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:12:45.447Z,1554851565.447 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:12:55.280Z,1554851575.280 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:12:55.284Z,1554851575.284 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-04-09T23:12:57.309Z,1554851577.309 [SBIT](IMPORTANT): SBIT PASSED
2019-04-09T23:12:57.354Z,1554851577.354 [CommandLine](IMPORTANT): got command configSet list
2019-04-09T23:12:57.355Z,1554851577.355 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-09T23:12:57.355Z,1554851577.355 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-04-09T23:12:57.356Z,1554851577.356 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-04-09T23:12:57.357Z,1554851577.357 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-04-09T23:12:57.357Z,1554851577.357 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;

2019-04-09T23:12:57.690Z,1554851577.690 [MissionManager](IMPORTANT): Started mission Startup
2019-04-09T23:12:57.691Z,1554851577.691 [Startup] Running Loop=1
2019-04-09T23:12:57.691Z,1554851577.691 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-09T23:12:57.691Z,1554851577.691 [Startup:A.GoToSurface] Running Loop=1
2019-04-09T23:12:57.691Z,1554851577.691 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:12:57.691Z,1554851577.691 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:12:57.692Z,1554851577.692 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:12:57.692Z,1554851577.692 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:12:57.694Z,1554851577.694 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:12:57.694Z,1554851577.694 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:12:57.695Z,1554851577.695 [Startup:StartupSatComms] Running Loop=1
2019-04-09T23:12:57.695Z,1554851577.695 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-09T23:12:57.696Z,1554851577.696 [Startup:StartupSatComms:A] Running Loop=1
2019-04-09T23:12:58.095Z,1554851578.095 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-09T23:13:05.366Z,1554851585.366 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:15.470Z,1554851595.470 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:25.550Z,1554851605.550 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:35.651Z,1554851615.651 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:45.375Z,1554851625.375 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:45.723Z,1554851625.723 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004907
2019-04-09T23:13:55.448Z,1554851635.448 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:13:57.878Z,1554851637.878 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-09T23:12:57.7Z
2019-04-09T23:13:57.878Z,1554851637.878 [Startup:StartupSatComms:A] Stopped
2019-04-09T23:13:57.878Z,1554851637.878 [Startup:StartupSatComms:B] Running Loop=1
2019-04-09T23:13:58.292Z,1554851638.292 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T23:14:03.424Z,1554851643.424 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T224416/Courier0019.lzma
2019-04-09T23:14:04.230Z,1554851644.230 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0019.lzma.bak
2019-04-09T23:14:04.231Z,1554851644.231 [DataOverHttps](INFO): SBD MOMSN=10520813
2019-04-09T23:14:05.557Z,1554851645.557 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:14:15.255Z,1554851655.255 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:14:15.642Z,1554851655.642 [DataOverHttps](INFO): Sending 480 bytes from file Logs/20190409T224416/Express0020.lzma
2019-04-09T23:14:16.446Z,1554851656.446 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0020.lzma.bak
2019-04-09T23:14:16.447Z,1554851656.447 [DataOverHttps](INFO): SBD MOMSN=10520834
2019-04-09T23:14:19.709Z,1554851659.709 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-04-09T23:14:19.709Z,1554851659.709 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-04-09T23:14:19.723Z,1554851659.723 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-04-09T23:14:20.163Z,1554851660.163 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-04-09T23:14:20.163Z,1554851660.163 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-04-09T23:14:25.360Z,1554851665.360 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:14:27.970Z,1554851667.970 [DataOverHttps](INFO): Sending 1273 bytes from file Logs/20190409T231108/Express0001.lzma
2019-04-09T23:14:28.774Z,1554851668.774 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Express0001.lzma.bak
2019-04-09T23:14:28.774Z,1554851668.774 [DataOverHttps](INFO): SBD MOMSN=10520837
2019-04-09T23:14:29.806Z,1554851669.806 [Startup:StartupSatComms:B] Stopped
2019-04-09T23:14:29.806Z,1554851669.806 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-09T23:14:29.807Z,1554851669.807 [Startup:StartupSatComms] Stopped
2019-04-09T23:14:29.807Z,1554851669.807 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-09T23:14:29.807Z,1554851669.807 [Startup](INFO): Completed Startup
2019-04-09T23:14:29.808Z,1554851669.808 [MissionManager](INFO): Startup is completed.
2019-04-09T23:14:29.808Z,1554851669.808 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-09T23:14:29.808Z,1554851669.808 [Startup] Stopped
2019-04-09T23:14:29.808Z,1554851669.808 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-09T23:14:29.808Z,1554851669.808 [Startup:A.GoToSurface] Stopped
2019-04-09T23:14:29.808Z,1554851669.808 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:14:30.239Z,1554851670.239 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:14:30.239Z,1554851670.239 [Default] Running Loop=1
2019-04-09T23:14:30.239Z,1554851670.239 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:14:30.239Z,1554851670.239 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:14:30.239Z,1554851670.239 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:14:30.240Z,1554851670.240 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:14:30.240Z,1554851670.240 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:14:30.240Z,1554851670.240 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:14:30.245Z,1554851670.245 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:14:30.245Z,1554851670.245 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:14:30.245Z,1554851670.245 [Default:A.Wait] Running Loop=1
2019-04-09T23:14:30.245Z,1554851670.245 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:14:35.447Z,1554851675.447 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:14:43.554Z,1554851683.554 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:14:43.554Z,1554851683.554 [Default:A.Wait] Stopped
2019-04-09T23:14:43.554Z,1554851683.554 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:14:43.958Z,1554851683.958 [Default:CheckIn] Running Loop=1
2019-04-09T23:14:43.958Z,1554851683.958 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:14:43.958Z,1554851683.958 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:14:44.379Z,1554851684.379 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-09T23:15:36.087Z,1554851736.087 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T23:15:36.087Z,1554851736.087 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,32768,-32768,V
2019-04-09T23:15:41.775Z,1554851741.775 [CommandLine](IMPORTANT): got command show stack
2019-04-09T23:15:41.775Z,1554851741.775 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-09T23:15:41.775Z,1554851741.775 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-09T23:15:41.776Z,1554851741.776 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS
2019-04-09T23:15:50.230Z,1554851750.230 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:15:50.231Z,1554851750.231 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:15:50.257Z,1554851750.257 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T23:15:50.261Z,1554851750.261 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T23:15:50.265Z,1554851750.265 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T23:15:50.268Z,1554851750.268 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T23:15:50.272Z,1554851750.272 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T23:15:50.273Z,1554851750.273 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T23:15:50.279Z,1554851750.279 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T23:15:50.309Z,1554851750.309 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:15:50.317Z,1554851750.317 [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>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <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-09T23:15:50.320Z,1554851750.320 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:15:50.614Z,1554851750.614 [Default] Stopped
2019-04-09T23:15:50.615Z,1554851750.615 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:15:50.615Z,1554851750.615 [Default:B.GoToSurface] Stopped
2019-04-09T23:15:50.615Z,1554851750.615 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:15:50.615Z,1554851750.615 [Default:CheckIn] Stopped
2019-04-09T23:15:50.615Z,1554851750.615 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:15:50.615Z,1554851750.615 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:15:50.616Z,1554851750.616 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T23:15:50.616Z,1554851750.616 [DUSBL] Running Loop=1
2019-04-09T23:15:50.616Z,1554851750.616 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T23:15:50.616Z,1554851750.616 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:15:50.616Z,1554851750.616 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:C] Running Loop=1
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:15:50.618Z,1554851750.618 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:15:50.619Z,1554851750.619 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:15:50.619Z,1554851750.619 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:15:50.619Z,1554851750.619 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:15:50.620Z,1554851750.620 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T23:15:50.624Z,1554851750.624 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T23:15:50.624Z,1554851750.624 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:15:50.624Z,1554851750.624 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:15:52.188Z,1554851752.188 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:52.595Z,1554851752.595 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:53.024Z,1554851753.024 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:53.398Z,1554851753.398 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:53.400Z,1554851753.400 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:15:53.409Z,1554851753.409 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231552.64*5E

2019-04-09T23:15:53.811Z,1554851753.811 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:54.208Z,1554851754.208 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:54.611Z,1554851754.611 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:54.616Z,1554851754.616 [Micromodem](ERROR): Response from modem unexpected: $CATXP,280*48

2019-04-09T23:15:54.617Z,1554851754.617 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:15:55.019Z,1554851755.019 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:55.024Z,1554851755.024 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231553.48*51

2019-04-09T23:15:55.419Z,1554851755.419 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:55.827Z,1554851755.827 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:15:55.830Z,1554851755.830 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:56.227Z,1554851756.227 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:15:56.229Z,1554851756.229 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231554.66*5A

2019-04-09T23:15:58.258Z,1554851758.258 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:58.655Z,1554851758.655 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:59.059Z,1554851759.059 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:59.463Z,1554851759.463 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:15:59.466Z,1554851759.466 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:15:59.470Z,1554851759.470 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:15:59.471Z,1554851759.471 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231558.71*50

2019-04-09T23:16:00.717Z,1554851760.717 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:16:00.717Z,1554851760.717 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:16:00.717Z,1554851760.717 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:16:00.718Z,1554851760.718 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:16:00.719Z,1554851760.719 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:16:01.870Z,1554851761.870 [CommandLine](IMPORTANT): got command stop
2019-04-09T23:16:01.871Z,1554851761.871 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-09T23:16:01.871Z,1554851761.871 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T23:16:01.891Z,1554851761.891 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:01.982Z,1554851761.982 [MissionManager](INFO): MissionManager is completed.
2019-04-09T23:16:01.982Z,1554851761.982 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL] Stopped
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL:A.Pitch] Stopped
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL:B.SetSpeed] Stopped
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL:C] Stopped
2019-04-09T23:16:01.982Z,1554851761.982 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:16:01.983Z,1554851761.983 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:16:01.983Z,1554851761.983 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:16:01.983Z,1554851761.983 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:16:01.983Z,1554851761.983 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:16:01.983Z,1554851761.983 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:02.340Z,1554851762.340 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:16:02.340Z,1554851762.340 [Default] Running Loop=1
2019-04-09T23:16:02.340Z,1554851762.340 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:16:02.341Z,1554851762.341 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:16:02.341Z,1554851762.341 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:16:02.341Z,1554851762.341 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:16:02.341Z,1554851762.341 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:16:02.342Z,1554851762.342 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:16:02.342Z,1554851762.342 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:16:02.342Z,1554851762.342 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:16:02.343Z,1554851762.343 [Default:A.Wait] Running Loop=1
2019-04-09T23:16:02.343Z,1554851762.343 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:16:04.670Z,1554851764.670 [CommandLine](IMPORTANT): got command show variable range
2019-04-09T23:16:04.672Z,1554851764.672 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-09T23:16:04.889Z,1554851764.889 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T23:16:04.890Z,1554851764.890 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-09T23:16:04.891Z,1554851764.891 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-09T23:16:04.893Z,1554851764.893 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-09T23:16:04.894Z,1554851764.894 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-09T23:16:04.894Z,1554851764.894 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-09T23:16:04.895Z,1554851764.895 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-09T23:16:13.686Z,1554851773.686 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-09T23:16:15.650Z,1554851775.650 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:16:15.650Z,1554851775.650 [Default:A.Wait] Stopped
2019-04-09T23:16:15.650Z,1554851775.650 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:16.050Z,1554851776.050 [Default:CheckIn] Running Loop=1
2019-04-09T23:16:16.051Z,1554851776.051 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:16:16.051Z,1554851776.051 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:16:19.101Z,1554851779.101 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T23:16:19.209Z,1554851779.209 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T23:16:19.210Z,1554851779.210 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T23:16:19.210Z,1554851779.210 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T23:16:19.210Z,1554851779.210 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T23:16:19.211Z,1554851779.211 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T23:16:19.211Z,1554851779.211 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T23:16:19.211Z,1554851779.211 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T23:16:19.212Z,1554851779.212 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T23:16:19.212Z,1554851779.212 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T23:16:19.213Z,1554851779.213 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T23:16:19.213Z,1554851779.213 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T23:16:19.213Z,1554851779.213 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T23:16:19.227Z,1554851779.227 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T23:16:19.227Z,1554851779.227 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T23:16:19.228Z,1554851779.228 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T23:16:19.301Z,1554851779.301 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T23:16:19.325Z,1554851779.325 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T23:16:19.325Z,1554851779.325 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T23:16:19.326Z,1554851779.326 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T23:16:19.326Z,1554851779.326 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T23:16:19.326Z,1554851779.326 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T23:16:19.327Z,1554851779.327 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T23:16:19.327Z,1554851779.327 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T23:16:19.327Z,1554851779.327 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T23:16:19.328Z,1554851779.328 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T23:16:19.328Z,1554851779.328 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T23:16:19.452Z,1554851779.452 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_voltage (volt)
2019-04-09T23:16:19.452Z,1554851779.452 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgVoltage (volt)
2019-04-09T23:16:19.452Z,1554851779.452 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_current (milliampere)
2019-04-09T23:16:19.454Z,1554851779.454 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgCurrent (milliampere)
2019-04-09T23:16:28.398Z,1554851788.398 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-04-09T23:16:33.373Z,1554851793.373 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:16:33.374Z,1554851793.374 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:16:33.415Z,1554851793.415 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T23:16:33.426Z,1554851793.426 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T23:16:33.478Z,1554851793.478 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T23:16:33.480Z,1554851793.480 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T23:16:33.503Z,1554851793.503 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T23:16:33.504Z,1554851793.504 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T23:16:33.517Z,1554851793.517 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T23:16:33.549Z,1554851793.549 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:16:33.568Z,1554851793.568 [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>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <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-09T23:16:33.578Z,1554851793.578 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:16:33.874Z,1554851793.874 [Default] Stopped
2019-04-09T23:16:33.875Z,1554851793.875 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:16:33.875Z,1554851793.875 [Default:B.GoToSurface] Stopped
2019-04-09T23:16:33.875Z,1554851793.875 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:16:33.875Z,1554851793.875 [Default:CheckIn] Stopped
2019-04-09T23:16:33.875Z,1554851793.875 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:16:33.875Z,1554851793.875 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:16:33.875Z,1554851793.875 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T23:16:33.875Z,1554851793.875 [DUSBL] Running Loop=1
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T23:16:33.876Z,1554851793.876 [DUSBL:C] Running Loop=1
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:16:33.877Z,1554851793.877 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:16:33.878Z,1554851793.878 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:16:33.878Z,1554851793.878 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T23:16:33.879Z,1554851793.879 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T23:16:33.879Z,1554851793.879 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:16:33.879Z,1554851793.879 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:16:35.427Z,1554851795.427 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:35.839Z,1554851795.839 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:16:35.841Z,1554851795.841 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:35.912Z,1554851795.912 [Reporter](INFO): acoustic_contact_range 9.479997 m
2019-04-09T23:16:35.917Z,1554851795.917 [Reporter](INFO): DUSBL_Hydroid.xAngle 15.250001 arcdeg
2019-04-09T23:16:38.259Z,1554851798.259 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:38.659Z,1554851798.659 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:39.084Z,1554851799.084 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:16:39.087Z,1554851799.087 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:39.187Z,1554851799.187 [Reporter](INFO): acoustic_contact_range 9.479997 m
2019-04-09T23:16:39.188Z,1554851799.188 [Reporter](INFO): DUSBL_Hydroid.xAngle 15.150000 arcdeg
2019-04-09T23:16:39.471Z,1554851799.471 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:16:39.472Z,1554851799.472 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231638.71*55

2019-04-09T23:16:41.487Z,1554851801.487 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:41.895Z,1554851801.895 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:42.303Z,1554851802.303 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:42.722Z,1554851802.722 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:16:42.725Z,1554851802.725 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:16:42.730Z,1554851802.730 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:16:42.731Z,1554851802.731 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,231641.94*50

2019-04-09T23:16:42.783Z,1554851802.783 [Reporter](INFO): acoustic_contact_range 203.339981 m
2019-04-09T23:16:42.784Z,1554851802.784 [Reporter](INFO): DUSBL_Hydroid.xAngle -27.700000 arcdeg
2019-04-09T23:16:43.770Z,1554851803.770 [CommandLine](IMPORTANT): got command stop
2019-04-09T23:16:43.771Z,1554851803.771 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T23:16:43.954Z,1554851803.954 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:16:43.954Z,1554851803.954 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:16:43.954Z,1554851803.954 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:43.954Z,1554851803.954 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:16:43.955Z,1554851803.955 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:16:43.956Z,1554851803.956 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:16:43.956Z,1554851803.956 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:16:43.956Z,1554851803.956 [MissionManager](INFO): MissionManager is completed.
2019-04-09T23:16:43.956Z,1554851803.956 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:A.Pitch] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:B.SetSpeed] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:C] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:16:43.957Z,1554851803.957 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:44.363Z,1554851804.363 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:16:44.363Z,1554851804.363 [Default] Running Loop=1
2019-04-09T23:16:44.363Z,1554851804.363 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:16:44.363Z,1554851804.363 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:16:44.363Z,1554851804.363 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:16:44.364Z,1554851804.364 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:16:44.364Z,1554851804.364 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:16:44.364Z,1554851804.364 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:16:44.365Z,1554851804.365 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:16:44.365Z,1554851804.365 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:16:44.366Z,1554851804.366 [Default:A.Wait] Running Loop=1
2019-04-09T23:16:44.366Z,1554851804.366 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:16:57.670Z,1554851817.670 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:16:57.670Z,1554851817.670 [Default:A.Wait] Stopped
2019-04-09T23:16:57.670Z,1554851817.670 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:16:58.111Z,1554851818.111 [Default:CheckIn] Running Loop=1
2019-04-09T23:16:58.111Z,1554851818.111 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:16:58.111Z,1554851818.111 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:17:00.479Z,1554851820.479 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T23:17:01.301Z,1554851821.301 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:17:05.741Z,1554851825.741 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:17:06.137Z,1554851826.137 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231611.00,A,3648.16614,N,12147.28217,W,0.000,154.50,090419,,,A*78
2019-04-09T23:17:06.140Z,1554851826.140 [NAL9602](INFO): GPS fix at 20190409T231611: (36.802769, -121.788036)
2019-04-09T23:17:06.216Z,1554851826.216 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:17:06.221Z,1554851826.221 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:17:06.608Z,1554851826.608 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T23:17:09.547Z,1554851829.547 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:17:14.580Z,1554851834.580 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190409T231108/Courier0004.lzma
2019-04-09T23:17:15.386Z,1554851835.386 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Courier0004.lzma.bak
2019-04-09T23:17:15.386Z,1554851835.386 [DataOverHttps](INFO): SBD MOMSN=10521071
2019-04-09T23:17:19.646Z,1554851839.646 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:17:29.228Z,1554851849.228 [DataOverHttps](INFO): Sending 1805 bytes from file Logs/20190409T231108/Express0005.lzma
2019-04-09T23:17:29.750Z,1554851849.750 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:17:30.030Z,1554851850.030 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Express0005.lzma.bak
2019-04-09T23:17:30.030Z,1554851850.030 [DataOverHttps](INFO): SBD MOMSN=10521074
2019-04-09T23:17:30.996Z,1554851850.996 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:17:30.996Z,1554851850.996 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:17:30.996Z,1554851850.996 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:17:38.620Z,1554851858.620 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:17:39.847Z,1554851859.847 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:17:49.950Z,1554851869.950 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:00.052Z,1554851880.052 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:10.160Z,1554851890.160 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:19.847Z,1554851899.847 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:29.546Z,1554851909.546 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:39.650Z,1554851919.650 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:49.746Z,1554851929.746 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:18:49.749Z,1554851929.749 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-04-09T23:18:54.597Z,1554851934.597 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-04-09T23:18:59.846Z,1554851939.846 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:19:09.945Z,1554851949.945 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:19:20.059Z,1554851960.059 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:19:30.161Z,1554851970.161 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:20:00.457Z,1554852000.457 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-09T23:20:00.457Z,1554852000.457 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-04-09T23:22:01.247Z,1554852121.247 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:11.354Z,1554852131.354 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:21.453Z,1554852141.453 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:31.547Z,1554852151.547 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:31.568Z,1554852151.568 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:22:31.568Z,1554852151.568 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:22:31.568Z,1554852151.568 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:22:31.568Z,1554852151.568 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:22:31.962Z,1554852151.962 [Default:CheckIn:D] Stopped
2019-04-09T23:22:31.962Z,1554852151.962 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:22:32.416Z,1554852152.416 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.793311 min 
2019-04-09T23:22:32.416Z,1554852152.416 [Default:CheckIn:E] Stopped
2019-04-09T23:22:32.416Z,1554852152.416 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:22:32.417Z,1554852152.417 [Default:CheckIn] Stopped
2019-04-09T23:22:32.417Z,1554852152.417 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:22:32.417Z,1554852152.417 [Default:CheckIn](INFO): Running loop #2
2019-04-09T23:22:32.417Z,1554852152.417 [Default:CheckIn] Running Loop=2
2019-04-09T23:22:32.417Z,1554852152.417 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:22:32.418Z,1554852152.418 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:22:33.961Z,1554852153.961 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:22:34.353Z,1554852154.353 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232139.00,A,3648.16653,N,12147.27958,W,0.019,154.50,090419,,,A*72
2019-04-09T23:22:34.355Z,1554852154.355 [NAL9602](INFO): GPS fix at 20190409T232139: (36.802776, -121.787993)
2019-04-09T23:22:34.388Z,1554852154.388 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:22:34.388Z,1554852154.388 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:22:40.204Z,1554852160.204 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190409T231108/Courier0007.lzma
2019-04-09T23:22:41.010Z,1554852161.010 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Courier0007.lzma.bak
2019-04-09T23:22:41.010Z,1554852161.010 [DataOverHttps](INFO): SBD MOMSN=10521135
2019-04-09T23:22:41.656Z,1554852161.656 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:51.755Z,1554852171.755 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:22:52.858Z,1554852172.858 [DataOverHttps](INFO): Sending 1061 bytes from file Logs/20190409T231108/Express0008.lzma
2019-04-09T23:22:53.662Z,1554852173.662 [DataOverHttps](INFO): Moved sent file to Logs/20190409T231108/Express0008.lzma.bak
2019-04-09T23:22:53.662Z,1554852173.662 [DataOverHttps](INFO): SBD MOMSN=10521138
2019-04-09T23:22:54.166Z,1554852174.166 [CommandLine](IMPORTANT): got command show stack
2019-04-09T23:22:54.166Z,1554852174.166 [CommandLine](IMPORTANT): Behavior Stack:

2019-04-09T23:22:54.166Z,1554852174.166 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-04-09T23:22:54.166Z,1554852174.166 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_Iridium
2019-04-09T23:22:54.576Z,1554852174.576 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:22:54.576Z,1554852174.576 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:22:54.576Z,1554852174.576 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:22:56.636Z,1554852176.636 [CommandLine](IMPORTANT): got command show variable range
2019-04-09T23:22:56.637Z,1554852176.637 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-09T23:22:56.866Z,1554852176.866 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T23:22:56.867Z,1554852176.867 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-09T23:22:56.868Z,1554852176.868 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-09T23:22:56.876Z,1554852176.876 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-09T23:22:56.876Z,1554852176.876 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-09T23:22:56.881Z,1554852176.881 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-09T23:22:56.882Z,1554852176.882 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-09T23:23:01.448Z,1554852181.448 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:23:03.673Z,1554852183.673 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-09T23:23:05.080Z,1554852185.080 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-04-09T23:23:05.153Z,1554852185.153 [NAL9602](FAULT): received: 
+CSQ:0

OK
2019-04-09T23:23:05.153Z,1554852185.153 [NAL9602] Data Fault, FailCount= 1
2019-04-09T23:23:05.153Z,1554852185.153 [NAL9602](ERROR): Data Fault
2019-04-09T23:23:05.298Z,1554852185.298 [CBIT](ERROR): Data Fault in component: NAL9602
2019-04-09T23:23:05.455Z,1554852185.455 [NAL9602](INFO): Powering down
2019-04-09T23:23:05.911Z,1554852185.911 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T23:23:05.000Z,1554852186.000 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T23:23:06.008Z,1554852186.008 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T23:23:06.009Z,1554852186.009 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T23:23:06.009Z,1554852186.009 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T23:23:06.010Z,1554852186.010 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T23:23:06.010Z,1554852186.010 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T23:23:06.011Z,1554852186.011 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T23:23:06.011Z,1554852186.011 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T23:23:06.011Z,1554852186.011 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T23:23:06.012Z,1554852186.012 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T23:23:06.012Z,1554852186.012 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T23:23:06.012Z,1554852186.012 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T23:23:06.115Z,1554852186.115 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T23:23:06.116Z,1554852186.116 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T23:23:06.116Z,1554852186.116 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T23:23:06.141Z,1554852186.141 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T23:23:06.141Z,1554852186.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T23:23:06.142Z,1554852186.142 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T23:23:06.142Z,1554852186.142 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T23:23:06.142Z,1554852186.142 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T23:23:06.143Z,1554852186.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T23:23:06.143Z,1554852186.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T23:23:06.143Z,1554852186.143 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T23:23:06.144Z,1554852186.144 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T23:23:06.144Z,1554852186.144 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T23:23:06.153Z,1554852186.153 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T23:23:06.227Z,1554852186.227 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_voltage (volt)
2019-04-09T23:23:06.227Z,1554852186.227 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgVoltage (volt)
2019-04-09T23:23:06.228Z,1554852186.228 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_current (milliampere)
2019-04-09T23:23:06.228Z,1554852186.228 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgCurrent (milliampere)
2019-04-09T23:23:06.413Z,1554852186.413 [CBIT](INFO): Clearing failed state for component NAL9602
2019-04-09T23:23:06.413Z,1554852186.413 [NAL9602] No Fault, FailCount= 1
2019-04-09T23:23:11.140Z,1554852191.140 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:23:12.105Z,1554852192.105 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-04-09T23:23:17.030Z,1554852197.030 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:23:17.031Z,1554852197.031 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:23:17.114Z,1554852197.114 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T23:23:17.117Z,1554852197.117 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T23:23:17.119Z,1554852197.119 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T23:23:17.121Z,1554852197.121 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T23:23:17.123Z,1554852197.123 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T23:23:17.124Z,1554852197.124 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T23:23:17.129Z,1554852197.129 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T23:23:17.136Z,1554852197.136 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T23:23:17.141Z,1554852197.141 [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>
        <When>
            <Arg Name="EnabledDUSBL"/>
        </When>
            <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-09T23:23:17.143Z,1554852197.143 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T23:23:17.216Z,1554852197.216 [Default] Stopped
2019-04-09T23:23:17.216Z,1554852197.216 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:23:17.216Z,1554852197.216 [Default:B.GoToSurface] Stopped
2019-04-09T23:23:17.216Z,1554852197.216 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:23:17.216Z,1554852197.216 [Default:CheckIn] Stopped
2019-04-09T23:23:17.216Z,1554852197.216 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:23:17.216Z,1554852197.216 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:23:17.216Z,1554852197.216 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:23:17.221Z,1554852197.221 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL] Running Loop=1
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:23:17.221Z,1554852197.221 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:C] Running Loop=1
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:23:17.222Z,1554852197.222 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:23:17.223Z,1554852197.223 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:23:17.223Z,1554852197.223 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:23:17.224Z,1554852197.224 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T23:23:17.224Z,1554852197.224 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T23:23:17.229Z,1554852197.229 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T23:23:17.229Z,1554852197.229 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T23:23:18.791Z,1554852198.791 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:19.191Z,1554852199.191 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:23:19.193Z,1554852199.193 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:19.234Z,1554852199.234 [Reporter](INFO): acoustic_contact_range 64.200005 m
2019-04-09T23:23:19.235Z,1554852199.235 [Reporter](INFO): DUSBL_Hydroid.xAngle 42.400001 arcdeg
2019-04-09T23:23:21.251Z,1554852201.251 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:23:21.615Z,1554852201.615 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:22.037Z,1554852202.037 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:22.447Z,1554852202.447 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:23:22.450Z,1554852202.450 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:22.606Z,1554852202.606 [Reporter](INFO): acoustic_contact_range 4.440000 m
2019-04-09T23:23:22.606Z,1554852202.606 [Reporter](INFO): DUSBL_Hydroid.xAngle 32.950001 arcdeg
2019-04-09T23:23:22.831Z,1554852202.831 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:23:22.832Z,1554852202.832 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,232322.07*59

2019-04-09T23:23:24.847Z,1554852204.847 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:25.251Z,1554852205.251 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:25.655Z,1554852205.655 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:26.071Z,1554852206.071 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:26.076Z,1554852206.076 [Micromodem](ERROR): Response from modem unexpected: $CATXF,280*5E

2019-04-09T23:23:26.078Z,1554852206.078 [Micromodem](ERROR): Response from modem unexpected: $SNTTA,,,,,232325.29*52

2019-04-09T23:23:26.463Z,1554852206.463 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T23:23:26.465Z,1554852206.465 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:26.510Z,1554852206.510 [Reporter](INFO): acoustic_contact_range 9.540000 m
2019-04-09T23:23:26.510Z,1554852206.510 [Reporter](INFO): DUSBL_Hydroid.xAngle 15.350000 arcdeg
2019-04-09T23:23:27.308Z,1554852207.308 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T23:23:27.309Z,1554852207.309 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:23:27.309Z,1554852207.309 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:23:27.309Z,1554852207.309 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T23:23:27.309Z,1554852207.309 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T23:23:27.310Z,1554852207.310 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:23:28.891Z,1554852208.891 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T23:23:29.015Z,1554852209.015 [CommandLine](IMPORTANT): got command stop
2019-04-09T23:23:29.016Z,1554852209.016 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T23:23:29.052Z,1554852209.052 [MissionManager](INFO): MissionManager is completed.
2019-04-09T23:23:29.052Z,1554852209.052 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:A.Pitch] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:B.SetSpeed] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:C] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T23:23:29.053Z,1554852209.053 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:23:29.335Z,1554852209.335 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T23:23:29.336Z,1554852209.336 [Default] Running Loop=1
2019-04-09T23:23:29.336Z,1554852209.336 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T23:23:29.336Z,1554852209.336 [Default:B.GoToSurface] Running Loop=1
2019-04-09T23:23:29.336Z,1554852209.336 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T23:23:29.336Z,1554852209.336 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T23:23:29.353Z,1554852209.353 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T23:23:29.353Z,1554852209.353 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T23:23:29.353Z,1554852209.353 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T23:23:29.354Z,1554852209.354 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T23:23:29.354Z,1554852209.354 [Default:A.Wait] Running Loop=1
2019-04-09T23:23:29.354Z,1554852209.354 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:23:31.349Z,1554852211.349 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:23:35.755Z,1554852215.755 [NAL9602](INFO): Powering up NAL9602
2019-04-09T23:23:41.039Z,1554852221.039 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:23:42.654Z,1554852222.654 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T23:23:42.655Z,1554852222.655 [Default:A.Wait] Stopped
2019-04-09T23:23:42.655Z,1554852222.655 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:23:43.054Z,1554852223.054 [Default:CheckIn] Running Loop=1
2019-04-09T23:23:43.054Z,1554852223.054 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:23:43.055Z,1554852223.055 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:23:46.663Z,1554852226.663 [NAL9602](INFO): NAL9602 initialized
2019-04-09T23:23:47.485Z,1554852227.485 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:23:50.736Z,1554852230.736 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:24:00.847Z,1554852240.847 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:24:10.543Z,1554852250.543 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:24:20.231Z,1554852260.231 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:24:32.922Z,1554852272.922 [CommandLine](IMPORTANT): got command restart application
2019-04-09T23:24:33.929Z,1554852273.929 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:33.929Z,1554852273.929 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:33.930Z,1554852273.930 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-04-09T23:24:33.930Z,1554852273.930 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:33.930Z,1554852273.930 [CommandLine](INFO): Join timeout helper Thread ID is 1568
2019-04-09T23:24:33.934Z,1554852273.934 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-09T23:24:33.934Z,1554852273.934 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:33.938Z,1554852273.938 [NavChartDb](INFO): Join timeout helper Thread ID is 1569
2019-04-09T23:24:34.289Z,1554852274.289 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:34.289Z,1554852274.289 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.297Z,1554852274.297 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-09T23:24:34.297Z,1554852274.297 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.297Z,1554852274.297 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1570
2019-04-09T23:24:34.641Z,1554852274.641 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:34.641Z,1554852274.641 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T23:24:34.642Z,1554852274.642 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.657Z,1554852274.657 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-09T23:24:34.657Z,1554852274.657 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.657Z,1554852274.657 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1571
2019-04-09T23:24:34.785Z,1554852274.785 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:34.785Z,1554852274.785 [CTD_NeilBrown](INFO): Powering down
2019-04-09T23:24:34.797Z,1554852274.797 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.801Z,1554852274.801 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-09T23:24:34.801Z,1554852274.801 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:34.801Z,1554852274.801 [Radio_Surface](INFO): Join timeout helper Thread ID is 1572
2019-04-09T23:24:35.038Z,1554852275.038 [Radio_Surface](INFO): Powering down
2019-04-09T23:24:35.040Z,1554852275.040 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:35.041Z,1554852275.041 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.051Z,1554852275.051 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-09T23:24:35.052Z,1554852275.052 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.053Z,1554852275.053 [DataOverHttps](INFO): Join timeout helper Thread ID is 1573
2019-04-09T23:24:35.317Z,1554852275.317 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:35.318Z,1554852275.318 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.338Z,1554852275.338 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-09T23:24:35.338Z,1554852275.338 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.338Z,1554852275.338 [logger](INFO): Join timeout helper Thread ID is 1574
2019-04-09T23:24:35.401Z,1554852275.401 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:35.401Z,1554852275.401 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.417Z,1554852275.417 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-09T23:24:35.417Z,1554852275.417 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.418Z,1554852275.418 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-09T23:24:35.418Z,1554852275.418 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.418Z,1554852275.418 [controlThread](INFO): Join timeout helper Thread ID is 1575
2019-04-09T23:24:35.529Z,1554852275.529 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:24:35.529Z,1554852275.529 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-09T23:24:35.529Z,1554852275.529 [AHRS_M2](INFO): Powering down
2019-04-09T23:24:35.601Z,1554852275.601 [DUSBL_Hydroid](INFO): Powering down
2019-04-09T23:24:35.673Z,1554852275.673 [Micromodem](INFO): Powering down
2019-04-09T23:24:35.769Z,1554852275.769 [NAL9602](INFO): Powering down
2019-04-09T23:24:35.841Z,1554852275.841 [RDI_Pathfinder](INFO): Powering down
2019-04-09T23:24:35.843Z,1554852275.843 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-09T23:24:35.843Z,1554852275.843 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-09T23:24:35.844Z,1554852275.844 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-09T23:24:35.845Z,1554852275.845 [MissionManager](INFO): Uninitializing Mission Default
2019-04-09T23:24:35.845Z,1554852275.845 [Default] Stopped
2019-04-09T23:24:35.845Z,1554852275.845 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:24:35.845Z,1554852275.845 [Default:B.GoToSurface] Stopped
2019-04-09T23:24:35.845Z,1554852275.845 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:24:35.845Z,1554852275.845 [Default:CheckIn] Stopped
2019-04-09T23:24:35.845Z,1554852275.845 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:24:35.845Z,1554852275.845 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:24:35.847Z,1554852275.847 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-09T23:24:35.848Z,1554852275.848 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-09T23:24:35.848Z,1554852275.848 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-09T23:24:35.848Z,1554852275.848 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-09T23:24:35.849Z,1554852275.849 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-09T23:24:35.849Z,1554852275.849 [BuoyancyServo](INFO): Powering down
2019-04-09T23:24:35.861Z,1554852275.861 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-09T23:24:35.861Z,1554852275.861 [ElevatorServo](INFO): Powering down
2019-04-09T23:24:35.862Z,1554852275.862 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-09T23:24:35.862Z,1554852275.862 [MassServo](INFO): Powering down
2019-04-09T23:24:35.863Z,1554852275.863 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T23:24:35.863Z,1554852275.863 [RudderServo](INFO): Powering down
2019-04-09T23:24:35.863Z,1554852275.863 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-09T23:24:35.864Z,1554852275.864 [ThrusterServo](INFO): Powering down
2019-04-09T23:24:35.864Z,1554852275.864 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-09T23:24:35.865Z,1554852275.865 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-09T23:24:35.865Z,1554852275.865 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-09T23:24:35.865Z,1554852275.865 [CBIT](DEBUG): Powering off loads.
2019-04-09T23:24:35.877Z,1554852275.877 [CBIT](DEBUG): Disabling WDT.
2019-04-09T23:24:35.888Z,1554852275.888 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-09T23:24:35.889Z,1554852275.889 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.936Z,1554852275.936 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.945Z,1554852275.945 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.989Z,1554852275.989 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:35.991Z,1554852275.991 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:36.046Z,1554852276.046 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:24:36.117Z,1554852276.117 [logger ThreadHandler](INFO): Thread cancelled.