2019-04-09T22:44:16.062Z,1554849856.062 [Supervisor](DEBUG): Initializing supervisor.
2019-04-09T22:44:16.065Z,1554849856.065 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-04-09T22:44:16.065Z,1554849856.065 [SyncHandler](INFO): Protected caller Thread ID is 1285
2019-04-09T22:44:16.066Z,1554849856.066 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-04-09T22:44:16.067Z,1554849856.067 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-04-09T22:44:16.067Z,1554849856.067 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1286
2019-04-09T22:44:16.071Z,1554849856.071 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-04-09T22:44:16.083Z,1554849856.083 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-04-09T22:44:16.084Z,1554849856.084 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-04-09T22:44:16.084Z,1554849856.084 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1287
2019-04-09T22:44:16.085Z,1554849856.085 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-04-09T22:44:16.086Z,1554849856.086 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-04-09T22:44:16.087Z,1554849856.087 [logger ThreadHandler](INFO): Protected caller Thread ID is 1288
2019-04-09T22:44:16.089Z,1554849856.089 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-04-09T22:44:16.089Z,1554849856.089 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-04-09T22:44:16.090Z,1554849856.090 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-04-09T22:44:16.514Z,1554849856.514 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-04-09T22:44:16.514Z,1554849856.514 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-04-09T22:44:16.613Z,1554849856.613 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-04-09T22:44:16.613Z,1554849856.613 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-04-09T22:44:16.939Z,1554849856.939 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-04-09T22:44:16.940Z,1554849856.940 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-04-09T22:44:17.083Z,1554849857.083 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-04-09T22:44:17.084Z,1554849857.084 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-04-09T22:44:17.276Z,1554849857.276 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-04-09T22:44:17.277Z,1554849857.277 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-04-09T22:44:17.735Z,1554849857.735 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-04-09T22:44:17.736Z,1554849857.736 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-04-09T22:44:17.947Z,1554849857.947 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-04-09T22:44:17.948Z,1554849857.948 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-04-09T22:44:18.094Z,1554849858.094 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-04-09T22:44:18.095Z,1554849858.095 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-04-09T22:44:18.289Z,1554849858.289 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-04-09T22:44:18.290Z,1554849858.290 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-04-09T22:44:18.386Z,1554849858.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-04-09T22:44:18.387Z,1554849858.387 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-04-09T22:44:18.727Z,1554849858.727 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-04-09T22:44:18.727Z,1554849858.727 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-04-09T22:44:18.843Z,1554849858.843 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-04-09T22:44:19.084Z,1554849859.084 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-04-09T22:44:19.085Z,1554849859.085 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-04-09T22:44:19.731Z,1554849859.731 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-04-09T22:44:19.732Z,1554849859.732 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-04-09T22:44:20.128Z,1554849860.128 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-04-09T22:44:20.130Z,1554849860.130 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-04-09T22:44:20.131Z,1554849860.131 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-04-09T22:44:20.341Z,1554849860.341 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-04-09T22:44:20.442Z,1554849860.442 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-04-09T22:44:20.542Z,1554849860.542 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-04-09T22:44:20.773Z,1554849860.773 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-04-09T22:44:20.773Z,1554849860.773 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-04-09T22:44:20.858Z,1554849860.858 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-04-09T22:44:20.952Z,1554849860.952 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-04-09T22:44:21.049Z,1554849861.049 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-04-09T22:44:21.132Z,1554849861.132 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-04-09T22:44:21.243Z,1554849861.243 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-04-09T22:44:21.422Z,1554849861.422 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-04-09T22:44:21.559Z,1554849861.559 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-04-09T22:44:21.559Z,1554849861.559 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-04-09T22:44:21.571Z,1554849861.571 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-04-09T22:44:21.953Z,1554849861.953 [AHRS_M2] Loaded
2019-04-09T22:44:21.954Z,1554849861.954 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-04-09T22:44:22.029Z,1554849862.029 [DataOverHttps] Loaded
2019-04-09T22:44:22.030Z,1554849862.030 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-04-09T22:44:22.031Z,1554849862.031 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-04-09T22:44:22.031Z,1554849862.031 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1367
2019-04-09T22:44:22.045Z,1554849862.045 [Depth_Keller] Loaded
2019-04-09T22:44:22.045Z,1554849862.045 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-04-09T22:44:22.050Z,1554849862.050 [DropWeight] Loaded
2019-04-09T22:44:22.050Z,1554849862.050 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-04-09T22:44:22.106Z,1554849862.106 [DUSBL_Hydroid] Loaded
2019-04-09T22:44:22.106Z,1554849862.106 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-04-09T22:44:22.146Z,1554849862.146 [Micromodem] Loaded
2019-04-09T22:44:22.146Z,1554849862.146 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-04-09T22:44:22.244Z,1554849862.244 [NAL9602] Loaded
2019-04-09T22:44:22.244Z,1554849862.244 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-04-09T22:44:22.260Z,1554849862.260 [Onboard] Loaded
2019-04-09T22:44:22.260Z,1554849862.260 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-04-09T22:44:22.266Z,1554849862.266 [PowerOnly] Loaded
2019-04-09T22:44:22.266Z,1554849862.266 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-04-09T22:44:22.273Z,1554849862.273 [Radio_Surface] Loaded
2019-04-09T22:44:22.273Z,1554849862.273 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-04-09T22:44:22.274Z,1554849862.274 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-04-09T22:44:22.274Z,1554849862.274 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1368
2019-04-09T22:44:22.319Z,1554849862.319 [RDI_Pathfinder] Loaded
2019-04-09T22:44:22.319Z,1554849862.319 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-04-09T22:44:23.802Z,1554849863.802 [BPC1] Loaded
2019-04-09T22:44:23.803Z,1554849863.803 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-04-09T22:44:23.803Z,1554849863.803 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-04-09T22:44:23.804Z,1554849863.804 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-04-09T22:44:23.837Z,1554849863.837 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-04-09T22:44:23.838Z,1554849863.838 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-04-09T22:44:24.251Z,1554849864.251 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-04-09T22:44:24.251Z,1554849864.251 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-04-09T22:44:24.272Z,1554849864.272 [NavChart] Loaded
2019-04-09T22:44:24.272Z,1554849864.272 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-04-09T22:44:24.276Z,1554849864.276 [UniversalFixResidualReporter] Loaded
2019-04-09T22:44:24.277Z,1554849864.277 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-04-09T22:44:24.277Z,1554849864.277 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-04-09T22:44:24.278Z,1554849864.278 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-04-09T22:44:24.433Z,1554849864.433 [BuoyancyServo] Loaded
2019-04-09T22:44:24.433Z,1554849864.433 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-04-09T22:44:24.448Z,1554849864.448 [ElevatorServo] Loaded
2019-04-09T22:44:24.449Z,1554849864.449 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-04-09T22:44:24.463Z,1554849864.463 [MassServo] Loaded
2019-04-09T22:44:24.463Z,1554849864.463 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-04-09T22:44:24.479Z,1554849864.479 [RudderServo] Loaded
2019-04-09T22:44:24.479Z,1554849864.479 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-04-09T22:44:24.494Z,1554849864.494 [ThrusterServo] Loaded
2019-04-09T22:44:24.494Z,1554849864.494 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-04-09T22:44:24.494Z,1554849864.494 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-04-09T22:44:24.495Z,1554849864.495 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-04-09T22:44:24.741Z,1554849864.741 [CTD_NeilBrown] Loaded
2019-04-09T22:44:24.742Z,1554849864.742 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-04-09T22:44:24.743Z,1554849864.743 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CF4E0
2019-04-09T22:44:24.743Z,1554849864.743 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1369
2019-04-09T22:44:24.787Z,1554849864.787 [WetLabsSeaOWL_UV_A] Loaded
2019-04-09T22:44:24.788Z,1554849864.788 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-04-09T22:44:24.789Z,1554849864.789 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FF4E0
2019-04-09T22:44:24.789Z,1554849864.789 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1370
2019-04-09T22:44:24.790Z,1554849864.790 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-04-09T22:44:24.790Z,1554849864.790 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-04-09T22:44:25.061Z,1554849865.061 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-04-09T22:44:25.062Z,1554849865.062 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-04-09T22:44:25.102Z,1554849865.102 [DepthRateCalculator] Loaded
2019-04-09T22:44:25.102Z,1554849865.102 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-04-09T22:44:25.108Z,1554849865.108 [PitchRateCalculator] Loaded
2019-04-09T22:44:25.108Z,1554849865.108 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-04-09T22:44:25.120Z,1554849865.120 [SpeedCalculator] Loaded
2019-04-09T22:44:25.121Z,1554849865.121 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-04-09T22:44:25.141Z,1554849865.141 [TempGradientCalculator] Loaded
2019-04-09T22:44:25.142Z,1554849865.142 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-04-09T22:44:25.147Z,1554849865.147 [YawRateCalculator] Loaded
2019-04-09T22:44:25.147Z,1554849865.147 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-04-09T22:44:25.188Z,1554849865.188 [ElevatorOffsetCalculator] Loaded
2019-04-09T22:44:25.188Z,1554849865.188 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-04-09T22:44:25.188Z,1554849865.188 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-04-09T22:44:25.189Z,1554849865.189 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-04-09T22:44:25.322Z,1554849865.322 [SBIT](DEBUG): Construct Startup Built In Test.
2019-04-09T22:44:25.345Z,1554849865.345 [SBIT] Loaded
2019-04-09T22:44:25.345Z,1554849865.345 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-04-09T22:44:25.346Z,1554849865.346 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-04-09T22:44:25.358Z,1554849865.358 [IBIT] Loaded
2019-04-09T22:44:25.358Z,1554849865.358 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-04-09T22:44:25.361Z,1554849865.361 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-04-09T22:44:25.499Z,1554849865.499 [CBIT] Loaded
2019-04-09T22:44:25.500Z,1554849865.500 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-04-09T22:44:25.500Z,1554849865.500 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-04-09T22:44:25.501Z,1554849865.501 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-04-09T22:44:25.569Z,1554849865.569 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-04-09T22:44:25.570Z,1554849865.570 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-04-09T22:44:25.669Z,1554849865.669 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-04-09T22:44:25.669Z,1554849865.669 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-04-09T22:44:25.734Z,1554849865.734 [VerticalControl](DEBUG): Construct VerticalControl.
2019-04-09T22:44:25.818Z,1554849865.818 [VerticalControl] Loaded
2019-04-09T22:44:25.819Z,1554849865.819 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-04-09T22:44:25.819Z,1554849865.819 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-04-09T22:44:25.876Z,1554849865.876 [HorizontalControl] Loaded
2019-04-09T22:44:25.876Z,1554849865.876 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-04-09T22:44:25.877Z,1554849865.877 [SpeedControl](DEBUG): Construct SpeedControl.
2019-04-09T22:44:25.879Z,1554849865.879 [SpeedControl] Loaded
2019-04-09T22:44:25.879Z,1554849865.879 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-04-09T22:44:25.880Z,1554849865.880 [LoopControl](DEBUG): Construct LoopControl.
2019-04-09T22:44:25.880Z,1554849865.880 [LoopControl] Loaded
2019-04-09T22:44:25.881Z,1554849865.881 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-04-09T22:44:25.881Z,1554849865.881 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-04-09T22:44:25.882Z,1554849865.882 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-04-09T22:44:25.908Z,1554849865.908 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-04-09T22:44:25.912Z,1554849865.912 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-04-09T22:44:25.913Z,1554849865.913 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-04-09T22:44:25.920Z,1554849865.920 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-04-09T22:44:25.921Z,1554849865.921 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACF4E0
2019-04-09T22:44:25.921Z,1554849865.921 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1371
2019-04-09T22:44:25.926Z,1554849865.926 [Supervisor](INFO): Main Thread ID is 802
2019-04-09T22:44:25.926Z,1554849865.926 [Supervisor](DEBUG): Running supervisor.
2019-04-09T22:44:25.927Z,1554849865.927 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1372
2019-04-09T22:44:25.929Z,1554849865.929 [controlThread ThreadHandler](INFO): Handler Thread ID is 1373
2019-04-09T22:44:25.929Z,1554849865.929 [controlThread](DEBUG): Initializing ControlThread
2019-04-09T22:44:25.936Z,1554849865.936 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-04-09T22:44:25.936Z,1554849865.936 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-04-09T22:44:25.937Z,1554849865.937 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-04-09T22:44:25.938Z,1554849865.938 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-04-09T22:44:25.938Z,1554849865.938 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-04-09T22:44:25.938Z,1554849865.938 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-04-09T22:44:25.939Z,1554849865.939 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-04-09T22:44:25.939Z,1554849865.939 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-04-09T22:44:25.940Z,1554849865.940 [SBIT](INFO): Initialize SBIT Component.
2019-04-09T22:44:25.940Z,1554849865.940 [SBIT](IMPORTANT): git: 2019-03-18-31-ge98d5dc
2019-04-09T22:44:25.940Z,1554849865.940 [SBIT](INFO): git hash: e98d5dc50cbc39e402f19b9946ff4dc0776c8725
2019-04-09T22:44:25.941Z,1554849865.941 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-04-09T22:44:25.941Z,1554849865.941 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-04-09T22:44:25.942Z,1554849865.942 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-04-09T22:44:25.943Z,1554849865.943 [IBIT](INFO): Initialize IBIT Component.
2019-04-09T22:44:25.943Z,1554849865.943 [CBIT](DEBUG): Initialize CBIT Component.
2019-04-09T22:44:25.944Z,1554849865.944 [logger ThreadHandler](INFO): Handler Thread ID is 1374
2019-04-09T22:44:25.957Z,1554849865.957 [CBIT](DEBUG): Initialized mux pins.
2019-04-09T22:44:25.957Z,1554849865.957 [CBIT](DEBUG): Initializing the watchdog timer.
2019-04-09T22:44:25.961Z,1554849865.961 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1375
2019-04-09T22:44:25.962Z,1554849865.962 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-04-09T22:44:25.969Z,1554849865.969 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1376
2019-04-09T22:44:25.977Z,1554849865.977 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1377
2019-04-09T22:44:25.978Z,1554849865.978 [CTD_NeilBrown](INFO): Powering down
2019-04-09T22:44:25.981Z,1554849865.981 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-04-09T22:44:25.981Z,1554849865.981 [CBIT](DEBUG): Initializing heartbeat.
2019-04-09T22:44:26.009Z,1554849866.009 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1378
2019-04-09T22:44:26.010Z,1554849866.010 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T22:44:26.037Z,1554849866.037 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1379
2019-04-09T22:44:26.047Z,1554849866.047 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-04-09T22:44:26.047Z,1554849866.047 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-04-09T22:44:26.048Z,1554849866.048 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-04-09T22:44:26.048Z,1554849866.048 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-04-09T22:44:26.048Z,1554849866.048 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-04-09T22:44:26.048Z,1554849866.048 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-04-09T22:44:26.048Z,1554849866.048 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-04-09T22:44:26.049Z,1554849866.049 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-04-09T22:44:26.049Z,1554849866.049 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-04-09T22:44:26.049Z,1554849866.049 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-04-09T22:44:26.049Z,1554849866.049 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-04-09T22:44:26.049Z,1554849866.049 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-04-09T22:44:26.050Z,1554849866.050 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-04-09T22:44:26.050Z,1554849866.050 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-04-09T22:44:26.050Z,1554849866.050 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-04-09T22:44:26.050Z,1554849866.050 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-04-09T22:44:26.053Z,1554849866.053 [CBIT](DEBUG): Deactivating GF circuits.
2019-04-09T22:44:26.053Z,1554849866.053 [CBIT](DEBUG): Deactivating emergency mode.
2019-04-09T22:44:26.089Z,1554849866.089 [CBIT](DEBUG): Backplane powered.
2019-04-09T22:44:26.089Z,1554849866.089 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-04-09T22:44:26.091Z,1554849866.091 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-04-09T22:44:26.091Z,1554849866.091 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-04-09T22:44:26.092Z,1554849866.092 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-04-09T22:44:26.093Z,1554849866.093 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-04-09T22:44:26.102Z,1554849866.102 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T22:44:26.122Z,1554849866.122 [MissionManager](DEBUG):
2019-04-09T22:44:26.122Z,1554849866.122 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-04-09T22:44:26.202Z,1554849866.202 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-04-09T22:44:26.203Z,1554849866.203 [Default:A.Wait](DEBUG): Construct Wait.
2019-04-09T22:44:26.205Z,1554849866.205 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-04-09T22:44:26.216Z,1554849866.216 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-04-09T22:44:26.243Z,1554849866.243 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-04-09T22:44:26.248Z,1554849866.248 [Default:E.Execute](DEBUG): Construct Execute.
2019-04-09T22:44:26.267Z,1554849866.267 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2019-04-09T22:44:26.272Z,1554849866.272 [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-09T22:44:26.285Z,1554849866.285 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-04-09T22:44:26.319Z,1554849866.319 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-04-09T22:44:26.320Z,1554849866.320 [DUSBL_Hydroid](INFO): Powering up
2019-04-09T22:44:26.320Z,1554849866.320 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-04-09T22:44:26.373Z,1554849866.373 [Radio_Surface](INFO): Powering up
2019-04-09T22:44:26.405Z,1554849866.405 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T22:44:26.422Z,1554849866.422 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:26.429Z,1554849866.429 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-04-09T22:44:26.430Z,1554849866.430 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:26.437Z,1554849866.437 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-04-09T22:44:26.438Z,1554849866.438 [MassServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:26.445Z,1554849866.445 [MassServo](DEBUG): Initializing MassServo.
2019-04-09T22:44:26.446Z,1554849866.446 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:26.453Z,1554849866.453 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T22:44:26.454Z,1554849866.454 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:26.469Z,1554849866.469 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-04-09T22:44:26.699Z,1554849866.699 [Micromodem](INFO): Powering up
2019-04-09T22:44:26.699Z,1554849866.699 [Micromodem](DEBUG): Initializing Micromodem.
2019-04-09T22:44:26.733Z,1554849866.733 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-04-09T22:44:27.413Z,1554849867.413 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-04-09T22:44:27.413Z,1554849867.413 [RudderServo](FAULT): Rudder failed to initialize
2019-04-09T22:44:27.413Z,1554849867.413 [RudderServo] Communications Fault, FailCount= 1
2019-04-09T22:44:27.413Z,1554849867.413 [RudderServo](ERROR): Communications Fault
2019-04-09T22:44:27.524Z,1554849867.524 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-04-09T22:44:27.702Z,1554849867.702 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T22:44:27.702Z,1554849867.702 [RudderServo](INFO): Powering down
2019-04-09T22:44:28.368Z,1554849868.368 [RudderServo](DEBUG): Initializing EZServoServo.
2019-04-09T22:44:28.490Z,1554849868.490 [RudderServo](DEBUG): Initializing RudderServo.
2019-04-09T22:44:28.494Z,1554849868.494 [CBIT](INFO): Clearing failed state for component RudderServo
2019-04-09T22:44:28.494Z,1554849868.494 [RudderServo] No Fault, FailCount= 1
2019-04-09T22:44:39.706Z,1554849879.706 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-04-09T22:44:44.538Z,1554849884.538 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-04-09T22:44:52.608Z,1554849892.608 [NAL9602](INFO): Powering up NAL9602
2019-04-09T22:44:53.823Z,1554849893.823 [Micromodem](ERROR): Response from modem unexpected: $CADQF,193,1*5B
2019-04-09T22:44:54.223Z,1554849894.223 [Micromodem](ERROR): Response from modem unexpected: $CAMSG,BAD_CRC,0*21
2019-04-09T22:44:54.637Z,1554849894.637 [Micromodem](ERROR): Response from modem unexpected: $CACST,6,1,20190409224452.560720,05,381,13,0096,0150,246,00,00,02,02,0,-01,-01,3,2,1,1,-999,-99.9,-9.99,-999,-9.99,193,0.00,-999,9760,4000*59
2019-04-09T22:45:03.521Z,1554849903.521 [NAL9602](INFO): NAL9602 initialized
2019-04-09T22:45:04.341Z,1554849904.341 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:45:10.443Z,1554849910.443 [SBIT](IMPORTANT): Beginning Startup BIT
2019-04-09T22:45:10.451Z,1554849910.451 [CBIT](IMPORTANT): Beginning ground fault scan
2019-04-09T22:45:21.613Z,1554849921.613 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.020257
CHAN A1 (24V): -0.025630
CHAN A2 (12V): -0.007109
CHAN A3 (5V): -0.002113
CHAN B0 (3.3V): 0.000163
CHAN B1 (3.15aV): 0.000220
CHAN B2 (3.15bV): -0.000028
CHAN B3 (GND): 0.002083
OPEN: 0.006301
Full Scale Calc: 4.765 mA, -1.589 mA
2019-04-09T22:45:36.254Z,1554849936.254 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:45:46.352Z,1554849946.352 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:46:02.996Z,1554849962.996 [NAL9602](INFO): SBD MO Status=2, MOMSN=3158, MT Status=2, MTMSN=0
2019-04-09T22:46:02.996Z,1554849962.996 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-04-09T22:46:03.836Z,1554849963.836 [SBIT](IMPORTANT): SBIT PASSED
2019-04-09T22:46:03.867Z,1554849963.867 [CommandLine](IMPORTANT): got command configSet list
2019-04-09T22:46:03.868Z,1554849963.868 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-04-09T22:46:03.869Z,1554849963.869 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=20 count;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;
2019-04-09T22:46:03.870Z,1554849963.870 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;
2019-04-09T22:46:03.871Z,1554849963.871 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;
2019-04-09T22:46:03.871Z,1554849963.871 [CommandLine](IMPORTANT): VerticalControl.massDefault=6 millimeter;
2019-04-09T22:46:04.230Z,1554849964.230 [MissionManager](IMPORTANT): Started mission Startup
2019-04-09T22:46:04.230Z,1554849964.230 [Startup] Running Loop=1
2019-04-09T22:46:04.231Z,1554849964.231 [Startup](DEBUG): Aggregate::initialize Startup
2019-04-09T22:46:04.231Z,1554849964.231 [Startup:A.GoToSurface] Running Loop=1
2019-04-09T22:46:04.231Z,1554849964.231 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T22:46:04.231Z,1554849964.231 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T22:46:04.232Z,1554849964.232 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T22:46:04.232Z,1554849964.232 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T22:46:04.233Z,1554849964.233 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T22:46:04.233Z,1554849964.233 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T22:46:04.235Z,1554849964.235 [Startup:StartupSatComms] Running Loop=1
2019-04-09T22:46:04.235Z,1554849964.235 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-04-09T22:46:04.235Z,1554849964.235 [Startup:StartupSatComms:A] Running Loop=1
2019-04-09T22:46:04.648Z,1554849964.648 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-04-09T22:46:52.119Z,1554850012.119 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005052
2019-04-09T22:47:04.426Z,1554850024.426 [Startup:StartupSatComms:A](INFO): Timed out from 2019-04-09T22:46:04.2Z
2019-04-09T22:47:04.426Z,1554850024.426 [Startup:StartupSatComms:A] Stopped
2019-04-09T22:47:04.427Z,1554850024.427 [Startup:StartupSatComms:B] Running Loop=1
2019-04-09T22:47:04.843Z,1554850024.843 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T22:47:09.888Z,1554850029.888 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190409T221340/Courier0025.lzma
2019-04-09T22:47:10.695Z,1554850030.695 [DataOverHttps](INFO): Moved sent file to Logs/20190409T221340/Courier0025.lzma.bak
2019-04-09T22:47:10.696Z,1554850030.696 [DataOverHttps](INFO): SBD MOMSN=10520382
2019-04-09T22:47:22.049Z,1554850042.049 [DataOverHttps](INFO): Sending 321 bytes from file Logs/20190409T221340/Express0026.lzma
2019-04-09T22:47:22.854Z,1554850042.854 [DataOverHttps](INFO): Moved sent file to Logs/20190409T221340/Express0026.lzma.bak
2019-04-09T22:47:22.854Z,1554850042.854 [DataOverHttps](INFO): SBD MOMSN=10520384
2019-04-09T22:47:26.264Z,1554850046.264 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-04-09T22:47:26.264Z,1554850046.264 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-04-09T22:47:26.287Z,1554850046.287 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-04-09T22:47:26.687Z,1554850046.687 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-04-09T22:47:26.687Z,1554850046.687 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-04-09T22:47:34.146Z,1554850054.146 [DataOverHttps](INFO): Sending 1383 bytes from file Logs/20190409T224416/Express0001.lzma
2019-04-09T22:47:34.950Z,1554850054.950 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0001.lzma.bak
2019-04-09T22:47:34.950Z,1554850054.950 [DataOverHttps](INFO): SBD MOMSN=10520390
2019-04-09T22:47:35.950Z,1554850055.950 [Startup:StartupSatComms:B] Stopped
2019-04-09T22:47:35.950Z,1554850055.950 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-04-09T22:47:35.950Z,1554850055.950 [Startup:StartupSatComms] Stopped
2019-04-09T22:47:35.950Z,1554850055.950 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-04-09T22:47:35.951Z,1554850055.951 [Startup](INFO): Completed Startup
2019-04-09T22:47:35.951Z,1554850055.951 [MissionManager](INFO): Startup is completed.
2019-04-09T22:47:35.951Z,1554850055.951 [MissionManager](INFO): Uninitializing Mission Startup
2019-04-09T22:47:35.951Z,1554850055.951 [Startup] Stopped
2019-04-09T22:47:35.951Z,1554850055.951 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-04-09T22:47:35.951Z,1554850055.951 [Startup:A.GoToSurface] Stopped
2019-04-09T22:47:35.951Z,1554850055.951 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T22:47:36.338Z,1554850056.338 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T22:47:36.338Z,1554850056.338 [Default] Running Loop=1
2019-04-09T22:47:36.338Z,1554850056.338 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T22:47:36.338Z,1554850056.338 [Default:B.GoToSurface] Running Loop=1
2019-04-09T22:47:36.338Z,1554850056.338 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T22:47:36.339Z,1554850056.339 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T22:47:36.339Z,1554850056.339 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T22:47:36.339Z,1554850056.339 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T22:47:36.340Z,1554850056.340 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T22:47:36.340Z,1554850056.340 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T22:47:36.340Z,1554850056.340 [Default:A.Wait] Running Loop=1
2019-04-09T22:47:36.340Z,1554850056.340 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:47:49.674Z,1554850069.674 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T22:47:49.674Z,1554850069.674 [Default:A.Wait] Stopped
2019-04-09T22:47:49.674Z,1554850069.674 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:47:50.098Z,1554850070.098 [Default:CheckIn] Running Loop=1
2019-04-09T22:47:50.098Z,1554850070.098 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T22:47:50.098Z,1554850070.098 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T22:47:50.493Z,1554850070.493 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-04-09T22:48:13.099Z,1554850093.099 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:48:23.208Z,1554850103.208 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:48:33.308Z,1554850113.308 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:48:36.557Z,1554850116.557 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-04-09T22:48:36.557Z,1554850116.557 [RDI_Pathfinder](ERROR): Failed to parse:
:BD, -0.96, -0.00, 5.00
2019-04-09T22:48:43.010Z,1554850123.010 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:48:53.108Z,1554850133.108 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:03.190Z,1554850143.190 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:12.906Z,1554850152.906 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:22.619Z,1554850162.619 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:32.710Z,1554850172.710 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:35.941Z,1554850175.941 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-09T22:49:35.941Z,1554850175.941 [RDI_Pathfinder](ERROR): Failed to parse:
:RA, 0.00, 0.00, 91.93, 95.26
2019-04-09T22:49:42.813Z,1554850182.813 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:49:52.483Z,1554850192.483 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:50:02.196Z,1554850202.196 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:50:06.607Z,1554850206.607 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T22:50:07.425Z,1554850207.425 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:50:07.817Z,1554850207.817 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224913.00,A,3648.16654,N,12147.28739,W,0.369,60.86,090419,,,A*4D
2019-04-09T22:50:07.820Z,1554850207.820 [NAL9602](INFO): GPS fix at 20190409T224913: (36.802776, -121.788123)
2019-04-09T22:50:07.955Z,1554850207.955 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T22:50:07.955Z,1554850207.955 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T22:50:08.275Z,1554850208.275 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-04-09T22:50:12.014Z,1554850212.014 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:50:16.248Z,1554850216.248 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190409T224416/Courier0004.lzma
2019-04-09T22:50:17.054Z,1554850217.054 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0004.lzma.bak
2019-04-09T22:50:17.054Z,1554850217.054 [DataOverHttps](INFO): SBD MOMSN=10520444
2019-04-09T22:50:22.126Z,1554850222.126 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:50:30.351Z,1554850230.351 [DataOverHttps](INFO): Sending 778 bytes from file Logs/20190409T224416/Express0005.lzma
2019-04-09T22:50:31.558Z,1554850231.558 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0005.lzma.bak
2019-04-09T22:50:31.558Z,1554850231.558 [DataOverHttps](INFO): SBD MOMSN=10520447
2019-04-09T22:50:32.214Z,1554850232.214 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:50:32.668Z,1554850232.668 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T22:50:32.668Z,1554850232.668 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T22:50:32.668Z,1554850232.668 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:50:36.667Z,1554850236.667 [RDI_Pathfinder](ERROR): Failed to parse:
:B -1.06, -0.91, -0.19, 0.00, 8.00
2019-04-09T22:50:40.274Z,1554850240.274 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T22:50:55.347Z,1554850255.347 [CommandLine](IMPORTANT): got command show variable range
2019-04-09T22:50:55.350Z,1554850255.350 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-04-09T22:50:55.501Z,1554850255.501 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T22:50:55.502Z,1554850255.502 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-04-09T22:50:55.502Z,1554850255.502 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-04-09T22:50:55.505Z,1554850255.505 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-04-09T22:50:55.506Z,1554850255.506 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-04-09T22:50:55.506Z,1554850255.506 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-04-09T22:50:55.507Z,1554850255.507 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-04-09T22:51:03.162Z,1554850263.162 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-04-09T22:51:05.225Z,1554850265.225 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-04-09T22:51:05.277Z,1554850265.277 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-04-09T22:51:05.277Z,1554850265.277 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-04-09T22:51:05.278Z,1554850265.278 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-04-09T22:51:05.278Z,1554850265.278 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-04-09T22:51:05.278Z,1554850265.278 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-04-09T22:51:05.279Z,1554850265.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-04-09T22:51:05.279Z,1554850265.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-04-09T22:51:05.279Z,1554850265.279 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-04-09T22:51:05.280Z,1554850265.280 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-04-09T22:51:05.280Z,1554850265.280 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-04-09T22:51:05.281Z,1554850265.281 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-04-09T22:51:05.281Z,1554850265.281 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-04-09T22:51:05.294Z,1554850265.294 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-04-09T22:51:05.294Z,1554850265.294 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-04-09T22:51:05.295Z,1554850265.295 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-04-09T22:51:05.299Z,1554850265.299 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (enum)
2019-04-09T22:51:05.299Z,1554850265.299 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-04-09T22:51:05.300Z,1554850265.300 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-04-09T22:51:05.300Z,1554850265.300 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-04-09T22:51:05.301Z,1554850265.301 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-04-09T22:51:05.301Z,1554850265.301 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-04-09T22:51:05.301Z,1554850265.301 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-04-09T22:51:05.302Z,1554850265.302 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-04-09T22:51:05.302Z,1554850265.302 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-04-09T22:51:05.303Z,1554850265.303 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-04-09T22:51:05.303Z,1554850265.303 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-04-09T22:51:12.010Z,1554850272.010 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-04-09T22:51:15.922Z,1554850275.922 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:51:15.923Z,1554850275.923 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:51:15.994Z,1554850275.994 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 90.000000 min
2019-04-09T22:51:16.006Z,1554850276.006 [MissionManager](INFO): DefineArg DUSBL.NumberOfRequests = 10.000000 count
2019-04-09T22:51:16.026Z,1554850276.026 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-04-09T22:51:16.038Z,1554850276.038 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-04-09T22:51:16.053Z,1554850276.053 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-04-09T22:51:16.054Z,1554850276.054 [DUSBL:A.Pitch](DEBUG): Construct.
2019-04-09T22:51:16.089Z,1554850276.089 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-04-09T22:51:16.121Z,1554850276.121 [DUSBL:RequestRepeater:C.Wait](DEBUG): Construct Wait.
2019-04-09T22:51:16.137Z,1554850276.137 [MissionManager](DEBUG):
This mission is requests a DUSBL arming.
How long to let the mission run.
90
Number of pings to requst.
10
Transponder Address.
2
Number of pings requested each time.
1
Automatically set to true if the DUSBL is enabled. Set to false to disable
reading from the DUSBL.
0
10
2019-04-09T22:51:16.139Z,1554850276.139 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL.xml
2019-04-09T22:51:16.276Z,1554850276.276 [Default] Stopped
2019-04-09T22:51:16.276Z,1554850276.276 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T22:51:16.276Z,1554850276.276 [Default:B.GoToSurface] Stopped
2019-04-09T22:51:16.276Z,1554850276.276 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T22:51:16.276Z,1554850276.276 [Default:CheckIn] Stopped
2019-04-09T22:51:16.276Z,1554850276.276 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T22:51:16.276Z,1554850276.276 [Default:CheckIn:C.Wait] Stopped
2019-04-09T22:51:16.276Z,1554850276.276 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:51:16.289Z,1554850276.289 [MissionManager](IMPORTANT): Started mission DUSBL
2019-04-09T22:51:16.290Z,1554850276.290 [DUSBL] Running Loop=1
2019-04-09T22:51:16.291Z,1554850276.291 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-04-09T22:51:16.291Z,1554850276.291 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:51:16.291Z,1554850276.291 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-04-09T22:51:16.292Z,1554850276.292 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:51:16.292Z,1554850276.292 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-04-09T22:51:16.292Z,1554850276.292 [DUSBL:C] Running Loop=1
2019-04-09T22:51:16.292Z,1554850276.292 [DUSBL:RequestRepeater] Running Loop=1
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:51:16.305Z,1554850276.305 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:51:16.306Z,1554850276.306 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:51:16.307Z,1554850276.307 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_range
2019-04-09T22:51:16.307Z,1554850276.307 [DUSBL:C](DEBUG): Initialize ReadDataComponent to sense acoustic_contact_direction_vehicle_frame
2019-04-09T22:51:16.307Z,1554850276.307 [DUSBL:B.SetSpeed] Running Loop=1
2019-04-09T22:51:16.308Z,1554850276.308 [DUSBL:A.Pitch] Running Loop=1
2019-04-09T22:51:17.863Z,1554850277.863 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:21.895Z,1554850281.895 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:22.294Z,1554850282.294 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T22:51:22.334Z,1554850282.334 [Reporter](INFO): acoustic_contact_range 4.020000 m
2019-04-09T22:51:22.335Z,1554850282.335 [Reporter](INFO): DUSBL_Hydroid.xAngle 37.100000 arcdeg
2019-04-09T22:51:25.927Z,1554850285.927 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:26.334Z,1554850286.334 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T22:51:26.385Z,1554850286.385 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:51:26.385Z,1554850286.385 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:51:26.385Z,1554850286.385 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:51:26.385Z,1554850286.385 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater](INFO): Running loop #2
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater] Running Loop=2
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:51:26.386Z,1554850286.386 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:51:26.401Z,1554850286.401 [Reporter](INFO): acoustic_contact_range 76.800003 m
2019-04-09T22:51:26.402Z,1554850286.402 [Reporter](INFO): DUSBL_Hydroid.xAngle 33.800000 arcdeg
2019-04-09T22:51:29.967Z,1554850289.967 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:30.371Z,1554850290.371 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T22:51:30.464Z,1554850290.464 [Reporter](INFO): acoustic_contact_range 13.980000 m
2019-04-09T22:51:30.473Z,1554850290.473 [Reporter](INFO): DUSBL_Hydroid.xAngle 12.950000 arcdeg
2019-04-09T22:51:34.007Z,1554850294.007 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:34.420Z,1554850294.420 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T22:51:34.520Z,1554850294.520 [Reporter](INFO): acoustic_contact_range 9.059999 m
2019-04-09T22:51:34.526Z,1554850294.526 [Reporter](INFO): DUSBL_Hydroid.xAngle 14.600001 arcdeg
2019-04-09T22:51:36.887Z,1554850296.887 [DUSBL:RequestRepeater:C.Wait](INFO): Done Waiting.
2019-04-09T22:51:36.887Z,1554850296.887 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:51:36.887Z,1554850296.887 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:51:36.888Z,1554850296.888 [DUSBL:RequestRepeater](INFO): Completed DUSBL:RequestRepeater
2019-04-09T22:51:36.888Z,1554850296.888 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:51:36.888Z,1554850296.888 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:51:36.888Z,1554850296.888 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater](INFO): Running loop #3
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater] Running Loop=3
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater:A] Running Loop=1
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater:B] Running Loop=1
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater:C.Wait] Running Loop=1
2019-04-09T22:51:36.889Z,1554850296.889 [DUSBL:RequestRepeater:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:51:38.051Z,1554850298.051 [DUSBL_Hydroid](INFO): ****** ping requested ******
2019-04-09T22:51:38.451Z,1554850298.451 [DUSBL_Hydroid](INFO): publishing direction and range info
2019-04-09T22:51:38.536Z,1554850298.536 [Reporter](INFO): acoustic_contact_range 9.180000 m
2019-04-09T22:51:38.543Z,1554850298.543 [Reporter](INFO): DUSBL_Hydroid.xAngle 11.150000 arcdeg
2019-04-09T22:51:40.930Z,1554850300.930 [CommandLine](IMPORTANT): got command stop
2019-04-09T22:51:40.931Z,1554850300.931 [CommandLine](IMPORTANT): Scheduling is paused
2019-04-09T22:51:40.931Z,1554850300.931 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-04-09T22:51:41.307Z,1554850301.307 [MissionManager](INFO): MissionManager is completed.
2019-04-09T22:51:41.307Z,1554850301.307 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL] Stopped
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:A.Pitch] Stopped
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:B.SetSpeed] Stopped
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:C] Stopped
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:RequestRepeater] Stopped
2019-04-09T22:51:41.307Z,1554850301.307 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-04-09T22:51:41.308Z,1554850301.308 [DUSBL:RequestRepeater:A] Stopped
2019-04-09T22:51:41.308Z,1554850301.308 [DUSBL:RequestRepeater:B] Stopped
2019-04-09T22:51:41.308Z,1554850301.308 [DUSBL:RequestRepeater:C.Wait] Stopped
2019-04-09T22:51:41.308Z,1554850301.308 [DUSBL:RequestRepeater:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:51:41.717Z,1554850301.717 [MissionManager](IMPORTANT): Started mission Default
2019-04-09T22:51:41.717Z,1554850301.717 [Default] Running Loop=1
2019-04-09T22:51:41.717Z,1554850301.717 [Default](DEBUG): Aggregate::initialize Default
2019-04-09T22:51:41.717Z,1554850301.717 [Default:B.GoToSurface] Running Loop=1
2019-04-09T22:51:41.717Z,1554850301.717 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-04-09T22:51:41.718Z,1554850301.718 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-04-09T22:51:41.718Z,1554850301.718 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-04-09T22:51:41.718Z,1554850301.718 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-04-09T22:51:41.718Z,1554850301.718 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-04-09T22:51:41.719Z,1554850301.719 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-04-09T22:51:41.719Z,1554850301.719 [Default:A.Wait] Running Loop=1
2019-04-09T22:51:41.719Z,1554850301.719 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:51:55.048Z,1554850315.048 [Default:A.Wait](INFO): Done Waiting.
2019-04-09T22:51:55.048Z,1554850315.048 [Default:A.Wait] Stopped
2019-04-09T22:51:55.048Z,1554850315.048 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:51:55.456Z,1554850315.456 [Default:CheckIn] Running Loop=1
2019-04-09T22:51:55.456Z,1554850315.456 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T22:51:55.456Z,1554850315.456 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T22:51:57.053Z,1554850317.053 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:51:57.448Z,1554850317.448 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225103.00,A,3648.16948,N,12147.27992,W,0.214,60.86,090419,,,A*4C
2019-04-09T22:51:57.451Z,1554850317.451 [NAL9602](INFO): GPS fix at 20190409T225103: (36.802825, -121.787999)
2019-04-09T22:51:57.475Z,1554850317.475 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T22:51:57.475Z,1554850317.475 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T22:52:10.256Z,1554850330.256 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190409T224416/Courier0007.lzma
2019-04-09T22:52:11.062Z,1554850331.062 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0007.lzma.bak
2019-04-09T22:52:11.062Z,1554850331.062 [DataOverHttps](INFO): SBD MOMSN=10520453
2019-04-09T22:52:27.900Z,1554850347.900 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-04-09T22:52:27.977Z,1554850347.977 [NAL9602](FAULT): received:
+CSQ:0
OK58, 2, 0, 0, 0
OK
2019-04-09T22:52:27.977Z,1554850347.977 [NAL9602] Data Fault, FailCount= 1
2019-04-09T22:52:27.977Z,1554850347.977 [NAL9602](ERROR): Data Fault
2019-04-09T22:52:28.122Z,1554850348.122 [CBIT](ERROR): Data Fault in component: NAL9602
2019-04-09T22:52:28.306Z,1554850348.306 [NAL9602](INFO): Powering down
2019-04-09T22:52:29.157Z,1554850349.157 [CBIT](INFO): Clearing failed state for component NAL9602
2019-04-09T22:52:29.157Z,1554850349.157 [NAL9602] No Fault, FailCount= 1
2019-04-09T22:52:29.670Z,1554850349.670 [DataOverHttps](INFO): Sending 1253 bytes from file Logs/20190409T224416/Express0008.lzma
2019-04-09T22:52:30.478Z,1554850350.478 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0008.lzma.bak
2019-04-09T22:52:30.478Z,1554850350.478 [DataOverHttps](INFO): SBD MOMSN=10520469
2019-04-09T22:52:31.615Z,1554850351.615 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T22:52:31.615Z,1554850351.615 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T22:52:31.615Z,1554850351.615 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:52:58.606Z,1554850378.606 [NAL9602](INFO): Powering up NAL9602
2019-04-09T22:53:04.703Z,1554850384.703 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:53:09.523Z,1554850389.523 [NAL9602](INFO): NAL9602 initialized
2019-04-09T22:53:14.382Z,1554850394.382 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:53:24.081Z,1554850404.081 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:53:33.782Z,1554850413.782 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:53:40.626Z,1554850420.626 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T22:53:43.880Z,1554850423.880 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:53:53.974Z,1554850433.974 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:03.686Z,1554850443.686 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:13.765Z,1554850453.765 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:23.928Z,1554850463.928 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:33.968Z,1554850473.968 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:44.076Z,1554850484.076 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:54:54.176Z,1554850494.176 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:55:04.258Z,1554850504.258 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:55:13.978Z,1554850513.978 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:55:24.101Z,1554850524.101 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:57:32.148Z,1554850652.148 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T22:57:32.148Z,1554850652.148 [Default:CheckIn:C.Wait] Stopped
2019-04-09T22:57:32.148Z,1554850652.148 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T22:57:32.148Z,1554850652.148 [Default:CheckIn:D] Running Loop=1
2019-04-09T22:57:32.603Z,1554850652.603 [Default:CheckIn:D] Stopped
2019-04-09T22:57:32.604Z,1554850652.604 [Default:CheckIn:E] Running Loop=1
2019-04-09T22:57:32.960Z,1554850652.960 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.848106 min
2019-04-09T22:57:32.960Z,1554850652.960 [Default:CheckIn:E] Stopped
2019-04-09T22:57:32.960Z,1554850652.960 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T22:57:32.960Z,1554850652.960 [Default:CheckIn] Stopped
2019-04-09T22:57:32.961Z,1554850652.961 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T22:57:32.961Z,1554850652.961 [Default:CheckIn](INFO): Running loop #2
2019-04-09T22:57:32.961Z,1554850652.961 [Default:CheckIn] Running Loop=2
2019-04-09T22:57:32.961Z,1554850652.961 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T22:57:32.961Z,1554850652.961 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T22:57:34.561Z,1554850654.561 [NAL9602](DEBUG): Fix Requested
2019-04-09T22:57:34.956Z,1554850654.956 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225640.00,A,3648.18391,N,12147.28993,W,0.486,355.33,090419,,,A*74
2019-04-09T22:57:34.958Z,1554850654.958 [NAL9602](INFO): GPS fix at 20190409T225640: (36.803065, -121.788166)
2019-04-09T22:57:34.000Z,1554850655.000 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T22:57:34.000Z,1554850655.000 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T22:57:37.031Z,1554850657.031 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T22:57:40.948Z,1554850660.948 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190409T224416/Courier0010.lzma
2019-04-09T22:57:41.754Z,1554850661.754 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0010.lzma.bak
2019-04-09T22:57:41.754Z,1554850661.754 [DataOverHttps](INFO): SBD MOMSN=10520608
2019-04-09T22:57:54.152Z,1554850674.152 [DataOverHttps](INFO): Sending 819 bytes from file Logs/20190409T224416/Express0011.lzma
2019-04-09T22:57:54.836Z,1554850674.836 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:57:54.950Z,1554850674.950 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0011.lzma.bak
2019-04-09T22:57:54.950Z,1554850674.950 [DataOverHttps](INFO): SBD MOMSN=10520611
2019-04-09T22:57:56.056Z,1554850676.056 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T22:57:56.056Z,1554850676.056 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T22:57:56.056Z,1554850676.056 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T22:58:04.561Z,1554850684.561 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:58:07.741Z,1554850687.741 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T22:58:14.626Z,1554850694.626 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:58:24.731Z,1554850704.731 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:58:34.427Z,1554850714.427 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:58:44.559Z,1554850724.559 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:58:54.629Z,1554850734.629 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:04.724Z,1554850744.724 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:14.410Z,1554850754.410 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:24.103Z,1554850764.103 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:33.816Z,1554850773.816 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:43.541Z,1554850783.541 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T22:59:53.612Z,1554850793.612 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:00:03.712Z,1554850803.712 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:00:13.391Z,1554850813.391 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:01:01.898Z,1554850861.898 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T23:01:01.898Z,1554850861.898 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040916085196,35, 0.0,1448.9, 0
2019-04-09T23:02:44.553Z,1554850964.553 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:02:54.230Z,1554850974.230 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:02:56.684Z,1554850976.684 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:02:56.685Z,1554850976.685 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:02:56.685Z,1554850976.685 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:02:56.685Z,1554850976.685 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:02:57.066Z,1554850977.066 [Default:CheckIn:D] Stopped
2019-04-09T23:02:57.066Z,1554850977.066 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:02:57.479Z,1554850977.479 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.255815 min
2019-04-09T23:02:57.479Z,1554850977.479 [Default:CheckIn:E] Stopped
2019-04-09T23:02:57.480Z,1554850977.480 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:02:57.480Z,1554850977.480 [Default:CheckIn] Stopped
2019-04-09T23:02:57.481Z,1554850977.481 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:02:57.481Z,1554850977.481 [Default:CheckIn](INFO): Running loop #3
2019-04-09T23:02:57.481Z,1554850977.481 [Default:CheckIn] Running Loop=3
2019-04-09T23:02:57.481Z,1554850977.481 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:02:57.481Z,1554850977.481 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:02:59.089Z,1554850979.089 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:02:59.483Z,1554850979.483 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230205.00,A,3648.16543,N,12147.27819,W,0.292,355.33,090419,,,A*7D
2019-04-09T23:02:59.485Z,1554850979.485 [NAL9602](INFO): GPS fix at 20190409T230205: (36.802757, -121.787970)
2019-04-09T23:02:59.534Z,1554850979.534 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:02:59.534Z,1554850979.534 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:03:04.382Z,1554850984.382 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:03:11.068Z,1554850991.068 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190409T224416/Courier0013.lzma
2019-04-09T23:03:11.874Z,1554850991.874 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0013.lzma.bak
2019-04-09T23:03:11.874Z,1554850991.874 [DataOverHttps](INFO): SBD MOMSN=10520643
2019-04-09T23:03:14.488Z,1554850994.488 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:03:24.050Z,1554851004.050 [DataOverHttps](INFO): Sending 845 bytes from file Logs/20190409T224416/Express0014.lzma
2019-04-09T23:03:24.181Z,1554851004.181 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:03:24.854Z,1554851004.854 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0014.lzma.bak
2019-04-09T23:03:24.854Z,1554851004.854 [DataOverHttps](INFO): SBD MOMSN=10520647
2019-04-09T23:03:25.860Z,1554851005.860 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:03:25.860Z,1554851005.860 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:03:25.860Z,1554851005.860 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:03:34.293Z,1554851014.293 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:03:43.979Z,1554851023.979 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:03:54.192Z,1554851034.192 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:03.977Z,1554851043.977 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:14.067Z,1554851054.067 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:23.787Z,1554851063.787 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:33.472Z,1554851073.472 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:43.620Z,1554851083.620 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:04:53.257Z,1554851093.257 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:05:02.957Z,1554851102.957 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:05:57.913Z,1554851157.913 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-04-09T23:05:57.913Z,1554851157.913 [RDI_Pathfinder](ERROR): Failed to parse:
:RA, 0.00, 0.00, 0.00, 0.00
2019-04-09T23:07:34.047Z,1554851254.047 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:07:44.158Z,1554851264.158 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:07:53.847Z,1554851273.847 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:01.500Z,1554851281.500 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-04-09T23:08:03.935Z,1554851283.935 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:13.647Z,1554851293.647 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:23.334Z,1554851303.334 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:26.583Z,1554851306.583 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-04-09T23:08:26.583Z,1554851306.583 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:08:26.583Z,1554851306.583 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:08:26.584Z,1554851306.584 [Default:CheckIn:D] Running Loop=1
2019-04-09T23:08:26.984Z,1554851306.984 [Default:CheckIn:D] Stopped
2019-04-09T23:08:26.984Z,1554851306.984 [Default:CheckIn:E] Running Loop=1
2019-04-09T23:08:27.388Z,1554851307.388 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.754443 min
2019-04-09T23:08:27.388Z,1554851307.388 [Default:CheckIn:E] Stopped
2019-04-09T23:08:27.388Z,1554851307.388 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-04-09T23:08:27.388Z,1554851307.388 [Default:CheckIn] Stopped
2019-04-09T23:08:27.389Z,1554851307.389 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:08:27.389Z,1554851307.389 [Default:CheckIn](INFO): Running loop #4
2019-04-09T23:08:27.389Z,1554851307.389 [Default:CheckIn] Running Loop=4
2019-04-09T23:08:27.389Z,1554851307.389 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-04-09T23:08:27.389Z,1554851307.389 [Default:CheckIn:Read_GPS] Running Loop=1
2019-04-09T23:08:28.985Z,1554851308.985 [NAL9602](DEBUG): Fix Requested
2019-04-09T23:08:29.385Z,1554851309.385 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,230735.00,A,3648.16871,N,12147.28577,W,0.117,183.77,090419,,,A*7A
2019-04-09T23:08:29.387Z,1554851309.387 [NAL9602](INFO): GPS fix at 20190409T230735: (36.802812, -121.788096)
2019-04-09T23:08:29.431Z,1554851309.431 [Default:CheckIn:Read_GPS] Stopped
2019-04-09T23:08:29.431Z,1554851309.431 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-04-09T23:08:33.030Z,1554851313.030 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:35.308Z,1554851315.308 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190409T224416/Courier0016.lzma
2019-04-09T23:08:36.114Z,1554851316.114 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Courier0016.lzma.bak
2019-04-09T23:08:36.114Z,1554851316.114 [DataOverHttps](INFO): SBD MOMSN=10520669
2019-04-09T23:08:43.139Z,1554851323.139 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:08:47.954Z,1554851327.954 [DataOverHttps](INFO): Sending 1092 bytes from file Logs/20190409T224416/Express0017.lzma
2019-04-09T23:08:48.750Z,1554851328.750 [DataOverHttps](INFO): Moved sent file to Logs/20190409T224416/Express0017.lzma.bak
2019-04-09T23:08:48.750Z,1554851328.750 [DataOverHttps](INFO): SBD MOMSN=10520672
2019-04-09T23:08:49.672Z,1554851329.672 [Default:CheckIn:Read_Iridium] Stopped
2019-04-09T23:08:49.672Z,1554851329.672 [Default:CheckIn:C.Wait] Running Loop=1
2019-04-09T23:08:49.672Z,1554851329.672 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-04-09T23:08:52.846Z,1554851332.846 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:00.915Z,1554851340.915 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T23:09:00.916Z,1554851340.916 [RDI_Pathfinder](ERROR): Failed to parse:
:BS, 22, +17,A
2019-04-09T23:09:01.707Z,1554851341.707 [NAL9602](INFO): Not Powering down - fast GPS
2019-04-09T23:09:02.930Z,1554851342.930 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:12.239Z,1554851352.239 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-04-09T23:09:12.240Z,1554851352.240 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-2768,-32768,V
2019-04-09T23:09:13.030Z,1554851353.030 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:15.860Z,1554851355.860 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-04-09T23:09:15.860Z,1554851355.860 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19040916170596,35.0, 0.0,1448.9, 0
2019-04-09T23:09:22.753Z,1554851362.753 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:32.425Z,1554851372.425 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:42.563Z,1554851382.563 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:09:52.632Z,1554851392.632 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7).
2019-04-09T23:11:05.067Z,1554851465.067 [CommandLine](IMPORTANT): got command restart application
2019-04-09T23:11:06.073Z,1554851466.073 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:06.073Z,1554851466.073 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.185Z,1554851466.185 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2019-04-09T23:11:06.185Z,1554851466.185 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.185Z,1554851466.185 [CommandLine](INFO): Join timeout helper Thread ID is 1431
2019-04-09T23:11:06.186Z,1554851466.186 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-04-09T23:11:06.186Z,1554851466.186 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.187Z,1554851466.187 [NavChartDb](INFO): Join timeout helper Thread ID is 1432
2019-04-09T23:11:06.309Z,1554851466.309 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:06.309Z,1554851466.309 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.325Z,1554851466.325 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-04-09T23:11:06.325Z,1554851466.325 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.325Z,1554851466.325 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1433
2019-04-09T23:11:06.385Z,1554851466.385 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:06.385Z,1554851466.385 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-04-09T23:11:06.386Z,1554851466.386 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.405Z,1554851466.405 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-04-09T23:11:06.405Z,1554851466.405 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.405Z,1554851466.405 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1434
2019-04-09T23:11:06.493Z,1554851466.493 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:06.493Z,1554851466.493 [CTD_NeilBrown](INFO): Powering down
2019-04-09T23:11:06.505Z,1554851466.505 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.505Z,1554851466.505 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-04-09T23:11:06.505Z,1554851466.505 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.506Z,1554851466.506 [Radio_Surface](INFO): Join timeout helper Thread ID is 1435
2019-04-09T23:11:06.893Z,1554851466.893 [Radio_Surface](INFO): Powering down
2019-04-09T23:11:06.894Z,1554851466.894 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:06.894Z,1554851466.894 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.902Z,1554851466.902 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-04-09T23:11:06.902Z,1554851466.902 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:06.902Z,1554851466.902 [DataOverHttps](INFO): Join timeout helper Thread ID is 1436
2019-04-09T23:11:07.113Z,1554851467.113 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:07.113Z,1554851467.113 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.121Z,1554851467.121 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-04-09T23:11:07.121Z,1554851467.121 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.122Z,1554851467.122 [logger](INFO): Join timeout helper Thread ID is 1437
2019-04-09T23:11:07.165Z,1554851467.165 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:07.165Z,1554851467.165 [logger ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.181Z,1554851467.181 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-04-09T23:11:07.181Z,1554851467.181 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.182Z,1554851467.182 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-04-09T23:11:07.182Z,1554851467.182 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.182Z,1554851467.182 [controlThread](INFO): Join timeout helper Thread ID is 1438
2019-04-09T23:11:07.325Z,1554851467.325 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-04-09T23:11:07.325Z,1554851467.325 [controlThread](DEBUG): Uninitializing ControlThread
2019-04-09T23:11:07.325Z,1554851467.325 [AHRS_M2](INFO): Powering down
2019-04-09T23:11:07.398Z,1554851467.398 [DUSBL_Hydroid](INFO): Powering down
2019-04-09T23:11:07.469Z,1554851467.469 [Micromodem](INFO): Powering down
2019-04-09T23:11:07.565Z,1554851467.565 [NAL9602](INFO): Powering down
2019-04-09T23:11:07.637Z,1554851467.637 [RDI_Pathfinder](INFO): Powering down
2019-04-09T23:11:07.639Z,1554851467.639 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-04-09T23:11:07.639Z,1554851467.639 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-04-09T23:11:07.640Z,1554851467.640 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-04-09T23:11:07.640Z,1554851467.640 [MissionManager](INFO): Uninitializing Mission Default
2019-04-09T23:11:07.641Z,1554851467.641 [Default] Stopped
2019-04-09T23:11:07.641Z,1554851467.641 [Default](DEBUG): Aggregate::uninitialize Default
2019-04-09T23:11:07.641Z,1554851467.641 [Default:B.GoToSurface] Stopped
2019-04-09T23:11:07.641Z,1554851467.641 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-04-09T23:11:07.641Z,1554851467.641 [Default:CheckIn] Stopped
2019-04-09T23:11:07.641Z,1554851467.641 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-04-09T23:11:07.641Z,1554851467.641 [Default:CheckIn:C.Wait] Stopped
2019-04-09T23:11:07.641Z,1554851467.641 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-04-09T23:11:07.644Z,1554851467.644 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-04-09T23:11:07.644Z,1554851467.644 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-04-09T23:11:07.644Z,1554851467.644 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-04-09T23:11:07.644Z,1554851467.644 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-04-09T23:11:07.645Z,1554851467.645 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-04-09T23:11:07.645Z,1554851467.645 [BuoyancyServo](INFO): Powering down
2019-04-09T23:11:07.657Z,1554851467.657 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-04-09T23:11:07.657Z,1554851467.657 [ElevatorServo](INFO): Powering down
2019-04-09T23:11:07.658Z,1554851467.658 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-04-09T23:11:07.658Z,1554851467.658 [MassServo](INFO): Powering down
2019-04-09T23:11:07.659Z,1554851467.659 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-04-09T23:11:07.659Z,1554851467.659 [RudderServo](INFO): Powering down
2019-04-09T23:11:07.659Z,1554851467.659 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-04-09T23:11:07.660Z,1554851467.660 [ThrusterServo](INFO): Powering down
2019-04-09T23:11:07.660Z,1554851467.660 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-04-09T23:11:07.661Z,1554851467.661 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-04-09T23:11:07.661Z,1554851467.661 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-04-09T23:11:07.661Z,1554851467.661 [CBIT](DEBUG): Powering off loads.
2019-04-09T23:11:07.672Z,1554851467.672 [CBIT](DEBUG): Disabling WDT.
2019-04-09T23:11:07.684Z,1554851467.684 [CBIT](DEBUG): Opening all GF detection circuits.
2019-04-09T23:11:07.685Z,1554851467.685 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.740Z,1554851467.740 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.749Z,1554851467.749 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.793Z,1554851467.793 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.795Z,1554851467.795 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.850Z,1554851467.850 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-04-09T23:11:07.922Z,1554851467.922 [logger ThreadHandler](INFO): Thread cancelled.