2019-05-21T14:56:20.234Z,1558450580.234 [Supervisor](DEBUG): Initializing supervisor. 2019-05-21T14:56:20.237Z,1558450580.237 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-21T14:56:20.238Z,1558450580.238 [SyncHandler](INFO): Protected caller Thread ID is 2962 2019-05-21T14:56:20.238Z,1558450580.238 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-21T14:56:20.239Z,1558450580.239 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-21T14:56:20.239Z,1558450580.239 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2963 2019-05-21T14:56:20.242Z,1558450580.242 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-21T14:56:20.255Z,1558450580.255 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-21T14:56:20.256Z,1558450580.256 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-21T14:56:20.256Z,1558450580.256 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2964 2019-05-21T14:56:20.257Z,1558450580.257 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-21T14:56:20.258Z,1558450580.258 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-21T14:56:20.258Z,1558450580.258 [logger ThreadHandler](INFO): Protected caller Thread ID is 2965 2019-05-21T14:56:20.261Z,1558450580.261 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-21T14:56:20.261Z,1558450580.261 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-21T14:56:20.262Z,1558450580.262 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-21T14:56:21.314Z,1558450581.314 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-21T14:56:21.315Z,1558450581.315 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-21T14:56:21.482Z,1558450581.482 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-21T14:56:21.482Z,1558450581.482 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-21T14:56:21.949Z,1558450581.949 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-21T14:56:21.949Z,1558450581.949 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-21T14:56:22.090Z,1558450582.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-21T14:56:22.090Z,1558450582.090 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-21T14:56:22.281Z,1558450582.281 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-21T14:56:22.281Z,1558450582.281 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-21T14:56:22.733Z,1558450582.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-21T14:56:22.733Z,1558450582.733 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-21T14:56:22.941Z,1558450582.941 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-21T14:56:22.942Z,1558450582.942 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-21T14:56:23.086Z,1558450583.086 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-21T14:56:23.087Z,1558450583.087 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-21T14:56:23.279Z,1558450583.279 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-21T14:56:23.280Z,1558450583.280 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-21T14:56:23.374Z,1558450583.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-21T14:56:23.375Z,1558450583.375 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-21T14:56:23.694Z,1558450583.694 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-21T14:56:23.695Z,1558450583.695 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-21T14:56:23.774Z,1558450583.774 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-21T14:56:23.876Z,1558450583.876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-21T14:56:23.876Z,1558450583.876 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-21T14:56:24.464Z,1558450584.464 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-21T14:56:24.465Z,1558450584.465 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-21T14:56:24.851Z,1558450584.851 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-21T14:56:24.853Z,1558450584.853 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/ 2019-05-21T14:56:24.854Z,1558450584.854 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg 2019-05-21T14:56:25.102Z,1558450585.102 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg 2019-05-21T14:56:25.404Z,1558450585.404 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg 2019-05-21T14:56:25.523Z,1558450585.523 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg 2019-05-21T14:56:25.870Z,1558450585.870 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-21T14:56:25.871Z,1558450585.871 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg 2019-05-21T14:56:26.051Z,1558450586.051 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg 2019-05-21T14:56:26.145Z,1558450586.145 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg 2019-05-21T14:56:26.243Z,1558450586.243 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg 2019-05-21T14:56:26.326Z,1558450586.326 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg 2019-05-21T14:56:26.432Z,1558450586.432 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg 2019-05-21T14:56:26.610Z,1558450586.610 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg 2019-05-21T14:56:26.740Z,1558450586.740 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/ 2019-05-21T14:56:26.740Z,1558450586.740 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-21T14:56:26.755Z,1558450586.755 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-21T14:56:27.129Z,1558450587.129 [AHRS_M2] Loaded 2019-05-21T14:56:27.129Z,1558450587.129 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-05-21T14:56:27.203Z,1558450587.203 [DataOverHttps] Loaded 2019-05-21T14:56:27.204Z,1558450587.204 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-05-21T14:56:27.205Z,1558450587.205 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407614E0 2019-05-21T14:56:27.205Z,1558450587.205 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3044 2019-05-21T14:56:27.218Z,1558450587.218 [Depth_Keller] Loaded 2019-05-21T14:56:27.219Z,1558450587.219 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-21T14:56:27.223Z,1558450587.223 [DropWeight] Loaded 2019-05-21T14:56:27.224Z,1558450587.224 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-05-21T14:56:27.280Z,1558450587.280 [DUSBL_Hydroid] Loaded 2019-05-21T14:56:27.280Z,1558450587.280 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread. 2019-05-21T14:56:27.327Z,1558450587.327 [Micromodem] Loaded 2019-05-21T14:56:27.327Z,1558450587.327 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread. 2019-05-21T14:56:27.424Z,1558450587.424 [NAL9602] Loaded 2019-05-21T14:56:27.424Z,1558450587.424 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-21T14:56:27.440Z,1558450587.440 [Onboard] Loaded 2019-05-21T14:56:27.440Z,1558450587.440 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-21T14:56:27.446Z,1558450587.446 [PowerOnly] Loaded 2019-05-21T14:56:27.446Z,1558450587.446 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread. 2019-05-21T14:56:27.453Z,1558450587.453 [Radio_Surface] Loaded 2019-05-21T14:56:27.453Z,1558450587.453 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-21T14:56:27.454Z,1558450587.454 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407914E0 2019-05-21T14:56:27.455Z,1558450587.455 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3045 2019-05-21T14:56:27.499Z,1558450587.499 [RDI_Pathfinder] Loaded 2019-05-21T14:56:27.499Z,1558450587.499 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2019-05-21T14:56:28.979Z,1558450588.979 [BPC1] Loaded 2019-05-21T14:56:28.979Z,1558450588.979 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-05-21T14:56:28.979Z,1558450588.979 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-21T14:56:28.980Z,1558450588.980 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-21T14:56:28.993Z,1558450588.993 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-21T14:56:28.993Z,1558450588.993 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-21T14:56:29.099Z,1558450589.099 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-21T14:56:29.099Z,1558450589.099 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-21T14:56:29.120Z,1558450589.120 [NavChart] Loaded 2019-05-21T14:56:29.120Z,1558450589.120 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-21T14:56:29.124Z,1558450589.124 [UniversalFixResidualReporter] Loaded 2019-05-21T14:56:29.124Z,1558450589.124 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-21T14:56:29.125Z,1558450589.125 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-21T14:56:29.125Z,1558450589.125 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-21T14:56:29.230Z,1558450589.230 [BuoyancyServo] Loaded 2019-05-21T14:56:29.230Z,1558450589.230 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-21T14:56:29.245Z,1558450589.245 [ElevatorServo] Loaded 2019-05-21T14:56:29.246Z,1558450589.246 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-21T14:56:29.261Z,1558450589.261 [MassServo] Loaded 2019-05-21T14:56:29.261Z,1558450589.261 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-21T14:56:29.276Z,1558450589.276 [RudderServo] Loaded 2019-05-21T14:56:29.276Z,1558450589.276 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-21T14:56:29.291Z,1558450589.291 [ThrusterServo] Loaded 2019-05-21T14:56:29.291Z,1558450589.291 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-21T14:56:29.292Z,1558450589.292 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-21T14:56:29.292Z,1558450589.292 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-21T14:56:29.538Z,1558450589.538 [CTD_NeilBrown] Loaded 2019-05-21T14:56:29.538Z,1558450589.538 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-05-21T14:56:29.539Z,1558450589.539 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D34E0 2019-05-21T14:56:29.539Z,1558450589.539 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3046 2019-05-21T14:56:29.584Z,1558450589.584 [WetLabsSeaOWL_UV_A] Loaded 2019-05-21T14:56:29.585Z,1558450589.585 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread. 2019-05-21T14:56:29.586Z,1558450589.586 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409034E0 2019-05-21T14:56:29.586Z,1558450589.586 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3047 2019-05-21T14:56:29.587Z,1558450589.587 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-21T14:56:29.587Z,1558450589.587 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-21T14:56:29.874Z,1558450589.874 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-21T14:56:29.875Z,1558450589.875 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-21T14:56:29.915Z,1558450589.915 [DepthRateCalculator] Loaded 2019-05-21T14:56:29.916Z,1558450589.916 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-21T14:56:29.921Z,1558450589.921 [PitchRateCalculator] Loaded 2019-05-21T14:56:29.922Z,1558450589.922 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-21T14:56:29.934Z,1558450589.934 [SpeedCalculator] Loaded 2019-05-21T14:56:29.934Z,1558450589.934 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-21T14:56:29.956Z,1558450589.956 [TempGradientCalculator] Loaded 2019-05-21T14:56:29.956Z,1558450589.956 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-21T14:56:29.961Z,1558450589.961 [YawRateCalculator] Loaded 2019-05-21T14:56:29.962Z,1558450589.962 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-21T14:56:30.003Z,1558450590.003 [ElevatorOffsetCalculator] Loaded 2019-05-21T14:56:30.003Z,1558450590.003 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-21T14:56:30.004Z,1558450590.004 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-21T14:56:30.004Z,1558450590.004 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-21T14:56:30.134Z,1558450590.134 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-21T14:56:30.156Z,1558450590.156 [SBIT] Loaded 2019-05-21T14:56:30.156Z,1558450590.156 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-21T14:56:30.157Z,1558450590.157 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-21T14:56:30.168Z,1558450590.168 [IBIT] Loaded 2019-05-21T14:56:30.169Z,1558450590.169 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-21T14:56:30.172Z,1558450590.172 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-21T14:56:30.556Z,1558450590.556 [CBIT] Loaded 2019-05-21T14:56:30.556Z,1558450590.556 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-21T14:56:30.557Z,1558450590.557 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-21T14:56:30.557Z,1558450590.557 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-21T14:56:30.793Z,1558450590.793 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-21T14:56:30.794Z,1558450590.794 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-21T14:56:30.890Z,1558450590.890 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-21T14:56:30.890Z,1558450590.890 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-21T14:56:30.956Z,1558450590.956 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-21T14:56:31.041Z,1558450591.041 [VerticalControl] Loaded 2019-05-21T14:56:31.041Z,1558450591.041 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-21T14:56:31.042Z,1558450591.042 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-21T14:56:31.099Z,1558450591.099 [HorizontalControl] Loaded 2019-05-21T14:56:31.100Z,1558450591.100 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-21T14:56:31.100Z,1558450591.100 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-21T14:56:31.102Z,1558450591.102 [SpeedControl] Loaded 2019-05-21T14:56:31.102Z,1558450591.102 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-21T14:56:31.103Z,1558450591.103 [LoopControl](DEBUG): Construct LoopControl. 2019-05-21T14:56:31.104Z,1558450591.104 [LoopControl] Loaded 2019-05-21T14:56:31.104Z,1558450591.104 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-21T14:56:31.104Z,1558450591.104 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-21T14:56:31.105Z,1558450591.105 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-21T14:56:31.131Z,1558450591.131 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-21T14:56:31.134Z,1558450591.134 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-21T14:56:31.135Z,1558450591.135 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-21T14:56:31.142Z,1558450591.142 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-21T14:56:31.143Z,1558450591.143 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADA4E0 2019-05-21T14:56:31.144Z,1558450591.144 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3048 2019-05-21T14:56:31.148Z,1558450591.148 [Supervisor](INFO): Main Thread ID is 2961 2019-05-21T14:56:31.148Z,1558450591.148 [Supervisor](DEBUG): Running supervisor. 2019-05-21T14:56:31.149Z,1558450591.149 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3049 2019-05-21T14:56:31.151Z,1558450591.151 [controlThread ThreadHandler](INFO): Handler Thread ID is 3050 2019-05-21T14:56:31.152Z,1558450591.152 [controlThread](DEBUG): Initializing ControlThread 2019-05-21T14:56:31.160Z,1558450591.160 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-21T14:56:31.160Z,1558450591.160 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-21T14:56:31.162Z,1558450591.162 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-21T14:56:31.162Z,1558450591.162 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-21T14:56:31.162Z,1558450591.162 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-21T14:56:31.162Z,1558450591.162 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-21T14:56:31.163Z,1558450591.163 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-21T14:56:31.163Z,1558450591.163 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-21T14:56:31.164Z,1558450591.164 [SBIT](INFO): Initialize SBIT Component. 2019-05-21T14:56:31.164Z,1558450591.164 [SBIT](IMPORTANT): git: 2019-05-01-9-g5be6d91 2019-05-21T14:56:31.164Z,1558450591.164 [SBIT](INFO): git hash: 5be6d91bfd1d3ef858080230e47d423d1f938b96 2019-05-21T14:56:31.165Z,1558450591.165 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-21T14:56:31.166Z,1558450591.166 [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-05-21T14:56:31.167Z,1558450591.167 [SBIT](INFO): Beginning SBIT in 52.000000 seconds. 2019-05-21T14:56:31.168Z,1558450591.168 [IBIT](INFO): Initialize IBIT Component. 2019-05-21T14:56:31.169Z,1558450591.169 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-21T14:56:31.170Z,1558450591.170 [logger ThreadHandler](INFO): Handler Thread ID is 3051 2019-05-21T14:56:31.181Z,1558450591.181 [CBIT](DEBUG): Initialized mux pins. 2019-05-21T14:56:31.181Z,1558450591.181 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-21T14:56:31.189Z,1558450591.189 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3052 2019-05-21T14:56:31.190Z,1558450591.190 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-05-21T14:56:31.201Z,1558450591.201 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3053 2019-05-21T14:56:31.205Z,1558450591.205 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-21T14:56:31.205Z,1558450591.205 [CBIT](DEBUG): Initializing heartbeat. 2019-05-21T14:56:31.213Z,1558450591.213 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3054 2019-05-21T14:56:31.214Z,1558450591.214 [CTD_NeilBrown](INFO): Powering down 2019-05-21T14:56:31.249Z,1558450591.249 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3055 2019-05-21T14:56:31.250Z,1558450591.250 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-21T14:56:31.277Z,1558450591.277 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-21T14:56:31.277Z,1558450591.277 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-21T14:56:31.278Z,1558450591.278 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3056 2019-05-21T14:56:31.281Z,1558450591.281 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-21T14:56:31.281Z,1558450591.281 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-21T14:56:31.281Z,1558450591.281 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-21T14:56:31.281Z,1558450591.281 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-21T14:56:31.281Z,1558450591.281 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-21T14:56:31.282Z,1558450591.282 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-21T14:56:31.282Z,1558450591.282 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-21T14:56:31.282Z,1558450591.282 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-21T14:56:31.282Z,1558450591.282 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-21T14:56:31.282Z,1558450591.282 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-21T14:56:31.283Z,1558450591.283 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-21T14:56:31.313Z,1558450591.313 [CBIT](DEBUG): Backplane powered. 2019-05-21T14:56:31.313Z,1558450591.313 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-21T14:56:31.315Z,1558450591.315 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-21T14:56:31.315Z,1558450591.315 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-21T14:56:31.316Z,1558450591.316 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-21T14:56:31.317Z,1558450591.317 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-21T14:56:31.326Z,1558450591.326 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-21T14:56:31.357Z,1558450591.357 [MissionManager](DEBUG): 2019-05-21T14:56:31.358Z,1558450591.358 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-21T14:56:31.418Z,1558450591.418 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-21T14:56:31.420Z,1558450591.420 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-21T14:56:31.421Z,1558450591.421 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-21T14:56:31.456Z,1558450591.456 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-21T14:56:31.474Z,1558450591.474 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-21T14:56:31.480Z,1558450591.480 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-21T14:56:31.491Z,1558450591.491 [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-05-21T14:56:31.505Z,1558450591.505 [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-05-21T14:56:31.517Z,1558450591.517 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-05-21T14:56:31.561Z,1558450591.561 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar 2019-05-21T14:56:31.571Z,1558450591.570 [DUSBL_Hydroid](INFO): Powering up 2019-05-21T14:56:31.571Z,1558450591.571 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid. 2019-05-21T14:56:31.605Z,1558450591.605 [Radio_Surface](INFO): Powering up 2019-05-21T14:56:31.606Z,1558450591.606 [Micromodem](INFO): Start 2019-05-21T14:56:31.661Z,1558450591.661 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-21T14:56:31.675Z,1558450591.675 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:31.681Z,1558450591.681 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-21T14:56:31.682Z,1558450591.682 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:31.689Z,1558450591.689 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-21T14:56:31.690Z,1558450591.690 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:31.705Z,1558450591.705 [MassServo](DEBUG): Initializing MassServo. 2019-05-21T14:56:31.706Z,1558450591.706 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:31.717Z,1558450591.717 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-21T14:56:31.718Z,1558450591.718 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:31.740Z,1558450591.740 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-21T14:56:31.930Z,1558450591.930 [Micromodem](INFO): Starting 2019-05-21T14:56:31.931Z,1558450591.931 [Micromodem](INFO): Powering up 2019-05-21T14:56:31.931Z,1558450591.931 [Micromodem](DEBUG): Initializing Micromodem. 2019-05-21T14:56:31.969Z,1558450591.969 [DepthRateCalculator](ERROR): Depth measurement is not active 2019-05-21T14:56:32.323Z,1558450592.323 [Micromodem](INFO): Starting 2019-05-21T14:56:32.649Z,1558450592.649 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-05-21T14:56:32.649Z,1558450592.649 [RudderServo](FAULT): Rudder failed to initialize 2019-05-21T14:56:32.649Z,1558450592.649 [RudderServo] Communications Fault, FailCount= 1 2019-05-21T14:56:32.649Z,1558450592.649 [RudderServo](ERROR): Communications Fault 2019-05-21T14:56:32.760Z,1558450592.760 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-05-21T14:56:32.770Z,1558450592.770 [Micromodem](INFO): Starting 2019-05-21T14:56:32.938Z,1558450592.938 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-21T14:56:32.938Z,1558450592.938 [RudderServo](INFO): Powering down 2019-05-21T14:56:33.174Z,1558450593.174 [Micromodem](INFO): Starting 2019-05-21T14:56:33.578Z,1558450593.578 [Micromodem](INFO): Starting 2019-05-21T14:56:33.605Z,1558450593.605 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-21T14:56:33.727Z,1558450593.727 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-21T14:56:33.732Z,1558450593.732 [CBIT](INFO): Clearing failed state for component RudderServo 2019-05-21T14:56:33.732Z,1558450593.732 [RudderServo] No Fault, FailCount= 1 2019-05-21T14:56:33.982Z,1558450593.982 [Micromodem](INFO): Starting 2019-05-21T14:56:34.386Z,1558450594.386 [Micromodem](INFO): Starting 2019-05-21T14:56:34.858Z,1558450594.858 [Micromodem](INFO): Starting 2019-05-21T14:56:35.218Z,1558450595.218 [Micromodem](INFO): Starting 2019-05-21T14:56:35.622Z,1558450595.622 [Micromodem](INFO): Starting 2019-05-21T14:56:36.090Z,1558450596.090 [Micromodem](INFO): Starting 2019-05-21T14:56:36.092Z,1558450596.092 [Micromodem](INFO): Nmea in: $CAREV,145635,INIT,2.0.27690*4D 2019-05-21T14:56:36.442Z,1558450596.442 [Micromodem](INFO): Starting 2019-05-21T14:56:36.444Z,1558450596.444 [Micromodem](INFO): Nmea in: $CAREV,145635,SLOT1,2.0.27690*62 2019-05-21T14:56:36.846Z,1558450596.846 [Micromodem](INFO): Starting 2019-05-21T14:56:36.847Z,1558450596.847 [Micromodem](INFO): Nmea in: $CAREV,145635,AUV,2.0.27690*15 2019-05-21T14:56:36.848Z,1558450596.848 [Micromodem](INFO): Starting 2019-05-21T14:56:36.849Z,1558450596.849 [Micromodem](INFO): Nmea in: $CAREV,145635,COPROC,0.10.0.46*40 2019-05-21T14:56:36.849Z,1558450596.849 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33 2019-05-21T14:56:36.850Z,1558450596.850 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33 2019-05-21T14:56:36.850Z,1558450596.850 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31 2019-05-21T14:56:36.850Z,1558450596.850 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64 2019-05-21T14:56:36.850Z,1558450596.850 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B 2019-05-21T14:56:37.254Z,1558450597.254 [Micromodem](INFO): Starting 2019-05-21T14:56:37.255Z,1558450597.255 [Micromodem](INFO): Nmea in: $CATMG,2019-05-21T14:56:35Z,RTC,RTC*72 2019-05-21T14:56:37.654Z,1558450597.654 [Micromodem](INFO): Starting 2019-05-21T14:56:38.058Z,1558450598.058 [Micromodem](INFO): Starting 2019-05-21T14:56:38.462Z,1558450598.462 [Micromodem](INFO): Starting 2019-05-21T14:56:38.866Z,1558450598.866 [Micromodem](INFO): Starting 2019-05-21T14:56:39.274Z,1558450599.274 [Micromodem](INFO): Starting 2019-05-21T14:56:39.674Z,1558450599.674 [Micromodem](INFO): Starting 2019-05-21T14:56:40.062Z,1558450600.062 [Micromodem](INFO): Starting 2019-05-21T14:56:40.462Z,1558450600.462 [Micromodem](INFO): Starting 2019-05-21T14:56:40.867Z,1558450600.867 [Micromodem](INFO): Starting 2019-05-21T14:56:41.259Z,1558450601.259 [Micromodem](INFO): Starting 2019-05-21T14:56:41.662Z,1558450601.662 [Micromodem](INFO): Starting 2019-05-21T14:56:42.074Z,1558450602.074 [Micromodem](INFO): Starting 2019-05-21T14:56:42.466Z,1558450602.466 [Micromodem](INFO): Starting 2019-05-21T14:56:42.766Z,1558450602.766 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004392 2019-05-21T14:56:42.870Z,1558450602.870 [Micromodem](INFO): Starting 2019-05-21T14:56:43.274Z,1558450603.274 [Micromodem](INFO): Starting 2019-05-21T14:56:43.678Z,1558450603.678 [Micromodem](INFO): Starting 2019-05-21T14:56:44.082Z,1558450604.082 [Micromodem](INFO): Starting 2019-05-21T14:56:44.486Z,1558450604.486 [Micromodem](INFO): Starting 2019-05-21T14:56:44.894Z,1558450604.894 [Micromodem](INFO): Starting 2019-05-21T14:56:44.920Z,1558450604.920 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-05-21T14:56:45.298Z,1558450605.298 [Micromodem](INFO): Starting 2019-05-21T14:56:45.699Z,1558450605.699 [Micromodem](INFO): Starting 2019-05-21T14:56:46.102Z,1558450606.102 [Micromodem](INFO): Starting 2019-05-21T14:56:46.103Z,1558450606.103 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31 2019-05-21T14:56:46.104Z,1558450606.104 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31 2019-05-21T14:56:46.506Z,1558450606.506 [Micromodem](INFO): Starting 2019-05-21T14:56:46.507Z,1558450606.507 [Micromodem](INFO): Nmea in: $CAREV,145645,AUV,2.0.27690*12 2019-05-21T14:56:46.910Z,1558450606.910 [Micromodem](INFO): Starting 2019-05-21T14:56:46.911Z,1558450606.911 [Micromodem](INFO): Nmea in: $CAREV,145645,COPROC,0.10.0.46*47 2019-05-21T14:56:47.314Z,1558450607.314 [Micromodem](INFO): Starting 2019-05-21T14:56:47.723Z,1558450607.723 [Micromodem](INFO): Starting 2019-05-21T14:56:48.122Z,1558450608.122 [Micromodem](INFO): Starting 2019-05-21T14:56:48.526Z,1558450608.526 [Micromodem](INFO): Starting 2019-05-21T14:56:48.932Z,1558450608.932 [Micromodem](INFO): Starting 2019-05-21T14:56:49.334Z,1558450609.334 [Micromodem](INFO): Starting 2019-05-21T14:56:49.738Z,1558450609.738 [DUSBL_Hydroid](INFO): DUSBL Version:O 2019-05-21T14:56:49.753Z,1558450609.753 [Micromodem](INFO): Starting 2019-05-21T14:56:50.142Z,1558450610.142 [Micromodem](INFO): Starting 2019-05-21T14:56:50.550Z,1558450610.550 [Micromodem](INFO): Starting 2019-05-21T14:56:50.950Z,1558450610.950 [Micromodem](INFO): Starting 2019-05-21T14:56:51.354Z,1558450611.354 [Micromodem](INFO): Starting 2019-05-21T14:56:51.762Z,1558450611.762 [Micromodem](INFO): Starting 2019-05-21T14:56:52.166Z,1558450612.166 [Micromodem](INFO): Starting 2019-05-21T14:56:52.570Z,1558450612.570 [Micromodem](INFO): Starting 2019-05-21T14:56:52.974Z,1558450612.974 [Micromodem](INFO): Starting 2019-05-21T14:56:53.374Z,1558450613.374 [Micromodem](INFO): Starting 2019-05-21T14:56:53.778Z,1558450613.778 [Micromodem](INFO): Starting 2019-05-21T14:56:54.186Z,1558450614.186 [Micromodem](INFO): Starting 2019-05-21T14:56:54.586Z,1558450614.586 [Micromodem](INFO): Starting 2019-05-21T14:56:54.990Z,1558450614.990 [Micromodem](INFO): Starting 2019-05-21T14:56:55.394Z,1558450615.394 [Micromodem](INFO): Starting 2019-05-21T14:56:55.802Z,1558450615.802 [Micromodem](INFO): Starting 2019-05-21T14:56:56.206Z,1558450616.206 [Micromodem](INFO): Starting 2019-05-21T14:56:56.207Z,1558450616.207 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33 2019-05-21T14:56:56.207Z,1558450616.207 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2019-05-21T14:56:56.606Z,1558450616.606 [Micromodem](INFO): Starting 2019-05-21T14:56:56.608Z,1558450616.608 [Micromodem](INFO): Nmea in: $CAREV,145655,AUV,2.0.27690*13 2019-05-21T14:56:57.010Z,1558450617.010 [Micromodem](INFO): Starting 2019-05-21T14:56:57.011Z,1558450617.011 [Micromodem](INFO): Nmea in: $CAREV,145655,COPROC,0.10.0.46*46 2019-05-21T14:56:57.418Z,1558450617.418 [Micromodem](INFO): Starting 2019-05-21T14:56:57.822Z,1558450617.822 [Micromodem](INFO): Starting 2019-05-21T14:56:57.823Z,1558450617.823 [NAL9602](INFO): Powering up NAL9602 2019-05-21T14:56:58.226Z,1558450618.226 [Micromodem](INFO): Starting 2019-05-21T14:56:58.634Z,1558450618.634 [Micromodem](INFO): Starting 2019-05-21T14:56:59.034Z,1558450619.034 [Micromodem](INFO): Starting 2019-05-21T14:56:59.434Z,1558450619.434 [Micromodem](INFO): Starting 2019-05-21T14:56:59.850Z,1558450619.850 [Micromodem](INFO): Starting 2019-05-21T14:57:00.246Z,1558450620.246 [Micromodem](INFO): Starting 2019-05-21T14:57:00.650Z,1558450620.650 [Micromodem](INFO): Starting 2019-05-21T14:57:01.062Z,1558450621.062 [Micromodem](INFO): Starting 2019-05-21T14:57:01.454Z,1558450621.454 [Micromodem](INFO): Starting 2019-05-21T14:57:01.858Z,1558450621.858 [Micromodem](INFO): Starting 2019-05-21T14:57:02.269Z,1558450622.269 [Micromodem](INFO): Starting 2019-05-21T14:57:02.666Z,1558450622.666 [Micromodem](INFO): Starting 2019-05-21T14:57:03.070Z,1558450623.070 [Micromodem](INFO): Starting 2019-05-21T14:57:03.474Z,1558450623.474 [Micromodem](INFO): Starting 2019-05-21T14:57:03.878Z,1558450623.878 [Micromodem](INFO): Starting 2019-05-21T14:57:04.282Z,1558450624.282 [Micromodem](INFO): Starting 2019-05-21T14:57:04.686Z,1558450624.686 [Micromodem](INFO): Starting 2019-05-21T14:57:05.090Z,1558450625.090 [Micromodem](INFO): Starting 2019-05-21T14:57:05.502Z,1558450625.502 [Micromodem](INFO): Starting 2019-05-21T14:57:05.902Z,1558450625.902 [Micromodem](INFO): Starting 2019-05-21T14:57:05.904Z,1558450625.904 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpi $CAREV,145705,AUV,2.0.27690*17 2019-05-21T14:57:05.904Z,1558450625.904 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACFG,nav.dt.txtrig_gpi $CAREV,145705,AUV,2.0.27690*17 2019-05-21T14:57:05.904Z,1558450625.904 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64 2019-05-21T14:57:06.307Z,1558450626.307 [Micromodem](INFO): Starting 2019-05-21T14:57:06.308Z,1558450626.308 [Micromodem](INFO): Nmea in: $CAREV,145705,COPROC,0.10.0.46*42 2019-05-21T14:57:06.710Z,1558450626.710 [Micromodem](INFO): Starting 2019-05-21T14:57:07.114Z,1558450627.114 [Micromodem](INFO): Starting 2019-05-21T14:57:07.518Z,1558450627.518 [Micromodem](INFO): Starting 2019-05-21T14:57:07.922Z,1558450627.922 [Micromodem](INFO): Starting 2019-05-21T14:57:08.326Z,1558450628.326 [Micromodem](INFO): Starting 2019-05-21T14:57:08.730Z,1558450628.730 [Micromodem](INFO): Starting 2019-05-21T14:57:08.731Z,1558450628.731 [NAL9602](INFO): NAL9602 initialized 2019-05-21T14:57:09.134Z,1558450629.134 [Micromodem](INFO): Starting 2019-05-21T14:57:09.538Z,1558450629.538 [Micromodem](INFO): Starting 2019-05-21T14:57:09.553Z,1558450629.553 [NAL9602](DEBUG): Fix Requested 2019-05-21T14:57:09.946Z,1558450629.946 [Micromodem](INFO): Starting 2019-05-21T14:57:10.346Z,1558450630.346 [Micromodem](INFO): Starting 2019-05-21T14:57:10.750Z,1558450630.750 [Micromodem](INFO): Starting 2019-05-21T14:57:11.154Z,1558450631.154 [Micromodem](INFO): Starting 2019-05-21T14:57:11.558Z,1558450631.558 [Micromodem](INFO): Starting 2019-05-21T14:57:11.966Z,1558450631.966 [Micromodem](INFO): Starting 2019-05-21T14:57:12.366Z,1558450632.366 [Micromodem](INFO): Starting 2019-05-21T14:57:12.770Z,1558450632.770 [Micromodem](INFO): Starting 2019-05-21T14:57:13.174Z,1558450633.174 [Micromodem](INFO): Starting 2019-05-21T14:57:13.586Z,1558450633.586 [Micromodem](INFO): Starting 2019-05-21T14:57:13.982Z,1558450633.982 [Micromodem](INFO): Starting 2019-05-21T14:57:14.386Z,1558450634.386 [Micromodem](INFO): Starting 2019-05-21T14:57:14.808Z,1558450634.808 [Micromodem](INFO): Starting 2019-05-21T14:57:15.194Z,1558450635.194 [Micromodem](INFO): Starting 2019-05-21T14:57:15.610Z,1558450635.610 [Micromodem](INFO): Starting 2019-05-21T14:57:16.007Z,1558450636.007 [Micromodem](INFO): Starting 2019-05-21T14:57:16.008Z,1558450636.008 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66 2019-05-21T14:57:16.008Z,1558450636.008 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B 2019-05-21T14:57:16.414Z,1558450636.414 [Micromodem](INFO): Starting 2019-05-21T14:57:16.415Z,1558450636.415 [Micromodem](INFO): Nmea in: $CAREV,145715,AUV,2.0.27690*16 2019-05-21T14:57:16.814Z,1558450636.814 [Micromodem](INFO): Starting 2019-05-21T14:57:16.815Z,1558450636.815 [Micromodem](INFO): Nmea in: $CAREV,145715,COPROC,0.10.0.46*43 2019-05-21T14:57:17.218Z,1558450637.218 [Micromodem](INFO): Starting 2019-05-21T14:57:17.618Z,1558450637.618 [Micromodem](INFO): Starting 2019-05-21T14:57:18.022Z,1558450638.022 [Micromodem](INFO): Starting 2019-05-21T14:57:18.426Z,1558450638.426 [Micromodem](INFO): Starting 2019-05-21T14:57:18.830Z,1558450638.830 [Micromodem](INFO): Starting 2019-05-21T14:57:19.241Z,1558450639.241 [Micromodem](INFO): Starting 2019-05-21T14:57:19.642Z,1558450639.642 [Micromodem](INFO): Starting 2019-05-21T14:57:20.042Z,1558450640.042 [Micromodem](INFO): Starting 2019-05-21T14:57:20.446Z,1558450640.446 [Micromodem](INFO): Starting 2019-05-21T14:57:20.854Z,1558450640.854 [Micromodem](INFO): Starting 2019-05-21T14:57:21.254Z,1558450641.254 [Micromodem](INFO): Starting 2019-05-21T14:57:21.658Z,1558450641.658 [Micromodem](INFO): Starting 2019-05-21T14:57:22.062Z,1558450642.062 [Micromodem](INFO): Starting 2019-05-21T14:57:22.466Z,1558450642.466 [Micromodem](INFO): Starting 2019-05-21T14:57:22.870Z,1558450642.870 [Micromodem](INFO): Starting 2019-05-21T14:57:23.274Z,1558450643.274 [Micromodem](INFO): Starting 2019-05-21T14:57:23.678Z,1558450643.678 [Micromodem](INFO): Starting 2019-05-21T14:57:23.735Z,1558450643.735 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-21T14:57:23.747Z,1558450643.747 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-21T14:57:24.086Z,1558450644.086 [Micromodem](INFO): Starting 2019-05-21T14:57:24.486Z,1558450644.486 [Micromodem](INFO): Starting 2019-05-21T14:57:24.890Z,1558450644.890 [Micromodem](INFO): Starting 2019-05-21T14:57:25.294Z,1558450645.294 [Micromodem](INFO): Starting 2019-05-21T14:57:25.702Z,1558450645.702 [Micromodem](INFO): Starting 2019-05-21T14:57:26.118Z,1558450646.118 [Micromodem](INFO): Starting 2019-05-21T14:57:26.119Z,1558450646.119 [Micromodem](INFO): Nmea in: $CACFG,BND,1*39 2019-05-21T14:57:26.120Z,1558450646.120 [Micromodem](DEBUG): Nmea buf: $CCTMS,2019-05-21T14:57:27Z,0*7A 2019-05-21T14:57:26.120Z,1558450646.120 [Micromodem](INFO): Nmea out: $CCTMS,2019-05-21T14:57:27Z,0*7A 2019-05-21T14:57:26.792Z,1558450646.792 [Micromodem](INFO): Starting 2019-05-21T14:57:26.793Z,1558450646.793 [Micromodem](INFO): Nmea in: $CAREV,145725,AUV,2.0.27690*15 2019-05-21T14:57:27.150Z,1558450647.150 [Micromodem](INFO): Starting 2019-05-21T14:57:27.151Z,1558450647.151 [Micromodem](INFO): Nmea in: $CAREV,145725,COPROC,0.10.0.46*40 2019-05-21T14:57:27.566Z,1558450647.566 [Micromodem](INFO): Starting 2019-05-21T14:57:27.567Z,1558450647.567 [Micromodem](INFO): Nmea in: $CATMS,0,2019-05-21T14:57:27Z*78 2019-05-21T14:57:31.224Z,1558450651.224 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-05-21T14:57:34.922Z,1558450654.922 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.009654 CHAN A1 (24V): -0.028160 CHAN A2 (12V): -0.007067 CHAN A3 (5V): -0.002187 CHAN B0 (3.3V): 0.000007 CHAN B1 (3.15aV): -0.000422 CHAN B2 (3.15bV): 0.000089 CHAN B3 (GND): 0.002545 OPEN: 0.005317 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-21T14:57:36.043Z,1558450656.043 [Micromodem](INFO): Nmea in: $CATMG,2019-05-21T14:57:27Z,USER_CMD,RTC*31 2019-05-21T14:57:36.044Z,1558450656.044 [Micromodem](INFO): Nmea in: $CAREV,145736,AUV,2.0.27690*17 2019-05-21T14:57:45.971Z,1558450665.971 [Micromodem](INFO): Nmea in: $CAREV,145736,COPROC,0.10.0.46*42 2019-05-21T14:57:45.972Z,1558450665.972 [Micromodem](INFO): Nmea in: $CAREV,145746,AUV,2.0.27690*10 2019-05-21T14:57:56.067Z,1558450676.067 [Micromodem](INFO): Nmea in: $CAREV,145746,COPROC,0.10.0.46*45 2019-05-21T14:57:56.068Z,1558450676.068 [Micromodem](INFO): Nmea in: $CAREV,145756,AUV,2.0.27690*11 2019-05-21T14:58:06.317Z,1558450686.317 [Micromodem](INFO): Nmea in: $CAREV,145756,COPROC,0.10.0.46*44 2019-05-21T14:58:06.318Z,1558450686.318 [Micromodem](INFO): Nmea in: $CAREV,145806,AUV,2.0.27690*1B 2019-05-21T14:58:09.976Z,1558450689.976 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00, 84.00 2019-05-21T14:58:15.999Z,1558450695.999 [Micromodem](INFO): Nmea in: $CAREV,145806,COPROC,0.10.0.46*4E 2019-05-21T14:58:16.001Z,1558450696.001 [Micromodem](INFO): Nmea in: $CAREV,145816,AUV,2.0.27690*1A 2019-05-21T14:58:17.254Z,1558450697.254 [SBIT](IMPORTANT): SBIT PASSED 2019-05-21T14:58:17.326Z,1558450697.326 [CommandLine](IMPORTANT): got command configSet list 2019-05-21T14:58:17.326Z,1558450697.326 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool; 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count; 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter; 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree; 2019-05-21T14:58:17.327Z,1558450697.327 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=525 cubic_centimeter; 2019-05-21T14:58:17.328Z,1558450697.328 [CommandLine](IMPORTANT): VerticalControl.massDefault=-8 millimeter; 2019-05-21T14:58:17.646Z,1558450697.646 [MissionManager](IMPORTANT): Started mission Startup 2019-05-21T14:58:17.646Z,1558450697.646 [Startup] Running Loop=1 2019-05-21T14:58:17.646Z,1558450697.646 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-21T14:58:17.646Z,1558450697.646 [Startup:A.GoToSurface] Running Loop=1 2019-05-21T14:58:17.646Z,1558450697.646 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-21T14:58:17.647Z,1558450697.647 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-21T14:58:17.647Z,1558450697.647 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-21T14:58:17.648Z,1558450697.648 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-21T14:58:17.648Z,1558450697.648 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-21T14:58:17.649Z,1558450697.649 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-21T14:58:17.650Z,1558450697.650 [Startup:StartupSatComms] Running Loop=1 2019-05-21T14:58:17.650Z,1558450697.650 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-21T14:58:17.650Z,1558450697.650 [Startup:StartupSatComms:A] Running Loop=1 2019-05-21T14:58:18.085Z,1558450698.085 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-21T14:58:26.099Z,1558450706.099 [Micromodem](INFO): Nmea in: $CAREV,145816,COPROC,0.10.0.46*4F 2019-05-21T14:58:26.100Z,1558450706.100 [Micromodem](INFO): Nmea in: $CAREV,145826,AUV,2.0.27690*19 2019-05-21T14:58:26.131Z,1558450706.131 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-05-21T14:58:36.204Z,1558450716.204 [Micromodem](INFO): Nmea in: $CAREV,145826,COPROC,0.10.0.46*4C 2019-05-21T14:58:36.205Z,1558450716.205 [Micromodem](INFO): Nmea in: $CAREV,145836,AUV,2.0.27690*18 2019-05-21T14:58:45.899Z,1558450725.899 [Micromodem](INFO): Nmea in: $CAREV,145836,COPROC,0.10.0.46*4D 2019-05-21T14:58:45.900Z,1558450725.900 [Micromodem](INFO): Nmea in: $CAREV,145846,AUV,2.0.27690*1F 2019-05-21T14:58:55.995Z,1558450735.995 [Micromodem](INFO): Nmea in: $CAREV,145846,COPROC,0.10.0.46*4A 2019-05-21T14:58:55.996Z,1558450735.996 [Micromodem](INFO): Nmea in: $CAREV,145856,AUV,2.0.27690*1E 2019-05-21T14:59:06.104Z,1558450746.104 [Micromodem](INFO): Nmea in: $CAREV,145856,COPROC,0.10.0.46*4B 2019-05-21T14:59:06.105Z,1558450746.105 [Micromodem](INFO): Nmea in: $CAREV,145906,AUV,2.0.27690*1A 2019-05-21T14:59:16.204Z,1558450756.204 [Micromodem](INFO): Nmea in: $CAREV,145906,COPROC,0.10.0.46*4F 2019-05-21T14:59:16.205Z,1558450756.205 [Micromodem](INFO): Nmea in: $CAREV,145916,AUV,2.0.27690*1B 2019-05-21T14:59:17.871Z,1558450757.871 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-21T14:58:17.7Z 2019-05-21T14:59:17.871Z,1558450757.871 [Startup:StartupSatComms:A] Stopped 2019-05-21T14:59:17.871Z,1558450757.871 [Startup:StartupSatComms:B] Running Loop=1 2019-05-21T14:59:18.274Z,1558450758.274 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-21T14:59:24.883Z,1558450764.883 [CommandLine](IMPORTANT): got command run ./Missions/Insert/MicromodemComms.xml 2019-05-21T14:59:24.883Z,1558450764.883 [MissionManager](INFO): Loading Mission: ./Missions/Insert/MicromodemComms.xml 2019-05-21T14:59:24.896Z,1558450764.896 [MissionManager](INFO): DefineArg MicromodemComms.Timeout = 10.000000 min 2019-05-21T14:59:24.900Z,1558450764.900 [MissionManager](DEBUG): 10 2019-05-21T14:59:24.902Z,1558450764.902 [CommandLine](IMPORTANT): Running ./Missions/Insert/MicromodemComms.xml 2019-05-21T14:59:25.004Z,1558450765.004 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190521T141134/Courier0004.lzma 2019-05-21T14:59:25.810Z,1558450765.810 [DataOverHttps](INFO): Moved sent file to Logs/20190521T141134/Courier0004.lzma.bak 2019-05-21T14:59:25.811Z,1558450765.811 [DataOverHttps](INFO): SBD MOMSN=11130582 2019-05-21T14:59:25.900Z,1558450765.900 [Micromodem](INFO): Nmea in: $CAREV,145916,COPROC,0.10.0.46*4E 2019-05-21T14:59:25.901Z,1558450765.901 [Micromodem](INFO): Nmea in: $CAREV,145926,AUV,2.0.27690*18 2019-05-21T14:59:31.189Z,1558450771.189 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-05-21T14:59:31.189Z,1558450771.189 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-21T14:59:31.207Z,1558450771.207 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-21T14:59:31.586Z,1558450771.586 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-21T14:59:31.586Z,1558450771.586 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-05-21T14:59:35.991Z,1558450775.991 [Micromodem](INFO): Nmea in: $CAREV,145926,COPROC,0.10.0.46*4D 2019-05-21T14:59:35.993Z,1558450775.993 [Micromodem](INFO): Nmea in: $CAREV,145936,AUV,2.0.27690*19 2019-05-21T14:59:46.091Z,1558450786.091 [Micromodem](INFO): Nmea in: $CAREV,145936,COPROC,0.10.0.46*4C 2019-05-21T14:59:46.092Z,1558450786.092 [Micromodem](INFO): Nmea in: $CAREV,145946,AUV,2.0.27690*1E 2019-05-21T14:59:47.621Z,1558450787.621 [DataOverHttps](INFO): Sending 267 bytes from file Logs/20190520T161244/Express0580.lzma 2019-05-21T14:59:48.427Z,1558450788.427 [DataOverHttps](INFO): Moved sent file to Logs/20190520T161244/Express0580.lzma.bak 2019-05-21T14:59:48.427Z,1558450788.427 [DataOverHttps](INFO): SBD MOMSN=11130585 2019-05-21T14:59:52.078Z,1558450792.078 [CommandLine](IMPORTANT): got command show stack 2019-05-21T14:59:52.079Z,1558450792.079 [CommandLine](IMPORTANT): Behavior Stack: 2019-05-21T14:59:52.079Z,1558450792.079 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface 2019-05-21T14:59:52.079Z,1558450792.079 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B 2019-05-21T14:59:56.200Z,1558450796.200 [Micromodem](INFO): Nmea in: $CAREV,145946,COPROC,0.10.0.46*4B 2019-05-21T14:59:56.201Z,1558450796.201 [Micromodem](INFO): Nmea in: $CAREV,145956,AUV,2.0.27690*1F 2019-05-21T15:00:03.780Z,1558450803.780 [CommandLine](IMPORTANT): got command show stack 2019-05-21T15:00:03.780Z,1558450803.780 [CommandLine](IMPORTANT): Behavior Stack: 2019-05-21T15:00:03.781Z,1558450803.781 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface 2019-05-21T15:00:03.781Z,1558450803.781 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B 2019-05-21T15:00:05.892Z,1558450805.892 [Micromodem](INFO): Nmea in: $CAREV,145956,COPROC,0.10.0.46*4A 2019-05-21T15:00:05.893Z,1558450805.893 [Micromodem](INFO): Nmea in: $CAREV,150006,AUV,2.0.27690*17 2019-05-21T15:00:15.987Z,1558450815.987 [Micromodem](INFO): Nmea in: $CAREV,150006,COPROC,0.10.0.46*42 2019-05-21T15:00:15.988Z,1558450815.988 [Micromodem](INFO): Nmea in: $CAREV,150016,AUV,2.0.27690*16 2019-05-21T15:00:18.039Z,1558450818.039 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-21T14:59:17.9Z 2019-05-21T15:00:18.039Z,1558450818.039 [Startup:StartupSatComms:B] Stopped 2019-05-21T15:00:18.039Z,1558450818.039 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-21T15:00:18.039Z,1558450818.039 [Startup:StartupSatComms] Stopped 2019-05-21T15:00:18.039Z,1558450818.039 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-21T15:00:18.040Z,1558450818.040 [Startup](INFO): Completed Startup 2019-05-21T15:00:18.040Z,1558450818.040 [MissionManager](INFO): Startup is completed. 2019-05-21T15:00:18.041Z,1558450818.041 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-21T15:00:18.041Z,1558450818.041 [Startup] Stopped 2019-05-21T15:00:18.041Z,1558450818.041 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-21T15:00:18.041Z,1558450818.041 [Startup:A.GoToSurface] Stopped 2019-05-21T15:00:18.041Z,1558450818.041 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-21T15:00:18.438Z,1558450818.438 [MissionManager](IMPORTANT): Started mission MicromodemComms 2019-05-21T15:00:18.438Z,1558450818.438 [MicromodemComms] Running Loop=1 2019-05-21T15:00:18.438Z,1558450818.438 [MicromodemComms](DEBUG): Aggregate::initialize MicromodemComms 2019-05-21T15:00:18.438Z,1558450818.438 [MicromodemComms:CheckIn] Running Loop=1 2019-05-21T15:00:18.438Z,1558450818.438 [MicromodemComms:CheckIn](DEBUG): Aggregate::initialize MicromodemComms:CheckIn 2019-05-21T15:00:18.438Z,1558450818.438 [MicromodemComms:CheckIn:A] Running Loop=1 2019-05-21T15:00:18.439Z,1558450818.439 [MicromodemComms:CheckIn:A](DEBUG): Initialize ReadDataComponent to sense Micromodem.platform_communications 2019-05-21T15:00:20.225Z,1558450820.225 [Micromodem](DEBUG): Nmea buf: $CCCYC,0,1,10,1,0,3*6B 2019-05-21T15:00:20.225Z,1558450820.225 [Micromodem](INFO): Nmea out: $CCCYC,0,1,10,1,0,3*6B 2019-05-21T15:00:20.443Z,1558450820.443 [Micromodem](INFO): Nmea in: $CAREV,150016,COPROC,0.10.0.46*43 2019-05-21T15:00:20.444Z,1558450820.444 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:20.844Z,1558450820.844 [Micromodem](INFO): Nmea in: $CACYC,0,1,10,1,0,3*69 2019-05-21T15:00:20.853Z,1558450820.853 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:21.246Z,1558450821.246 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:21.633Z,1558450821.633 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:22.027Z,1558450822.027 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:22.431Z,1558450822.431 [Micromodem](INFO): Nmea in: $CADRQ,150020,1,10,0,64,1*70 2019-05-21T15:00:22.432Z,1558450822.432 [Micromodem](INFO): Received CADRQ with unexpected frame#: 1 2019-05-21T15:00:22.432Z,1558450822.432 [Micromodem](DEBUG): Nmea buf: $CCTXD,6,1,1,10,2,1,1,1,128*6B 2019-05-21T15:00:22.432Z,1558450822.432 [Micromodem](INFO): Nmea out: $CCTXD,6,1,1,10,2,1,1,1,128*6B 2019-05-21T15:00:22.434Z,1558450822.434 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:22.831Z,1558450822.831 [Micromodem](INFO): Nmea in: $CAERR,150022,DATA_TIMEOUT,1*4A 2019-05-21T15:00:22.831Z,1558450822.831 [Micromodem](ERROR): Response from modem unexpected: $CAERR,150022,DATA_TIMEOUT,1*4A 2019-05-21T15:00:22.832Z,1558450822.832 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:23.235Z,1558450823.235 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:23.642Z,1558450823.642 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:24.047Z,1558450824.047 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:24.447Z,1558450824.447 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:24.858Z,1558450824.858 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:25.263Z,1558450825.263 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:25.658Z,1558450825.658 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:26.068Z,1558450826.068 [Micromodem](INFO): Nmea in: $CAER,5002,NI ,15,Wrong number of arguments*49 2019-05-21T15:00:26.068Z,1558450826.068 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAER,5002,NI ,15,Wrong number of arguments*49 2019-05-21T15:00:26.068Z,1558450826.068 [Micromodem](INFO): Nmea out: $CCTXD,6,1,1,10,2,1,1,1,128*6B 2019-05-21T15:00:26.069Z,1558450826.069 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:26.475Z,1558450826.475 [Micromodem](INFO): Nmea in: $CAREV,150026,AUV,2.0.27690*15 2019-05-21T15:00:26.476Z,1558450826.476 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:26.871Z,1558450826.871 [Micromodem](INFO): Nmea in: $CAREV,150026,COPROC,0.10.0.46*40 2019-05-21T15:00:26.871Z,1558450826.871 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:27.275Z,1558450827.275 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:27.679Z,1558450827.679 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:28.082Z,1558450828.082 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:28.486Z,1558450828.486 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:28.895Z,1558450828.895 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:29.295Z,1558450829.295 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:29.698Z,1558450829.698 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:30.107Z,1558450830.107 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:30.506Z,1558450830.506 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:30.910Z,1558450830.910 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:31.319Z,1558450831.319 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:31.732Z,1558450831.732 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:32.126Z,1558450832.126 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:32.543Z,1558450832.543 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:32.931Z,1558450832.931 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:33.340Z,1558450833.340 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:33.744Z,1558450833.744 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:34.154Z,1558450834.154 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:34.550Z,1558450834.550 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:34.951Z,1558450834.951 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:35.355Z,1558450835.355 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:35.778Z,1558450835.778 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:36.167Z,1558450836.167 [Micromodem](INFO): Nmea in: $CAERR,1006NI ,15,Wrong number of arguments*4D 2019-05-21T15:00:36.168Z,1558450836.168 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAERR,1006NI ,15,Wrong number of arguments*4D 2019-05-21T15:00:36.168Z,1558450836.168 [Micromodem](INFO): Nmea out: $CCTXD,6,1,1,10,2,1,1,1,128*6B 2019-05-21T15:00:36.171Z,1558450836.171 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:36.567Z,1558450836.567 [Micromodem](INFO): Nmea in: $CAREV,150036,AUV,2.0.27690*14 2019-05-21T15:00:36.567Z,1558450836.567 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:36.975Z,1558450836.975 [Micromodem](INFO): Nmea in: $CAREV,150036,COPROC,0.10.0.46*41 2019-05-21T15:00:36.975Z,1558450836.975 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:37.375Z,1558450837.375 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:37.782Z,1558450837.782 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:38.182Z,1558450838.182 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:38.591Z,1558450838.591 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:38.991Z,1558450838.991 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:39.399Z,1558450839.399 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:39.811Z,1558450839.811 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:40.214Z,1558450840.214 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:40.606Z,1558450840.606 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:41.015Z,1558450841.015 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:41.414Z,1558450841.414 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:41.826Z,1558450841.826 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:42.227Z,1558450842.227 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:42.627Z,1558450842.627 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:42.873Z,1558450842.873 [CommandLine](IMPORTANT): got command quit 2019-05-21T15:00:43.030Z,1558450843.030 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:43.439Z,1558450843.439 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:43.838Z,1558450843.838 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:43.877Z,1558450843.877 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-05-21T15:00:43.877Z,1558450843.877 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:43.877Z,1558450843.877 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:43.905Z,1558450843.905 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-05-21T15:00:43.905Z,1558450843.905 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:43.906Z,1558450843.906 [CommandLine](INFO): Join timeout helper Thread ID is 3075 2019-05-21T15:00:43.913Z,1558450843.913 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-05-21T15:00:43.913Z,1558450843.913 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:43.913Z,1558450843.913 [NavChartDb](INFO): Join timeout helper Thread ID is 3076 2019-05-21T15:00:44.129Z,1558450844.129 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.130Z,1558450844.130 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.141Z,1558450844.141 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-05-21T15:00:44.141Z,1558450844.141 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.141Z,1558450844.141 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 3077 2019-05-21T15:00:44.209Z,1558450844.209 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.209Z,1558450844.209 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-05-21T15:00:44.210Z,1558450844.210 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.221Z,1558450844.221 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-05-21T15:00:44.221Z,1558450844.221 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.221Z,1558450844.221 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3078 2019-05-21T15:00:44.242Z,1558450844.242 [Micromodem](INFO): ************** SENDING_TRANSMIT ************** 2019-05-21T15:00:44.286Z,1558450844.286 [MissionManager](INFO): MissionManager is completed. 2019-05-21T15:00:44.286Z,1558450844.286 [MissionManager](INFO): Uninitializing Mission MicromodemComms 2019-05-21T15:00:44.286Z,1558450844.286 [MicromodemComms] Stopped 2019-05-21T15:00:44.286Z,1558450844.286 [MicromodemComms](DEBUG): Aggregate::uninitialize MicromodemComms 2019-05-21T15:00:44.286Z,1558450844.286 [MicromodemComms:CheckIn] Stopped 2019-05-21T15:00:44.286Z,1558450844.286 [MicromodemComms:CheckIn](DEBUG): Aggregate::uninitialize MicromodemComms:CheckIn 2019-05-21T15:00:44.286Z,1558450844.286 [MicromodemComms:CheckIn:A] Stopped 2019-05-21T15:00:44.297Z,1558450844.297 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.297Z,1558450844.297 [CTD_NeilBrown](INFO): Powering down 2019-05-21T15:00:44.309Z,1558450844.309 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.329Z,1558450844.329 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-05-21T15:00:44.329Z,1558450844.329 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.329Z,1558450844.329 [Radio_Surface](INFO): Join timeout helper Thread ID is 3079 2019-05-21T15:00:44.509Z,1558450844.509 [Radio_Surface](INFO): Powering down 2019-05-21T15:00:44.510Z,1558450844.510 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.510Z,1558450844.510 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.518Z,1558450844.518 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-05-21T15:00:44.518Z,1558450844.518 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.520Z,1558450844.520 [DataOverHttps](INFO): Join timeout helper Thread ID is 3080 2019-05-21T15:00:44.678Z,1558450844.678 [MissionManager](IMPORTANT): Started mission Default 2019-05-21T15:00:44.678Z,1558450844.678 [Default] Running Loop=1 2019-05-21T15:00:44.678Z,1558450844.678 [Default](DEBUG): Aggregate::initialize Default 2019-05-21T15:00:44.678Z,1558450844.678 [Default:B.GoToSurface] Running Loop=1 2019-05-21T15:00:44.678Z,1558450844.678 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-21T15:00:44.678Z,1558450844.678 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-21T15:00:44.679Z,1558450844.679 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-21T15:00:44.679Z,1558450844.679 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-21T15:00:44.679Z,1558450844.679 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-21T15:00:44.680Z,1558450844.680 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-21T15:00:44.680Z,1558450844.680 [Default:A.Wait] Running Loop=1 2019-05-21T15:00:44.680Z,1558450844.680 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-21T15:00:44.709Z,1558450844.709 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.709Z,1558450844.709 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.717Z,1558450844.717 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-05-21T15:00:44.718Z,1558450844.718 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.718Z,1558450844.718 [logger](INFO): Join timeout helper Thread ID is 3081 2019-05-21T15:00:44.729Z,1558450844.729 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:44.729Z,1558450844.729 [logger ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.739Z,1558450844.739 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-05-21T15:00:44.739Z,1558450844.739 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.739Z,1558450844.739 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-05-21T15:00:44.739Z,1558450844.739 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:44.739Z,1558450844.739 [controlThread](INFO): Join timeout helper Thread ID is 3082 2019-05-21T15:00:45.041Z,1558450845.041 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-05-21T15:00:45.041Z,1558450845.041 [controlThread](DEBUG): Uninitializing ControlThread 2019-05-21T15:00:45.041Z,1558450845.041 [AHRS_M2](INFO): Powering down 2019-05-21T15:00:45.113Z,1558450845.113 [DUSBL_Hydroid](INFO): Powering down 2019-05-21T15:00:45.205Z,1558450845.205 [Micromodem](INFO): uninitialize 2019-05-21T15:00:45.205Z,1558450845.205 [Micromodem](INFO): Powering down 2019-05-21T15:00:45.301Z,1558450845.301 [NAL9602](INFO): Powering down 2019-05-21T15:00:45.373Z,1558450845.373 [RDI_Pathfinder](INFO): Powering down 2019-05-21T15:00:45.375Z,1558450845.375 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-05-21T15:00:45.375Z,1558450845.375 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-05-21T15:00:45.376Z,1558450845.376 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-05-21T15:00:45.376Z,1558450845.376 [MissionManager](INFO): Uninitializing Mission Default 2019-05-21T15:00:45.377Z,1558450845.377 [Default] Stopped 2019-05-21T15:00:45.377Z,1558450845.377 [Default](DEBUG): Aggregate::uninitialize Default 2019-05-21T15:00:45.377Z,1558450845.377 [Default:A.Wait] Stopped 2019-05-21T15:00:45.377Z,1558450845.377 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-21T15:00:45.377Z,1558450845.377 [Default:B.GoToSurface] Stopped 2019-05-21T15:00:45.377Z,1558450845.377 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-21T15:00:45.379Z,1558450845.379 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-05-21T15:00:45.379Z,1558450845.379 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-05-21T15:00:45.380Z,1558450845.380 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-05-21T15:00:45.380Z,1558450845.380 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-05-21T15:00:45.380Z,1558450845.380 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-05-21T15:00:45.380Z,1558450845.380 [BuoyancyServo](INFO): Powering down 2019-05-21T15:00:45.393Z,1558450845.393 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-05-21T15:00:45.393Z,1558450845.393 [ElevatorServo](INFO): Powering down 2019-05-21T15:00:45.394Z,1558450845.394 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-05-21T15:00:45.394Z,1558450845.394 [MassServo](INFO): Powering down 2019-05-21T15:00:45.395Z,1558450845.395 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-05-21T15:00:45.395Z,1558450845.395 [RudderServo](INFO): Powering down 2019-05-21T15:00:45.395Z,1558450845.395 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-05-21T15:00:45.396Z,1558450845.396 [ThrusterServo](INFO): Powering down 2019-05-21T15:00:45.396Z,1558450845.396 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-05-21T15:00:45.397Z,1558450845.397 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-05-21T15:00:45.397Z,1558450845.397 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-05-21T15:00:45.397Z,1558450845.397 [CBIT](DEBUG): Powering off loads. 2019-05-21T15:00:45.409Z,1558450845.409 [CBIT](DEBUG): Disabling WDT. 2019-05-21T15:00:45.421Z,1558450845.421 [CBIT](DEBUG): Opening all GF detection circuits. 2019-05-21T15:00:45.422Z,1558450845.422 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.478Z,1558450845.478 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.487Z,1558450845.487 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.527Z,1558450845.527 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.529Z,1558450845.529 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.583Z,1558450845.583 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-05-21T15:00:45.641Z,1558450845.641 [logger ThreadHandler](INFO): Thread cancelled.