2019-07-25T22:00:29.395Z,1564092029.395 [Supervisor](DEBUG): Initializing supervisor.
2019-07-25T22:00:29.398Z,1564092029.398 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-07-25T22:00:29.399Z,1564092029.399 [SyncHandler](INFO): Protected caller Thread ID is 4160
2019-07-25T22:00:29.399Z,1564092029.399 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-07-25T22:00:29.400Z,1564092029.400 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-07-25T22:00:29.401Z,1564092029.401 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 4161
2019-07-25T22:00:29.404Z,1564092029.404 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-07-25T22:00:29.416Z,1564092029.416 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-07-25T22:00:29.417Z,1564092029.417 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-07-25T22:00:29.417Z,1564092029.417 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 4162
2019-07-25T22:00:29.418Z,1564092029.418 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-07-25T22:00:29.419Z,1564092029.419 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-07-25T22:00:29.419Z,1564092029.419 [logger ThreadHandler](INFO): Protected caller Thread ID is 4163
2019-07-25T22:00:29.421Z,1564092029.421 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-07-25T22:00:29.421Z,1564092029.421 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-07-25T22:00:29.423Z,1564092029.423 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-07-25T22:00:29.624Z,1564092029.624 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-07-25T22:00:29.625Z,1564092029.625 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-07-25T22:00:29.706Z,1564092029.706 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-07-25T22:00:30.140Z,1564092030.140 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-07-25T22:00:30.140Z,1564092030.140 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-07-25T22:00:30.474Z,1564092030.474 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-07-25T22:00:30.474Z,1564092030.474 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-07-25T22:00:30.571Z,1564092030.571 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-07-25T22:00:30.571Z,1564092030.571 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-07-25T22:00:30.869Z,1564092030.869 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-07-25T22:00:30.869Z,1564092030.869 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-07-25T22:00:31.064Z,1564092031.064 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-07-25T22:00:31.065Z,1564092031.065 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-07-25T22:00:31.525Z,1564092031.525 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-07-25T22:00:31.526Z,1564092031.526 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-07-25T22:00:31.707Z,1564092031.707 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-07-25T22:00:31.708Z,1564092031.708 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-07-25T22:00:31.809Z,1564092031.809 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-07-25T22:00:31.810Z,1564092031.810 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-07-25T22:00:32.406Z,1564092032.406 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-07-25T22:00:32.407Z,1564092032.407 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-07-25T22:00:32.799Z,1564092032.799 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-07-25T22:00:32.799Z,1564092032.799 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-07-25T22:00:32.995Z,1564092032.995 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-07-25T22:00:32.996Z,1564092032.996 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-07-25T22:00:33.142Z,1564092033.142 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-07-25T22:00:33.142Z,1564092033.142 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-07-25T22:00:33.292Z,1564092033.292 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-07-25T22:00:33.294Z,1564092033.294 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2019-07-25T22:00:33.295Z,1564092033.295 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2019-07-25T22:00:33.388Z,1564092033.388 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2019-07-25T22:00:33.475Z,1564092033.475 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2019-07-25T22:00:33.579Z,1564092033.579 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2019-07-25T22:00:33.664Z,1564092033.664 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2019-07-25T22:00:33.761Z,1564092033.761 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2019-07-25T22:00:33.864Z,1564092033.864 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2019-07-25T22:00:34.177Z,1564092034.177 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2019-07-25T22:00:34.291Z,1564092034.291 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2019-07-25T22:00:34.461Z,1564092034.461 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2019-07-25T22:00:34.598Z,1564092034.598 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2019-07-25T22:00:34.719Z,1564092034.719 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2019-07-25T22:00:34.949Z,1564092034.949 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-07-25T22:00:34.950Z,1564092034.950 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2019-07-25T22:00:34.951Z,1564092034.951 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-07-25T22:00:34.971Z,1564092034.971 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-07-25T22:00:35.038Z,1564092035.038 [VerticalControl](DEBUG): Construct VerticalControl.
2019-07-25T22:00:35.148Z,1564092035.148 [VerticalControl] Loaded
2019-07-25T22:00:35.148Z,1564092035.148 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-07-25T22:00:35.149Z,1564092035.149 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-07-25T22:00:35.216Z,1564092035.216 [HorizontalControl] Loaded
2019-07-25T22:00:35.216Z,1564092035.216 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-07-25T22:00:35.217Z,1564092035.217 [SpeedControl](DEBUG): Construct SpeedControl.
2019-07-25T22:00:35.222Z,1564092035.222 [SpeedControl] Loaded
2019-07-25T22:00:35.222Z,1564092035.222 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-07-25T22:00:35.223Z,1564092035.223 [LoopControl](DEBUG): Construct LoopControl.
2019-07-25T22:00:35.224Z,1564092035.224 [LoopControl] Loaded
2019-07-25T22:00:35.224Z,1564092035.224 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-07-25T22:00:35.224Z,1564092035.224 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-07-25T22:00:35.225Z,1564092035.225 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-07-25T22:00:35.238Z,1564092035.238 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-07-25T22:00:35.239Z,1564092035.239 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-07-25T22:00:35.335Z,1564092035.335 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-07-25T22:00:35.336Z,1564092035.336 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-07-25T22:00:35.459Z,1564092035.459 [BuoyancyServo] Loaded
2019-07-25T22:00:35.459Z,1564092035.459 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-07-25T22:00:35.470Z,1564092035.470 [ElevatorServo] Loaded
2019-07-25T22:00:35.471Z,1564092035.471 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-07-25T22:00:35.481Z,1564092035.481 [MassServo] Loaded
2019-07-25T22:00:35.481Z,1564092035.481 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-07-25T22:00:35.492Z,1564092035.492 [RudderServo] Loaded
2019-07-25T22:00:35.493Z,1564092035.493 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-07-25T22:00:35.503Z,1564092035.503 [ThrusterServo] Loaded
2019-07-25T22:00:35.504Z,1564092035.504 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-07-25T22:00:35.504Z,1564092035.504 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-07-25T22:00:35.505Z,1564092035.505 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-07-25T22:00:35.611Z,1564092035.611 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-07-25T22:00:35.611Z,1564092035.611 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-07-25T22:00:35.632Z,1564092035.632 [NavChart] Loaded
2019-07-25T22:00:35.632Z,1564092035.632 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-07-25T22:00:35.636Z,1564092035.636 [UniversalFixResidualReporter] Loaded
2019-07-25T22:00:35.636Z,1564092035.636 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-07-25T22:00:35.637Z,1564092035.637 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-07-25T22:00:35.637Z,1564092035.637 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-07-25T22:00:35.706Z,1564092035.706 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-07-25T22:00:35.707Z,1564092035.707 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-07-25T22:00:36.035Z,1564092036.035 [DataOverHttps] Loaded
2019-07-25T22:00:36.035Z,1564092036.035 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-07-25T22:00:36.036Z,1564092036.036 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087D4E0
2019-07-25T22:00:36.037Z,1564092036.037 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4245
2019-07-25T22:00:36.050Z,1564092036.050 [Depth_Keller] Loaded
2019-07-25T22:00:36.050Z,1564092036.050 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-07-25T22:00:36.145Z,1564092036.145 [NAL9602] Loaded
2019-07-25T22:00:36.146Z,1564092036.146 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-07-25T22:00:36.162Z,1564092036.162 [Onboard] Loaded
2019-07-25T22:00:36.162Z,1564092036.162 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-07-25T22:00:36.165Z,1564092036.165 [Radio_Surface] Loaded
2019-07-25T22:00:36.165Z,1564092036.165 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-07-25T22:00:36.166Z,1564092036.166 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AD4E0
2019-07-25T22:00:36.167Z,1564092036.167 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4246
2019-07-25T22:00:38.300Z,1564092038.300 [BPC1] Loaded
2019-07-25T22:00:38.301Z,1564092038.301 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-07-25T22:00:38.301Z,1564092038.301 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-07-25T22:00:38.302Z,1564092038.302 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-07-25T22:00:38.342Z,1564092038.342 [DepthRateCalculator] Loaded
2019-07-25T22:00:38.343Z,1564092038.343 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-07-25T22:00:38.348Z,1564092038.348 [PitchRateCalculator] Loaded
2019-07-25T22:00:38.348Z,1564092038.348 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-07-25T22:00:38.359Z,1564092038.359 [SpeedCalculator] Loaded
2019-07-25T22:00:38.360Z,1564092038.360 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-07-25T22:00:38.381Z,1564092038.381 [TempGradientCalculator] Loaded
2019-07-25T22:00:38.381Z,1564092038.381 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-07-25T22:00:38.386Z,1564092038.386 [YawRateCalculator] Loaded
2019-07-25T22:00:38.387Z,1564092038.387 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-07-25T22:00:38.416Z,1564092038.416 [ElevatorOffsetCalculator] Loaded
2019-07-25T22:00:38.416Z,1564092038.416 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-07-25T22:00:38.417Z,1564092038.417 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-07-25T22:00:38.417Z,1564092038.417 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-07-25T22:00:38.616Z,1564092038.616 [ESPComponent] Loaded
2019-07-25T22:00:38.616Z,1564092038.616 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-07-25T22:00:38.630Z,1564092038.630 [PAR_Licor] Loaded
2019-07-25T22:00:38.630Z,1564092038.630 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-07-25T22:00:38.631Z,1564092038.631 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-07-25T22:00:38.632Z,1564092038.632 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-07-25T22:00:38.664Z,1564092038.664 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-07-25T22:00:38.664Z,1564092038.664 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-07-25T22:00:38.949Z,1564092038.949 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-07-25T22:00:38.949Z,1564092038.949 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-07-25T22:00:39.079Z,1564092039.079 [SBIT](DEBUG): Construct Startup Built In Test.
2019-07-25T22:00:39.090Z,1564092039.090 [SBIT] Loaded
2019-07-25T22:00:39.090Z,1564092039.090 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-07-25T22:00:39.091Z,1564092039.091 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-07-25T22:00:39.102Z,1564092039.102 [IBIT] Loaded
2019-07-25T22:00:39.103Z,1564092039.103 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-07-25T22:00:39.106Z,1564092039.106 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-07-25T22:00:39.240Z,1564092039.240 [CBIT] Loaded
2019-07-25T22:00:39.240Z,1564092039.240 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-07-25T22:00:39.240Z,1564092039.240 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-07-25T22:00:39.244Z,1564092039.244 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-07-25T22:00:39.245Z,1564092039.245 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-07-25T22:00:39.251Z,1564092039.251 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-07-25T22:00:39.252Z,1564092039.252 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A7F4E0
2019-07-25T22:00:39.253Z,1564092039.253 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4247
2019-07-25T22:00:39.257Z,1564092039.257 [Supervisor](INFO): Main Thread ID is 1790
2019-07-25T22:00:39.258Z,1564092039.258 [Supervisor](DEBUG): Running supervisor.
2019-07-25T22:00:39.258Z,1564092039.258 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4248
2019-07-25T22:00:39.261Z,1564092039.261 [controlThread ThreadHandler](INFO): Handler Thread ID is 4249
2019-07-25T22:00:39.261Z,1564092039.261 [controlThread](DEBUG): Initializing ControlThread
2019-07-25T22:00:39.262Z,1564092039.262 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-07-25T22:00:39.264Z,1564092039.264 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-07-25T22:00:39.264Z,1564092039.264 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-07-25T22:00:39.265Z,1564092039.265 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-07-25T22:00:39.266Z,1564092039.266 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-07-25T22:00:39.267Z,1564092039.267 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-07-25T22:00:39.270Z,1564092039.270 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-07-25T22:00:39.271Z,1564092039.271 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-07-25T22:00:39.271Z,1564092039.271 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-07-25T22:00:39.271Z,1564092039.271 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-07-25T22:00:39.272Z,1564092039.272 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-07-25T22:00:39.272Z,1564092039.272 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-07-25T22:00:39.274Z,1564092039.274 [SBIT](INFO): Initialize SBIT Component.
2019-07-25T22:00:39.274Z,1564092039.274 [SBIT](IMPORTANT): git: 2019-07-23
2019-07-25T22:00:39.274Z,1564092039.274 [SBIT](INFO): git hash: 66f82fd8c0ed4c5b011038c11738fd4b7b507f51
2019-07-25T22:00:39.275Z,1564092039.275 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-07-25T22:00:39.276Z,1564092039.276 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
2019-07-25T22:00:39.277Z,1564092039.277 [SBIT](INFO): Beginning SBIT in 29.000000 seconds.
2019-07-25T22:00:39.277Z,1564092039.277 [IBIT](INFO): Initialize IBIT Component.
2019-07-25T22:00:39.278Z,1564092039.278 [CBIT](DEBUG): Initialize CBIT Component.
2019-07-25T22:00:39.279Z,1564092039.279 [logger ThreadHandler](INFO): Handler Thread ID is 4250
2019-07-25T22:00:39.289Z,1564092039.289 [CBIT](DEBUG): Initialized mux pins.
2019-07-25T22:00:39.289Z,1564092039.289 [CBIT](DEBUG): Initializing the watchdog timer.
2019-07-25T22:00:39.298Z,1564092039.298 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4251
2019-07-25T22:00:39.299Z,1564092039.299 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-07-25T22:00:39.310Z,1564092039.310 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4252
2019-07-25T22:00:39.313Z,1564092039.313 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-07-25T22:00:39.313Z,1564092039.313 [CBIT](DEBUG): Initializing heartbeat.
2019-07-25T22:00:39.322Z,1564092039.322 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4253
2019-07-25T22:00:39.325Z,1564092039.325 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-07-25T22:00:39.325Z,1564092039.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-07-25T22:00:39.325Z,1564092039.325 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-07-25T22:00:39.325Z,1564092039.325 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-07-25T22:00:39.326Z,1564092039.326 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-07-25T22:00:39.326Z,1564092039.326 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-07-25T22:00:39.326Z,1564092039.326 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-07-25T22:00:39.326Z,1564092039.326 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-07-25T22:00:39.326Z,1564092039.326 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-07-25T22:00:39.327Z,1564092039.327 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-07-25T22:00:39.328Z,1564092039.328 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-07-25T22:00:39.385Z,1564092039.385 [CBIT](DEBUG): Deactivating GF circuits.
2019-07-25T22:00:39.385Z,1564092039.385 [CBIT](DEBUG): Deactivating emergency mode.
2019-07-25T22:00:39.421Z,1564092039.421 [CBIT](DEBUG): Backplane powered.
2019-07-25T22:00:39.422Z,1564092039.422 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-07-25T22:00:39.433Z,1564092039.433 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-25T22:00:39.443Z,1564092039.443 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-07-25T22:00:39.444Z,1564092039.444 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-07-25T22:00:39.524Z,1564092039.524 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-07-25T22:00:39.525Z,1564092039.525 [Default:A.Wait](DEBUG): Construct Wait.
2019-07-25T22:00:39.527Z,1564092039.527 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-07-25T22:00:39.566Z,1564092039.566 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-07-25T22:00:39.568Z,1564092039.568 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-07-25T22:00:39.590Z,1564092039.590 [Default:E.Execute](DEBUG): Construct Execute.
2019-07-25T22:00:39.593Z,1564092039.593 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-07-25T22:00:39.605Z,1564092039.605 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-25T22:00:39.620Z,1564092039.620 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2019-07-25T22:00:39.713Z,1564092039.713 [Radio_Surface](INFO): Powering up
2019-07-25T22:00:39.787Z,1564092039.787 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-07-25T22:00:39.821Z,1564092039.821 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:39.849Z,1564092039.849 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-07-25T22:00:39.850Z,1564092039.850 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:39.858Z,1564092039.858 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-07-25T22:00:39.859Z,1564092039.859 [MassServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:39.866Z,1564092039.866 [MassServo](DEBUG): Initializing MassServo.
2019-07-25T22:00:39.867Z,1564092039.867 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:39.874Z,1564092039.874 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-25T22:00:39.875Z,1564092039.875 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:39.882Z,1564092039.882 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-07-25T22:00:40.801Z,1564092040.801 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-07-25T22:00:40.801Z,1564092040.801 [RudderServo](FAULT): Rudder failed to initialize
2019-07-25T22:00:40.802Z,1564092040.802 [RudderServo] Communications Fault, FailCount= 1
2019-07-25T22:00:40.802Z,1564092040.802 [RudderServo](ERROR): Communications Fault
2019-07-25T22:00:40.912Z,1564092040.912 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-07-25T22:00:41.118Z,1564092041.118 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-25T22:00:41.118Z,1564092041.118 [RudderServo](INFO): Powering down
2019-07-25T22:00:41.780Z,1564092041.780 [RudderServo](DEBUG): Initializing EZServoServo.
2019-07-25T22:00:41.898Z,1564092041.898 [RudderServo](DEBUG): Initializing RudderServo.
2019-07-25T22:00:41.902Z,1564092041.902 [CBIT](INFO): Clearing failed state for component RudderServo
2019-07-25T22:00:41.902Z,1564092041.902 [RudderServo] No Fault, FailCount= 1
2019-07-25T22:00:49.557Z,1564092049.557 [CBIT](CRITICAL): Environmental Failure. Press:14.766173 PSI. Humidity:36%. Temp:26 C. ABORTING MISSION
2019-07-25T22:00:49.558Z,1564092049.558 [Supervisor](INFO): Stop Mission called by CBIT::monitorEnvironmentals
2019-07-25T22:00:49.979Z,1564092049.979 [CommandLine](FAULT): Scheduling is paused
2019-07-25T22:00:49.979Z,1564092049.979 [CBIT](INFO): Critical error at 20190725T220049
2019-07-25T22:01:06.375Z,1564092066.375 [NAL9602](INFO): Powering up NAL9602
2019-07-25T22:01:08.862Z,1564092068.862 [SBIT](IMPORTANT): Beginning Startup BIT
2019-07-25T22:01:08.866Z,1564092068.866 [CBIT](IMPORTANT): Beginning ground fault scan
2019-07-25T22:01:17.378Z,1564092077.378 [NAL9602](INFO): NAL9602 initialized
2019-07-25T22:01:18.197Z,1564092078.197 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:01:19.874Z,1564092079.874 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.010652
CHAN A1 (24V): 4.592929
CHAN A2 (12V): -0.002086
CHAN A3 (5V): 4.753929
CHAN B0 (3.3V): 0.001770
CHAN B1 (3.15aV): -0.000643
CHAN B2 (3.15bV): -0.000008
CHAN B3 (GND): 0.000638
OPEN: -0.000417
Full Scale Calc: 4.765 mA, -1.589 mA
2019-07-25T22:02:02.091Z,1564092122.091 [SBIT](IMPORTANT): SBIT PASSED
2019-07-25T22:02:02.137Z,1564092122.137 [CommandLine](IMPORTANT): got command configSet list
2019-07-25T22:02:02.138Z,1564092122.138 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-07-25T22:02:02.141Z,1564092122.141 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=0 count;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=6 hour;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): CBIT.abortDepth=296 meter;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): CBIT.stopDepth=288 meter;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-07-25T22:02:02.142Z,1564092122.142 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 5.000000 meter;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 10.000000 meter;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): Express linearApproximation depth 5.000000 meter;

2019-07-25T22:02:02.143Z,1564092122.143 [CommandLine](IMPORTANT): Express linearApproximation latitude 0.005000 degree;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): Express linearApproximation longitude 0.005000 degree;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=274 cubic_centimeter;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): VerticalControl.massDefault=-2.3 millimeter;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-31 millimeter;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=30 millimeter;

2019-07-25T22:02:02.144Z,1564092122.144 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool;

2019-07-25T22:02:02.495Z,1564092122.495 [MissionManager](IMPORTANT): Started mission Startup
2019-07-25T22:02:02.495Z,1564092122.495 [Startup] Running Loop=1
2019-07-25T22:02:02.496Z,1564092122.496 [Startup](DEBUG): Aggregate::initialize Startup
2019-07-25T22:02:02.496Z,1564092122.496 [Startup:A.GoToSurface] Running Loop=1
2019-07-25T22:02:02.496Z,1564092122.496 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T22:02:02.496Z,1564092122.496 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T22:02:02.497Z,1564092122.497 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T22:02:02.497Z,1564092122.497 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T22:02:02.498Z,1564092122.498 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T22:02:02.498Z,1564092122.498 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T22:02:02.499Z,1564092122.499 [Startup:StartupSatComms] Running Loop=1
2019-07-25T22:02:02.499Z,1564092122.499 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-07-25T22:02:02.499Z,1564092122.499 [Startup:StartupSatComms:A] Running Loop=1
2019-07-25T22:02:02.895Z,1564092122.895 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-07-25T22:02:39.658Z,1564092159.658 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T22:02:39.658Z,1564092159.658 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-07-25T22:02:39.658Z,1564092159.658 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T22:02:39.668Z,1564092159.668 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T22:02:40.058Z,1564092160.058 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T22:02:40.058Z,1564092160.058 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-07-25T22:03:02.673Z,1564092182.673 [Startup:StartupSatComms:A](INFO): Timed out from 2019-07-25T22:02:02.5Z
2019-07-25T22:03:02.673Z,1564092182.673 [Startup:StartupSatComms:A] Stopped
2019-07-25T22:03:02.673Z,1564092182.673 [Startup:StartupSatComms:B] Running Loop=1
2019-07-25T22:03:03.079Z,1564092183.079 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-07-25T22:03:18.067Z,1564092198.067 [DataOverHttps](IMPORTANT): SBD MTMSN=20190725T220306
2019-07-25T22:03:18.072Z,1564092198.072 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005342
2019-07-25T22:03:23.469Z,1564092203.469 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20190725T214501/Courier0004.lzma
2019-07-25T22:03:23.472Z,1564092203.472 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.CartridgeType -4 count;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 0.1 minute;run 
2019-07-25T22:03:23.485Z,1564092203.485 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-07-25T22:03:23.485Z,1564092203.485 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-07-25T22:03:23.508Z,1564092203.508 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-07-25T22:03:23.511Z,1564092203.511 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-07-25T22:03:23.514Z,1564092203.514 [MissionManager](INFO): DefineArg sample.CartridgeType = -1.000000 count
2019-07-25T22:03:23.517Z,1564092203.517 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-07-25T22:03:23.519Z,1564092203.519 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-07-25T22:03:23.521Z,1564092203.521 [sample:A.AbortSample](DEBUG): Construct.
2019-07-25T22:03:23.523Z,1564092203.523 [sample:B.Pitch](DEBUG): Construct.
2019-07-25T22:03:23.529Z,1564092203.529 [sample:C.SetSpeed](DEBUG): Construct.
2019-07-25T22:03:23.531Z,1564092203.531 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-07-25T22:03:23.724Z,1564092203.724 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-07-25T22:03:23.727Z,1564092203.727 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-07-25T22:03:23.731Z,1564092203.731 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-07-25T22:03:23.733Z,1564092203.733 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-07-25T22:03:23.737Z,1564092203.737 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-07-25T22:03:23.749Z,1564092203.749 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-07-25T22:03:23.757Z,1564092203.757 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPCartridgeType = nan count
2019-07-25T22:03:23.777Z,1564092203.777 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-07-25T22:03:23.781Z,1564092203.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-07-25T22:03:23.784Z,1564092203.784 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 273.999991 cc
2019-07-25T22:03:23.787Z,1564092203.787 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-07-25T22:03:23.794Z,1564092203.794 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:03:23.796Z,1564092203.796 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-07-25T22:03:23.820Z,1564092203.820 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-07-25T22:03:23.848Z,1564092203.848 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:03:23.851Z,1564092203.851 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T22:03:23.851Z,1564092203.851 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T22:03:23.851Z,1564092203.851 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T22:03:23.852Z,1564092203.852 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T22:03:23.855Z,1564092203.855 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:03:23.879Z,1564092203.879 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T22:03:23.879Z,1564092203.879 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T22:03:23.879Z,1564092203.879 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T22:03:23.880Z,1564092203.880 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T22:03:23.923Z,1564092203.923 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

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

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code.
    </Description><Units:count/><Value>-1</Value></DefineArg>
    
    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

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

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

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:ESPCartridgeType"/><Arg Name="CartridgeType"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-07-25T22:03:23.923Z,1564092203.923 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-07-25T22:03:28.704Z,1564092208.704 [CommandLine](IMPORTANT): got command set sample.CartridgeType -4.000000 count
2019-07-25T22:03:28.705Z,1564092208.705 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 2.000000 count
2019-07-25T22:03:28.706Z,1564092208.706 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 0.100000 minute
2019-07-25T22:03:28.707Z,1564092208.707 [CommandLine](IMPORTANT): got command run 
2019-07-25T22:03:28.709Z,1564092208.709 [CommandLine](IMPORTANT): Running 
2019-07-25T22:03:29.115Z,1564092209.115 [DataOverHttps](INFO): Moved sent file to Logs/20190725T214501/Courier0004.lzma.bak
2019-07-25T22:03:29.115Z,1564092209.115 [DataOverHttps](INFO): SBD MOMSN=11476087
2019-07-25T22:03:39.853Z,1564092219.853 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20190725T220029/Courier0000.lzma
2019-07-25T22:03:40.659Z,1564092220.659 [DataOverHttps](INFO): Moved sent file to Logs/20190725T220029/Courier0000.lzma.bak
2019-07-25T22:03:40.659Z,1564092220.659 [DataOverHttps](INFO): SBD MOMSN=11476090
2019-07-25T22:03:51.684Z,1564092231.684 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190725T220029/Courier0004.lzma
2019-07-25T22:03:52.491Z,1564092232.491 [DataOverHttps](INFO): Moved sent file to Logs/20190725T220029/Courier0004.lzma.bak
2019-07-25T22:03:52.491Z,1564092232.491 [DataOverHttps](INFO): SBD MOMSN=11476094
2019-07-25T22:03:59.575Z,1564092239.575 [CommandLine](IMPORTANT): got command show stack
2019-07-25T22:03:59.575Z,1564092239.575 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-25T22:03:59.576Z,1564092239.576 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-07-25T22:03:59.576Z,1564092239.576 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2019-07-25T22:04:02.891Z,1564092242.891 [Startup:StartupSatComms:B](INFO): Timed out from 2019-07-25T22:03:02.7Z
2019-07-25T22:04:02.891Z,1564092242.891 [Startup:StartupSatComms:B] Stopped
2019-07-25T22:04:02.891Z,1564092242.891 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-07-25T22:04:02.892Z,1564092242.892 [Startup:StartupSatComms] Stopped
2019-07-25T22:04:02.892Z,1564092242.892 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-07-25T22:04:02.892Z,1564092242.892 [Startup](INFO): Completed Startup
2019-07-25T22:04:02.893Z,1564092242.893 [MissionManager](INFO): Startup is completed.
2019-07-25T22:04:02.893Z,1564092242.893 [MissionManager](INFO): Uninitializing Mission Startup
2019-07-25T22:04:02.893Z,1564092242.893 [Startup] Stopped
2019-07-25T22:04:02.893Z,1564092242.893 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-07-25T22:04:02.893Z,1564092242.893 [Startup:A.GoToSurface] Stopped
2019-07-25T22:04:02.893Z,1564092242.893 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T22:04:03.326Z,1564092243.326 [MissionManager](IMPORTANT): Started mission sample
2019-07-25T22:04:03.326Z,1564092243.326 [sample] Running Loop=1
2019-07-25T22:04:03.326Z,1564092243.326 [sample](DEBUG): Aggregate::initialize sample
2019-07-25T22:04:03.326Z,1564092243.326 [sample:A.AbortSample] Running Loop=1
2019-07-25T22:04:03.326Z,1564092243.326 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-07-25T22:04:03.327Z,1564092243.327 [sample:B.Pitch] Running Loop=1
2019-07-25T22:04:03.327Z,1564092243.327 [sample:B.Pitch](DEBUG): Initialize.
2019-07-25T22:04:03.327Z,1564092243.327 [sample:C.SetSpeed] Running Loop=1
2019-07-25T22:04:03.327Z,1564092243.327 [sample:C.SetSpeed](DEBUG): Initialize.
2019-07-25T22:04:03.327Z,1564092243.327 [sample:E] Running Loop=1
2019-07-25T22:04:03.328Z,1564092243.328 [sample:E] Stopped
2019-07-25T22:04:03.328Z,1564092243.328 [sample:F] Running Loop=1
2019-07-25T22:04:03.328Z,1564092243.328 [sample:C.SetSpeed] Running Loop=1
2019-07-25T22:04:03.328Z,1564092243.328 [sample:B.Pitch] Running Loop=1
2019-07-25T22:04:03.328Z,1564092243.328 [sample:A.AbortSample] Running Loop=1
2019-07-25T22:04:03.696Z,1564092243.696 [sample:F] Stopped
2019-07-25T22:04:03.696Z,1564092243.696 [sample:G] Running Loop=1
2019-07-25T22:04:03.987Z,1564092243.987 [DataOverHttps](INFO): Sending 1708 bytes from file Logs/20190725T214501/Express0005.lzma
2019-07-25T22:04:04.083Z,1564092244.083 [sample:G] Stopped
2019-07-25T22:04:04.083Z,1564092244.083 [sample:SampleRepeater] Running Loop=1
2019-07-25T22:04:04.083Z,1564092244.083 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-07-25T22:04:04.083Z,1564092244.083 [sample:SampleRepeater:Sample] Running Loop=1
2019-07-25T22:04:04.083Z,1564092244.083 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-07-25T22:04:04.480Z,1564092244.480 [sample:SampleAtDepth] Running Loop=1
2019-07-25T22:04:04.480Z,1564092244.480 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-07-25T22:04:04.480Z,1564092244.480 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-07-25T22:04:04.480Z,1564092244.480 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-07-25T22:04:04.480Z,1564092244.480 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-07-25T22:04:04.481Z,1564092244.481 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2019-07-25T22:04:04.481Z,1564092244.481 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-07-25T22:04:04.481Z,1564092244.481 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-07-25T22:04:04.482Z,1564092244.482 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-07-25T22:04:04.791Z,1564092244.791 [DataOverHttps](INFO): Moved sent file to Logs/20190725T214501/Express0005.lzma.bak
2019-07-25T22:04:04.791Z,1564092244.791 [DataOverHttps](INFO): SBD MOMSN=11476096
2019-07-25T22:04:20.067Z,1564092260.067 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 7.000000 meter
2019-07-25T22:04:20.069Z,1564092260.069 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-07-25T22:04:20.331Z,1564092260.331 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-25T22:04:20.650Z,1564092260.650 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-07-25T22:04:20.650Z,1564092260.650 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-07-25T22:04:20.651Z,1564092260.651 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-07-25T22:04:21.049Z,1564092261.049 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 7.000000 m , settling for 0.100000 min 
2019-07-25T22:04:21.049Z,1564092261.049 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-07-25T22:04:21.049Z,1564092261.049 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-07-25T22:04:21.049Z,1564092261.049 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-07-25T22:04:21.049Z,1564092261.049 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T22:04:27.529Z,1564092267.529 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-07-25T22:04:27.529Z,1564092267.529 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-07-25T22:04:27.529Z,1564092267.529 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T22:04:27.529Z,1564092267.529 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-07-25T22:04:27.529Z,1564092267.529 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T22:04:27.530Z,1564092267.530 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-07-25T22:04:27.530Z,1564092267.530 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-07-25T22:04:27.530Z,1564092267.530 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T22:04:27.923Z,1564092267.923 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Running Loop=1
2019-07-25T22:04:27.924Z,1564092267.924 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:04:27.924Z,1564092267.924 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Running Loop=1
2019-07-25T22:04:28.319Z,1564092268.319 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Stopped
2019-07-25T22:04:28.319Z,1564092268.319 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:04:28.320Z,1564092268.320 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Stopped
2019-07-25T22:04:28.320Z,1564092268.320 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:04:28.320Z,1564092268.320 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-07-25T22:04:28.743Z,1564092268.743 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-07-25T22:04:29.543Z,1564092269.543 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2019-07-25T22:04:29.546Z,1564092269.546 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2019-07-25T22:04:30.017Z,1564092270.017 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:30.753Z,1564092270.753 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:31.547Z,1564092271.547 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:32.351Z,1564092272.351 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:33.163Z,1564092273.163 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:33.983Z,1564092273.983 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:34.786Z,1564092274.786 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:35.582Z,1564092275.582 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:36.391Z,1564092276.391 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:37.205Z,1564092277.205 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:38.007Z,1564092278.007 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:38.814Z,1564092278.814 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:39.634Z,1564092279.634 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:40.445Z,1564092280.445 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:40.850Z,1564092280.850 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T22:04:40.850Z,1564092280.850 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-07-25T22:04:40.850Z,1564092280.850 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T22:04:40.890Z,1564092280.890 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T22:04:41.239Z,1564092281.239 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:41.282Z,1564092281.282 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T22:04:41.282Z,1564092281.282 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-07-25T22:04:42.047Z,1564092282.047 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:42.912Z,1564092282.912 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:43.738Z,1564092283.738 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:44.495Z,1564092284.495 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:45.293Z,1564092285.293 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:46.086Z,1564092286.086 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:46.899Z,1564092286.899 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:47.713Z,1564092287.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:48.515Z,1564092288.515 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:49.315Z,1564092289.315 [CommandLine](IMPORTANT): got command stop
2019-07-25T22:04:49.315Z,1564092289.315 [CommandLine](IMPORTANT): Scheduling is paused
2019-07-25T22:04:49.315Z,1564092289.315 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-07-25T22:04:49.325Z,1564092289.325 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:04:49.332Z,1564092289.332 [MissionManager](INFO): MissionManager is completed.
2019-07-25T22:04:49.332Z,1564092289.332 [MissionManager](INFO): Uninitializing Mission sample
2019-07-25T22:04:49.332Z,1564092289.332 [sample] Stopped
2019-07-25T22:04:49.333Z,1564092289.333 [sample](DEBUG): Aggregate::uninitialize sample
2019-07-25T22:04:49.333Z,1564092289.333 [sample:A.AbortSample] Stopped
2019-07-25T22:04:49.333Z,1564092289.333 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-07-25T22:04:49.333Z,1564092289.333 [sample:B.Pitch] Stopped
2019-07-25T22:04:49.333Z,1564092289.333 [sample:C.SetSpeed] Stopped
2019-07-25T22:04:49.333Z,1564092289.333 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-07-25T22:04:49.333Z,1564092289.333 [sample:SampleAtDepth] Stopped
2019-07-25T22:04:49.333Z,1564092289.333 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleRepeater] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleRepeater:Sample] Stopped
2019-07-25T22:04:49.334Z,1564092289.334 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-07-25T22:04:49.743Z,1564092289.743 [MissionManager](IMPORTANT): Started mission Default
2019-07-25T22:04:49.743Z,1564092289.743 [Default] Running Loop=1
2019-07-25T22:04:49.743Z,1564092289.743 [Default](DEBUG): Aggregate::initialize Default
2019-07-25T22:04:49.743Z,1564092289.743 [Default:B.GoToSurface] Running Loop=1
2019-07-25T22:04:49.743Z,1564092289.743 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T22:04:49.743Z,1564092289.743 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T22:04:49.744Z,1564092289.744 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T22:04:49.744Z,1564092289.744 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T22:04:49.744Z,1564092289.744 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T22:04:49.745Z,1564092289.745 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T22:04:49.745Z,1564092289.745 [Default:A.Wait] Running Loop=1
2019-07-25T22:04:49.745Z,1564092289.745 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-25T22:04:50.137Z,1564092290.137 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-07-25T22:04:50.137Z,1564092290.137 [ESPComponent](IMPORTANT): [sample #0] No ESP summary messages.
2019-07-25T22:04:50.138Z,1564092290.138 [ESPComponent](INFO): powering down ESP
2019-07-25T22:04:50.156Z,1564092290.156 [ESPComponent](INFO): powering down ESP secondary power supply
2019-07-25T22:04:56.075Z,1564092296.075 [CommandLine](IMPORTANT): got command maintain clear
2019-07-25T22:04:56.502Z,1564092296.502 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-25T22:05:03.143Z,1564092303.143 [Default:A.Wait](INFO): Done Waiting.
2019-07-25T22:05:03.143Z,1564092303.143 [Default:A.Wait] Stopped
2019-07-25T22:05:03.143Z,1564092303.143 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T22:05:03.544Z,1564092303.544 [Default:CheckIn] Running Loop=1
2019-07-25T22:05:03.545Z,1564092303.545 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-07-25T22:05:03.545Z,1564092303.545 [Default:CheckIn:Read_GPS] Running Loop=1
2019-07-25T22:05:03.956Z,1564092303.956 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-07-25T22:06:20.686Z,1564092380.686 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-07-25T22:06:21.505Z,1564092381.505 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:26.361Z,1564092386.361 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:29.177Z,1564092389.177 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:31.201Z,1564092391.201 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:33.221Z,1564092393.221 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:35.241Z,1564092395.241 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:38.469Z,1564092398.469 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:41.297Z,1564092401.297 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:41.736Z,1564092401.736 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-07-25T22:06:41.736Z,1564092401.736 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-07-25T22:06:41.736Z,1564092401.736 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-07-25T22:06:41.746Z,1564092401.746 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-07-25T22:06:41.847Z,1564092401.847 [DataOverHttps](IMPORTANT): SBD MTMSN=20190725T220630
2019-07-25T22:06:42.139Z,1564092402.139 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-07-25T22:06:42.139Z,1564092402.139 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-07-25T22:06:44.529Z,1564092404.529 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:46.805Z,1564092406.805 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.CartridgeType -4 count;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 0.1 minute;run 
2019-07-25T22:06:46.818Z,1564092406.818 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-07-25T22:06:46.819Z,1564092406.819 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-07-25T22:06:46.861Z,1564092406.861 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-07-25T22:06:46.863Z,1564092406.863 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-07-25T22:06:46.865Z,1564092406.865 [MissionManager](INFO): DefineArg sample.CartridgeType = -1.000000 count
2019-07-25T22:06:46.867Z,1564092406.867 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-07-25T22:06:46.869Z,1564092406.869 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-07-25T22:06:46.870Z,1564092406.870 [sample:A.AbortSample](DEBUG): Construct.
2019-07-25T22:06:46.871Z,1564092406.871 [sample:B.Pitch](DEBUG): Construct.
2019-07-25T22:06:46.876Z,1564092406.876 [sample:C.SetSpeed](DEBUG): Construct.
2019-07-25T22:06:46.878Z,1564092406.878 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-07-25T22:06:46.978Z,1564092406.978 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-07-25T22:06:46.980Z,1564092406.980 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-07-25T22:06:46.987Z,1564092406.987 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-07-25T22:06:46.989Z,1564092406.989 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-07-25T22:06:46.995Z,1564092406.995 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-07-25T22:06:47.002Z,1564092407.002 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-07-25T22:06:47.004Z,1564092407.004 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPCartridgeType = nan count
2019-07-25T22:06:47.022Z,1564092407.022 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-07-25T22:06:47.025Z,1564092407.025 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-07-25T22:06:47.032Z,1564092407.032 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 273.999991 cc
2019-07-25T22:06:47.038Z,1564092407.038 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-07-25T22:06:47.047Z,1564092407.047 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:06:47.054Z,1564092407.054 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-07-25T22:06:47.063Z,1564092407.063 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-07-25T22:06:47.090Z,1564092407.090 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:06:47.092Z,1564092407.092 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T22:06:47.092Z,1564092407.092 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T22:06:47.093Z,1564092407.093 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T22:06:47.093Z,1564092407.093 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T22:06:47.105Z,1564092407.105 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-07-25T22:06:47.128Z,1564092407.128 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-07-25T22:06:47.128Z,1564092407.128 [MissionManager](ERROR): Slate does not contain celsius
2019-07-25T22:06:47.128Z,1564092407.128 [MissionManager](ERROR): Slate does not contain WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-07-25T22:06:47.129Z,1564092407.129 [MissionManager](ERROR): Slate does not contain microgram_per_liter
2019-07-25T22:06:47.183Z,1564092407.183 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

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

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code.
    </Description><Units:count/><Value>-1</Value></DefineArg>
    
    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

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

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

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:ESPCartridgeType"/><Arg Name="CartridgeType"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-07-25T22:06:47.184Z,1564092407.184 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-07-25T22:06:47.357Z,1564092407.357 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:50.589Z,1564092410.589 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:51.714Z,1564092411.714 [CommandLine](IMPORTANT): got command set sample.CartridgeType -4.000000 count
2019-07-25T22:06:51.715Z,1564092411.715 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 2.000000 count
2019-07-25T22:06:51.716Z,1564092411.716 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 0.100000 minute
2019-07-25T22:06:51.716Z,1564092411.716 [CommandLine](IMPORTANT): got command run 
2019-07-25T22:06:51.718Z,1564092411.718 [CommandLine](IMPORTANT): Running 
2019-07-25T22:06:51.847Z,1564092411.847 [Default] Stopped
2019-07-25T22:06:51.847Z,1564092411.847 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-25T22:06:51.847Z,1564092411.847 [Default:B.GoToSurface] Stopped
2019-07-25T22:06:51.847Z,1564092411.847 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T22:06:51.847Z,1564092411.847 [Default:CheckIn] Stopped
2019-07-25T22:06:51.847Z,1564092411.847 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-07-25T22:06:51.847Z,1564092411.847 [Default:CheckIn:Read_GPS] Stopped
2019-07-25T22:06:51.847Z,1564092411.847 [MissionManager](IMPORTANT): Started mission sample
2019-07-25T22:06:51.848Z,1564092411.848 [sample] Running Loop=1
2019-07-25T22:06:51.848Z,1564092411.848 [sample](DEBUG): Aggregate::initialize sample
2019-07-25T22:06:51.848Z,1564092411.848 [sample:A.AbortSample] Running Loop=1
2019-07-25T22:06:51.848Z,1564092411.848 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-07-25T22:06:51.848Z,1564092411.848 [sample:B.Pitch] Running Loop=1
2019-07-25T22:06:51.848Z,1564092411.848 [sample:B.Pitch](DEBUG): Initialize.
2019-07-25T22:06:51.848Z,1564092411.848 [sample:C.SetSpeed] Running Loop=1
2019-07-25T22:06:51.848Z,1564092411.848 [sample:C.SetSpeed](DEBUG): Initialize.
2019-07-25T22:06:51.848Z,1564092411.848 [sample:E] Running Loop=1
2019-07-25T22:06:51.849Z,1564092411.849 [sample:E] Stopped
2019-07-25T22:06:51.853Z,1564092411.853 [sample:F] Running Loop=1
2019-07-25T22:06:51.853Z,1564092411.853 [sample:C.SetSpeed] Running Loop=1
2019-07-25T22:06:51.854Z,1564092411.854 [sample:B.Pitch] Running Loop=1
2019-07-25T22:06:51.854Z,1564092411.854 [sample:A.AbortSample] Running Loop=1
2019-07-25T22:06:52.223Z,1564092412.223 [sample:F] Stopped
2019-07-25T22:06:52.223Z,1564092412.223 [sample:G] Running Loop=1
2019-07-25T22:06:52.626Z,1564092412.626 [sample:G] Stopped
2019-07-25T22:06:52.626Z,1564092412.626 [sample:SampleRepeater] Running Loop=1
2019-07-25T22:06:52.626Z,1564092412.626 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-07-25T22:06:52.626Z,1564092412.626 [sample:SampleRepeater:Sample] Running Loop=1
2019-07-25T22:06:52.626Z,1564092412.626 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-07-25T22:06:53.027Z,1564092413.027 [sample:SampleAtDepth] Running Loop=1
2019-07-25T22:06:53.027Z,1564092413.027 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-07-25T22:06:53.027Z,1564092413.027 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-07-25T22:06:53.027Z,1564092413.027 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-07-25T22:06:53.027Z,1564092413.027 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-07-25T22:06:53.028Z,1564092413.028 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2019-07-25T22:06:53.028Z,1564092413.028 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-07-25T22:06:53.028Z,1564092413.028 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-07-25T22:06:53.028Z,1564092413.028 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-07-25T22:06:53.417Z,1564092413.417 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:56.249Z,1564092416.249 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:06:58.265Z,1564092418.265 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:01.501Z,1564092421.501 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:04.329Z,1564092424.329 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:07.561Z,1564092427.561 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:10.385Z,1564092430.385 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:13.617Z,1564092433.617 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:16.445Z,1564092436.445 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:18.632Z,1564092438.632 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 7.000000 meter
2019-07-25T22:07:18.633Z,1564092438.633 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-07-25T22:07:18.938Z,1564092438.938 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-07-25T22:07:19.277Z,1564092439.277 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T22:07:19.299Z,1564092439.299 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-07-25T22:07:19.300Z,1564092439.300 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-07-25T22:07:19.711Z,1564092439.711 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 7.000000 m , settling for 0.100000 min 
2019-07-25T22:07:19.712Z,1564092439.712 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-07-25T22:07:19.712Z,1564092439.712 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-07-25T22:07:19.712Z,1564092439.712 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-07-25T22:07:19.712Z,1564092439.712 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-07-25T22:07:21.297Z,1564092441.297 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:23.317Z,1564092443.317 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-07-25T22:07:26.159Z,1564092446.159 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-07-25T22:07:26.160Z,1564092446.160 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-07-25T22:07:26.545Z,1564092446.545 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T22:07:26.571Z,1564092446.571 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Running Loop=1
2019-07-25T22:07:26.572Z,1564092446.572 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:07:26.572Z,1564092446.572 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Running Loop=1
2019-07-25T22:07:26.979Z,1564092446.979 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A] Stopped
2019-07-25T22:07:26.979Z,1564092446.979 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:07:26.979Z,1564092446.979 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge] Stopped
2019-07-25T22:07:26.979Z,1564092446.979 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2019-07-25T22:07:26.980Z,1564092446.980 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-07-25T22:07:27.383Z,1564092447.383 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-07-25T22:07:28.575Z,1564092448.575 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:29.377Z,1564092449.377 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:29.392Z,1564092449.392 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:30.201Z,1564092450.201 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:30.994Z,1564092450.994 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:31.809Z,1564092451.809 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:32.605Z,1564092452.605 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:32.629Z,1564092452.629 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:33.429Z,1564092453.429 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:34.231Z,1564092454.231 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:35.036Z,1564092455.036 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:35.436Z,1564092455.436 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:35.859Z,1564092455.859 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:36.651Z,1564092456.651 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:37.470Z,1564092457.470 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:38.286Z,1564092458.286 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:38.670Z,1564092458.670 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:39.111Z,1564092459.111 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:39.886Z,1564092459.886 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:40.691Z,1564092460.691 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:41.497Z,1564092461.497 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:41.513Z,1564092461.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:42.323Z,1564092462.323 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:43.118Z,1564092463.118 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:43.923Z,1564092463.923 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:44.321Z,1564092464.321 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:44.745Z,1564092464.745 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:45.539Z,1564092465.539 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:46.341Z,1564092466.341 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:46.358Z,1564092466.358 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:47.165Z,1564092467.165 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:47.964Z,1564092467.964 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:48.771Z,1564092468.771 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:49.577Z,1564092469.577 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:49.593Z,1564092469.593 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:50.401Z,1564092470.401 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:51.259Z,1564092471.259 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:52.026Z,1564092472.026 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:52.401Z,1564092472.401 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:52.840Z,1564092472.840 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:53.623Z,1564092473.623 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:54.426Z,1564092474.426 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:55.239Z,1564092475.239 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:55.633Z,1564092475.633 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:56.065Z,1564092476.065 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:56.854Z,1564092476.854 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:57.659Z,1564092477.659 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:58.469Z,1564092478.469 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:07:58.485Z,1564092478.485 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:07:59.292Z,1564092479.292 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:00.082Z,1564092480.082 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:00.891Z,1564092480.891 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:01.697Z,1564092481.697 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:01.713Z,1564092481.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:02.519Z,1564092482.519 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:03.319Z,1564092483.319 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:04.138Z,1564092484.138 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:04.525Z,1564092484.525 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:04.970Z,1564092484.970 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:05.742Z,1564092485.742 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:06.551Z,1564092486.551 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:07.349Z,1564092487.349 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:07.365Z,1564092487.365 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:08.177Z,1564092488.177 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:08.980Z,1564092488.980 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:09.373Z,1564092489.373 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:09.793Z,1564092489.793 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:10.596Z,1564092490.596 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-07-25T22:08:10.600Z,1564092490.600 [BPC1](INFO): Received data from all battery sticks.
2019-07-25T22:08:10.601Z,1564092490.601 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:11.394Z,1564092491.394 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:12.206Z,1564092492.206 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:12.601Z,1564092492.601 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:13.029Z,1564092493.029 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:13.837Z,1564092493.837 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:14.022Z,1564092494.022 [CommandLine](IMPORTANT): got command show stack
2019-07-25T22:08:14.022Z,1564092494.022 [CommandLine](IMPORTANT): Behavior Stack:

2019-07-25T22:08:14.023Z,1564092494.023 [sample](IMPORTANT): Priority 0: sample:A.AbortSample
2019-07-25T22:08:14.023Z,1564092494.023 [sample](IMPORTANT): Priority 1: sample:B.Pitch
2019-07-25T22:08:14.023Z,1564092494.023 [sample](IMPORTANT): Priority 2: sample:C.SetSpeed
2019-07-25T22:08:14.024Z,1564092494.024 [sample:SampleAtDepth:SampleWrapper](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:A.Pitch
2019-07-25T22:08:14.024Z,1564092494.024 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 4: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP
2019-07-25T22:08:14.627Z,1564092494.627 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:15.429Z,1564092495.429 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:15.445Z,1564092495.445 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:16.253Z,1564092496.253 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:17.050Z,1564092497.050 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:17.863Z,1564092497.863 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:18.665Z,1564092498.665 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:18.680Z,1564092498.680 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:19.489Z,1564092499.489 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:20.286Z,1564092500.286 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:21.094Z,1564092501.094 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:21.489Z,1564092501.489 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:21.912Z,1564092501.912 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:22.715Z,1564092502.715 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:23.518Z,1564092503.518 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:24.322Z,1564092504.322 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:24.721Z,1564092504.721 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:25.145Z,1564092505.145 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:25.254Z,1564092505.254 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-07-25T22:08:25.289Z,1564092505.289 [Radio_Surface](INFO): Powering down
2019-07-25T22:08:25.948Z,1564092505.948 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:26.750Z,1564092506.750 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:27.553Z,1564092507.553 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:27.569Z,1564092507.569 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:28.376Z,1564092508.376 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:29.175Z,1564092509.175 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:29.975Z,1564092509.975 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:30.377Z,1564092510.377 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:30.563Z,1564092510.563 [CommandLine](IMPORTANT): got command restart application
2019-07-25T22:08:30.804Z,1564092510.804 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:31.569Z,1564092511.569 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-07-25T22:08:31.570Z,1564092511.570 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:31.570Z,1564092511.570 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:31.594Z,1564092511.594 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port
2019-07-25T22:08:31.607Z,1564092511.607 [MissionManager](INFO): MissionManager is completed.
2019-07-25T22:08:31.608Z,1564092511.608 [MissionManager](INFO): Uninitializing Mission sample
2019-07-25T22:08:31.608Z,1564092511.608 [sample] Stopped
2019-07-25T22:08:31.608Z,1564092511.608 [sample](DEBUG): Aggregate::uninitialize sample
2019-07-25T22:08:31.608Z,1564092511.608 [sample:A.AbortSample] Stopped
2019-07-25T22:08:31.608Z,1564092511.608 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-07-25T22:08:31.608Z,1564092511.608 [sample:B.Pitch] Stopped
2019-07-25T22:08:31.608Z,1564092511.608 [sample:C.SetSpeed] Stopped
2019-07-25T22:08:31.608Z,1564092511.608 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-07-25T22:08:31.608Z,1564092511.608 [sample:SampleAtDepth] Stopped
2019-07-25T22:08:31.608Z,1564092511.608 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-07-25T22:08:31.608Z,1564092511.608 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleRepeater] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleRepeater:Sample] Stopped
2019-07-25T22:08:31.609Z,1564092511.609 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-07-25T22:08:31.721Z,1564092511.721 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-07-25T22:08:31.721Z,1564092511.721 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:31.722Z,1564092511.722 [CommandLine](INFO): Join timeout helper Thread ID is 4282
2019-07-25T22:08:31.733Z,1564092511.733 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-07-25T22:08:31.733Z,1564092511.733 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:31.734Z,1564092511.734 [NavChartDb](INFO): Join timeout helper Thread ID is 4283
2019-07-25T22:08:31.929Z,1564092511.929 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:31.930Z,1564092511.930 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:31.937Z,1564092511.937 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-07-25T22:08:31.937Z,1564092511.937 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:31.938Z,1564092511.938 [Radio_Surface](INFO): Join timeout helper Thread ID is 4284
2019-07-25T22:08:32.018Z,1564092512.018 [MissionManager](IMPORTANT): Started mission Default
2019-07-25T22:08:32.018Z,1564092512.018 [Default] Running Loop=1
2019-07-25T22:08:32.019Z,1564092512.019 [Default](DEBUG): Aggregate::initialize Default
2019-07-25T22:08:32.019Z,1564092512.019 [Default:B.GoToSurface] Running Loop=1
2019-07-25T22:08:32.019Z,1564092512.019 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-07-25T22:08:32.019Z,1564092512.019 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-07-25T22:08:32.019Z,1564092512.019 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-07-25T22:08:32.020Z,1564092512.020 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-07-25T22:08:32.020Z,1564092512.020 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-07-25T22:08:32.020Z,1564092512.020 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-07-25T22:08:32.021Z,1564092512.021 [Default:A.Wait] Running Loop=1
2019-07-25T22:08:32.021Z,1564092512.021 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-07-25T22:08:32.157Z,1564092512.157 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:32.158Z,1564092512.158 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.181Z,1564092512.181 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-07-25T22:08:32.181Z,1564092512.181 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.181Z,1564092512.181 [DataOverHttps](INFO): Join timeout helper Thread ID is 4286
2019-07-25T22:08:32.401Z,1564092512.401 [NAL9602](DEBUG): Fix Requested
2019-07-25T22:08:32.416Z,1564092512.416 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-07-25T22:08:32.416Z,1564092512.416 [ESPComponent](IMPORTANT): [sample #0] No ESP summary messages.
2019-07-25T22:08:32.417Z,1564092512.417 [ESPComponent](INFO): powering down ESP
2019-07-25T22:08:32.417Z,1564092512.417 [ESPComponent](INFO): powering down ESP secondary power supply
2019-07-25T22:08:32.526Z,1564092512.526 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:32.526Z,1564092512.526 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.527Z,1564092512.527 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-07-25T22:08:32.527Z,1564092512.527 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.527Z,1564092512.527 [logger](INFO): Join timeout helper Thread ID is 4288
2019-07-25T22:08:32.594Z,1564092512.594 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:32.595Z,1564092512.595 [logger ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.607Z,1564092512.607 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-07-25T22:08:32.607Z,1564092512.607 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.607Z,1564092512.607 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-07-25T22:08:32.607Z,1564092512.607 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.607Z,1564092512.607 [controlThread](INFO): Join timeout helper Thread ID is 4289
2019-07-25T22:08:32.617Z,1564092512.617 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-07-25T22:08:32.617Z,1564092512.617 [controlThread](DEBUG): Uninitializing ControlThread
2019-07-25T22:08:32.618Z,1564092512.618 [NAL9602](INFO): Powering down
2019-07-25T22:08:32.622Z,1564092512.622 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-07-25T22:08:32.623Z,1564092512.623 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-07-25T22:08:32.623Z,1564092512.623 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-07-25T22:08:32.624Z,1564092512.624 [MissionManager](INFO): Uninitializing Mission Default
2019-07-25T22:08:32.624Z,1564092512.624 [Default] Stopped
2019-07-25T22:08:32.624Z,1564092512.624 [Default](DEBUG): Aggregate::uninitialize Default
2019-07-25T22:08:32.624Z,1564092512.624 [Default:A.Wait] Stopped
2019-07-25T22:08:32.624Z,1564092512.624 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-07-25T22:08:32.624Z,1564092512.624 [Default:B.GoToSurface] Stopped
2019-07-25T22:08:32.624Z,1564092512.624 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-07-25T22:08:32.627Z,1564092512.627 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-07-25T22:08:32.627Z,1564092512.627 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-07-25T22:08:32.628Z,1564092512.628 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-07-25T22:08:32.628Z,1564092512.628 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-07-25T22:08:32.628Z,1564092512.628 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-07-25T22:08:32.628Z,1564092512.628 [BuoyancyServo](INFO): Powering down
2019-07-25T22:08:32.757Z,1564092512.757 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-07-25T22:08:32.758Z,1564092512.758 [ElevatorServo](INFO): Powering down
2019-07-25T22:08:32.759Z,1564092512.759 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-07-25T22:08:32.759Z,1564092512.759 [MassServo](INFO): Powering down
2019-07-25T22:08:32.760Z,1564092512.760 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-07-25T22:08:32.760Z,1564092512.760 [RudderServo](INFO): Powering down
2019-07-25T22:08:32.761Z,1564092512.761 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-07-25T22:08:32.761Z,1564092512.761 [ThrusterServo](INFO): Powering down
2019-07-25T22:08:32.762Z,1564092512.762 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-07-25T22:08:32.762Z,1564092512.762 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-07-25T22:08:32.763Z,1564092512.763 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-07-25T22:08:32.763Z,1564092512.763 [CBIT](DEBUG): Powering off loads.
2019-07-25T22:08:32.773Z,1564092512.773 [CBIT](DEBUG): Disabling WDT.
2019-07-25T22:08:32.785Z,1564092512.785 [CBIT](DEBUG): Opening all GF detection circuits.
2019-07-25T22:08:32.786Z,1564092512.786 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:32.998Z,1564092512.998 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:33.004Z,1564092513.004 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:33.069Z,1564092513.069 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-07-25T22:08:33.128Z,1564092513.128 [logger ThreadHandler](INFO): Thread cancelled.