2019-07-10T23:16:49.907Z,1562800609.907 [Supervisor](DEBUG): Initializing supervisor.
2019-07-10T23:16:49.918Z,1562800609.918 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-10T23:16:49.919Z,1562800609.919 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-07-10T23:16:49.919Z,1562800609.919 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-10T23:16:49.930Z,1562800609.930 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-10T23:16:49.931Z,1562800609.931 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-07-10T23:16:49.933Z,1562800609.933 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-10T23:16:49.955Z,1562800609.955 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-10T23:16:49.966Z,1562800609.966 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-10T23:16:49.967Z,1562800609.967 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-07-10T23:16:49.968Z,1562800609.968 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-10T23:16:49.978Z,1562800609.978 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-10T23:16:49.979Z,1562800609.979 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-07-10T23:16:49.981Z,1562800609.981 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-10T23:16:49.981Z,1562800609.981 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-10T23:16:49.985Z,1562800609.985 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-10T23:16:50.834Z,1562800610.834 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-10T23:16:50.836Z,1562800610.836 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-10T23:16:51.001Z,1562800611.001 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-10T23:16:51.003Z,1562800611.003 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-10T23:16:51.617Z,1562800611.617 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-10T23:16:51.618Z,1562800611.618 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-10T23:16:51.864Z,1562800611.864 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-10T23:16:51.866Z,1562800611.866 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-10T23:16:52.067Z,1562800612.067 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-10T23:16:52.069Z,1562800612.069 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-10T23:16:52.550Z,1562800612.550 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-10T23:16:52.551Z,1562800612.551 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-10T23:16:52.951Z,1562800612.951 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-10T23:16:52.953Z,1562800612.953 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-10T23:16:53.095Z,1562800613.095 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-10T23:16:53.097Z,1562800613.097 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-10T23:16:53.287Z,1562800613.287 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-10T23:16:53.288Z,1562800613.288 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-10T23:16:53.383Z,1562800613.383 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-10T23:16:53.385Z,1562800613.385 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-10T23:16:53.680Z,1562800613.680 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-10T23:16:53.681Z,1562800613.681 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-10T23:16:53.761Z,1562800613.761 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-10T23:16:53.862Z,1562800613.862 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-10T23:16:53.864Z,1562800613.864 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-10T23:16:54.447Z,1562800614.447 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-10T23:16:54.447Z,1562800614.447 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-10T23:16:54.832Z,1562800614.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-10T23:16:54.834Z,1562800614.834 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-07-10T23:16:54.837Z,1562800614.837 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-07-10T23:16:55.044Z,1562800615.044 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-07-10T23:16:55.143Z,1562800615.143 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-07-10T23:16:55.241Z,1562800615.241 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-07-10T23:16:55.466Z,1562800615.466 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-10T23:16:55.467Z,1562800615.467 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-07-10T23:16:55.551Z,1562800615.551 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-07-10T23:16:55.644Z,1562800615.644 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-07-10T23:16:55.741Z,1562800615.741 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-07-10T23:16:55.822Z,1562800615.822 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-07-10T23:16:55.928Z,1562800615.928 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-07-10T23:16:56.105Z,1562800616.105 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-07-10T23:16:56.232Z,1562800616.232 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-07-10T23:16:56.236Z,1562800616.236 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-10T23:16:56.969Z,1562800616.969 [AHRS_M2] Loaded
2019-07-10T23:16:56.969Z,1562800616.969 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-07-10T23:16:57.110Z,1562800617.110 [DataOverHttps] Loaded
2019-07-10T23:16:57.111Z,1562800617.111 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-10T23:16:57.112Z,1562800617.112 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407654E0
2019-07-10T23:16:57.112Z,1562800617.112 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 888
2019-07-10T23:16:57.125Z,1562800617.125 [Depth_Keller] Loaded
2019-07-10T23:16:57.125Z,1562800617.125 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-10T23:16:57.130Z,1562800617.130 [DropWeight] Loaded
2019-07-10T23:16:57.130Z,1562800617.130 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-07-10T23:16:57.187Z,1562800617.187 [DUSBL_Hydroid] Loaded
2019-07-10T23:16:57.187Z,1562800617.187 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-07-10T23:16:57.235Z,1562800617.235 [Micromodem] Loaded
2019-07-10T23:16:57.235Z,1562800617.235 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-07-10T23:16:57.333Z,1562800617.333 [NAL9602] Loaded
2019-07-10T23:16:57.333Z,1562800617.333 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-10T23:16:57.348Z,1562800617.348 [Onboard] Loaded
2019-07-10T23:16:57.349Z,1562800617.349 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-10T23:16:57.355Z,1562800617.355 [PowerOnly] Loaded
2019-07-10T23:16:57.355Z,1562800617.355 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-07-10T23:16:57.362Z,1562800617.362 [Radio_Surface] Loaded
2019-07-10T23:16:57.362Z,1562800617.362 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-10T23:16:57.363Z,1562800617.363 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407954E0
2019-07-10T23:16:57.363Z,1562800617.363 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 889
2019-07-10T23:16:57.407Z,1562800617.407 [RDI_Pathfinder] Loaded
2019-07-10T23:16:57.407Z,1562800617.407 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-07-10T23:16:58.890Z,1562800618.890 [BPC1] Loaded
2019-07-10T23:16:58.890Z,1562800618.890 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-10T23:16:58.891Z,1562800618.891 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-10T23:16:58.892Z,1562800618.892 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-10T23:16:58.947Z,1562800618.947 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-10T23:16:58.948Z,1562800618.948 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-10T23:16:59.573Z,1562800619.573 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-10T23:16:59.574Z,1562800619.574 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-10T23:16:59.594Z,1562800619.594 [NavChart] Loaded
2019-07-10T23:16:59.594Z,1562800619.594 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-10T23:16:59.598Z,1562800619.598 [UniversalFixResidualReporter] Loaded
2019-07-10T23:16:59.598Z,1562800619.598 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-10T23:16:59.599Z,1562800619.599 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-10T23:16:59.600Z,1562800619.600 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-10T23:16:59.729Z,1562800619.729 [BuoyancyServo] Loaded
2019-07-10T23:16:59.730Z,1562800619.730 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-10T23:16:59.745Z,1562800619.745 [ElevatorServo] Loaded
2019-07-10T23:16:59.745Z,1562800619.745 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-10T23:16:59.760Z,1562800619.760 [MassServo] Loaded
2019-07-10T23:16:59.760Z,1562800619.760 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-10T23:16:59.775Z,1562800619.775 [RudderServo] Loaded
2019-07-10T23:16:59.775Z,1562800619.775 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-10T23:16:59.790Z,1562800619.790 [ThrusterServo] Loaded
2019-07-10T23:16:59.790Z,1562800619.790 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-10T23:16:59.791Z,1562800619.791 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-10T23:16:59.791Z,1562800619.791 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-10T23:17:00.113Z,1562800620.113 [CTD_NeilBrown] Loaded
2019-07-10T23:17:00.113Z,1562800620.113 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-07-10T23:17:00.114Z,1562800620.114 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E04E0
2019-07-10T23:17:00.115Z,1562800620.115 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 890
2019-07-10T23:17:00.159Z,1562800620.159 [WetLabsSeaOWL_UV_A] Loaded
2019-07-10T23:17:00.159Z,1562800620.159 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-07-10T23:17:00.160Z,1562800620.160 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409104E0
2019-07-10T23:17:00.161Z,1562800620.161 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 891
2019-07-10T23:17:00.161Z,1562800620.161 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-10T23:17:00.162Z,1562800620.162 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-10T23:17:00.502Z,1562800620.502 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-10T23:17:00.504Z,1562800620.504 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-10T23:17:00.560Z,1562800620.560 [DepthRateCalculator] Loaded
2019-07-10T23:17:00.560Z,1562800620.560 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-10T23:17:00.566Z,1562800620.566 [PitchRateCalculator] Loaded
2019-07-10T23:17:00.566Z,1562800620.566 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-10T23:17:00.578Z,1562800620.578 [SpeedCalculator] Loaded
2019-07-10T23:17:00.579Z,1562800620.579 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-10T23:17:00.599Z,1562800620.599 [TempGradientCalculator] Loaded
2019-07-10T23:17:00.600Z,1562800620.600 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-10T23:17:00.605Z,1562800620.605 [YawRateCalculator] Loaded
2019-07-10T23:17:00.605Z,1562800620.605 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-10T23:17:00.646Z,1562800620.646 [ElevatorOffsetCalculator] Loaded
2019-07-10T23:17:00.646Z,1562800620.646 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-10T23:17:00.647Z,1562800620.647 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-10T23:17:00.647Z,1562800620.647 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-10T23:17:00.809Z,1562800620.809 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-10T23:17:00.831Z,1562800620.831 [SBIT] Loaded
2019-07-10T23:17:00.831Z,1562800620.831 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-10T23:17:00.832Z,1562800620.832 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-10T23:17:00.843Z,1562800620.843 [IBIT] Loaded
2019-07-10T23:17:00.844Z,1562800620.844 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-10T23:17:00.847Z,1562800620.847 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-10T23:17:00.987Z,1562800620.987 [CBIT] Loaded
2019-07-10T23:17:00.988Z,1562800620.988 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-10T23:17:00.988Z,1562800620.988 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-10T23:17:00.989Z,1562800620.989 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-10T23:17:01.112Z,1562800621.112 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-10T23:17:01.112Z,1562800621.112 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-10T23:17:01.237Z,1562800621.237 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-10T23:17:01.237Z,1562800621.237 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-10T23:17:01.325Z,1562800621.325 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-10T23:17:01.408Z,1562800621.408 [VerticalControl] Loaded
2019-07-10T23:17:01.409Z,1562800621.409 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-10T23:17:01.409Z,1562800621.409 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-10T23:17:01.466Z,1562800621.466 [HorizontalControl] Loaded
2019-07-10T23:17:01.466Z,1562800621.466 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-10T23:17:01.467Z,1562800621.467 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-10T23:17:01.469Z,1562800621.469 [SpeedControl] Loaded
2019-07-10T23:17:01.469Z,1562800621.469 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-10T23:17:01.470Z,1562800621.470 [LoopControl](DEBUG): Construct LoopControl.
2019-07-10T23:17:01.470Z,1562800621.470 [LoopControl] Loaded
2019-07-10T23:17:01.471Z,1562800621.471 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-10T23:17:01.471Z,1562800621.471 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-10T23:17:01.472Z,1562800621.472 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-10T23:17:01.519Z,1562800621.519 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-10T23:17:01.523Z,1562800621.523 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-10T23:17:01.524Z,1562800621.524 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-10T23:17:01.530Z,1562800621.530 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-10T23:17:01.531Z,1562800621.531 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AEC4E0
2019-07-10T23:17:01.532Z,1562800621.532 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 892
2019-07-10T23:17:01.536Z,1562800621.536 [Supervisor](INFO): Main Thread ID is 802
2019-07-10T23:17:01.536Z,1562800621.536 [Supervisor](DEBUG): Running supervisor.
2019-07-10T23:17:01.537Z,1562800621.537 [CommandLine ThreadHandler](INFO): Handler Thread ID is 893
2019-07-10T23:17:01.539Z,1562800621.539 [controlThread ThreadHandler](INFO): Handler Thread ID is 894
2019-07-10T23:17:01.540Z,1562800621.540 [controlThread](DEBUG): Initializing ControlThread
2019-07-10T23:17:01.546Z,1562800621.546 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-10T23:17:01.546Z,1562800621.546 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-10T23:17:01.547Z,1562800621.547 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-10T23:17:01.547Z,1562800621.547 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-10T23:17:01.548Z,1562800621.548 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-10T23:17:01.548Z,1562800621.548 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-10T23:17:01.548Z,1562800621.548 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-10T23:17:01.549Z,1562800621.549 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-10T23:17:01.549Z,1562800621.549 [SBIT](INFO): Initialize SBIT Component.
2019-07-10T23:17:01.550Z,1562800621.550 [SBIT](IMPORTANT): git: 2019-07-01-2-g8df750c
2019-07-10T23:17:01.550Z,1562800621.550 [SBIT](INFO): git hash: 8df750cfd7ab665d8785a0cb54650bf6fbbccb32
2019-07-10T23:17:01.551Z,1562800621.551 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-10T23:17:01.552Z,1562800621.552 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-07-10T23:17:01.553Z,1562800621.553 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-07-10T23:17:01.553Z,1562800621.553 [IBIT](INFO): Initialize IBIT Component.
2019-07-10T23:17:01.554Z,1562800621.554 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-10T23:17:01.555Z,1562800621.555 [logger ThreadHandler](INFO): Handler Thread ID is 895
2019-07-10T23:17:01.566Z,1562800621.566 [CBIT](DEBUG): Initialized mux pins.
2019-07-10T23:17:01.566Z,1562800621.566 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-07-10T23:17:01.567Z,1562800621.567 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-10T23:17:01.575Z,1562800621.575 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 896
2019-07-10T23:17:01.576Z,1562800621.576 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-10T23:17:01.587Z,1562800621.587 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 897
2019-07-10T23:17:01.590Z,1562800621.590 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-10T23:17:01.590Z,1562800621.590 [CBIT](DEBUG): Initializing heartbeat.
2019-07-10T23:17:01.599Z,1562800621.599 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 898
2019-07-10T23:17:01.600Z,1562800621.600 [CTD_NeilBrown](INFO): Powering down
2019-07-10T23:17:01.627Z,1562800621.627 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 899
2019-07-10T23:17:01.628Z,1562800621.628 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-10T23:17:01.662Z,1562800621.662 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-10T23:17:01.662Z,1562800621.662 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-10T23:17:01.663Z,1562800621.663 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 900
2019-07-10T23:17:01.671Z,1562800621.671 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-10T23:17:01.672Z,1562800621.672 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-10T23:17:01.673Z,1562800621.673 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-10T23:17:01.674Z,1562800621.674 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-10T23:17:01.674Z,1562800621.674 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-10T23:17:01.674Z,1562800621.674 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-10T23:17:01.698Z,1562800621.698 [CBIT](DEBUG): Backplane powered.
2019-07-10T23:17:01.699Z,1562800621.699 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-10T23:17:01.700Z,1562800621.700 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-10T23:17:01.701Z,1562800621.701 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-10T23:17:01.702Z,1562800621.702 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-10T23:17:01.703Z,1562800621.703 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-10T23:17:01.725Z,1562800621.725 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-10T23:17:01.752Z,1562800621.752 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-07-10T23:17:01.753Z,1562800621.753 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-10T23:17:01.835Z,1562800621.835 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-10T23:17:01.836Z,1562800621.836 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-10T23:17:01.838Z,1562800621.838 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-10T23:17:01.873Z,1562800621.873 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-10T23:17:01.875Z,1562800621.875 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-10T23:17:01.897Z,1562800621.897 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-10T23:17:01.900Z,1562800621.900 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-07-10T23:17:01.910Z,1562800621.910 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-10T23:17:01.925Z,1562800621.925 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-07-10T23:17:01.990Z,1562800621.990 [Radio_Surface](INFO): Powering up
2019-07-10T23:17:02.061Z,1562800622.061 [DUSBL_Hydroid](INFO): Powering up
2019-07-10T23:17:02.061Z,1562800622.061 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-07-10T23:17:02.152Z,1562800622.152 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:02.159Z,1562800622.159 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-10T23:17:02.160Z,1562800622.160 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:02.167Z,1562800622.167 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-10T23:17:02.167Z,1562800622.167 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:02.175Z,1562800622.175 [MassServo](DEBUG): Initializing MassServo.
2019-07-10T23:17:02.175Z,1562800622.175 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:02.183Z,1562800622.183 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-10T23:17:02.183Z,1562800622.183 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:02.191Z,1562800622.191 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-10T23:17:02.355Z,1562800622.355 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-07-10T23:17:02.356Z,1562800622.356 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-07-10T23:17:02.356Z,1562800622.356 [DropWeight] Hardware Fault, FailCount= 1
2019-07-10T23:17:02.356Z,1562800622.356 [DropWeight](ERROR): Hardware Fault
2019-07-10T23:17:02.358Z,1562800622.358 [Micromodem](INFO): Powering up
2019-07-10T23:17:02.358Z,1562800622.358 [Micromodem](DEBUG): Initializing Micromodem.
2019-07-10T23:17:02.423Z,1562800622.423 [CommandLine](FAULT): Scheduling is paused
2019-07-10T23:17:02.423Z,1562800622.423 [CBIT](INFO): Critical error at 20190710T231702
2019-07-10T23:17:02.423Z,1562800622.423 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-07-10T23:17:02.426Z,1562800622.426 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-07-10T23:17:02.426Z,1562800622.426 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-07-10T23:17:03.050Z,1562800623.050 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-10T23:17:03.050Z,1562800623.050 [RudderServo](FAULT): Rudder failed to initialize
2019-07-10T23:17:03.051Z,1562800623.051 [RudderServo] Communications Fault, FailCount= 1
2019-07-10T23:17:03.051Z,1562800623.051 [RudderServo](ERROR): Communications Fault
2019-07-10T23:17:03.184Z,1562800623.184 [CBIT](INFO): Critical error at 20190710T231702
2019-07-10T23:17:03.186Z,1562800623.186 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-10T23:17:03.355Z,1562800623.355 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-10T23:17:03.355Z,1562800623.355 [RudderServo](INFO): Powering down
2019-07-10T23:17:04.031Z,1562800624.031 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-10T23:17:04.151Z,1562800624.151 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-10T23:17:04.155Z,1562800624.155 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-10T23:17:04.155Z,1562800624.155 [RudderServo] No Fault, FailCount= 1
2019-07-10T23:17:07.274Z,1562800627.274 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-07-10T23:17:07.677Z,1562800627.677 [Micromodem](INFO): Nmea in: $CATMG,2019-07-10T23:17:06Z,RTC,RTC*73

2019-07-10T23:17:07.677Z,1562800627.677 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-07-10T23:17:06Z,RTC,RTC*73

2019-07-10T23:17:08.164Z,1562800628.164 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-07-10T23:17:08.165Z,1562800628.165 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-07-10T23:17:08.564Z,1562800628.564 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-07-10T23:17:08.565Z,1562800628.565 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-07-10T23:17:08.969Z,1562800628.969 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-07-10T23:17:08.969Z,1562800628.969 [Micromodem](INFO): Nmea out: $CCCFG,nav.nst,1*4D

2019-07-10T23:17:09.372Z,1562800629.372 [Micromodem](INFO): Nmea in: $CACFG,nav.nst,1*4F

2019-07-10T23:17:09.373Z,1562800629.373 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-07-10T23:17:09.776Z,1562800629.776 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-07-10T23:17:09.777Z,1562800629.777 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-07-10T23:17:10.172Z,1562800630.172 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-07-10T23:17:10.173Z,1562800630.173 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-07-10T23:17:10.565Z,1562800630.565 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-07-10T23:17:10.565Z,1562800630.565 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-07-10T23:17:10.964Z,1562800630.964 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-07-10T23:17:10.965Z,1562800630.965 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-07-10T23:17:11.376Z,1562800631.376 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-07-10T23:17:11.377Z,1562800631.377 [Micromodem](INFO): Nmea out: $CCCLK,2019,07,10,23,17,12*4C

2019-07-10T23:17:11.768Z,1562800631.768 [Micromodem](INFO): Nmea in: $CACLK,2019,7,10,23,17,12*7E

2019-07-10T23:17:12.585Z,1562800632.585 [Micromodem](INFO): Nmea in: $CATMS,0,2019-07-10T23:17:13Z*7F

2019-07-10T23:17:12.604Z,1562800632.604 [Micromodem](INFO): Nmea in: $CATMG,2019-07-10T23:17:13Z,USER_CMD,RTC*36

2019-07-10T23:17:15.426Z,1562800635.426 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-07-10T23:17:20.248Z,1562800640.248 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-07-10T23:17:27.517Z,1562800647.517 [NAL9602](INFO): Powering up NAL9602
2019-07-10T23:17:29.985Z,1562800649.985 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-10T23:17:29.993Z,1562800649.993 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-10T23:17:38.520Z,1562800658.520 [NAL9602](INFO): NAL9602 initialized
2019-07-10T23:17:39.331Z,1562800659.331 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:17:41.014Z,1562800661.014 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.022483
CHAN A1 (24V): -0.026834
CHAN A2 (12V): -0.006700
CHAN A3 (5V): -0.002015
CHAN B0 (3.3V): 0.000316
CHAN B1 (3.15aV): 0.000067
CHAN B2 (3.15bV): 0.000117
CHAN B3 (GND): 0.001803
OPEN: 0.009199
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-10T23:18:07.766Z,1562800687.766 [NAL9602](INFO): SBD MO Status=2, MOMSN=8105, MT Status=2, MTMSN=0
2019-07-10T23:18:07.766Z,1562800687.766 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-10T23:18:23.229Z,1562800703.229 [SBIT](IMPORTANT): SBIT PASSED
2019-07-10T23:18:23.299Z,1562800703.299 [CommandLine](IMPORTANT): got command configSet list
2019-07-10T23:18:23.300Z,1562800703.300 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-10T23:18:23.303Z,1562800703.303 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=25 count;

2019-07-10T23:18:23.303Z,1562800703.303 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity=3 count;

2019-07-10T23:18:23.303Z,1562800703.303 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-10T23:18:23.656Z,1562800703.656 [MissionManager](IMPORTANT): Started mission Startup
2019-07-10T23:18:23.656Z,1562800703.656 [Startup] Running Loop=1
2019-07-10T23:18:23.657Z,1562800703.657 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-10T23:18:23.657Z,1562800703.657 [Startup:A.GoToSurface] Running Loop=1
2019-07-10T23:18:23.657Z,1562800703.657 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-10T23:18:23.657Z,1562800703.657 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-10T23:18:23.658Z,1562800703.658 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-10T23:18:23.658Z,1562800703.658 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-10T23:18:23.659Z,1562800703.659 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-10T23:18:23.659Z,1562800703.659 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-10T23:18:23.661Z,1562800703.661 [Startup:StartupSatComms] Running Loop=1
2019-07-10T23:18:23.661Z,1562800703.661 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-10T23:18:23.661Z,1562800703.661 [Startup:StartupSatComms:A] Running Loop=1
2019-07-10T23:18:24.068Z,1562800704.068 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-10T23:18:45.003Z,1562800725.003 [NAL9602](INFO): SBD MO Status=2, MOMSN=8105, MT Status=2, MTMSN=0
2019-07-10T23:18:45.003Z,1562800725.003 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-10T23:19:17.322Z,1562800757.322 [NAL9602](INFO): SBD MO Status=0, MOMSN=8105, MT Status=0, MTMSN=0
2019-07-10T23:19:17.322Z,1562800757.322 [NAL9602](INFO): No messages in MT queue
2019-07-10T23:19:18.146Z,1562800758.146 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:20.567Z,1562800760.567 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:23.406Z,1562800763.406 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:23.828Z,1562800763.828 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-10T23:18:23.7Z
2019-07-10T23:19:23.828Z,1562800763.828 [Startup:StartupSatComms:A] Stopped
2019-07-10T23:19:23.828Z,1562800763.828 [Startup:StartupSatComms:B] Running Loop=1
2019-07-10T23:19:24.228Z,1562800764.228 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-10T23:19:25.831Z,1562800765.831 [Micromodem](INFO): Outgoing frame #1, 64 bytes: C86F265D000000005D00000400900000000000000000151D80030C5669BF31555EAE1409A708CE2489B0D24F922C4E73F3619C1A3D5DFEC97D4617D39DECC9F9
2019-07-10T23:19:25.832Z,1562800765.832 [Micromodem](INFO): Outgoing frame #2, 64 bytes: D52273BBDD98A4DB401BB167FDE8FF4BDFCD8B8FE87823FF7BF2D6E6E0D045B7E24DB8AFBA5ACB1D83B5C6476A317016181C3D382C1B44214BBF83246E2E1AA5
2019-07-10T23:19:25.832Z,1562800765.832 [Micromodem](INFO): Outgoing frame #3, 11 bytes: 4C299C6A0940345923C000
2019-07-10T23:19:25.833Z,1562800765.833 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-10T23:19:25.976Z,1562800765.976 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-10T23:19:26.316Z,1562800766.316 [Micromodem](INFO): Nmea in: $CADRQ,231926,1,9,0,64,1*43

2019-07-10T23:19:26.317Z,1562800766.317 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,C86F265D000000005D00000400900000000000000000151D80030C5669BF31555EAE1409A708CE2489B0D24F922C4E73F3619C1A3D5DFEC97D4617D39DECC9F9*77

2019-07-10T23:19:26.335Z,1562800766.335 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:26.401Z,1562800766.401 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-07-10T23:19:26.401Z,1562800766.401 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  93.43,  94.92,   0.00
2019-07-10T23:19:26.716Z,1562800766.716 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:19:27.120Z,1562800767.120 [Micromodem](INFO): Nmea in: $CADRQ,231927,1,9,0,64,2*41

2019-07-10T23:19:27.121Z,1562800767.121 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,D52273BBDD98A4DB401BB167FDE8FF4BDFCD8B8FE87823FF7BF2D6E6E0D045B7E24DB8AFBA5ACB1D83B5C6476A317016181C3D382C1B44214BBF83246E2E1AA5*02

2019-07-10T23:19:27.550Z,1562800767.550 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:19:27.944Z,1562800767.944 [Micromodem](INFO): Nmea in: $CADRQ,231927,1,9,0,64,3*40

2019-07-10T23:19:27.945Z,1562800767.945 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,4C299C6A0940345923C000*74

2019-07-10T23:19:28.336Z,1562800768.336 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,11*73

2019-07-10T23:19:28.736Z,1562800768.736 [Micromodem](INFO): Nmea in: $CATXP,139*49

2019-07-10T23:19:29.558Z,1562800769.558 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:32.391Z,1562800772.391 [Micromodem](INFO): Nmea in: $CATXF,139*5F

2019-07-10T23:19:32.406Z,1562800772.406 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:32.774Z,1562800772.774 [Micromodem](INFO): Nmea in: $CAXST,6,20190710,231928.716139,3,0,200,4000,10000,1,1,9,1,3,3,3,139*45

2019-07-10T23:19:33.332Z,1562800773.332 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.006927
2019-07-10T23:19:35.618Z,1562800775.618 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:38.446Z,1562800778.446 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:40.790Z,1562800780.790 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190710T230752/Courier0000.lzma
2019-07-10T23:19:41.270Z,1562800781.270 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:41.596Z,1562800781.596 [DataOverHttps](INFO): Moved sent file to Logs/20190710T230752/Courier0000.lzma.bak
2019-07-10T23:19:41.596Z,1562800781.596 [DataOverHttps](INFO): SBD MOMSN=11438285
2019-07-10T23:19:44.506Z,1562800784.506 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:47.334Z,1562800787.334 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:50.566Z,1562800790.566 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:53.406Z,1562800793.406 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:53.674Z,1562800793.674 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190710T231649/Courier0000.lzma
2019-07-10T23:19:54.480Z,1562800794.480 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Courier0000.lzma.bak
2019-07-10T23:19:54.480Z,1562800794.480 [DataOverHttps](INFO): SBD MOMSN=11438290
2019-07-10T23:19:56.626Z,1562800796.626 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:19:59.455Z,1562800799.455 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:01.890Z,1562800801.890 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-10T23:20:01.891Z,1562800801.891 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-10T23:20:01.927Z,1562800801.927 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-10T23:20:02.282Z,1562800802.282 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:02.350Z,1562800802.350 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-10T23:20:02.354Z,1562800802.354 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-10T23:20:05.530Z,1562800805.530 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:07.363Z,1562800807.363 [DataOverHttps](INFO): Sending 753 bytes from file Logs/20190710T225603/Express0001.lzma
2019-07-10T23:20:08.152Z,1562800808.152 [DataOverHttps](INFO): Moved sent file to Logs/20190710T225603/Express0001.lzma.bak
2019-07-10T23:20:08.152Z,1562800808.152 [DataOverHttps](INFO): SBD MOMSN=11438295
2019-07-10T23:20:08.347Z,1562800808.347 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:11.574Z,1562800811.574 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:14.410Z,1562800814.410 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:17.638Z,1562800817.638 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:18.027Z,1562800818.027 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231903.00,A,3648.17019,N,12147.28076,W,0.292,192.48,100719,,,A*7A
2019-07-10T23:20:18.030Z,1562800818.030 [NAL9602](INFO): GPS fix at 20190710T231903: (36.802836, -121.788013)
2019-07-10T23:20:23.248Z,1562800823.248 [DataOverHttps](INFO): Sending 209 bytes from file Logs/20190710T225603/Express0005.lzma
2019-07-10T23:20:24.044Z,1562800824.044 [DataOverHttps](INFO): Moved sent file to Logs/20190710T225603/Express0005.lzma.bak
2019-07-10T23:20:24.044Z,1562800824.044 [DataOverHttps](INFO): SBD MOMSN=11438313
2019-07-10T23:20:24.145Z,1562800824.145 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-10T23:19:23.8Z
2019-07-10T23:20:24.145Z,1562800824.145 [Startup:StartupSatComms:B] Stopped
2019-07-10T23:20:24.145Z,1562800824.145 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-10T23:20:24.145Z,1562800824.145 [Startup:StartupSatComms] Stopped
2019-07-10T23:20:24.146Z,1562800824.146 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-10T23:20:24.151Z,1562800824.151 [Startup](INFO): Completed Startup
2019-07-10T23:20:24.151Z,1562800824.151 [MissionManager](INFO): Startup is completed.
2019-07-10T23:20:24.151Z,1562800824.151 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-10T23:20:24.151Z,1562800824.151 [Startup] Stopped
2019-07-10T23:20:24.151Z,1562800824.151 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-10T23:20:24.151Z,1562800824.151 [Startup:A.GoToSurface] Stopped
2019-07-10T23:20:24.151Z,1562800824.151 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-10T23:20:24.565Z,1562800824.565 [MissionManager](IMPORTANT): Started mission Default
2019-07-10T23:20:24.565Z,1562800824.565 [Default] Running Loop=1
2019-07-10T23:20:24.565Z,1562800824.565 [Default](DEBUG): Aggregate::initialize Default
2019-07-10T23:20:24.565Z,1562800824.565 [Default:B.GoToSurface] Running Loop=1
2019-07-10T23:20:24.565Z,1562800824.565 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-10T23:20:24.566Z,1562800824.566 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-10T23:20:24.566Z,1562800824.566 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-10T23:20:24.571Z,1562800824.571 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-10T23:20:24.571Z,1562800824.571 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-10T23:20:24.572Z,1562800824.572 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-10T23:20:24.572Z,1562800824.572 [Default:A.Wait] Running Loop=1
2019-07-10T23:20:24.572Z,1562800824.572 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-10T23:20:37.882Z,1562800837.882 [Default:A.Wait](INFO): Done Waiting.
2019-07-10T23:20:37.883Z,1562800837.883 [Default:A.Wait] Stopped
2019-07-10T23:20:37.883Z,1562800837.883 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-10T23:20:38.279Z,1562800838.279 [Default:CheckIn] Running Loop=1
2019-07-10T23:20:38.279Z,1562800838.279 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-10T23:20:38.279Z,1562800838.279 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-10T23:20:38.673Z,1562800838.673 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-10T23:20:39.858Z,1562800839.858 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:20:40.250Z,1562800840.250 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,231925.00,A,3648.16924,N,12147.28119,W,0.350,192.48,100719,,,A*7F
2019-07-10T23:20:40.256Z,1562800840.256 [NAL9602](INFO): GPS fix at 20190710T231925: (36.802821, -121.788020)
2019-07-10T23:20:40.284Z,1562800840.284 [Default:CheckIn:Read_GPS] Stopped
2019-07-10T23:20:40.284Z,1562800840.284 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-10T23:20:40.715Z,1562800840.715 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-10T23:20:41.056Z,1562800841.056 [Micromodem](ERROR): Buffer fill timout failure.
2019-07-10T23:20:42.755Z,1562800842.755 [Micromodem](INFO): Outgoing frame #1, 64 bytes: E171265D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567
2019-07-10T23:20:42.756Z,1562800842.756 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE
2019-07-10T23:20:42.895Z,1562800842.895 [Micromodem](INFO): Outgoing frame #3, 64 bytes: C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D18516091C61B380A86BEADAD434
2019-07-10T23:20:42.895Z,1562800842.895 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-10T23:20:43.848Z,1562800843.848 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-10T23:20:44.264Z,1562800844.264 [Micromodem](INFO): Nmea in: $CADRQ,232043,1,9,0,64,1*4A

2019-07-10T23:20:44.264Z,1562800844.264 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,E171265D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*0E

2019-07-10T23:20:44.657Z,1562800844.657 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:20:45.064Z,1562800845.064 [Micromodem](INFO): Nmea in: $CADRQ,232045,1,9,0,64,2*4F

2019-07-10T23:20:45.065Z,1562800845.065 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE3619E02B8F4A169EC22D30546A87042BC836DF836B942BC3C4A9EFC1B6C4BDD91F97B2782B4B03CB56EA92D77C6909485B9FDE*74

2019-07-10T23:20:45.468Z,1562800845.468 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:20:45.876Z,1562800845.876 [Micromodem](INFO): Nmea in: $CADRQ,232045,1,9,0,64,3*4E

2019-07-10T23:20:45.876Z,1562800845.876 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,C9BA76D6E11C7243AB9F1CB76D4E14F7CBE1C6B0B40F2F0A19DC25B10B3C6279A2D80F52F03F1275F5BE973EA20943C61E76D18516091C61B380A86BEADAD434*7B

2019-07-10T23:20:46.282Z,1562800846.282 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:20:46.676Z,1562800846.676 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-07-10T23:20:47.615Z,1562800847.615 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190710T231649/Courier0004.lzma
2019-07-10T23:20:48.420Z,1562800848.420 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Courier0004.lzma.bak
2019-07-10T23:20:48.420Z,1562800848.420 [DataOverHttps](INFO): SBD MOMSN=11438317
2019-07-10T23:20:50.312Z,1562800850.312 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-07-10T23:20:50.717Z,1562800850.717 [Micromodem](INFO): Nmea in: $CAXST,6,20190710,232046.703337,3,0,200,4000,10000,1,1,9,1,3,3,3,192*4E

2019-07-10T23:21:02.251Z,1562800862.251 [DataOverHttps](INFO): Sending 100 bytes from file Logs/20190710T225603/Express0008.lzma
2019-07-10T23:21:03.056Z,1562800863.056 [DataOverHttps](INFO): Moved sent file to Logs/20190710T225603/Express0008.lzma.bak
2019-07-10T23:21:03.056Z,1562800863.056 [DataOverHttps](INFO): SBD MOMSN=11438320
2019-07-10T23:21:13.388Z,1562800873.388 [NAL9602](INFO): Powering down
2019-07-10T23:21:17.588Z,1562800877.588 [DataOverHttps](INFO): Sending 794 bytes from file Logs/20190710T230752/Express0001.lzma
2019-07-10T23:21:18.392Z,1562800878.392 [DataOverHttps](INFO): Moved sent file to Logs/20190710T230752/Express0001.lzma.bak
2019-07-10T23:21:18.392Z,1562800878.392 [DataOverHttps](INFO): SBD MOMSN=11438323
2019-07-10T23:21:32.575Z,1562800892.575 [DataOverHttps](INFO): Sending 759 bytes from file Logs/20190710T231649/Express0001.lzma
2019-07-10T23:21:33.381Z,1562800893.381 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Express0001.lzma.bak
2019-07-10T23:21:33.382Z,1562800893.382 [DataOverHttps](INFO): SBD MOMSN=11438347
2019-07-10T23:21:48.002Z,1562800908.002 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20190710T231649/Express0005.lzma
2019-07-10T23:21:48.087Z,1562800908.087 [Micromodem](ERROR): Buffer fill timout failure.
2019-07-10T23:21:48.808Z,1562800908.808 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Express0005.lzma.bak
2019-07-10T23:21:48.808Z,1562800908.808 [DataOverHttps](INFO): SBD MOMSN=11438366
2019-07-10T23:21:49.424Z,1562800909.424 [Default:CheckIn:Read_Iridium] Stopped
2019-07-10T23:21:49.425Z,1562800909.425 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-10T23:21:49.425Z,1562800909.425 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-10T23:25:05.867Z,1562801105.867 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-10T23:25:05.870Z,1562801105.870 [BPC1](INFO): Received data from all battery sticks.
2019-07-10T23:26:49.689Z,1562801209.689 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-07-10T23:26:49.689Z,1562801209.689 [Default:CheckIn:C.Wait] Stopped
2019-07-10T23:26:49.689Z,1562801209.689 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-10T23:26:49.689Z,1562801209.689 [Default:CheckIn:D] Running Loop=1
2019-07-10T23:26:50.089Z,1562801210.089 [Default:CheckIn:D] Stopped
2019-07-10T23:26:50.089Z,1562801210.089 [Default:CheckIn:E] Running Loop=1
2019-07-10T23:26:50.506Z,1562801210.506 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.425405 min 
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn:E] Stopped
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn] Stopped
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn](INFO): Running loop #2
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn] Running Loop=2
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-10T23:26:50.507Z,1562801210.507 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-10T23:26:51.276Z,1562801211.276 [NAL9602](INFO): Powering up
2019-07-10T23:27:02.179Z,1562801222.179 [NAL9602](INFO): NAL9602 initialized
2019-07-10T23:27:03.002Z,1562801223.002 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:27:32.487Z,1562801252.487 [NAL9602](INFO): SBD MO Status=2, MOMSN=8106, MT Status=2, MTMSN=0
2019-07-10T23:27:32.487Z,1562801252.487 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-07-10T23:27:49.885Z,1562801269.885 [NAL9602](INFO): SBD MO Status=0, MOMSN=8106, MT Status=0, MTMSN=0
2019-07-10T23:27:49.885Z,1562801269.885 [NAL9602](INFO): No messages in MT queue
2019-07-10T23:27:50.706Z,1562801270.706 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:27:53.527Z,1562801273.527 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:27:56.758Z,1562801276.758 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:27:59.606Z,1562801279.606 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:28:02.414Z,1562801282.414 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:28:05.246Z,1562801285.246 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:28:08.482Z,1562801288.482 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:28:08.868Z,1562801288.868 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,232654.00,A,3648.16731,N,12147.28421,W,0.019,0.00,100719,,,A*79
2019-07-10T23:28:08.870Z,1562801288.870 [NAL9602](INFO): GPS fix at 20190710T232654: (36.802788, -121.788070)
2019-07-10T23:28:08.901Z,1562801288.901 [Default:CheckIn:Read_GPS] Stopped
2019-07-10T23:28:08.901Z,1562801288.901 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-07-10T23:28:11.322Z,1562801291.322 [Micromodem](INFO): Outgoing frame #1, 64 bytes: E171265D070001005D00000400830100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A
2019-07-10T23:28:11.323Z,1562801291.323 [Micromodem](INFO): Outgoing frame #2, 64 bytes: EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256AEDD60B95108769F11B6F1CAFDFCAA023BD2A6AC8267BF03117F45C2DD2DCA8C8EEBE5F9
2019-07-10T23:28:11.323Z,1562801291.323 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 7BD9043D223D555CF9F8C344436B63EF13BFE530A3AD5AB43B65A7E1E292F063AFC71143C404EE6C0C15F8C17F27639635E69D99E40BDFBF335BF6B6E69D7C4D
2019-07-10T23:28:11.324Z,1562801291.324 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-07-10T23:28:11.492Z,1562801291.492 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-07-10T23:28:11.856Z,1562801291.856 [Micromodem](INFO): Nmea in: $CADRQ,232812,1,9,0,64,1*46

2019-07-10T23:28:11.857Z,1562801291.857 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,E171265D070001005D00000400830100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A*79

2019-07-10T23:28:12.260Z,1562801292.260 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:28:12.670Z,1562801292.670 [Micromodem](INFO): Nmea in: $CADRQ,232812,1,9,0,64,2*45

2019-07-10T23:28:12.671Z,1562801292.671 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C256AEDD60B95108769F11B6F1CAFDFCAA023BD2A6AC8267BF03117F45C2DD2DCA8C8EEBE5F9*70

2019-07-10T23:28:13.068Z,1562801293.068 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:28:13.472Z,1562801293.472 [Micromodem](INFO): Nmea in: $CADRQ,232813,1,9,0,64,3*45

2019-07-10T23:28:13.473Z,1562801293.473 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,7BD9043D223D555CF9F8C344436B63EF13BFE530A3AD5AB43B65A7E1E292F063AFC71143C404EE6C0C15F8C17F27639635E69D99E40BDFBF335BF6B6E69D7C4D*73

2019-07-10T23:28:13.876Z,1562801293.876 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-07-10T23:28:14.280Z,1562801294.280 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-07-10T23:28:16.223Z,1562801296.223 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190710T231649/Courier0007.lzma
2019-07-10T23:28:17.028Z,1562801297.028 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Courier0007.lzma.bak
2019-07-10T23:28:17.028Z,1562801297.028 [DataOverHttps](INFO): SBD MOMSN=11438373
2019-07-10T23:28:17.920Z,1562801297.920 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-07-10T23:28:18.321Z,1562801298.321 [Micromodem](INFO): Nmea in: $CAXST,6,20190710,232814.300411,3,0,200,4000,10000,1,1,9,1,3,3,3,192*45

2019-07-10T23:28:31.490Z,1562801311.490 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20190710T231649/Express0008.lzma
2019-07-10T23:28:32.296Z,1562801312.296 [DataOverHttps](INFO): Moved sent file to Logs/20190710T231649/Express0008.lzma.bak
2019-07-10T23:28:32.296Z,1562801312.296 [DataOverHttps](INFO): SBD MOMSN=11438376
2019-07-10T23:28:34.917Z,1562801314.917 [Default:CheckIn:Read_Iridium] Stopped
2019-07-10T23:28:34.918Z,1562801314.918 [Default:CheckIn:C.Wait] Running Loop=1
2019-07-10T23:28:34.918Z,1562801314.918 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-07-10T23:28:41.752Z,1562801321.752 [NAL9602](INFO): Powering down
2019-07-10T23:30:13.935Z,1562801413.935 [CommandLine](IMPORTANT): got command run ./Missions/DUSBL_Tracking.xml
2019-07-10T23:30:13.935Z,1562801413.935 [MissionManager](INFO): Loading Mission: ./Missions/DUSBL_Tracking.xml
2019-07-10T23:30:13.960Z,1562801413.960 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-07-10T23:30:13.964Z,1562801413.964 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-07-10T23:30:13.968Z,1562801413.968 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 8.000000 s
2019-07-10T23:30:13.972Z,1562801413.972 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-07-10T23:30:13.975Z,1562801413.975 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-07-10T23:30:13.976Z,1562801413.976 [DUSBL:A.Pitch](DEBUG): Construct.
2019-07-10T23:30:13.984Z,1562801413.984 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-07-10T23:30:14.191Z,1562801414.191 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-07-10T23:30:14.199Z,1562801414.199 [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>10</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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

</Mission>


2019-07-10T23:30:14.202Z,1562801414.202 [CommandLine](IMPORTANT): Running ./Missions/DUSBL_Tracking.xml
2019-07-10T23:30:14.310Z,1562801414.310 [Default] Stopped
2019-07-10T23:30:14.310Z,1562801414.310 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-10T23:30:14.310Z,1562801414.310 [Default:B.GoToSurface] Stopped
2019-07-10T23:30:14.310Z,1562801414.310 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-10T23:30:14.314Z,1562801414.314 [Default:CheckIn] Stopped
2019-07-10T23:30:14.314Z,1562801414.314 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-10T23:30:14.314Z,1562801414.314 [Default:CheckIn:C.Wait] Stopped
2019-07-10T23:30:14.315Z,1562801414.315 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-10T23:30:14.315Z,1562801414.315 [MissionManager](IMPORTANT): Started mission DUSBL
2019-07-10T23:30:14.315Z,1562801414.315 [DUSBL] Running Loop=1
2019-07-10T23:30:14.315Z,1562801414.315 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-07-10T23:30:14.315Z,1562801414.315 [DUSBL:A.Pitch] Running Loop=1
2019-07-10T23:30:14.315Z,1562801414.315 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-07-10T23:30:14.316Z,1562801414.316 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-10T23:30:14.316Z,1562801414.316 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-07-10T23:30:14.316Z,1562801414.316 [DUSBL:C.] Running Loop=1
2019-07-10T23:30:14.316Z,1562801414.316 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-07-10T23:30:14.318Z,1562801414.318 [DUSBL:RequestRepeater] Running Loop=1
2019-07-10T23:30:14.318Z,1562801414.318 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-07-10T23:30:14.320Z,1562801414.320 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-07-10T23:30:14.320Z,1562801414.320 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-07-10T23:30:14.321Z,1562801414.321 [DUSBL:C.] Running Loop=1
2019-07-10T23:30:14.330Z,1562801414.330 [DUSBL:B.SetSpeed] Running Loop=1
2019-07-10T23:30:14.330Z,1562801414.330 [DUSBL:A.Pitch] Running Loop=1
2019-07-10T23:30:22.404Z,1562801422.404 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-07-10T23:30:23.157Z,1562801423.157 [Micromodem](INFO): Nmea out: $CCPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*53

2019-07-10T23:30:23.561Z,1562801423.561 [Micromodem](INFO): Nmea in: $SNPGT,14500,28,4A1C0370,1000,24000,0,0,0,0,2000,0*4E

2019-07-10T23:30:26.400Z,1562801426.400 [DUSBL_Hydroid](ERROR): No response from remote modem.
2019-07-10T23:30:28.652Z,1562801428.652 [CommandLine](IMPORTANT): got command stop
2019-07-10T23:30:28.652Z,1562801428.652 [CommandLine](IMPORTANT): Scheduling is paused
2019-07-10T23:30:28.652Z,1562801428.652 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-10T23:30:28.838Z,1562801428.838 [MissionManager](INFO): MissionManager is completed.
2019-07-10T23:30:28.838Z,1562801428.838 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:A.Pitch] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:B.SetSpeed] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:C.] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:RequestRepeater] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-07-10T23:30:28.839Z,1562801428.839 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-10T23:30:29.245Z,1562801429.245 [MissionManager](IMPORTANT): Started mission Default
2019-07-10T23:30:29.245Z,1562801429.245 [Default] Running Loop=1
2019-07-10T23:30:29.246Z,1562801429.246 [Default](DEBUG): Aggregate::initialize Default
2019-07-10T23:30:29.246Z,1562801429.246 [Default:B.GoToSurface] Running Loop=1
2019-07-10T23:30:29.246Z,1562801429.246 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-10T23:30:29.250Z,1562801429.250 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-10T23:30:29.251Z,1562801429.251 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-10T23:30:29.251Z,1562801429.251 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-10T23:30:29.251Z,1562801429.251 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-10T23:30:29.252Z,1562801429.252 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-10T23:30:29.252Z,1562801429.252 [Default:A.Wait] Running Loop=1
2019-07-10T23:30:29.252Z,1562801429.252 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-10T23:30:42.586Z,1562801442.586 [Default:A.Wait](INFO): Done Waiting.
2019-07-10T23:30:42.586Z,1562801442.586 [Default:A.Wait] Stopped
2019-07-10T23:30:42.586Z,1562801442.586 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-10T23:30:42.982Z,1562801442.982 [Default:CheckIn] Running Loop=1
2019-07-10T23:30:42.982Z,1562801442.982 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-10T23:30:42.982Z,1562801442.982 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-10T23:30:43.761Z,1562801443.761 [NAL9602](INFO): Powering up
2019-07-10T23:30:54.672Z,1562801454.672 [NAL9602](INFO): NAL9602 initialized
2019-07-10T23:30:55.490Z,1562801455.490 [NAL9602](DEBUG): Fix Requested
2019-07-10T23:32:02.607Z,1562801522.607 [CBIT](INFO): Clearing failed state for component DropWeight
2019-07-10T23:32:02.607Z,1562801522.607 [DropWeight] No Fault, FailCount= 1
2019-07-10T23:32:16.260Z,1562801536.260 [CommandLine](IMPORTANT): got command restart application
2019-07-10T23:32:17.266Z,1562801537.266 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:17.267Z,1562801537.267 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:17.450Z,1562801537.450 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-10T23:32:17.450Z,1562801537.450 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:17.451Z,1562801537.451 [CommandLine](INFO): Join timeout helper Thread ID is 951
2019-07-10T23:32:17.458Z,1562801537.458 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-10T23:32:17.458Z,1562801537.458 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:17.459Z,1562801537.459 [NavChartDb](INFO): Join timeout helper Thread ID is 952
2019-07-10T23:32:17.646Z,1562801537.646 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:17.647Z,1562801537.647 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:17.650Z,1562801537.650 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-07-10T23:32:17.650Z,1562801537.650 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:17.651Z,1562801537.651 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 953
2019-07-10T23:32:18.006Z,1562801538.006 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.007Z,1562801538.007 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-07-10T23:32:18.007Z,1562801538.007 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.018Z,1562801538.018 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-07-10T23:32:18.018Z,1562801538.018 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.019Z,1562801538.019 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 954
2019-07-10T23:32:18.126Z,1562801538.126 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.127Z,1562801538.127 [CTD_NeilBrown](INFO): Powering down
2019-07-10T23:32:18.138Z,1562801538.138 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.146Z,1562801538.146 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-10T23:32:18.146Z,1562801538.146 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.147Z,1562801538.147 [Radio_Surface](INFO): Join timeout helper Thread ID is 955
2019-07-10T23:32:18.154Z,1562801538.154 [Radio_Surface](INFO): Powering down
2019-07-10T23:32:18.155Z,1562801538.155 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.156Z,1562801538.156 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.177Z,1562801538.177 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-10T23:32:18.178Z,1562801538.178 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.178Z,1562801538.178 [DataOverHttps](INFO): Join timeout helper Thread ID is 956
2019-07-10T23:32:18.442Z,1562801538.442 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.446Z,1562801538.446 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.455Z,1562801538.455 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-10T23:32:18.455Z,1562801538.455 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.456Z,1562801538.456 [logger](INFO): Join timeout helper Thread ID is 957
2019-07-10T23:32:18.470Z,1562801538.470 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.471Z,1562801538.471 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.475Z,1562801538.475 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-10T23:32:18.475Z,1562801538.475 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.475Z,1562801538.475 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-10T23:32:18.475Z,1562801538.475 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:18.476Z,1562801538.476 [controlThread](INFO): Join timeout helper Thread ID is 958
2019-07-10T23:32:18.686Z,1562801538.686 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-10T23:32:18.687Z,1562801538.687 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-10T23:32:18.687Z,1562801538.687 [AHRS_M2](INFO): Powering down
2019-07-10T23:32:18.759Z,1562801538.759 [DUSBL_Hydroid](INFO): Powering down
2019-07-10T23:32:18.831Z,1562801538.831 [Micromodem](INFO): Powering down
2019-07-10T23:32:18.927Z,1562801538.927 [NAL9602](INFO): Powering down
2019-07-10T23:32:18.998Z,1562801538.998 [RDI_Pathfinder](INFO): Powering down
2019-07-10T23:32:18.000Z,1562801539.000 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-10T23:32:19.001Z,1562801539.001 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-10T23:32:19.001Z,1562801539.001 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-10T23:32:19.001Z,1562801539.001 [MissionManager](INFO): Uninitializing Mission Default
2019-07-10T23:32:19.002Z,1562801539.002 [Default] Stopped
2019-07-10T23:32:19.002Z,1562801539.002 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-10T23:32:19.002Z,1562801539.002 [Default:B.GoToSurface] Stopped
2019-07-10T23:32:19.002Z,1562801539.002 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-10T23:32:19.002Z,1562801539.002 [Default:CheckIn] Stopped
2019-07-10T23:32:19.002Z,1562801539.002 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-10T23:32:19.002Z,1562801539.002 [Default:CheckIn:Read_GPS] Stopped
2019-07-10T23:32:19.005Z,1562801539.005 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-10T23:32:19.005Z,1562801539.005 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-10T23:32:19.005Z,1562801539.005 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-10T23:32:19.005Z,1562801539.005 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-10T23:32:19.006Z,1562801539.006 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-10T23:32:19.006Z,1562801539.006 [BuoyancyServo](INFO): Powering down
2019-07-10T23:32:19.018Z,1562801539.018 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-10T23:32:19.018Z,1562801539.018 [ElevatorServo](INFO): Powering down
2019-07-10T23:32:19.019Z,1562801539.019 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-10T23:32:19.019Z,1562801539.019 [MassServo](INFO): Powering down
2019-07-10T23:32:19.020Z,1562801539.020 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-10T23:32:19.020Z,1562801539.020 [RudderServo](INFO): Powering down
2019-07-10T23:32:19.021Z,1562801539.021 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-10T23:32:19.021Z,1562801539.021 [ThrusterServo](INFO): Powering down
2019-07-10T23:32:19.022Z,1562801539.022 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-10T23:32:19.022Z,1562801539.022 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-10T23:32:19.023Z,1562801539.023 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-10T23:32:19.023Z,1562801539.023 [CBIT](DEBUG): Powering off loads.
2019-07-10T23:32:19.034Z,1562801539.034 [CBIT](DEBUG): Disabling WDT.
2019-07-10T23:32:19.046Z,1562801539.046 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-10T23:32:19.047Z,1562801539.047 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.092Z,1562801539.092 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.101Z,1562801539.101 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.142Z,1562801539.142 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.144Z,1562801539.144 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.201Z,1562801539.201 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-10T23:32:19.270Z,1562801539.270 [logger ThreadHandler](INFO): Thread cancelled.