2019-08-15T18:14:19.298Z,1565892859.298 [Supervisor](DEBUG): Initializing supervisor.
2019-08-15T18:14:19.301Z,1565892859.301 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-15T18:14:19.302Z,1565892859.302 [SyncHandler](INFO): Protected caller Thread ID is 1044
2019-08-15T18:14:19.302Z,1565892859.302 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-15T18:14:19.303Z,1565892859.303 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-15T18:14:19.303Z,1565892859.303 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1045
2019-08-15T18:14:19.306Z,1565892859.306 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-15T18:14:19.318Z,1565892859.318 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-15T18:14:19.319Z,1565892859.319 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-15T18:14:19.319Z,1565892859.319 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1046
2019-08-15T18:14:19.320Z,1565892859.320 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-15T18:14:19.321Z,1565892859.321 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-15T18:14:19.321Z,1565892859.321 [logger ThreadHandler](INFO): Protected caller Thread ID is 1047
2019-08-15T18:14:19.323Z,1565892859.323 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-15T18:14:19.324Z,1565892859.324 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-15T18:14:19.325Z,1565892859.325 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-15T18:14:19.420Z,1565892859.420 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-15T18:14:19.420Z,1565892859.420 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-15T18:14:19.629Z,1565892859.629 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-15T18:14:19.630Z,1565892859.630 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-15T18:14:19.766Z,1565892859.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-15T18:14:19.767Z,1565892859.767 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-15T18:14:20.460Z,1565892860.460 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-15T18:14:20.460Z,1565892860.460 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-15T18:14:20.904Z,1565892860.904 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-15T18:14:20.905Z,1565892860.905 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-15T18:14:21.380Z,1565892861.380 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-15T18:14:21.380Z,1565892861.380 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-15T18:14:21.686Z,1565892861.686 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-15T18:14:21.686Z,1565892861.686 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-15T18:14:22.019Z,1565892862.019 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-15T18:14:22.020Z,1565892862.020 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-15T18:14:22.416Z,1565892862.416 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-15T18:14:22.416Z,1565892862.416 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-15T18:14:22.565Z,1565892862.565 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-15T18:14:22.565Z,1565892862.565 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-15T18:14:22.669Z,1565892862.669 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-15T18:14:22.670Z,1565892862.670 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-15T18:14:22.751Z,1565892862.751 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-15T18:14:22.852Z,1565892862.852 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-15T18:14:22.852Z,1565892862.852 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-15T18:14:23.048Z,1565892863.048 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-15T18:14:23.049Z,1565892863.049 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-15T18:14:23.255Z,1565892863.255 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-15T18:14:23.257Z,1565892863.257 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-08-15T18:14:23.258Z,1565892863.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-08-15T18:14:23.341Z,1565892863.341 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-08-15T18:14:23.570Z,1565892863.570 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-15T18:14:23.571Z,1565892863.571 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-08-15T18:14:23.667Z,1565892863.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-08-15T18:14:23.839Z,1565892863.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-08-15T18:14:24.052Z,1565892864.052 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-08-15T18:14:24.137Z,1565892864.137 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-08-15T18:14:24.239Z,1565892864.239 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-08-15T18:14:24.334Z,1565892864.334 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-08-15T18:14:24.492Z,1565892864.492 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-08-15T18:14:24.599Z,1565892864.599 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-08-15T18:14:24.698Z,1565892864.698 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-15T18:14:24.707Z,1565892864.707 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-15T18:14:24.804Z,1565892864.804 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-15T18:14:24.805Z,1565892864.805 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-15T18:14:24.935Z,1565892864.935 [BuoyancyServo] Loaded
2019-08-15T18:14:24.935Z,1565892864.935 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-15T18:14:24.950Z,1565892864.950 [ElevatorServo] Loaded
2019-08-15T18:14:24.950Z,1565892864.950 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-15T18:14:24.965Z,1565892864.965 [MassServo] Loaded
2019-08-15T18:14:24.965Z,1565892864.965 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-15T18:14:24.980Z,1565892864.980 [RudderServo] Loaded
2019-08-15T18:14:24.980Z,1565892864.980 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-15T18:14:24.995Z,1565892864.995 [ThrusterServo] Loaded
2019-08-15T18:14:24.995Z,1565892864.995 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-15T18:14:24.995Z,1565892864.995 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-15T18:14:24.996Z,1565892864.996 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-15T18:14:25.130Z,1565892865.130 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-15T18:14:25.160Z,1565892865.160 [SBIT] Loaded
2019-08-15T18:14:25.160Z,1565892865.160 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-15T18:14:25.160Z,1565892865.160 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-15T18:14:25.188Z,1565892865.188 [IBIT] Loaded
2019-08-15T18:14:25.188Z,1565892865.188 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-15T18:14:25.191Z,1565892865.191 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-15T18:14:25.606Z,1565892865.606 [CBIT] Loaded
2019-08-15T18:14:25.606Z,1565892865.606 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-15T18:14:25.606Z,1565892865.606 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-15T18:14:25.607Z,1565892865.607 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-15T18:14:26.085Z,1565892866.085 [Aanderaa_O2] Loaded
2019-08-15T18:14:26.085Z,1565892866.085 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-08-15T18:14:26.126Z,1565892866.126 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-08-15T18:14:26.147Z,1565892866.147 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-08-15T18:14:26.148Z,1565892866.148 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-08-15T18:14:26.153Z,1565892866.153 [CTD_Seabird](INFO): created writer for : depth
2019-08-15T18:14:26.154Z,1565892866.154 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-08-15T18:14:26.159Z,1565892866.159 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-08-15T18:14:26.160Z,1565892866.160 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-08-15T18:14:26.165Z,1565892866.165 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-08-15T18:14:26.165Z,1565892866.165 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-08-15T18:14:26.170Z,1565892866.170 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-08-15T18:14:26.171Z,1565892866.171 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-08-15T18:14:26.176Z,1565892866.176 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-08-15T18:14:26.177Z,1565892866.177 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-08-15T18:14:26.182Z,1565892866.182 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-08-15T18:14:26.242Z,1565892866.242 [CTD_Seabird] Loaded
2019-08-15T18:14:26.243Z,1565892866.243 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-08-15T18:14:26.250Z,1565892866.250 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066B4E0
2019-08-15T18:14:26.251Z,1565892866.251 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1126
2019-08-15T18:14:26.454Z,1565892866.454 [ESPComponent] Loaded
2019-08-15T18:14:26.454Z,1565892866.454 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-15T18:14:26.479Z,1565892866.479 [PAR_Licor] Loaded
2019-08-15T18:14:26.479Z,1565892866.479 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-08-15T18:14:26.526Z,1565892866.526 [WetLabsBB2FL] Loaded
2019-08-15T18:14:26.527Z,1565892866.527 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-08-15T18:14:26.528Z,1565892866.528 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069B4E0
2019-08-15T18:14:26.528Z,1565892866.528 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1127
2019-08-15T18:14:26.529Z,1565892866.529 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-15T18:14:26.529Z,1565892866.529 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-15T18:14:26.624Z,1565892866.624 [DepthRateCalculator] Loaded
2019-08-15T18:14:26.624Z,1565892866.624 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-15T18:14:26.630Z,1565892866.630 [PitchRateCalculator] Loaded
2019-08-15T18:14:26.630Z,1565892866.630 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-15T18:14:26.646Z,1565892866.646 [SpeedCalculator] Loaded
2019-08-15T18:14:26.646Z,1565892866.646 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-15T18:14:26.667Z,1565892866.667 [TempGradientCalculator] Loaded
2019-08-15T18:14:26.667Z,1565892866.667 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-15T18:14:26.673Z,1565892866.673 [YawRateCalculator] Loaded
2019-08-15T18:14:26.673Z,1565892866.673 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-15T18:14:26.706Z,1565892866.706 [ElevatorOffsetCalculator] Loaded
2019-08-15T18:14:26.706Z,1565892866.706 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-15T18:14:26.707Z,1565892866.707 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-15T18:14:26.707Z,1565892866.707 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-15T18:14:26.739Z,1565892866.739 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-15T18:14:26.739Z,1565892866.739 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-15T18:14:26.842Z,1565892866.842 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-15T18:14:26.843Z,1565892866.843 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-15T18:14:26.864Z,1565892866.864 [NavChart] Loaded
2019-08-15T18:14:26.864Z,1565892866.864 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-15T18:14:26.868Z,1565892866.868 [UniversalFixResidualReporter] Loaded
2019-08-15T18:14:26.868Z,1565892866.868 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-15T18:14:26.869Z,1565892866.869 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-15T18:14:26.869Z,1565892866.869 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-15T18:14:27.216Z,1565892867.216 [AHRS_M2] Loaded
2019-08-15T18:14:27.216Z,1565892867.216 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-15T18:14:27.293Z,1565892867.293 [DataOverHttps] Loaded
2019-08-15T18:14:27.293Z,1565892867.293 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-15T18:14:27.294Z,1565892867.294 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409744E0
2019-08-15T18:14:27.294Z,1565892867.294 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1128
2019-08-15T18:14:27.307Z,1565892867.307 [Depth_Keller] Loaded
2019-08-15T18:14:27.308Z,1565892867.308 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-15T18:14:27.312Z,1565892867.312 [DropWeight] Loaded
2019-08-15T18:14:27.313Z,1565892867.313 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-15T18:14:27.402Z,1565892867.402 [NAL9602] Loaded
2019-08-15T18:14:27.403Z,1565892867.403 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-15T18:14:27.408Z,1565892867.408 [Onboard] Loaded
2019-08-15T18:14:27.408Z,1565892867.408 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-15T18:14:27.412Z,1565892867.412 [Radio_Surface] Loaded
2019-08-15T18:14:27.412Z,1565892867.412 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-15T18:14:27.413Z,1565892867.413 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A44E0
2019-08-15T18:14:27.413Z,1565892867.413 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1129
2019-08-15T18:14:27.540Z,1565892867.540 [DAT] Loaded
2019-08-15T18:14:27.540Z,1565892867.540 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-08-15T18:14:28.818Z,1565892868.818 [BPC1] Loaded
2019-08-15T18:14:28.818Z,1565892868.818 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-15T18:14:28.819Z,1565892868.819 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-15T18:14:28.819Z,1565892868.819 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-15T18:14:28.887Z,1565892868.887 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-15T18:14:28.888Z,1565892868.888 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-15T18:14:28.952Z,1565892868.952 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-15T18:14:29.036Z,1565892869.036 [VerticalControl] Loaded
2019-08-15T18:14:29.037Z,1565892869.037 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-15T18:14:29.038Z,1565892869.038 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-15T18:14:29.095Z,1565892869.095 [HorizontalControl] Loaded
2019-08-15T18:14:29.096Z,1565892869.096 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-15T18:14:29.096Z,1565892869.096 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-15T18:14:29.098Z,1565892869.098 [SpeedControl] Loaded
2019-08-15T18:14:29.098Z,1565892869.098 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-15T18:14:29.099Z,1565892869.099 [LoopControl](DEBUG): Construct LoopControl.
2019-08-15T18:14:29.099Z,1565892869.099 [LoopControl] Loaded
2019-08-15T18:14:29.100Z,1565892869.100 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-15T18:14:29.100Z,1565892869.100 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-15T18:14:29.101Z,1565892869.101 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-15T18:14:29.114Z,1565892869.114 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-15T18:14:29.114Z,1565892869.114 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-15T18:14:29.401Z,1565892869.401 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-15T18:14:29.405Z,1565892869.405 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-15T18:14:29.405Z,1565892869.405 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-15T18:14:29.412Z,1565892869.412 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-15T18:14:29.413Z,1565892869.413 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0
2019-08-15T18:14:29.414Z,1565892869.414 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1130
2019-08-15T18:14:29.418Z,1565892869.418 [Supervisor](INFO): Main Thread ID is 803
2019-08-15T18:14:29.418Z,1565892869.418 [Supervisor](DEBUG): Running supervisor.
2019-08-15T18:14:29.419Z,1565892869.419 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1131
2019-08-15T18:14:29.421Z,1565892869.421 [controlThread ThreadHandler](INFO): Handler Thread ID is 1132
2019-08-15T18:14:29.422Z,1565892869.422 [controlThread](DEBUG): Initializing ControlThread
2019-08-15T18:14:29.424Z,1565892869.424 [SBIT](INFO): Initialize SBIT Component.
2019-08-15T18:14:29.424Z,1565892869.424 [SBIT](IMPORTANT): git: 2019-08-13
2019-08-15T18:14:29.424Z,1565892869.424 [SBIT](INFO): git hash: 6b080875362fb71081cecd990260e30fa66d1cc0
2019-08-15T18:14:29.425Z,1565892869.425 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-15T18:14:29.426Z,1565892869.426 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-08-15T18:14:29.427Z,1565892869.427 [SBIT](INFO): Beginning SBIT in 84.000000 seconds.
2019-08-15T18:14:29.428Z,1565892869.428 [IBIT](INFO): Initialize IBIT Component.
2019-08-15T18:14:29.428Z,1565892869.428 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-15T18:14:29.429Z,1565892869.429 [logger ThreadHandler](INFO): Handler Thread ID is 1133
2019-08-15T18:14:29.441Z,1565892869.441 [CBIT](DEBUG): Initialized mux pins.
2019-08-15T18:14:29.441Z,1565892869.441 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-15T18:14:29.449Z,1565892869.449 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1134
2019-08-15T18:14:29.450Z,1565892869.450 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-08-15T18:14:29.453Z,1565892869.453 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-08-15T18:14:29.455Z,1565892869.455 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1136
2019-08-15T18:14:29.456Z,1565892869.456 [WetLabsBB2FL](INFO): Powering down
2019-08-15T18:14:29.465Z,1565892869.465 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-15T18:14:29.465Z,1565892869.465 [CBIT](DEBUG): Initializing heartbeat.
2019-08-15T18:14:29.485Z,1565892869.485 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1137
2019-08-15T18:14:29.486Z,1565892869.486 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-15T18:14:29.497Z,1565892869.497 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1138
2019-08-15T18:14:29.513Z,1565892869.513 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1139
2019-08-15T18:14:29.516Z,1565892869.516 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-15T18:14:29.517Z,1565892869.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-15T18:14:29.517Z,1565892869.517 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-15T18:14:29.517Z,1565892869.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-15T18:14:29.517Z,1565892869.517 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-15T18:14:29.517Z,1565892869.517 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-15T18:14:29.518Z,1565892869.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-15T18:14:29.519Z,1565892869.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-15T18:14:29.519Z,1565892869.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-15T18:14:29.519Z,1565892869.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-15T18:14:29.519Z,1565892869.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-15T18:14:29.537Z,1565892869.537 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-15T18:14:29.537Z,1565892869.537 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-15T18:14:29.573Z,1565892869.573 [CBIT](DEBUG): Backplane powered.
2019-08-15T18:14:29.577Z,1565892869.577 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-15T18:14:29.578Z,1565892869.578 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-15T18:14:29.578Z,1565892869.578 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-15T18:14:29.578Z,1565892869.578 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-15T18:14:29.579Z,1565892869.579 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-15T18:14:29.579Z,1565892869.579 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-15T18:14:29.580Z,1565892869.580 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-15T18:14:29.581Z,1565892869.581 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-15T18:14:29.591Z,1565892869.591 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-15T18:14:29.601Z,1565892869.601 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-15T18:14:29.602Z,1565892869.602 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-15T18:14:29.602Z,1565892869.602 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-15T18:14:29.603Z,1565892869.603 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-15T18:14:29.634Z,1565892869.634 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-15T18:14:29.666Z,1565892869.666 [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-08-15T18:14:29.666Z,1565892869.666 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-15T18:14:29.735Z,1565892869.735 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-15T18:14:29.736Z,1565892869.736 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-15T18:14:29.754Z,1565892869.754 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-15T18:14:29.780Z,1565892869.780 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-15T18:14:29.783Z,1565892869.783 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-15T18:14:29.808Z,1565892869.808 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-15T18:14:29.811Z,1565892869.811 [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-08-15T18:14:29.825Z,1565892869.825 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-08-15T18:14:29.862Z,1565892869.862 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-15T18:14:29.901Z,1565892869.901 [Radio_Surface](INFO): Powering up
2019-08-15T18:14:29.924Z,1565892869.924 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-08-15T18:14:29.924Z,1565892869.924 [DAT](INFO): Powering up
2019-08-15T18:14:29.924Z,1565892869.924 [DAT](DEBUG): Initializing DAT.
2019-08-15T18:14:29.938Z,1565892869.938 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-08-15T18:14:30.023Z,1565892870.023 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:30.033Z,1565892870.033 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-15T18:14:30.034Z,1565892870.034 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:30.045Z,1565892870.045 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-15T18:14:30.046Z,1565892870.046 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:30.057Z,1565892870.057 [MassServo](DEBUG): Initializing MassServo.
2019-08-15T18:14:30.058Z,1565892870.058 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:30.069Z,1565892870.069 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-15T18:14:30.070Z,1565892870.070 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:30.081Z,1565892870.081 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-15T18:14:30.989Z,1565892870.989 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-08-15T18:14:30.989Z,1565892870.989 [RudderServo](FAULT): Rudder failed to initialize
2019-08-15T18:14:30.989Z,1565892870.989 [RudderServo] Communications Fault, FailCount= 1
2019-08-15T18:14:30.989Z,1565892870.989 [RudderServo](ERROR): Communications Fault
2019-08-15T18:14:31.102Z,1565892871.102 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-08-15T18:14:31.298Z,1565892871.298 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-15T18:14:31.298Z,1565892871.298 [RudderServo](INFO): Powering down
2019-08-15T18:14:31.959Z,1565892871.959 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:14:32.078Z,1565892872.078 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-15T18:14:32.082Z,1565892872.082 [CBIT](INFO): Clearing failed state for component RudderServo
2019-08-15T18:14:32.082Z,1565892872.082 [RudderServo] No Fault, FailCount= 1
2019-08-15T18:14:33.245Z,1565892873.245 [Aanderaa_O2](INFO): Powering down
2019-08-15T18:14:45.281Z,1565892885.281 [DAT](INFO): setting local address to 3
2019-08-15T18:14:45.685Z,1565892885.685 [DAT](INFO): set local address to 3
2019-08-15T18:14:57.806Z,1565892897.806 [NAL9602](INFO): Powering up NAL9602
2019-08-15T18:15:08.710Z,1565892908.710 [NAL9602](INFO): NAL9602 initialized
2019-08-15T18:15:09.521Z,1565892909.521 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:15:53.970Z,1565892953.970 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-15T18:15:53.974Z,1565892953.974 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-15T18:15:58.124Z,1565892958.124 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:16:05.025Z,1565892965.025 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.006603
CHAN A1 (24V): -0.023364
CHAN A2 (12V): -0.005338
CHAN A3 (5V): -0.002561
CHAN B0 (3.3V): -0.000802
CHAN B1 (3.15aV): -0.001153
CHAN B2 (3.15bV): -0.002064
CHAN B3 (GND): -0.000409
OPEN: 0.006990
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-15T18:16:05.400Z,1565892965.400 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-15T18:16:33.019Z,1565892993.019 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-15T18:16:47.239Z,1565893007.239 [SBIT](IMPORTANT): SBIT PASSED
2019-08-15T18:16:47.305Z,1565893007.305 [CommandLine](IMPORTANT): got command configSet list
2019-08-15T18:16:47.306Z,1565893007.306 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): BuoyancyServo.fastPumpDepth=5 meter;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): CTD_Seabird.minSalinityBound=0.01 practical_salinity_unit;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=1 bool;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=310 cubic_centimeter;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): VerticalControl.elevDeadband=0.1 degree;

2019-08-15T18:16:47.307Z,1565893007.307 [CommandLine](IMPORTANT): VerticalControl.kiDepthBuoy=0.3 reciprocal_second;

2019-08-15T18:16:47.308Z,1565893007.308 [CommandLine](IMPORTANT): VerticalControl.massDefault=16 millimeter;

2019-08-15T18:16:47.650Z,1565893007.650 [MissionManager](IMPORTANT): Started mission Startup
2019-08-15T18:16:47.650Z,1565893007.650 [Startup] Running Loop=1
2019-08-15T18:16:47.651Z,1565893007.651 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-15T18:16:47.651Z,1565893007.651 [Startup:A.GoToSurface] Running Loop=1
2019-08-15T18:16:47.651Z,1565893007.651 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-15T18:16:47.651Z,1565893007.651 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-15T18:16:47.652Z,1565893007.652 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-15T18:16:47.652Z,1565893007.652 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-15T18:16:47.653Z,1565893007.653 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-15T18:16:47.653Z,1565893007.653 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-15T18:16:47.655Z,1565893007.655 [Startup:StartupSatComms] Running Loop=1
2019-08-15T18:16:47.655Z,1565893007.655 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-15T18:16:47.655Z,1565893007.655 [Startup:StartupSatComms:A] Running Loop=1
2019-08-15T18:16:48.039Z,1565893008.039 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-15T18:16:53.256Z,1565893013.256 [NAL9602](INFO): SBD MO Status=2, MOMSN=31119, MT Status=2, MTMSN=0
2019-08-15T18:16:53.256Z,1565893013.256 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-15T18:17:29.673Z,1565893049.673 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-08-15T18:17:29.673Z,1565893049.673 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:17:29.684Z,1565893049.684 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:17:30.083Z,1565893050.083 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:17:30.083Z,1565893050.083 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-08-15T18:17:47.830Z,1565893067.830 [Startup:StartupSatComms:A](INFO): Timed out from 2019-08-15T18:16:47.7Z
2019-08-15T18:17:47.830Z,1565893067.830 [Startup:StartupSatComms:A] Stopped
2019-08-15T18:17:47.831Z,1565893067.831 [Startup:StartupSatComms:B] Running Loop=1
2019-08-15T18:17:48.224Z,1565893068.224 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-15T18:18:18.675Z,1565893098.675 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004898
2019-08-15T18:18:23.632Z,1565893103.632 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190815T175053/Courier0011.lzma
2019-08-15T18:18:24.438Z,1565893104.438 [DataOverHttps](INFO): Moved sent file to Logs/20190815T175053/Courier0011.lzma.bak
2019-08-15T18:18:24.439Z,1565893104.439 [DataOverHttps](INFO): SBD MOMSN=11577415
2019-08-15T18:18:34.369Z,1565893114.369 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:18:35.896Z,1565893115.896 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190815T175053/Express0013.lzma
2019-08-15T18:18:36.702Z,1565893116.702 [DataOverHttps](INFO): Moved sent file to Logs/20190815T175053/Express0013.lzma.bak
2019-08-15T18:18:36.703Z,1565893116.703 [DataOverHttps](INFO): SBD MOMSN=11577417
2019-08-15T18:18:48.130Z,1565893128.130 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-15T18:17:47.8Z
2019-08-15T18:18:48.130Z,1565893128.130 [Startup:StartupSatComms:B] Stopped
2019-08-15T18:18:48.130Z,1565893128.130 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-15T18:18:48.130Z,1565893128.130 [Startup:StartupSatComms] Stopped
2019-08-15T18:18:48.130Z,1565893128.130 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-15T18:18:48.131Z,1565893128.131 [Startup](INFO): Completed Startup
2019-08-15T18:18:48.131Z,1565893128.131 [MissionManager](INFO): Startup is completed.
2019-08-15T18:18:48.131Z,1565893128.131 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-15T18:18:48.132Z,1565893128.132 [Startup] Stopped
2019-08-15T18:18:48.132Z,1565893128.132 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-15T18:18:48.132Z,1565893128.132 [Startup:A.GoToSurface] Stopped
2019-08-15T18:18:48.132Z,1565893128.132 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-15T18:18:48.489Z,1565893128.489 [MissionManager](IMPORTANT): Started mission Default
2019-08-15T18:18:48.489Z,1565893128.489 [Default] Running Loop=1
2019-08-15T18:18:48.489Z,1565893128.489 [Default](DEBUG): Aggregate::initialize Default
2019-08-15T18:18:48.489Z,1565893128.489 [Default:B.GoToSurface] Running Loop=1
2019-08-15T18:18:48.489Z,1565893128.489 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-15T18:18:48.490Z,1565893128.490 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-15T18:18:48.490Z,1565893128.490 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-15T18:18:48.490Z,1565893128.490 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-15T18:18:48.491Z,1565893128.491 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-15T18:18:48.491Z,1565893128.491 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-15T18:18:48.491Z,1565893128.491 [Default:A.Wait] Running Loop=1
2019-08-15T18:18:48.491Z,1565893128.491 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:18:53.390Z,1565893133.390 [DataOverHttps](INFO): Sending 884 bytes from file Logs/20190815T181419/Express0001.lzma
2019-08-15T18:18:54.194Z,1565893134.194 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0001.lzma.bak
2019-08-15T18:18:54.194Z,1565893134.194 [DataOverHttps](INFO): SBD MOMSN=11577419
2019-08-15T18:19:01.436Z,1565893141.436 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:19:01.823Z,1565893141.823 [Default:A.Wait](INFO): Done Waiting.
2019-08-15T18:19:01.823Z,1565893141.823 [Default:A.Wait] Stopped
2019-08-15T18:19:01.823Z,1565893141.823 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:19:02.212Z,1565893142.212 [Default:CheckIn] Running Loop=1
2019-08-15T18:19:02.212Z,1565893142.212 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-15T18:19:02.212Z,1565893142.212 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-15T18:19:02.625Z,1565893142.625 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-15T18:19:10.768Z,1565893150.768 [CommandLine](IMPORTANT): got command get latitude
2019-08-15T18:19:10.769Z,1565893150.769 [CommandLine](FAULT): Element has no value
2019-08-15T18:20:11.674Z,1565893211.674 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-15T18:20:12.492Z,1565893212.492 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:15.321Z,1565893215.321 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:17.333Z,1565893217.333 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:19.361Z,1565893219.361 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:21.381Z,1565893221.381 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:24.609Z,1565893224.609 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:27.154Z,1565893227.154 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-15T18:20:27.437Z,1565893227.437 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:30.665Z,1565893230.665 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:30.724Z,1565893230.724 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-08-15T18:20:30.724Z,1565893230.724 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:30.762Z,1565893230.762 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:30.890Z,1565893230.890 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 42.216702 degree
2019-08-15T18:20:30.891Z,1565893230.891 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2019-08-15T18:20:30.892Z,1565893230.892 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -83.735893 degree
2019-08-15T18:20:30.902Z,1565893230.902 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2019-08-15T18:20:31.142Z,1565893231.142 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:31.142Z,1565893231.142 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-08-15T18:20:31.148Z,1565893231.148 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,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-08-15T18:20:31.902Z,1565893231.902 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:31.902Z,1565893231.902 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-08-15T18:20:31.903Z,1565893231.903 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:31.914Z,1565893231.914 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:32.319Z,1565893232.319 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:32.319Z,1565893232.319 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-08-15T18:20:33.100Z,1565893233.100 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:33.100Z,1565893233.100 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-08-15T18:20:33.100Z,1565893233.100 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:33.142Z,1565893233.142 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:33.497Z,1565893233.497 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:33.559Z,1565893233.559 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:33.559Z,1565893233.559 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-08-15T18:20:34.330Z,1565893234.330 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:34.330Z,1565893234.330 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-08-15T18:20:34.330Z,1565893234.330 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:34.340Z,1565893234.340 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:34.738Z,1565893234.738 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:34.739Z,1565893234.739 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-08-15T18:20:35.538Z,1565893235.538 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:35.538Z,1565893235.538 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-08-15T18:20:35.538Z,1565893235.538 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:35.548Z,1565893235.548 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:35.958Z,1565893235.958 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:35.959Z,1565893235.959 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-08-15T18:20:36.737Z,1565893236.737 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:36.774Z,1565893236.774 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:36.774Z,1565893236.774 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-08-15T18:20:36.774Z,1565893236.774 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:36.784Z,1565893236.784 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:37.193Z,1565893237.193 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:37.193Z,1565893237.193 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-08-15T18:20:37.956Z,1565893237.956 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:37.956Z,1565893237.956 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-08-15T18:20:37.956Z,1565893237.956 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:37.967Z,1565893237.967 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:38.398Z,1565893238.398 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:20:38.413Z,1565893238.413 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:38.413Z,1565893238.413 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-08-15T18:20:39.190Z,1565893239.190 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:39.190Z,1565893239.190 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2019-08-15T18:20:39.190Z,1565893239.190 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:39.200Z,1565893239.200 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:39.565Z,1565893239.565 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:39.610Z,1565893239.610 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:39.611Z,1565893239.611 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2019-08-15T18:20:40.390Z,1565893240.390 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:40.390Z,1565893240.390 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2019-08-15T18:20:40.390Z,1565893240.390 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:40.427Z,1565893240.427 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:40.789Z,1565893240.789 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:40.789Z,1565893240.789 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2019-08-15T18:20:41.594Z,1565893241.594 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:41.594Z,1565893241.594 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2019-08-15T18:20:41.594Z,1565893241.594 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:41.604Z,1565893241.604 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:42.058Z,1565893242.059 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:42.059Z,1565893242.059 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2019-08-15T18:20:42.385Z,1565893242.385 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:42.842Z,1565893242.842 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:42.842Z,1565893242.842 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2019-08-15T18:20:42.842Z,1565893242.842 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:42.853Z,1565893242.853 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:43.299Z,1565893243.299 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:43.299Z,1565893243.299 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2019-08-15T18:20:44.012Z,1565893244.012 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:44.012Z,1565893244.012 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2019-08-15T18:20:44.012Z,1565893244.012 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:44.026Z,1565893244.026 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:44.409Z,1565893244.409 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:44.443Z,1565893244.443 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:44.443Z,1565893244.443 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2019-08-15T18:20:45.238Z,1565893245.238 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2019-08-15T18:20:45.238Z,1565893245.238 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2019-08-15T18:20:45.238Z,1565893245.238 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-08-15T18:20:45.264Z,1565893245.264 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:45.348Z,1565893245.348 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893248.000000 second
2019-08-15T18:20:45.679Z,1565893245.679 [Default:CheckIn:Read_GPS] Stopped
2019-08-15T18:20:45.679Z,1565893245.679 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-15T18:20:45.704Z,1565893245.704 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-08-15T18:20:45.704Z,1565893245.704 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2019-08-15T18:20:46.043Z,1565893246.043 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-15T18:20:46.429Z,1565893246.429 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:20:52.032Z,1565893252.032 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20190815T181419/Courier0004.lzma
2019-08-15T18:20:52.839Z,1565893252.839 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0004.lzma.bak
2019-08-15T18:20:52.839Z,1565893252.839 [DataOverHttps](INFO): SBD MOMSN=11577448
2019-08-15T18:21:05.530Z,1565893265.530 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:21:06.425Z,1565893266.425 [DataOverHttps](INFO): Sending 319 bytes from file Logs/20190815T181419/Express0005.lzma
2019-08-15T18:21:07.231Z,1565893267.231 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0005.lzma.bak
2019-08-15T18:21:07.232Z,1565893267.232 [DataOverHttps](IMPORTANT): SBD MOMSN=11577451, MTMSN=20190815T181906
2019-08-15T18:21:08.272Z,1565893268.272 [Default:CheckIn:Read_Iridium] Stopped
2019-08-15T18:21:08.272Z,1565893268.272 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-15T18:21:08.272Z,1565893268.272 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:21:12.601Z,1565893272.601 [DataOverHttps](INFO): Received command:sched asap "load Science/esp_kiss.xml;set esp_kiss.ESPCartridgeType_2 -15 count;set esp_kiss.SettleTime 3 second;set esp_kiss.ApproachDepth 3 meter;set esp_kiss.ApproachSpeed 0 meter_per_second;set esp_kiss.MinAltitude 0 meter" 1807n 1 2
2019-08-15T18:21:12.684Z,1565893272.684 [CommandLine](IMPORTANT): got command schedule asap "load Science/esp_kiss.xml;set esp_kiss.ESPCartridgeType_2 -15 count;set esp_kiss.SettleTime 3 second;set esp_kiss.ApproachDepth 3 meter;set esp_kiss.ApproachSpeed 0 meter_per_second;set esp_kiss.MinAltitude 0 meter" 1807n 1 2.000000
2019-08-15T18:21:12.684Z,1565893272.684 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=1807n
2019-08-15T18:21:12.686Z,1565893272.686 [CommandLine](IMPORTANT): Scheduled #1 (#1 of 2 with id='1807n'): "load Science/esp_kiss.xml;set esp_kiss.ESPCartridgeType_2 -15 count;set esp_kiss.SettleTime 3 second;set esp_kiss.ApproachDepth 3 meter;set esp_kiss.ApproachSpeed 0 meter_per_second;set esp_kiss.MinAltitude 0 meter" ASAP
2019-08-15T18:21:13.406Z,1565893273.406 [DataOverHttps](IMPORTANT): SBD MTMSN=20190815T181912
2019-08-15T18:21:19.546Z,1565893279.546 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-15T18:21:20.088Z,1565893280.088 [DataOverHttps](INFO): Received command:sched asap "set esp_kiss.MinOffshore 0.0001 kilometer;run " 1807n 2 2
2019-08-15T18:21:20.109Z,1565893280.109 [CommandLine](IMPORTANT): got command schedule asap "set esp_kiss.MinOffshore 0.0001 kilometer;run " 1807n 2 2.000000
2019-08-15T18:21:20.110Z,1565893280.110 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=1807n
2019-08-15T18:21:20.111Z,1565893280.111 [CommandLine](IMPORTANT): Scheduled #2 (#2 of 2 with id='1807n'): "set esp_kiss.MinOffshore 0.0001 kilometer;run " ASAP
2019-08-15T18:21:20.285Z,1565893280.285 [CommandLine](IMPORTANT): got command load ./Missions/Science/esp_kiss.xml
2019-08-15T18:21:20.285Z,1565893280.285 [MissionManager](INFO): Loading Mission: ./Missions/Science/esp_kiss.xml
2019-08-15T18:21:20.514Z,1565893280.514 [MissionManager](INFO): DefineArg esp_kiss.MissionTimeout = 4.000000 h
2019-08-15T18:21:20.522Z,1565893280.522 [MissionManager](INFO): DefineArg esp_kiss.TargetDepth = 3.000000 m
2019-08-15T18:21:20.526Z,1565893280.526 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_1 = -4.000000 count
2019-08-15T18:21:20.529Z,1565893280.529 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_2 = -9.000000 count
2019-08-15T18:21:20.532Z,1565893280.532 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_3 = nan count
2019-08-15T18:21:20.540Z,1565893280.540 [MissionManager](INFO): DefineArg esp_kiss.ESPCartridgeType_4 = nan count
2019-08-15T18:21:20.548Z,1565893280.548 [MissionManager](INFO): DefineArg esp_kiss.SettleTime = 3.000000 min
2019-08-15T18:21:20.560Z,1565893280.560 [MissionManager](INFO): DefineArg esp_kiss.Speed = 0.000000 m/s
2019-08-15T18:21:20.571Z,1565893280.571 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepth = 2.000000 m
2019-08-15T18:21:20.583Z,1565893280.583 [MissionManager](INFO): DefineArg esp_kiss.ApproachSpeed = 0.700000 m/s
2019-08-15T18:21:20.594Z,1565893280.594 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthRate = 0.050000 m/s
2019-08-15T18:21:20.606Z,1565893280.606 [MissionManager](INFO): DefineArg esp_kiss.ApproachPitchLimit = 10.000000 arcdeg
2019-08-15T18:21:20.611Z,1565893280.611 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePreDive = 1.000000 min
2019-08-15T18:21:20.614Z,1565893280.614 [MissionManager](INFO): DefineArg esp_kiss.ApproachSettleTimePostDive = 1.000000 min
2019-08-15T18:21:20.621Z,1565893280.621 [MissionManager](INFO): DefineArg esp_kiss.ApproachDepthTimeout = 15.000000 min
2019-08-15T18:21:20.624Z,1565893280.624 [MissionManager](INFO): DefineArg esp_kiss.kpDepth = 0.070000 rad/m
2019-08-15T18:21:20.632Z,1565893280.632 [MissionManager](INFO): DefineArg esp_kiss.DepthDeadband = 0.010000 m
2019-08-15T18:21:20.650Z,1565893280.650 [MissionManager](INFO): DefineArg esp_kiss.MinAltitude = 2.000000 m
2019-08-15T18:21:20.661Z,1565893280.661 [MissionManager](INFO): DefineArg esp_kiss.MaxDepth = 5.000000 m
2019-08-15T18:21:20.664Z,1565893280.664 [MissionManager](INFO): DefineArg esp_kiss.MinOffshore = 1.000000 km
2019-08-15T18:21:20.672Z,1565893280.672 [MissionManager](INFO): DefineOutput esp_kiss.ESPCartridgeType = nan count
2019-08-15T18:21:20.677Z,1565893280.677 [esp_kiss:A.AbortSample](DEBUG): Construct.
2019-08-15T18:21:20.678Z,1565893280.678 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml
2019-08-15T18:21:20.727Z,1565893280.727 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinAltitude = 5.000000 m
2019-08-15T18:21:20.779Z,1565893280.779 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MaxDepth = 200.000000 m
2019-08-15T18:21:20.782Z,1565893280.782 [MissionManager](INFO): DefineArg esp_kiss:StandardEnvelopes.MinOffshore = 2000.000000 m
2019-08-15T18:21:20.783Z,1565893280.783 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2019-08-15T18:21:20.811Z,1565893280.811 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2019-08-15T18:21:20.866Z,1565893280.866 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2019-08-15T18:21:20.921Z,1565893280.921 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml
2019-08-15T18:21:21.023Z,1565893281.023 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.DiveInterval = 3.000000 h
2019-08-15T18:21:21.026Z,1565893281.026 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.WaitForPitchUp = 10.000000 min
2019-08-15T18:21:21.058Z,1565893281.058 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfacePitch = 20.000000 arcdeg
2019-08-15T18:21:21.061Z,1565893281.061 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceDepthRate = nan m/s
2019-08-15T18:21:21.065Z,1565893281.065 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.SurfaceSpeed = 1.000000 m/s
2019-08-15T18:21:21.068Z,1565893281.068 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.GPSTimeout = 7.000000 min
2019-08-15T18:21:21.071Z,1565893281.071 [MissionManager](INFO): DefineArg esp_kiss:NeedComms.CommsTimeout = 30.000000 min
2019-08-15T18:21:21.107Z,1565893281.107 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-15T18:21:21.206Z,1565893281.206 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Construct Wait.
2019-08-15T18:21:21.220Z,1565893281.220 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2019-08-15T18:21:21.220Z,1565893281.220 [MissionManager](ERROR): Slate does not contain celsius
2019-08-15T18:21:21.232Z,1565893281.232 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2019-08-15T18:21:21.630Z,1565893281.630 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUS = 0 bool
2019-08-15T18:21:21.675Z,1565893281.675 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2019-08-15T18:21:21.679Z,1565893281.679 [MissionManager](INFO): DefineArg esp_kiss:Science.SampleISUSminPitch = -60.000000 arcdeg
2019-08-15T18:21:21.698Z,1565893281.698 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectChlActive = 0 bool
2019-08-15T18:21:21.705Z,1565893281.705 [MissionManager](INFO): DefineArg esp_kiss:Science.TimeWindowPeakReport = nan min
2019-08-15T18:21:21.708Z,1565893281.708 [MissionManager](INFO): DefineArg esp_kiss:Science.HighestChlPeakReportActive = 0 bool
2019-08-15T18:21:21.715Z,1565893281.715 [MissionManager](INFO): DefineArg esp_kiss:Science.PatchTracking = 0 bool
2019-08-15T18:21:21.718Z,1565893281.718 [MissionManager](INFO): DefineArg esp_kiss:Science.FilterWidthHorizontal = 3.000000 count
2019-08-15T18:21:21.730Z,1565893281.730 [MissionManager](INFO): DefineArg esp_kiss:Science.NumProfilesSlidingwindow = 100.000000 count
2019-08-15T18:21:21.737Z,1565893281.737 [MissionManager](INFO): DefineArg esp_kiss:Science.OffPeakFractionHorizontal = 80.000000 %
2019-08-15T18:21:21.740Z,1565893281.740 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectNO3Active = 0 bool
2019-08-15T18:21:21.747Z,1565893281.747 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectOilActive = 0 bool
2019-08-15T18:21:21.754Z,1565893281.754 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDetectFDOMActive = 0 bool
2019-08-15T18:21:21.761Z,1565893281.761 [MissionManager](INFO): DefineArg esp_kiss:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2019-08-15T18:21:21.769Z,1565893281.769 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledAanderaaO2 = 1.000000 bool
2019-08-15T18:21:21.772Z,1565893281.772 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledNeilBrown = 0.000000 bool
2019-08-15T18:21:21.780Z,1565893281.780 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledSeabird = 1.000000 bool
2019-08-15T18:21:21.784Z,1565893281.784 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledTurbulence_NPS = 0.000000 bool
2019-08-15T18:21:21.796Z,1565893281.796 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsBB2FL = 1.000000 bool
2019-08-15T18:21:21.804Z,1565893281.804 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2019-08-15T18:21:21.808Z,1565893281.808 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledWetLabsUBAT = 0.000000 bool
2019-08-15T18:21:21.819Z,1565893281.819 [MissionManager](INFO): DefineArg esp_kiss:Science.EnabledISUS = 0.000000 bool
2019-08-15T18:21:21.823Z,1565893281.823 [MissionManager](INFO): DefineArg esp_kiss:Science.LowPassWindowLength = 20.000000 count
2019-08-15T18:21:21.834Z,1565893281.834 [MissionManager](INFO): DefineArg esp_kiss:Science.MedianFilterLen = 5.000000 count
2019-08-15T18:21:21.841Z,1565893281.841 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlShallowBound = nan m
2019-08-15T18:21:21.844Z,1565893281.844 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakChlDeepBound = nan m
2019-08-15T18:21:21.851Z,1565893281.852 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakShallowBound = nan m
2019-08-15T18:21:21.855Z,1565893281.855 [MissionManager](INFO): DefineArg esp_kiss:Science.PeakDeepBound = nan m
2019-08-15T18:21:21.866Z,1565893281.866 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChl = 0.000000 ug/l
2019-08-15T18:21:21.873Z,1565893281.873 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlDepth = 0.000000 m
2019-08-15T18:21:21.877Z,1565893281.877 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlTemperature = 0.000000 degC
2019-08-15T18:21:21.884Z,1565893281.884 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLatitude = nan arcdeg
2019-08-15T18:21:21.895Z,1565893281.895 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakChlLongitude = nan arcdeg
2019-08-15T18:21:21.898Z,1565893281.898 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3 = 0.000000 umol/l
2019-08-15T18:21:21.905Z,1565893281.905 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Depth = 0.000000 m
2019-08-15T18:21:21.908Z,1565893281.908 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Latitude = nan arcdeg
2019-08-15T18:21:21.929Z,1565893281.929 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakNO3Longitude = nan arcdeg
2019-08-15T18:21:21.937Z,1565893281.937 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChl = 0.000000 m
2019-08-15T18:21:21.940Z,1565893281.940 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDepth = 0.000000 m
2019-08-15T18:21:22.005Z,1565893282.005 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLatitude = nan arcdeg
2019-08-15T18:21:22.008Z,1565893282.008 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlLongitude = nan arcdeg
2019-08-15T18:21:22.011Z,1565893282.011 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchChlDistance = nan m
2019-08-15T18:21:22.030Z,1565893282.030 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOil = 0.000000 kg/m3
2019-08-15T18:21:22.033Z,1565893282.033 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilDepth = 0.000000 m
2019-08-15T18:21:22.036Z,1565893282.036 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLatitude = nan arcdeg
2019-08-15T18:21:22.052Z,1565893282.052 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakOilLongitude = nan arcdeg
2019-08-15T18:21:22.064Z,1565893282.064 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOM = 0.000000 ppb
2019-08-15T18:21:22.067Z,1565893282.067 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMDepth = 0.000000 m
2019-08-15T18:21:22.070Z,1565893282.070 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLatitude = nan arcdeg
2019-08-15T18:21:22.081Z,1565893282.081 [MissionManager](INFO): DefineOutput esp_kiss:Science.PeakFDOMLongitude = nan arcdeg
2019-08-15T18:21:22.084Z,1565893282.084 [MissionManager](INFO): DefineOutput esp_kiss:Science.PatchFDOMDistance = nan m
2019-08-15T18:21:22.125Z,1565893282.125 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-08-15T18:21:22.159Z,1565893282.159 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2019-08-15T18:21:22.184Z,1565893282.184 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-08-15T18:21:22.244Z,1565893282.244 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-08-15T18:21:22.270Z,1565893282.270 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-08-15T18:21:22.296Z,1565893282.296 [esp_kiss:InitialDive:C.Pitch](DEBUG): Construct.
2019-08-15T18:21:22.322Z,1565893282.322 [esp_kiss:InitialDive:D.Point](DEBUG): Construct.
2019-08-15T18:21:22.333Z,1565893282.333 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Construct Buoyancy.
2019-08-15T18:21:22.338Z,1565893282.338 [esp_kiss:InitialDive:G.Wait](DEBUG): Construct Wait.
2019-08-15T18:21:22.406Z,1565893282.406 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Construct.
2019-08-15T18:21:22.408Z,1565893282.408 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-08-15T18:21:22.454Z,1565893282.454 [esp_kiss:InitialDive:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-08-15T18:21:22.475Z,1565893282.475 [esp_kiss:SettleAtDepth:B.Pitch](DEBUG): Construct.
2019-08-15T18:21:22.497Z,1565893282.497 [esp_kiss:SettleAtDepth:C.Wait](DEBUG): Construct Wait.
2019-08-15T18:21:22.500Z,1565893282.500 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2019-08-15T18:21:22.504Z,1565893282.504 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Construct.
2019-08-15T18:21:22.531Z,1565893282.531 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Construct.
2019-08-15T18:21:22.547Z,1565893282.547 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Construct Buoyancy.
2019-08-15T18:21:22.562Z,1565893282.562 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Construct.
2019-08-15T18:21:22.691Z,1565893282.691 [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:Control="Tethys/Control"
         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/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="esp_kiss">

    <Description>
        This mission takes ESP samples at the designated depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission.
    </Description><Units:hour/><Value>4</Value></DefineArg>

    <DefineArg Name="TargetDepth"><Description>
        Depth to sample at. Initialized to 3 m.
    </Description><Units:meter/><Value>3</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_1"><Description>
        Specifies ESP cartridge type code for sample# 1. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_2"><Description>
        Specifies ESP cartridge type code for sample# 2. Set to NaN to skip this sample.
    </Description><Units:count/><Value>-9</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_3"><Description>
        Specifies ESP cartridge type code for sample# 3. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

    <DefineArg Name="ESPCartridgeType_4"><Description>
        Specifies ESP cartridge type code for sample# 4. Set to NaN to skip this sample.
    </Description><Units:count/><Value>NaN</Value></DefineArg>

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

    <DefineArg Name="Speed"><Description>
        Vehicle speed while sampling. Set to zero to maintain depth using VBS (drift).
    </Description><Units:meter_per_second/><Value>0</Value></DefineArg>

    <DefineArg Name="ApproachDepth"><Description>
        Depth for initial descent form the surface. Initialized to 3 m.
    </Description><Units:meter/><Value>2</Value></DefineArg>

    <DefineArg Name="ApproachSpeed"><Description>
        Vehicle speed for initial descent form the surface to target depth. Set to zero
        to disable the thruster and descend using VBS (drift).
    </Description><Units:meter_per_second/><Value>0.7</Value></DefineArg>

    <DefineArg Name="ApproachDepthRate"><Description>
        Descent depth rate (Positive depth rate means going down).
    </Description><Units:meter_per_second/><Value>0.05</Value></DefineArg>

    <DefineArg Name="ApproachPitchLimit"><Description>
        Max vehicle pitch (+/-) when decending from the surface.
    </Description><Units:degree/><Value>10</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePreDive"><Description>
        Time duration for the vehicle to pump down the VBS *BEFORE* leaving the surface.
    </Description><Units:minute/><Value>1</Value></DefineArg>

    <DefineArg Name="ApproachSettleTimePostDive"><Description>
        Time duration for the vehicle to settle *AFTER* reaching the target depth.
    </Description><Units:minute/><Value>1</Value></DefineArg>

    <DefineArg Name="ApproachDepthTimeout"><Description>
        Maximum time duration for the vehicle to reach the target depth.
    </Description><Units:minute/><Value>15</Value></DefineArg>

    <DefineArg Name="kpDepth"><Description>
        Dive loop proportional gain (applied only while the vehicle is descending to target depth).
    </Description><Units:radian_per_meter/><Value>0.07</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed while sampling.
    </Description><Units:meter/><Value>0.01</Value></DefineArg>

    <DefineArg Name="MinAltitude"><Description>
        Minimum height above the sea floor for the entire mission.
    </Description><Units:meter/><Value>2</Value></DefineArg>

    <DefineArg Name="MaxDepth"><Description>
        Maximum allowable depth during the mission.
    </Description><Units:meter/><Value>5</Value></DefineArg>

    <DefineArg Name="MinOffshore"><Description>
        Minimum distance from the shoreline to maintain.
    </Description><Units:kilometer/><Value>1</Value></DefineArg>

    <DefineOutput Name="ESPCartridgeType"><Description>
        Mission parameter (don't change). Specifies ESP cartridge type code.
    </Description><Units:count/><Value>NaN</Value></DefineOutput>
    
    <!-- Mission timeout -->

    <Timeout Duration="MissionTimeout"/>

    <!-- Safety nets and surfacing behaviors -->

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

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

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MaxDepth"/><Arg Name="MaxDepth"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinAltitude"/><Arg Name="MinAltitude"/></Assign>

    <Assign><Sequence/><Arg Name="StandardEnvelopes:MinOffshore"/><Arg Name="MinOffshore"/></Assign>


    <Insert Filename="Insert/NeedComms.xml" Id="NeedComms"/>

    <Assign><Sequence/><Arg Name="NeedComms:DiveInterval"/><Arg Name="MissionTimeout"/></Assign>

    <Assign><Sequence/><Arg Name="NeedComms:WaitForPitchUp"/><Units:minute/><Value>0</Value></Assign>


    <Assign><Parallel/><Control:VerticalControl.depthDeadband/><Arg Name="DepthDeadband"/></Assign>

        
    <!-- Callable aggregate -->

    <Aggregate Id="SampleESP">
        
        <When>
            <Called/>
        </When>

        <Aggregate Id="sample">
            <Sequence/>

            <Syslog Severity="Important">At <Universal:depth/><Units:meter/>, settling for <Arg Name="SettleTime"/><Units:minute/></Syslog>

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

            <Syslog Severity="Important">Requesting ESP cartridge type:<Arg Name="ESPCartridgeType"/><Units:count/></Syslog>

            <Assign><Sequence/><Science:ESPComponent.cartridge/><Arg Name="ESPCartridgeType"/></Assign>

            <ReadDatum Id="TriggerESP">
                <Science:ESPComponent.sampling/>
            </ReadDatum>

            <Syslog Severity="Important">ESP sampling at <Universal:depth/><Units:meter/> in <Science:CTD_NeilBrown.bin_mean_sea_water_temperature/><Units:celsius/> water with <Science:WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water/><Units:microgram_per_liter/>chlorophyll fluorescence.</Syslog>

            <ReadDatum Id="WaitForESP">
                <Science:ESPComponent.sample_number/>
            </ReadDatum>
        </Aggregate>

    </Aggregate>


    <!-- Start mission sequence -->

    <Call Id="StartingMission" RefId="NeedComms"/>
    
    <Insert Filename="Insert/Science.xml"></Insert>

    <Aggregate Id="InitialDive">
        <Description>
            Descend from the surface to approach depth at ApproachSpeed, limit pitch,
            depth-rate, and hold the rudder.
        </Description>

        <Sequence/>

        <Assign><Parallel/><Control:VerticalControl.pitchLimit/><Arg Name="ApproachPitchLimit"/></Assign>

        <Assign><Parallel/><Control:VerticalControl.kpDepth/><Arg Name="kpDepth"/></Assign>

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

        <Guidance:Point>
            <Parallel/>
            <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
        </Guidance:Point>
        
        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
        </Guidance:Buoyancy>

        <Syslog Severity="Info">Waiting for <Arg Name="ApproachSettleTimePreDive"/><Units:minute/>while pumping down to neutral.</Syslog>

        <Guidance:Wait>
            <Description>Take a few moments to ensure the VBS reaches neutral.</Description>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="ApproachSettleTimePreDive"/></Setting>
        </Guidance:Wait>

        <Syslog>Moving to <Arg Name="ApproachDepth"/><Units:meter/></Syslog>

        <Aggregate Id="ApproachDepth">

            <Sequence/>

            <Guidance:SetSpeed>
                <Parallel/>
                <Setting><Guidance:SetSpeed.speed/><Arg Name="ApproachSpeed"/></Setting>
            </Guidance:SetSpeed>

            <Guidance:Pitch>
                <Sequence/>

                <Timeout Duration="ApproachDepthTimeout">
                    <Syslog Severity="Important">Timed out while trying to reach target depth at current depth of <Universal:depth/><Units:meter/>.</Syslog>
                    <Guidance:Execute>
                        <Sequence/>
                        <Setting><Guidance:Execute.command/><String>stop</String></Setting>
                    </Guidance:Execute>
                </Timeout>

                <Setting><Guidance:Pitch.depth/><Arg Name="ApproachDepth"/></Setting>
                <Setting><Guidance:Pitch.depthRate/><Arg Name="ApproachDepthRate"/></Setting>
            </Guidance:Pitch>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="SettleAtDepth">
        <Description>
            Take a few more moments here to ensure the vechile is settled at the target depth.
        </Description>

        <Sequence/>

        <Syslog Severity="Info">Reached <Universal:depth/><Units:meter/>, settling for <Arg Name="ApproachSettleTimePostDive"/><Units:minute/></Syslog>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.depth/><Arg Name="TargetDepth"/></Setting>
        </Guidance:Pitch>

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

    </Aggregate>

    <Aggregate Id="SampleAtTargetDepth">
        <Description>
            Maintain target depth and acquire ESP samples.
        </Description>

        <Sequence/>

        <Guidance:SetSpeed>
            <Parallel/>
            <Setting><Guidance:SetSpeed.speed/><Arg Name="Speed"/></Setting>
        </Guidance:SetSpeed>

        <Guidance:Pitch>
            <Parallel/>
            <Setting><Guidance:Pitch.depth/><Arg Name="TargetDepth"/></Setting>
        </Guidance:Pitch>
        
        <Aggregate Id="Spinout">
            <Description>
                A speed has been specified, spin in circels while sampling.
            </Description>
            
            <While>
                <Arg Name="Speed"/><Gt><Units:meter_per_second/><Value>0.0</Value></Gt>
            </While>
            
            <Guidance:Pitch Id="HoldMassPosition">
                <Parallel/>
                <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
            </Guidance:Pitch>
            
            <Guidance:Buoyancy Id="HoldBuoyancyPosition">
                <Parallel/>
                <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyNeutral/></Setting>
            </Guidance:Buoyancy>

            <Guidance:Point Id="HoldRudderAngle">
                <Setting><Guidance:Point.rudderAngle/><Units:degree/><Value>13</Value></Setting>
            </Guidance:Point>

        </Aggregate>

        <Aggregate Id="GrabSamples">

            <Sequence/>

            <Aggregate Id="Sample1">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_1"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_1"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample2">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_2"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_2"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample3">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_3"/></IsNaN>
                </Break>
                
                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_3"/></Assign>
                
                <Call RefId="SampleESP"/>
            </Aggregate>


            <Aggregate Id="Sample4">
                <Break>
                    <IsNaN><Arg Name="ESPCartridgeType_4"/></IsNaN>
                </Break>

                <Assign><Sequence/><Arg Name="ESPCartridgeType"/><Arg Name="ESPCartridgeType_4"/></Assign>

                <Call RefId="SampleESP"/>
            </Aggregate>

        </Aggregate>

    </Aggregate>

</Mission>


2019-08-15T18:21:22.691Z,1565893282.691 [CommandLine](IMPORTANT): Loaded ./Missions/Science/esp_kiss.xml
2019-08-15T18:21:32.718Z,1565893292.718 [CommandLine](IMPORTANT): got command set esp_kiss.ESPCartridgeType_2 -15.000000 count
2019-08-15T18:21:32.719Z,1565893292.719 [CommandLine](IMPORTANT): got command set esp_kiss.SettleTime 3.000000 second
2019-08-15T18:21:32.720Z,1565893292.720 [CommandLine](IMPORTANT): got command set esp_kiss.ApproachDepth 3.000000 meter
2019-08-15T18:21:32.721Z,1565893292.721 [CommandLine](IMPORTANT): got command set esp_kiss.ApproachSpeed 0.000000 meter_per_second
2019-08-15T18:21:32.722Z,1565893292.722 [CommandLine](IMPORTANT): got command set esp_kiss.MinAltitude 0.000000 meter
2019-08-15T18:21:33.410Z,1565893293.410 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:21:34.633Z,1565893294.633 [CommandLine](IMPORTANT): got command set esp_kiss.MinOffshore 0.000100 kilometer
2019-08-15T18:21:34.634Z,1565893294.634 [CommandLine](IMPORTANT): got command run 
2019-08-15T18:21:34.637Z,1565893294.637 [CommandLine](IMPORTANT): Running 
2019-08-15T18:21:34.942Z,1565893294.942 [Default] Stopped
2019-08-15T18:21:34.942Z,1565893294.942 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-15T18:21:34.943Z,1565893294.943 [Default:B.GoToSurface] Stopped
2019-08-15T18:21:34.943Z,1565893294.943 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-15T18:21:34.943Z,1565893294.943 [Default:CheckIn] Stopped
2019-08-15T18:21:34.943Z,1565893294.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-15T18:21:34.943Z,1565893294.943 [Default:CheckIn:C.Wait] Stopped
2019-08-15T18:21:34.943Z,1565893294.943 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:21:34.943Z,1565893294.943 [MissionManager](IMPORTANT): Started mission esp_kiss
2019-08-15T18:21:34.943Z,1565893294.943 [esp_kiss] Running Loop=1
2019-08-15T18:21:34.943Z,1565893294.943 [esp_kiss](DEBUG): Aggregate::initialize esp_kiss
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:A.AbortSample] Running Loop=1
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:A.AbortSample](INFO): Initializing AbortSample.
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::initialize esp_kiss:StandardEnvelopes
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-08-15T18:21:34.944Z,1565893294.944 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:I] Running Loop=1
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:Science] Running Loop=1
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:Science](DEBUG): Aggregate::initialize esp_kiss:Science
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:Science:A] Running Loop=1
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:Science:B] Running Loop=1
2019-08-15T18:21:34.945Z,1565893294.945 [esp_kiss:Science:C] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:D] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:E] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:F] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:G] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:H] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:Read_Oil] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:PeakDetectChl] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectChl
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2019-08-15T18:21:34.946Z,1565893294.946 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-08-15T18:21:34.948Z,1565893294.948 [esp_kiss:Science:HighestChlPeakReport] Running Loop=1
2019-08-15T18:21:34.948Z,1565893294.948 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize esp_kiss:Science:HighestChlPeakReport
2019-08-15T18:21:34.948Z,1565893294.948 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2019-08-15T18:21:34.949Z,1565893294.949 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2019-08-15T18:21:34.949Z,1565893294.949 [esp_kiss:Science:PeakDetectNO3] Running Loop=1
2019-08-15T18:21:34.949Z,1565893294.949 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectNO3
2019-08-15T18:21:34.949Z,1565893294.949 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2019-08-15T18:21:34.950Z,1565893294.950 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-08-15T18:21:34.951Z,1565893294.951 [esp_kiss:Science:PeakDetectOil] Running Loop=1
2019-08-15T18:21:34.951Z,1565893294.951 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectOil
2019-08-15T18:21:34.952Z,1565893294.952 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2019-08-15T18:21:34.952Z,1565893294.952 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-08-15T18:21:34.954Z,1565893294.954 [esp_kiss:Science:PeakDetectFDOM] Running Loop=1
2019-08-15T18:21:34.954Z,1565893294.954 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize esp_kiss:Science:PeakDetectFDOM
2019-08-15T18:21:34.954Z,1565893294.954 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2019-08-15T18:21:34.954Z,1565893294.954 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-08-15T18:21:34.956Z,1565893294.956 [esp_kiss:C] Running Loop=1
2019-08-15T18:21:34.956Z,1565893294.956 [esp_kiss:Science] Running Loop=1
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectFDOM] Stopped
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectFDOM
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectOil] Stopped
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectOil
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectNO3] Stopped
2019-08-15T18:21:34.958Z,1565893294.958 [esp_kiss:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectNO3
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:HighestChlPeakReport] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize esp_kiss:Science:HighestChlPeakReport
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectChl] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize esp_kiss:Science:PeakDetectChl
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:Read_Oil] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:H] Stopped
2019-08-15T18:21:34.959Z,1565893294.959 [esp_kiss:Science:G] Running Loop=1
2019-08-15T18:21:34.960Z,1565893294.960 [esp_kiss:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2019-08-15T18:21:34.960Z,1565893294.960 [esp_kiss:Science:F] Stopped
2019-08-15T18:21:34.960Z,1565893294.960 [esp_kiss:Science:E] Stopped
2019-08-15T18:21:34.960Z,1565893294.960 [esp_kiss:Science:D] Running Loop=1
2019-08-15T18:21:34.961Z,1565893294.961 [esp_kiss:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2019-08-15T18:21:34.962Z,1565893294.962 [esp_kiss:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2019-08-15T18:21:34.962Z,1565893294.962 [esp_kiss:Science:C] Running Loop=1
2019-08-15T18:21:34.963Z,1565893294.963 [esp_kiss:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2019-08-15T18:21:34.963Z,1565893294.963 [esp_kiss:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2019-08-15T18:21:34.963Z,1565893294.963 [esp_kiss:Science:B] Stopped
2019-08-15T18:21:34.963Z,1565893294.963 [esp_kiss:Science:A] Running Loop=1
2019-08-15T18:21:34.964Z,1565893294.964 [esp_kiss:Science:A](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_oxygen_in_sea_water
2019-08-15T18:21:34.964Z,1565893294.964 [esp_kiss:I] Running Loop=1
2019-08-15T18:21:34.965Z,1565893294.965 [esp_kiss:C] Stopped
2019-08-15T18:21:34.965Z,1565893294.965 [esp_kiss:D] Running Loop=1
2019-08-15T18:21:34.965Z,1565893294.965 [esp_kiss:StandardEnvelopes] Running Loop=1
2019-08-15T18:21:34.965Z,1565893294.965 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2019-08-15T18:21:34.966Z,1565893294.966 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2019-08-15T18:21:34.966Z,1565893294.966 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2019-08-15T18:21:34.967Z,1565893294.967 [esp_kiss:A.AbortSample] Running Loop=1
2019-08-15T18:21:35.090Z,1565893295.090 [WetLabsBB2FL](INFO): Opening uart, block timeout 10ths=2
2019-08-15T18:21:35.090Z,1565893295.090 [WetLabsBB2FL](INFO): Powering up
2019-08-15T18:21:35.210Z,1565893295.210 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-08-15T18:21:35.340Z,1565893295.340 [esp_kiss:D] Stopped
2019-08-15T18:21:35.340Z,1565893295.340 [esp_kiss:E] Running Loop=1
2019-08-15T18:21:35.757Z,1565893295.757 [esp_kiss:E] Stopped
2019-08-15T18:21:35.757Z,1565893295.757 [esp_kiss:G] Running Loop=1
2019-08-15T18:21:36.146Z,1565893296.146 [esp_kiss:G] Stopped
2019-08-15T18:21:36.146Z,1565893296.146 [esp_kiss:H] Running Loop=1
2019-08-15T18:21:36.542Z,1565893296.542 [esp_kiss:H] Stopped
2019-08-15T18:21:36.542Z,1565893296.542 [esp_kiss:StartingMission] Running Loop=1
2019-08-15T18:21:36.542Z,1565893296.542 [esp_kiss:StartingMission](DEBUG): Aggregate::initialize esp_kiss:StartingMission
2019-08-15T18:21:36.543Z,1565893296.543 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](ERROR): Altitude Measurement is not Active.
2019-08-15T18:21:36.960Z,1565893296.960 [esp_kiss:NeedComms] Running Loop=1
2019-08-15T18:21:36.960Z,1565893296.960 [esp_kiss:NeedComms](DEBUG): Aggregate::initialize esp_kiss:NeedComms
2019-08-15T18:21:36.960Z,1565893296.960 [esp_kiss:NeedComms:B.GoToSurface] Running Loop=1
2019-08-15T18:21:36.960Z,1565893296.960 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-15T18:21:36.961Z,1565893296.961 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s.
2019-08-15T18:21:36.961Z,1565893296.961 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees.
2019-08-15T18:21:36.962Z,1565893296.962 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s.
2019-08-15T18:21:36.962Z,1565893296.962 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-15T18:21:36.963Z,1565893296.963 [esp_kiss:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-15T18:21:36.963Z,1565893296.963 [esp_kiss:NeedComms:A] Running Loop=1
2019-08-15T18:21:36.965Z,1565893296.965 [esp_kiss:NeedComms:A](INFO): last time_fix was: 1565893248.000000 second since 1970/01/01T00:00:00Z 
2019-08-15T18:21:36.965Z,1565893296.965 [esp_kiss:NeedComms:A] Stopped
2019-08-15T18:21:37.358Z,1565893297.358 [esp_kiss:NeedComms:C] Running Loop=1
2019-08-15T18:21:37.760Z,1565893297.760 [esp_kiss:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-15T18:21:38.222Z,1565893298.222 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2019-08-15T18:21:38.953Z,1565893298.953 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:21:41.030Z,1565893301.030 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-15T18:21:51.954Z,1565893311.954 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-08-15T18:22:00.287Z,1565893320.287 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:22:00.288Z,1565893320.288 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:22:00.288Z,1565893320.288 [esp_kiss](IMPORTANT): Priority 0: esp_kiss:A.AbortSample
2019-08-15T18:22:00.288Z,1565893320.288 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 1: esp_kiss:StandardEnvelopes:A.AltitudeEnvelope
2019-08-15T18:22:00.289Z,1565893320.289 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 2: esp_kiss:StandardEnvelopes:B.DepthEnvelope
2019-08-15T18:22:00.289Z,1565893320.289 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 3: esp_kiss:StandardEnvelopes:C.OffshoreEnvelope
2019-08-15T18:22:00.289Z,1565893320.289 [esp_kiss:NeedComms](IMPORTANT): Priority 4: esp_kiss:NeedComms:B.GoToSurface
2019-08-15T18:22:00.290Z,1565893320.290 [esp_kiss:NeedComms](IMPORTANT): Priority 5: esp_kiss:NeedComms:C
2019-08-15T18:22:00.290Z,1565893320.290 [esp_kiss](IMPORTANT): Priority 6: esp_kiss:I
2019-08-15T18:22:00.291Z,1565893320.291 [esp_kiss:Science](IMPORTANT): Priority 7: esp_kiss:Science:A
2019-08-15T18:22:00.291Z,1565893320.291 [esp_kiss:Science](IMPORTANT): Priority 8: esp_kiss:Science:C
2019-08-15T18:22:00.292Z,1565893320.292 [esp_kiss:Science](IMPORTANT): Priority 9: esp_kiss:Science:D
2019-08-15T18:22:00.292Z,1565893320.292 [esp_kiss:Science](IMPORTANT): Priority 10: esp_kiss:Science:G
2019-08-15T18:22:03.359Z,1565893323.359 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:22:10.051Z,1565893330.051 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-08-15T18:22:10.129Z,1565893330.129 [NAL9602](FAULT): received: 
+CSQ:0

OK119, 2, 0, 0, 0

OK
2019-08-15T18:22:10.129Z,1565893330.129 [NAL9602] Data Fault, FailCount= 1
2019-08-15T18:22:10.129Z,1565893330.129 [NAL9602](ERROR): Data Fault
2019-08-15T18:22:10.230Z,1565893330.230 [CBIT](ERROR): Data Fault in component: NAL9602
2019-08-15T18:22:10.459Z,1565893330.459 [NAL9602](INFO): Powering down
2019-08-15T18:22:11.301Z,1565893331.301 [CBIT](INFO): Clearing failed state for component NAL9602
2019-08-15T18:22:11.301Z,1565893331.301 [NAL9602] No Fault, FailCount= 1
2019-08-15T18:22:14.104Z,1565893334.104 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893376.000000 second
2019-08-15T18:22:17.948Z,1565893337.948 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:22:25.247Z,1565893345.247 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-15T18:22:27.784Z,1565893347.784 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:22:27.784Z,1565893347.784 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:22:27.784Z,1565893347.784 [esp_kiss](IMPORTANT): Priority 0: esp_kiss:A.AbortSample
2019-08-15T18:22:27.785Z,1565893347.785 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 1: esp_kiss:StandardEnvelopes:A.AltitudeEnvelope
2019-08-15T18:22:27.785Z,1565893347.785 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 2: esp_kiss:StandardEnvelopes:B.DepthEnvelope
2019-08-15T18:22:27.786Z,1565893347.786 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 3: esp_kiss:StandardEnvelopes:C.OffshoreEnvelope
2019-08-15T18:22:27.786Z,1565893347.786 [esp_kiss:NeedComms](IMPORTANT): Priority 4: esp_kiss:NeedComms:B.GoToSurface
2019-08-15T18:22:27.786Z,1565893347.786 [esp_kiss:NeedComms](IMPORTANT): Priority 5: esp_kiss:NeedComms:C
2019-08-15T18:22:27.787Z,1565893347.787 [esp_kiss](IMPORTANT): Priority 6: esp_kiss:I
2019-08-15T18:22:27.788Z,1565893347.788 [esp_kiss:Science](IMPORTANT): Priority 7: esp_kiss:Science:A
2019-08-15T18:22:27.788Z,1565893347.788 [esp_kiss:Science](IMPORTANT): Priority 8: esp_kiss:Science:C
2019-08-15T18:22:27.789Z,1565893347.789 [esp_kiss:Science](IMPORTANT): Priority 9: esp_kiss:Science:D
2019-08-15T18:22:27.789Z,1565893347.789 [esp_kiss:Science](IMPORTANT): Priority 10: esp_kiss:Science:G
2019-08-15T18:22:40.577Z,1565893360.577 [CommandLine](IMPORTANT): got command failComponent
2019-08-15T18:22:40.578Z,1565893360.578 [CommandLine](IMPORTANT): Failed components:
2019-08-15T18:22:40.578Z,1565893360.578 [CommandLine](IMPORTANT): No failed Components.
2019-08-15T18:22:40.758Z,1565893360.758 [NAL9602](INFO): Powering up NAL9602
2019-08-15T18:22:47.807Z,1565893367.807 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-08-15T18:22:51.662Z,1565893371.662 [NAL9602](INFO): NAL9602 initialized
2019-08-15T18:22:52.485Z,1565893372.485 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:23:02.155Z,1565893382.155 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893376.000000 second
2019-08-15T18:23:02.233Z,1565893382.233 [esp_kiss:NeedComms:C] Stopped
2019-08-15T18:23:02.234Z,1565893382.234 [esp_kiss:NeedComms:D] Running Loop=1
2019-08-15T18:23:02.681Z,1565893382.681 [esp_kiss:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-15T18:23:03.019Z,1565893383.019 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-15T18:23:03.020Z,1565893383.020 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-15T18:23:03.020Z,1565893383.020 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-08-15T18:23:03.050Z,1565893383.050 [BPC1](INFO): Received data from all battery sticks.
2019-08-15T18:23:09.502Z,1565893389.502 [DataOverHttps](INFO): Sending 43 bytes from file Logs/20190815T181419/Courier0007.lzma
2019-08-15T18:23:10.306Z,1565893390.306 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0007.lzma.bak
2019-08-15T18:23:10.306Z,1565893390.306 [DataOverHttps](INFO): SBD MOMSN=11577462
2019-08-15T18:23:14.921Z,1565893394.921 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-15T18:23:24.184Z,1565893404.184 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190815T181419/Courier0010.lzma
2019-08-15T18:23:24.991Z,1565893404.991 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0010.lzma.bak
2019-08-15T18:23:24.992Z,1565893404.992 [DataOverHttps](INFO): SBD MOMSN=11577464
2019-08-15T18:23:31.264Z,1565893411.264 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893376.000000 second
2019-08-15T18:23:39.605Z,1565893419.605 [DataOverHttps](INFO): Sending 167 bytes from file Logs/20190815T181419/Courier0011.lzma
2019-08-15T18:23:40.410Z,1565893420.410 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0011.lzma.bak
2019-08-15T18:23:40.411Z,1565893420.411 [DataOverHttps](INFO): SBD MOMSN=11577466
2019-08-15T18:23:41.668Z,1565893421.668 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-15T18:23:53.875Z,1565893433.875 [DataOverHttps](INFO): Sending 1342 bytes from file Logs/20190815T181419/Express0008.lzma
2019-08-15T18:23:54.667Z,1565893434.667 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0008.lzma.bak
2019-08-15T18:23:54.667Z,1565893434.667 [DataOverHttps](INFO): SBD MOMSN=11577468
2019-08-15T18:24:00.933Z,1565893440.933 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893376.000000 second
2019-08-15T18:24:08.454Z,1565893448.454 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20190815T181419/Express0011.lzma
2019-08-15T18:24:09.259Z,1565893449.259 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0011.lzma.bak
2019-08-15T18:24:09.259Z,1565893449.259 [DataOverHttps](INFO): SBD MOMSN=11577522
2019-08-15T18:24:10.082Z,1565893450.082 [esp_kiss:NeedComms:D] Stopped
2019-08-15T18:24:10.082Z,1565893450.082 [esp_kiss:NeedComms:E] Running Loop=1
2019-08-15T18:24:10.487Z,1565893450.487 [esp_kiss:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-15T18:24:14.495Z,1565893454.495 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-15T18:24:18.940Z,1565893458.940 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:24:18.941Z,1565893458.941 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:24:18.942Z,1565893458.942 [esp_kiss](IMPORTANT): Priority 0: esp_kiss:A.AbortSample
2019-08-15T18:24:18.942Z,1565893458.942 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 1: esp_kiss:StandardEnvelopes:A.AltitudeEnvelope
2019-08-15T18:24:18.943Z,1565893458.943 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 2: esp_kiss:StandardEnvelopes:B.DepthEnvelope
2019-08-15T18:24:18.943Z,1565893458.943 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 3: esp_kiss:StandardEnvelopes:C.OffshoreEnvelope
2019-08-15T18:24:18.943Z,1565893458.943 [esp_kiss:NeedComms](IMPORTANT): Priority 4: esp_kiss:NeedComms:B.GoToSurface
2019-08-15T18:24:18.944Z,1565893458.944 [esp_kiss:NeedComms](IMPORTANT): Priority 5: esp_kiss:NeedComms:E
2019-08-15T18:24:18.944Z,1565893458.944 [esp_kiss](IMPORTANT): Priority 6: esp_kiss:I
2019-08-15T18:24:18.985Z,1565893458.985 [esp_kiss:Science](IMPORTANT): Priority 7: esp_kiss:Science:A
2019-08-15T18:24:18.986Z,1565893458.986 [esp_kiss:Science](IMPORTANT): Priority 8: esp_kiss:Science:C
2019-08-15T18:24:18.986Z,1565893458.986 [esp_kiss:Science](IMPORTANT): Priority 9: esp_kiss:Science:D
2019-08-15T18:24:18.986Z,1565893458.986 [esp_kiss:Science](IMPORTANT): Priority 10: esp_kiss:Science:G
2019-08-15T18:24:32.675Z,1565893472.675 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 0.000000 bool
2019-08-15T18:24:41.978Z,1565893481.978 [CommandLine](IMPORTANT): got command set NAL9602.platform_communications 1.000000 bool
2019-08-15T18:24:52.284Z,1565893492.284 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1565893504.000000 second
2019-08-15T18:24:52.543Z,1565893492.543 [esp_kiss:NeedComms:E] Stopped
2019-08-15T18:24:52.543Z,1565893492.543 [esp_kiss:NeedComms](INFO): Completed esp_kiss:NeedComms
2019-08-15T18:24:52.544Z,1565893492.544 [esp_kiss:NeedComms] Stopped
2019-08-15T18:24:52.544Z,1565893492.544 [esp_kiss:NeedComms](DEBUG): Aggregate::uninitialize esp_kiss:NeedComms
2019-08-15T18:24:52.544Z,1565893492.544 [esp_kiss:NeedComms:B.GoToSurface] Stopped
2019-08-15T18:24:52.544Z,1565893492.544 [esp_kiss:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-15T18:24:52.960Z,1565893492.960 [esp_kiss:StartingMission](INFO): Completed esp_kiss:StartingMission
2019-08-15T18:24:52.960Z,1565893492.960 [esp_kiss:StartingMission] Stopped
2019-08-15T18:24:52.960Z,1565893492.960 [esp_kiss:StartingMission](DEBUG): Aggregate::uninitialize esp_kiss:StartingMission
2019-08-15T18:24:52.960Z,1565893492.960 [esp_kiss:InitialDive] Running Loop=1
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive](DEBUG): Aggregate::initialize esp_kiss:InitialDive
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:A] Running Loop=1
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:B] Running Loop=1
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:C.Pitch](DEBUG): Initialize.
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:D.Point](DEBUG): Initialize.
2019-08-15T18:24:52.965Z,1565893492.965 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-08-15T18:24:52.966Z,1565893492.966 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-08-15T18:24:52.966Z,1565893492.966 [esp_kiss:InitialDive:F] Running Loop=1
2019-08-15T18:24:53.346Z,1565893493.346 [esp_kiss:InitialDive:F](INFO): Waiting for 1.000000 min while pumping down to neutral.
2019-08-15T18:24:53.347Z,1565893493.347 [esp_kiss:InitialDive:F] Stopped
2019-08-15T18:24:53.347Z,1565893493.347 [esp_kiss:InitialDive:G.Wait] Running Loop=1
2019-08-15T18:24:53.347Z,1565893493.347 [esp_kiss:InitialDive:G.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:24:53.347Z,1565893493.347 [esp_kiss:InitialDive:E.Buoyancy] Running Loop=1
2019-08-15T18:24:53.347Z,1565893493.347 [esp_kiss:InitialDive:D.Point] Running Loop=1
2019-08-15T18:24:53.348Z,1565893493.348 [esp_kiss:InitialDive:C.Pitch] Running Loop=1
2019-08-15T18:24:53.348Z,1565893493.348 [esp_kiss:InitialDive:B] Running Loop=1
2019-08-15T18:24:53.348Z,1565893493.348 [esp_kiss:InitialDive:A] Running Loop=1
2019-08-15T18:25:53.935Z,1565893553.935 [esp_kiss:InitialDive:G.Wait](INFO): Done Waiting.
2019-08-15T18:25:53.935Z,1565893553.935 [esp_kiss:InitialDive:G.Wait] Stopped
2019-08-15T18:25:53.935Z,1565893553.935 [esp_kiss:InitialDive:G.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:25:53.935Z,1565893553.935 [esp_kiss:InitialDive:H] Running Loop=1
2019-08-15T18:25:54.356Z,1565893554.356 [esp_kiss:InitialDive:H](INFO): Moving to 3.000000 m 
2019-08-15T18:25:54.356Z,1565893554.356 [esp_kiss:InitialDive:H] Stopped
2019-08-15T18:25:54.356Z,1565893554.356 [esp_kiss:InitialDive:ApproachDepth] Running Loop=1
2019-08-15T18:25:54.356Z,1565893554.356 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::initialize esp_kiss:InitialDive:ApproachDepth
2019-08-15T18:25:54.356Z,1565893554.356 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-08-15T18:25:54.357Z,1565893554.357 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Initialize.
2019-08-15T18:25:54.357Z,1565893554.357 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Running Loop=1
2019-08-15T18:25:54.357Z,1565893554.357 [esp_kiss:InitialDive:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-08-15T18:25:54.780Z,1565893554.780 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Running Loop=1
2019-08-15T18:26:00.337Z,1565893560.337 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter
2019-08-15T18:26:00.339Z,1565893560.339 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-08-15T18:26:00.471Z,1565893560.471 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,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-08-15T18:26:00.826Z,1565893560.826 [esp_kiss:InitialDive:ApproachDepth:B.Pitch] Stopped
2019-08-15T18:26:00.826Z,1565893560.826 [esp_kiss:InitialDive:ApproachDepth](INFO): Completed esp_kiss:InitialDive:ApproachDepth
2019-08-15T18:26:00.826Z,1565893560.826 [esp_kiss:InitialDive:ApproachDepth] Stopped
2019-08-15T18:26:00.827Z,1565893560.827 [esp_kiss:InitialDive:ApproachDepth](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive:ApproachDepth
2019-08-15T18:26:00.827Z,1565893560.827 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed] Stopped
2019-08-15T18:26:00.827Z,1565893560.827 [esp_kiss:InitialDive:ApproachDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive](INFO): Completed esp_kiss:InitialDive
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive](DEBUG): Aggregate::uninitialize esp_kiss:InitialDive
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:A] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:B] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:C.Pitch] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:D.Point] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:E.Buoyancy] Stopped
2019-08-15T18:26:00.828Z,1565893560.828 [esp_kiss:InitialDive:E.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-08-15T18:26:00.829Z,1565893560.829 [esp_kiss:SettleAtDepth] Running Loop=1
2019-08-15T18:26:00.829Z,1565893560.829 [esp_kiss:SettleAtDepth](DEBUG): Aggregate::initialize esp_kiss:SettleAtDepth
2019-08-15T18:26:00.829Z,1565893560.829 [esp_kiss:SettleAtDepth:B.Pitch] Running Loop=1
2019-08-15T18:26:00.829Z,1565893560.829 [esp_kiss:SettleAtDepth:B.Pitch](DEBUG): Initialize.
2019-08-15T18:26:00.829Z,1565893560.829 [esp_kiss:SettleAtDepth:A] Running Loop=1
2019-08-15T18:26:01.229Z,1565893561.229 [esp_kiss:SettleAtDepth:B.Pitch] Running Loop=1
2019-08-15T18:26:01.230Z,1565893561.230 [esp_kiss:SettleAtDepth:A](INFO): Reached 3.000000 m , settling for 1.000000 min 
2019-08-15T18:26:01.230Z,1565893561.230 [esp_kiss:SettleAtDepth:A] Stopped
2019-08-15T18:26:01.230Z,1565893561.230 [esp_kiss:SettleAtDepth:C.Wait] Running Loop=1
2019-08-15T18:26:01.230Z,1565893561.230 [esp_kiss:SettleAtDepth:C.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:26:41.404Z,1565893601.404 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-15T18:27:00.826Z,1565893620.826 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-15T18:27:01.193Z,1565893621.193 [Radio_Surface](INFO): Powering down
2019-08-15T18:27:01.857Z,1565893621.857 [esp_kiss:SettleAtDepth:C.Wait](INFO): Done Waiting.
2019-08-15T18:27:01.857Z,1565893621.857 [esp_kiss:SettleAtDepth:C.Wait] Stopped
2019-08-15T18:27:01.857Z,1565893621.857 [esp_kiss:SettleAtDepth:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SettleAtDepth](INFO): Completed esp_kiss:SettleAtDepth
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SettleAtDepth] Stopped
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SettleAtDepth](DEBUG): Aggregate::uninitialize esp_kiss:SettleAtDepth
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SettleAtDepth:B.Pitch] Stopped
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SampleAtTargetDepth] Running Loop=1
2019-08-15T18:27:01.858Z,1565893621.858 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:B.Pitch](DEBUG): Initialize.
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:Spinout] Running Loop=1
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:Spinout
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Running Loop=1
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch](DEBUG): Initialize.
2019-08-15T18:27:01.859Z,1565893621.859 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Running Loop=1
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Running Loop=1
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point](DEBUG): Initialize.
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:GrabSamples] Running Loop=1
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Running Loop=1
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-08-15T18:27:01.860Z,1565893621.860 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Running Loop=1
2019-08-15T18:27:02.249Z,1565893622.249 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:A] Stopped
2019-08-15T18:27:02.249Z,1565893622.249 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Running Loop=1
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::initialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout] Stopped
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:Spinout
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout:HoldMassPosition.Pitch] Stopped
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy] Stopped
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout:HoldBuoyancyPosition.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:Spinout:HoldRudderAngle.Point] Stopped
2019-08-15T18:27:02.250Z,1565893622.250 [esp_kiss:SampleAtTargetDepth:B.Pitch] Running Loop=1
2019-08-15T18:27:02.251Z,1565893622.251 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Running Loop=1
2019-08-15T18:27:02.694Z,1565893622.694 [esp_kiss:SampleESP] Running Loop=1
2019-08-15T18:27:02.695Z,1565893622.695 [esp_kiss:SampleESP](DEBUG): Aggregate::initialize esp_kiss:SampleESP
2019-08-15T18:27:02.695Z,1565893622.695 [esp_kiss:SampleESP:sample] Running Loop=1
2019-08-15T18:27:02.695Z,1565893622.695 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::initialize esp_kiss:SampleESP:sample
2019-08-15T18:27:02.695Z,1565893622.695 [esp_kiss:SampleESP:sample:A] Running Loop=1
2019-08-15T18:27:02.696Z,1565893622.696 [esp_kiss:SampleESP:sample:A](IMPORTANT): At 3.000000 m , settling for 0.050000 min 
2019-08-15T18:27:02.696Z,1565893622.696 [esp_kiss:SampleESP:sample:A] Stopped
2019-08-15T18:27:02.696Z,1565893622.696 [esp_kiss:SampleESP:sample:B.Wait] Running Loop=1
2019-08-15T18:27:02.696Z,1565893622.696 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:27:06.343Z,1565893626.343 [esp_kiss:SampleESP:sample:B.Wait](INFO): Done Waiting.
2019-08-15T18:27:06.343Z,1565893626.343 [esp_kiss:SampleESP:sample:B.Wait] Stopped
2019-08-15T18:27:06.343Z,1565893626.343 [esp_kiss:SampleESP:sample:B.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:27:06.343Z,1565893626.343 [esp_kiss:SampleESP:sample:C] Running Loop=1
2019-08-15T18:27:06.740Z,1565893626.740 [esp_kiss:SampleESP:sample:C](IMPORTANT): Requesting ESP cartridge type: -4.000000 count 
2019-08-15T18:27:06.740Z,1565893626.740 [esp_kiss:SampleESP:sample:C] Stopped
2019-08-15T18:27:06.740Z,1565893626.740 [esp_kiss:SampleESP:sample:D] Running Loop=1
2019-08-15T18:27:07.132Z,1565893627.132 [esp_kiss:SampleESP:sample:D] Stopped
2019-08-15T18:27:07.132Z,1565893627.132 [esp_kiss:SampleESP:sample:TriggerESP] Running Loop=1
2019-08-15T18:27:07.553Z,1565893627.553 [esp_kiss:SampleESP:sample:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-08-15T18:27:08.309Z,1565893628.309 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2019-08-15T18:27:08.312Z,1565893628.312 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2019-08-15T18:27:08.708Z,1565893628.708 [ESPComponent](INFO): powering up ESP
2019-08-15T18:27:08.725Z,1565893628.725 [ESPComponent](INFO): powering up ESP secondary power supply
2019-08-15T18:27:08.742Z,1565893628.742 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-08-15T18:27:09.017Z,1565893629.017 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-08-15T18:27:09.197Z,1565893629.197 [ESPComponent](INFO): console:
2019-08-15T18:27:09.925Z,1565893629.925 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2019-08-15T18:27:09.925Z,1565893629.925 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2019-08-15T18:27:09.925Z,1565893629.925 [BuoyancyServo] Communications Fault, FailCount= 1
2019-08-15T18:27:09.925Z,1565893629.925 [BuoyancyServo](ERROR): Communications Fault
2019-08-15T18:27:09.930Z,1565893629.930 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-08-15T18:27:09.936Z,1565893629.936 [ESPComponent](INFO): console:

2019-08-15T18:27:10.351Z,1565893630.351 [ESPComponent](INFO): console:NAND:  256 MiB
2019-08-15T18:27:10.760Z,1565893630.760 [ESPComponent](INFO): console:
BOOTMODE: SDMMC
2019-08-15T18:27:11.150Z,1565893631.150 [ESPComponent](INFO): console:

2019-08-15T18:27:11.557Z,1565893631.557 [ESPComponent](INFO): console:

2019-08-15T18:27:11.660Z,1565893631.660 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-15T18:27:11.660Z,1565893631.660 [BuoyancyServo](INFO): Powering down
2019-08-15T18:27:11.968Z,1565893631.968 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 18:00:17)
2019-08-15T18:27:11.980Z,1565893631.980 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-15T18:27:12.366Z,1565893632.366 [ESPComponent](INFO): console:

2019-08-15T18:27:12.472Z,1565893632.472 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-08-15T18:27:12.472Z,1565893632.472 [BuoyancyServo] No Fault, FailCount= 1
2019-08-15T18:27:12.762Z,1565893632.762 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-08-15T18:27:12.820Z,1565893632.820 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:27:12.857Z,1565893632.857 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-15T18:27:13.167Z,1565893633.167 [ESPComponent](INFO): console:
flash params are already written into flash
2019-08-15T18:27:13.573Z,1565893633.573 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-08-15T18:27:13.974Z,1565893633.974 [ESPComponent](INFO): console:
In:    serial
2019-08-15T18:27:14.388Z,1565893634.388 [ESPComponent](INFO): console:
Out:   serial
2019-08-15T18:27:14.790Z,1565893634.790 [ESPComponent](INFO): console:
Err:   serial
2019-08-15T18:27:15.186Z,1565893635.186 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-08-15T18:27:15.594Z,1565893635.594 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-08-15T18:27:15.994Z,1565893635.994 [ESPComponent](INFO): console:
mmc1 is available
2019-08-15T18:27:16.407Z,1565893636.407 [ESPComponent](INFO): console:
reading uImage
2019-08-15T18:27:16.804Z,1565893636.804 [ESPComponent](INFO): console:

2019-08-15T18:27:17.207Z,1565893637.207 [ESPComponent](INFO): console:
1681452 bytes read
2019-08-15T18:27:17.618Z,1565893637.618 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-08-15T18:27:18.015Z,1565893638.015 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-08-15T18:27:18.424Z,1565893638.424 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-08-15T18:27:18.823Z,1565893638.823 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-08-15T18:27:19.443Z,1565893639.443 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-08-15T18:27:19.840Z,1565893639.840 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-08-15T18:27:20.242Z,1565893640.242 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-08-15T18:27:20.649Z,1565893640.649 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-08-15T18:27:21.050Z,1565893641.050 [ESPComponent](INFO): console:
OK
2019-08-15T18:27:21.460Z,1565893641.460 [ESPComponent](INFO): console:

2019-08-15T18:27:21.860Z,1565893641.860 [ESPComponent](INFO): console:
Starting kernel ...
2019-08-15T18:27:22.262Z,1565893642.262 [ESPComponent](INFO): console:

2019-08-15T18:27:22.669Z,1565893642.669 [ESPComponent](INFO): console:
Uncompressing Linux... done, booting the kernel.
2019-08-15T18:27:23.071Z,1565893643.071 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-08-15T18:27:23.480Z,1565893643.480 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT data cache, VIVT instruction cache
2019-08-15T18:27:23.879Z,1565893643.879 [ESPComponent](INFO): console:
[    0.00] Machine: NXP EA313X
2019-08-15T18:27:24.286Z,1565893644.286 [ESPComponent](INFO): console:
[    0.00] Memory policy: ECC disabled, Data cache writeback
2019-08-15T18:27:24.690Z,1565893644.690 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-08-15T18:27:25.091Z,1565893645.091 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-08-15T18:27:25.497Z,1565893645.497 [ESPComponent](INFO): console:
[    0.29] MBARI ESP 3G
2019-08-15T18:27:25.901Z,1565893645.901 [ESPComponent](INFO): console:
[    0.39] bio: create slab <bio-0> at 0
2019-08-15T18:27:26.304Z,1565893646.304 [ESPComponent](INFO): console:
[    0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:26.710Z,1565893646.710 [ESPComponent](INFO): console:
[    0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:27.111Z,1565893647.111 [ESPComponent](INFO): console:
[    0.50] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:27.520Z,1565893647.520 [ESPComponent](INFO): console:
[    0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:27.922Z,1565893647.922 [ESPComponent](INFO): console:
[    0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:28.323Z,1565893648.323 [ESPComponent](INFO): console:
[    0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-08-15T18:27:28.730Z,1565893648.730 [ESPComponent](INFO): console:
[    0.56] NetWinder Floating Point Emulator V0.97 (double precision)
2019-08-15T18:27:29.131Z,1565893649.131 [ESPComponent](INFO): console:
[    0.58] yaffs Dec 14 2018 09:19:05 In. 
2019-08-15T18:27:29.535Z,1565893649.535 [ESPComponent](INFO): console:
[    0.72] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-08-15T18:27:29.942Z,1565893649.942 [ESPComponent](INFO): console:
[    2.26] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-08-15T18:27:30.342Z,1565893650.342 [ESPComponent](INFO): console:

2019-08-15T18:27:30.749Z,1565893650.749 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-08-15T18:27:31.150Z,1565893651.150 [ESPComponent](INFO): console:

2019-08-15T18:27:31.555Z,1565893651.555 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-08-15T18:27:31.961Z,1565893651.961 [ESPComponent](INFO): console:
ESPhonu
2019-08-15T18:27:32.362Z,1565893652.362 [ESPComponent](INFO): console:

2019-08-15T18:27:32.774Z,1565893652.774 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-08-15T18:27:33.170Z,1565893653.170 [ESPComponent](INFO): console:

2019-08-15T18:27:33.574Z,1565893653.574 [ESPComponent](INFO): console:Loading kernel modules
2019-08-15T18:27:33.982Z,1565893653.982 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-08-15T18:27:34.382Z,1565893654.382 [ESPComponent](INFO): console:
mount: /dev/mmcblk0p2 already mounted or /ca

2019-08-15T18:27:34.794Z,1565893654.794 [ESPComponent](INFO): console:Starting hotpls dispatcher udevd
2019-08-15T18:27:35.191Z,1565893655.191 [ESPComponent](INFO): console:
Set system clock to:  Thu Aug 15 14:25:28 EDT 2019
2019-08-15T18:27:35.594Z,1565893655.594 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-08-15T18:27:36.207Z,1565893656.207 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-08-15T18:27:36.606Z,1565893656.606 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-08-15T18:27:37.013Z,1565893657.013 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-08-15T18:27:37.415Z,1565893657.415 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-08-15T18:27:37.824Z,1565893657.824 [ESPComponent](INFO): console:
Starting portmap...
2019-08-15T18:27:38.222Z,1565893658.222 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-08-15T18:27:38.627Z,1565893658.627 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2019-08-15T18:27:39.034Z,1565893659.034 [ESPComponent](INFO): console:
Network unavailable:  Local time is Thu Aug 15 14:25:30 EDT 2019
2019-08-15T18:27:39.435Z,1565893659.435 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-08-15T18:27:39.843Z,1565893659.843 [ESPComponent](INFO): console:
Starting thttpd...
2019-08-15T18:27:40.242Z,1565893660.242 [ESPComponent](INFO): console:
Sending discover...
2019-08-15T18:27:40.646Z,1565893660.646 [ESPComponent](IMPORTANT): ESP has connected as client
2019-08-15T18:27:41.459Z,1565893661.459 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4
2019-08-15T18:27:41.460Z,1565893661.460 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-08-15T18:27:41.460Z,1565893661.460 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2019-08-15T18:27:41.543Z,1565893661.543 [esp_kiss:SampleESP:sample:TriggerESP] Stopped
2019-08-15T18:27:41.543Z,1565893661.543 [esp_kiss:SampleESP:sample:F] Running Loop=1
2019-08-15T18:27:41.923Z,1565893661.923 [esp_kiss:SampleESP:sample:F](IMPORTANT): ESP sampling at 3.000000 m inwater with 0.049020 ug/l chlorophyll fluorescence.
2019-08-15T18:27:41.923Z,1565893661.923 [esp_kiss:SampleESP:sample:F] Stopped
2019-08-15T18:27:41.923Z,1565893661.923 [esp_kiss:SampleESP:sample:WaitForESP] Running Loop=1
2019-08-15T18:27:42.335Z,1565893662.335 [esp_kiss:SampleESP:sample:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-08-15T18:27:42.666Z,1565893662.666 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2019-08-15T18:27:43.072Z,1565893663.072 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-08-15T18:27:44.686Z,1565893664.686 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2019-08-15T18:28:23.150Z,1565893703.150 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@59,archiveHiBiomass_bac)
2019-08-15T18:28:24.770Z,1565893704.770 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@100.0)
2019-08-15T18:28:25.574Z,1565893705.574 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@100.0)
2019-08-15T18:28:28.545Z,1565893708.545 [Radio_Surface](INFO): Powering up
2019-08-15T18:28:34.169Z,1565893714.169 [DataOverHttps](INFO): Radio surface powered ON.
2019-08-15T18:28:34.606Z,1565893714.606 [Radio_Surface](INFO): Powering down
2019-08-15T18:28:43.493Z,1565893723.493 [Radio_Surface](INFO): Powering up
2019-08-15T18:28:49.553Z,1565893729.553 [Radio_Surface](INFO): Powering down
2019-08-15T18:28:56.825Z,1565893736.825 [Radio_Surface](INFO): Powering up
2019-08-15T18:29:02.886Z,1565893742.886 [Radio_Surface](INFO): Powering down
2019-08-15T18:29:04.469Z,1565893744.469 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:29:04.873Z,1565893744.873 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-15T18:29:10.561Z,1565893750.561 [Radio_Surface](INFO): Powering up
2019-08-15T18:29:16.185Z,1565893756.185 [DataOverHttps](INFO): Radio surface powered ON.
2019-08-15T18:29:16.621Z,1565893756.621 [Radio_Surface](INFO): Powering down
2019-08-15T18:29:32.172Z,1565893772.172 [CTD_Seabird](ERROR): Failed to parse device response: 4,0.01685,0.00
2019-08-15T18:29:46.485Z,1565893786.485 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:29:46.889Z,1565893786.889 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-15T18:29:55.777Z,1565893795.777 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.203568
2019-08-15T18:30:41.057Z,1565893841.057 [Radio_Surface](INFO): Powering up
2019-08-15T18:30:46.325Z,1565893846.325 [DataOverHttps](INFO): Radio surface powered ON.
2019-08-15T18:30:47.117Z,1565893847.117 [Radio_Surface](INFO): Powering down
2019-08-15T18:30:58.028Z,1565893858.028 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2019-08-15T18:30:58.426Z,1565893858.426 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2019-08-15T18:31:16.625Z,1565893876.625 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:31:17.029Z,1565893877.029 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-15T18:33:09.761Z,1565893989.761 [Radio_Surface](INFO): Powering up
2019-08-15T18:33:14.082Z,1565893994.082 [CTD_Seabird](ERROR): Failed to parse device response: 4,0.01676,0.00
2019-08-15T18:33:15.053Z,1565893995.053 [DataOverHttps](INFO): Radio surface powered ON.
2019-08-15T18:33:45.353Z,1565894025.353 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:34:16.063Z,1565894056.063 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:34:25.317Z,1565894065.317 [Radio_Surface](INFO): Powering down
2019-08-15T18:34:46.765Z,1565894086.765 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:34:47.169Z,1565894087.169 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-15T18:38:12.190Z,1565894292.190 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:38:12.190Z,1565894292.190 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:38:12.190Z,1565894292.190 [esp_kiss](IMPORTANT): Priority 0: esp_kiss:A.AbortSample
2019-08-15T18:38:12.191Z,1565894292.191 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 1: esp_kiss:StandardEnvelopes:A.AltitudeEnvelope
2019-08-15T18:38:12.191Z,1565894292.191 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 2: esp_kiss:StandardEnvelopes:B.DepthEnvelope
2019-08-15T18:38:12.191Z,1565894292.191 [esp_kiss:StandardEnvelopes](IMPORTANT): Priority 3: esp_kiss:StandardEnvelopes:C.OffshoreEnvelope
2019-08-15T18:38:12.192Z,1565894292.192 [esp_kiss](IMPORTANT): Priority 4: esp_kiss:I
2019-08-15T18:38:12.192Z,1565894292.192 [esp_kiss:SampleESP:sample](IMPORTANT): Priority 5: esp_kiss:SampleESP:sample:WaitForESP
2019-08-15T18:38:12.194Z,1565894292.194 [esp_kiss:Science](IMPORTANT): Priority 6: esp_kiss:Science:A
2019-08-15T18:38:12.194Z,1565894292.194 [esp_kiss:Science](IMPORTANT): Priority 7: esp_kiss:Science:C
2019-08-15T18:38:12.195Z,1565894292.195 [esp_kiss:Science](IMPORTANT): Priority 8: esp_kiss:Science:D
2019-08-15T18:38:12.195Z,1565894292.195 [esp_kiss:Science](IMPORTANT): Priority 9: esp_kiss:Science:G
2019-08-15T18:38:12.195Z,1565894292.195 [esp_kiss:SampleAtTargetDepth](IMPORTANT): Priority 10: esp_kiss:SampleAtTargetDepth:A.SetSpeed
2019-08-15T18:38:12.196Z,1565894292.196 [esp_kiss:SampleAtTargetDepth](IMPORTANT): Priority 11: esp_kiss:SampleAtTargetDepth:B.Pitch
2019-08-15T18:40:01.207Z,1565894401.207 [VerticalControl](CRITICAL): Failure to ascend, stopping mission after 840.371460 seconds, depthRate=0.112946 m/s, pitch=-2.315562 deg.
2019-08-15T18:40:01.214Z,1565894401.214 [CommandLine](FAULT): Scheduling is paused
2019-08-15T18:40:01.214Z,1565894401.214 [CBIT](INFO): Critical error at 20190815T184001
2019-08-15T18:40:01.214Z,1565894401.214 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-08-15T18:40:01.604Z,1565894401.604 [MissionManager](INFO): MissionManager is completed.
2019-08-15T18:40:01.604Z,1565894401.604 [MissionManager](INFO): Uninitializing Mission esp_kiss
2019-08-15T18:40:01.604Z,1565894401.604 [esp_kiss] Stopped
2019-08-15T18:40:01.604Z,1565894401.604 [esp_kiss](DEBUG): Aggregate::uninitialize esp_kiss
2019-08-15T18:40:01.604Z,1565894401.604 [esp_kiss:A.AbortSample] Stopped
2019-08-15T18:40:01.604Z,1565894401.604 [esp_kiss:A.AbortSample](INFO): Uninitializing AbortSample.
2019-08-15T18:40:01.604Z,1565894401.604 [esp_kiss:StandardEnvelopes] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes](DEBUG): Aggregate::uninitialize esp_kiss:StandardEnvelopes
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:B.DepthEnvelope] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:I] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:SampleESP] Stopped
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:SampleESP](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP
2019-08-15T18:40:01.605Z,1565894401.605 [esp_kiss:SampleESP:sample] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:SampleESP:sample](DEBUG): Aggregate::uninitialize esp_kiss:SampleESP:sample
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:SampleESP:sample:WaitForESP] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science](DEBUG): Aggregate::uninitialize esp_kiss:Science
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science:A] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science:C] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science:D] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:Science:G] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:SampleAtTargetDepth] Stopped
2019-08-15T18:40:01.606Z,1565894401.606 [esp_kiss:SampleAtTargetDepth](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:A.SetSpeed] Stopped
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:B.Pitch] Stopped
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples] Stopped
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1] Stopped
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B] Stopped
2019-08-15T18:40:01.607Z,1565894401.607 [esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B](DEBUG): Aggregate::uninitialize esp_kiss:SampleAtTargetDepth:GrabSamples:Sample1:B
2019-08-15T18:40:01.661Z,1565894401.661 [WetLabsBB2FL](INFO): Powering down
2019-08-15T18:40:01.934Z,1565894401.934 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-08-15T18:40:01.934Z,1565894401.934 [ESPComponent](IMPORTANT): [sample #1] Stop sampling requested.
2019-08-15T18:40:01.980Z,1565894401.980 [MissionManager](IMPORTANT): Started mission Default
2019-08-15T18:40:01.980Z,1565894401.980 [Default] Running Loop=1
2019-08-15T18:40:01.980Z,1565894401.980 [Default](DEBUG): Aggregate::initialize Default
2019-08-15T18:40:01.980Z,1565894401.980 [Default:B.GoToSurface] Running Loop=1
2019-08-15T18:40:01.980Z,1565894401.980 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-15T18:40:01.981Z,1565894401.981 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-15T18:40:01.981Z,1565894401.981 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-15T18:40:01.982Z,1565894401.981 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-15T18:40:01.982Z,1565894401.982 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-15T18:40:01.982Z,1565894401.982 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-15T18:40:01.983Z,1565894401.983 [Default:A.Wait] Running Loop=1
2019-08-15T18:40:01.983Z,1565894401.983 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:40:02.338Z,1565894402.338 [Aanderaa_O2](INFO): Powering down
2019-08-15T18:40:02.339Z,1565894402.339 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.pauseFiltering
2019-08-15T18:40:02.383Z,1565894402.383 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -13.00 mm (1 active estimators).
2019-08-15T18:40:02.677Z,1565894402.677 [Radio_Surface](INFO): Powering up
2019-08-15T18:40:03.105Z,1565894403.105 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2019-08-15T18:40:03.105Z,1565894403.105 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2019-08-15T18:40:03.105Z,1565894403.105 [ThrusterServo] Communications Fault, FailCount= 1
2019-08-15T18:40:03.105Z,1565894403.105 [ThrusterServo](ERROR): Communications Fault
2019-08-15T18:40:03.109Z,1565894403.109 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2019-08-15T18:40:03.346Z,1565894403.346 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-15T18:40:03.346Z,1565894403.346 [ThrusterServo](INFO): Powering down
2019-08-15T18:40:04.090Z,1565894404.090 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-15T18:40:04.210Z,1565894404.210 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-15T18:40:04.213Z,1565894404.213 [CBIT](INFO): Clearing failed state for component ThrusterServo
2019-08-15T18:40:04.214Z,1565894404.214 [ThrusterServo] No Fault, FailCount= 1
2019-08-15T18:40:07.953Z,1565894407.953 [DataOverHttps](INFO): Radio surface powered ON.
2019-08-15T18:40:07.994Z,1565894407.994 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@246.61)
2019-08-15T18:40:07.995Z,1565894407.995 [ESPComponent](DEBUG): Writing sampleVolume=246.610001
2019-08-15T18:40:08.399Z,1565894408.399 [ESPComponent](IMPORTANT): In S_PAUSED received result: 246.61

2019-08-15T18:40:08.803Z,1565894408.803 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@246.61)
2019-08-15T18:40:11.226Z,1565894411.226 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@59,archiveHiBiomass_bac)
2019-08-15T18:40:15.309Z,1565894415.309 [Default:A.Wait](INFO): Done Waiting.
2019-08-15T18:40:15.309Z,1565894415.309 [Default:A.Wait] Stopped
2019-08-15T18:40:15.309Z,1565894415.309 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:40:37.656Z,1565894437.656 [CommandLine](IMPORTANT): got command maintain control SpeedControl.propOmegaAction 0.000000 revolution_per_minute
2019-08-15T18:40:37.666Z,1565894437.666 [ComponentRegistry](DEBUG): SyncComponent "Maintain_SpeedControl.propOmegaAction" handled in the control thread.
2019-08-15T18:40:37.677Z,1565894437.677 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_SpeedControl.propOmegaAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-08-15T18:40:38.253Z,1565894438.253 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:40:41.358Z,1565894441.358 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:40:41.359Z,1565894441.359 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:40:41.359Z,1565894441.359 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-08-15T18:40:49.154Z,1565894449.155 [CommandLine](IMPORTANT): got command maintain clear
2019-08-15T18:40:49.310Z,1565894449.310 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-08-15T18:40:49.680Z,1565894449.680 [Default:CheckIn] Running Loop=1
2019-08-15T18:40:49.681Z,1565894449.681 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-15T18:40:49.681Z,1565894449.681 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-15T18:40:51.240Z,1565894451.240 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-08-15T18:40:51.240Z,1565894451.240 [NAL9602] Data Fault, FailCount= 2
2019-08-15T18:40:51.240Z,1565894451.240 [NAL9602](ERROR): Data Fault
2019-08-15T18:40:51.449Z,1565894451.449 [CBIT](ERROR): Data Fault in component: NAL9602
2019-08-15T18:40:51.640Z,1565894451.640 [NAL9602](INFO): Powering down
2019-08-15T18:40:52.754Z,1565894452.754 [CBIT](INFO): Clearing failed state for component NAL9602
2019-08-15T18:40:52.754Z,1565894452.754 [NAL9602] No Fault, FailCount= 2
2019-08-15T18:40:55.978Z,1565894455.978 [CommandLine](IMPORTANT): got command show stack
2019-08-15T18:40:55.978Z,1565894455.978 [CommandLine](IMPORTANT): Behavior Stack:

2019-08-15T18:40:55.978Z,1565894455.978 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-08-15T18:40:55.978Z,1565894455.978 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS
2019-08-15T18:41:08.959Z,1565894468.959 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:41:21.730Z,1565894481.730 [NAL9602](INFO): Powering up NAL9602
2019-08-15T18:41:32.640Z,1565894492.640 [NAL9602](INFO): NAL9602 initialized
2019-08-15T18:41:33.469Z,1565894493.469 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:41:39.661Z,1565894499.661 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:42:10.365Z,1565894530.365 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:42:41.069Z,1565894561.069 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:43:11.773Z,1565894591.773 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:43:42.477Z,1565894622.477 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-08-15T18:43:48.277Z,1565894628.277 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003263
2019-08-15T18:45:50.030Z,1565894750.030 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-08-15T18:40:49.7Z
2019-08-15T18:45:50.030Z,1565894750.030 [Default:CheckIn:Read_GPS] Stopped
2019-08-15T18:45:50.030Z,1565894750.030 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-15T18:45:55.117Z,1565894755.117 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20190815T181419/Courier0013.lzma
2019-08-15T18:45:56.326Z,1565894756.326 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0013.lzma.bak
2019-08-15T18:45:56.327Z,1565894756.327 [DataOverHttps](INFO): SBD MOMSN=11577535
2019-08-15T18:46:07.603Z,1565894767.603 [DataOverHttps](INFO): Sending 1903 bytes from file Logs/20190815T181419/Express0014.lzma
2019-08-15T18:46:08.810Z,1565894768.810 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0014.lzma.bak
2019-08-15T18:46:08.811Z,1565894768.811 [DataOverHttps](INFO): SBD MOMSN=11577538
2019-08-15T18:46:09.879Z,1565894769.879 [Default:CheckIn:Read_Iridium] Stopped
2019-08-15T18:46:09.880Z,1565894769.880 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-15T18:46:09.880Z,1565894769.880 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:46:35.700Z,1565894795.700 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-15T18:47:06.426Z,1565894826.426 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-15T18:51:10.531Z,1565895070.531 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-15T18:51:10.531Z,1565895070.531 [Default:CheckIn:C.Wait] Stopped
2019-08-15T18:51:10.531Z,1565895070.531 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:51:10.532Z,1565895070.532 [Default:CheckIn:D] Running Loop=1
2019-08-15T18:51:10.940Z,1565895070.940 [Default:CheckIn:D] Stopped
2019-08-15T18:51:10.940Z,1565895070.940 [Default:CheckIn:E] Running Loop=1
2019-08-15T18:51:11.339Z,1565895071.339 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.149324 min 
2019-08-15T18:51:11.339Z,1565895071.339 [Default:CheckIn:E] Stopped
2019-08-15T18:51:11.339Z,1565895071.339 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn] Stopped
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn](INFO): Running loop #2
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn] Running Loop=2
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-15T18:51:11.340Z,1565895071.340 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-15T18:51:12.945Z,1565895072.945 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:51:44.036Z,1565895104.036 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-08-15T18:51:44.113Z,1565895104.113 [NAL9602](FAULT): received: 
+CSQ:0

OK119, 2, 0, 0, 0

OK
2019-08-15T18:51:44.113Z,1565895104.113 [NAL9602] Data Fault, FailCount= 3
2019-08-15T18:51:44.113Z,1565895104.113 [NAL9602](ERROR): Data Fault
2019-08-15T18:51:44.154Z,1565895104.154 [CBIT](ERROR): Data Fault in component: NAL9602
2019-08-15T18:51:44.444Z,1565895104.444 [NAL9602](INFO): Powering down
2019-08-15T18:51:45.283Z,1565895105.283 [CBIT](INFO): Clearing failed state for component NAL9602
2019-08-15T18:51:45.284Z,1565895105.284 [NAL9602] No Fault, FailCount= 3
2019-08-15T18:52:14.746Z,1565895134.746 [NAL9602](INFO): Powering up NAL9602
2019-08-15T18:52:25.650Z,1565895145.650 [NAL9602](INFO): NAL9602 initialized
2019-08-15T18:52:26.456Z,1565895146.456 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-08-15T18:52:26.456Z,1565895146.456 [NAL9602] Data Fault, FailCount= 4
2019-08-15T18:52:26.456Z,1565895146.456 [NAL9602](ERROR): Data Fault
2019-08-15T18:52:26.521Z,1565895146.521 [CBIT](ERROR): Data Fault in component: NAL9602
2019-08-15T18:52:26.866Z,1565895146.866 [NAL9602](INFO): Powering down
2019-08-15T18:52:27.704Z,1565895147.704 [CBIT](INFO): Clearing failed state for component NAL9602
2019-08-15T18:52:27.704Z,1565895147.704 [NAL9602] No Fault, FailCount= 4
2019-08-15T18:52:57.174Z,1565895177.174 [NAL9602](INFO): Powering up NAL9602
2019-08-15T18:52:59.578Z,1565895179.578 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@59,archiveHiBiomass_bac)
2019-08-15T18:53:08.072Z,1565895188.072 [NAL9602](INFO): NAL9602 initialized
2019-08-15T18:53:08.897Z,1565895188.897 [NAL9602](DEBUG): Fix Requested
2019-08-15T18:53:26.239Z,1565895206.239 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr' /LRAUV/ESPlogs &
2019-08-15T18:53:26.257Z,1565895206.257 [ESPComponent](INFO): closing pipe.
2019-08-15T18:53:26.642Z,1565895206.642 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2019-08-15T18:56:11.538Z,1565895371.538 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-08-15T18:51:11.3Z
2019-08-15T18:56:11.538Z,1565895371.538 [Default:CheckIn:Read_GPS] Stopped
2019-08-15T18:56:11.538Z,1565895371.538 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-15T18:56:15.570Z,1565895375.570 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-08-15T18:56:16.904Z,1565895376.904 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190815T181419/Courier0016.lzma
2019-08-15T18:56:17.710Z,1565895377.710 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Courier0016.lzma.bak
2019-08-15T18:56:17.711Z,1565895377.711 [DataOverHttps](INFO): SBD MOMSN=11577624
2019-08-15T18:56:28.957Z,1565895388.957 [DataOverHttps](INFO): Sending 454 bytes from file Logs/20190815T181419/Express0017.lzma
2019-08-15T18:56:29.762Z,1565895389.762 [DataOverHttps](INFO): Moved sent file to Logs/20190815T181419/Express0017.lzma.bak
2019-08-15T18:56:29.763Z,1565895389.763 [DataOverHttps](INFO): SBD MOMSN=11577626
2019-08-15T18:56:30.527Z,1565895390.527 [Default:CheckIn:Read_Iridium] Stopped
2019-08-15T18:56:30.527Z,1565895390.527 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-15T18:56:30.527Z,1565895390.527 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-15T18:56:46.262Z,1565895406.262 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-15T18:57:06.114Z,1565895426.114 [DataOverHttps](IMPORTANT): SBD MTMSN=20190815T185501
2019-08-15T18:57:11.120Z,1565895431.120 [DataOverHttps](INFO): Received command:restart app
2019-08-15T18:57:11.182Z,1565895431.182 [CommandLine](IMPORTANT): got command restart application
2019-08-15T18:57:12.185Z,1565895432.185 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:12.185Z,1565895432.185 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.321Z,1565895432.321 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-08-15T18:57:12.321Z,1565895432.321 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.323Z,1565895432.323 [CommandLine](INFO): Join timeout helper Thread ID is 1459
2019-08-15T18:57:12.324Z,1565895432.324 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-08-15T18:57:12.324Z,1565895432.324 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.324Z,1565895432.324 [NavChartDb](INFO): Join timeout helper Thread ID is 1460
2019-08-15T18:57:12.405Z,1565895432.405 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:12.405Z,1565895432.405 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.425Z,1565895432.425 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-08-15T18:57:12.425Z,1565895432.425 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.425Z,1565895432.425 [Radio_Surface](INFO): Join timeout helper Thread ID is 1461
2019-08-15T18:57:12.677Z,1565895432.677 [Radio_Surface](INFO): Powering down
2019-08-15T18:57:12.678Z,1565895432.678 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:12.678Z,1565895432.678 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.693Z,1565895432.693 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-08-15T18:57:12.693Z,1565895432.693 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.693Z,1565895432.693 [DataOverHttps](INFO): Join timeout helper Thread ID is 1462
2019-08-15T18:57:12.741Z,1565895432.741 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:12.741Z,1565895432.741 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.753Z,1565895432.753 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-08-15T18:57:12.753Z,1565895432.753 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:12.753Z,1565895432.753 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1463
2019-08-15T18:57:13.177Z,1565895433.177 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:13.177Z,1565895433.177 [WetLabsBB2FL](INFO): Powering down
2019-08-15T18:57:13.178Z,1565895433.178 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:13.186Z,1565895433.186 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-08-15T18:57:13.186Z,1565895433.186 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:13.186Z,1565895433.186 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1464
2019-08-15T18:57:14.113Z,1565895434.113 [CTD_Seabird](INFO): Powering down
2019-08-15T18:57:14.129Z,1565895434.129 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:14.129Z,1565895434.129 [CTD_Seabird](INFO): Powering down
2019-08-15T18:57:14.141Z,1565895434.141 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.147Z,1565895434.147 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-08-15T18:57:14.147Z,1565895434.147 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.147Z,1565895434.147 [logger](INFO): Join timeout helper Thread ID is 1465
2019-08-15T18:57:14.201Z,1565895434.201 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:14.201Z,1565895434.201 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.206Z,1565895434.206 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-08-15T18:57:14.206Z,1565895434.206 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.206Z,1565895434.206 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-08-15T18:57:14.206Z,1565895434.206 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.206Z,1565895434.206 [controlThread](INFO): Join timeout helper Thread ID is 1466
2019-08-15T18:57:14.525Z,1565895434.525 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-15T18:57:14.525Z,1565895434.525 [controlThread](DEBUG): Uninitializing ControlThread
2019-08-15T18:57:14.526Z,1565895434.526 [Aanderaa_O2](INFO): Powering down
2019-08-15T18:57:14.529Z,1565895434.529 [AHRS_M2](INFO): Powering down
2019-08-15T18:57:14.530Z,1565895434.530 [NAL9602](INFO): Powering down
2019-08-15T18:57:14.531Z,1565895434.531 [DAT](INFO): Powering down
2019-08-15T18:57:14.532Z,1565895434.532 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-08-15T18:57:14.532Z,1565895434.532 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-08-15T18:57:14.533Z,1565895434.533 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-08-15T18:57:14.533Z,1565895434.533 [MissionManager](INFO): Uninitializing Mission Default
2019-08-15T18:57:14.533Z,1565895434.533 [Default] Stopped
2019-08-15T18:57:14.533Z,1565895434.533 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-15T18:57:14.534Z,1565895434.534 [Default:B.GoToSurface] Stopped
2019-08-15T18:57:14.534Z,1565895434.534 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-15T18:57:14.534Z,1565895434.534 [Default:CheckIn] Stopped
2019-08-15T18:57:14.534Z,1565895434.534 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-15T18:57:14.534Z,1565895434.534 [Default:CheckIn:C.Wait] Stopped
2019-08-15T18:57:14.534Z,1565895434.534 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-15T18:57:14.536Z,1565895434.536 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-08-15T18:57:14.536Z,1565895434.536 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-08-15T18:57:14.537Z,1565895434.537 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-08-15T18:57:14.537Z,1565895434.537 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-08-15T18:57:14.537Z,1565895434.537 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-15T18:57:14.537Z,1565895434.537 [BuoyancyServo](INFO): Powering down
2019-08-15T18:57:14.549Z,1565895434.549 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-08-15T18:57:14.549Z,1565895434.549 [ElevatorServo](INFO): Powering down
2019-08-15T18:57:14.550Z,1565895434.550 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-08-15T18:57:14.550Z,1565895434.550 [MassServo](INFO): Powering down
2019-08-15T18:57:14.551Z,1565895434.551 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-15T18:57:14.551Z,1565895434.551 [RudderServo](INFO): Powering down
2019-08-15T18:57:14.551Z,1565895434.551 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-15T18:57:14.551Z,1565895434.551 [ThrusterServo](INFO): Powering down
2019-08-15T18:57:14.552Z,1565895434.552 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-08-15T18:57:14.552Z,1565895434.552 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-08-15T18:57:14.553Z,1565895434.553 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-08-15T18:57:14.553Z,1565895434.553 [CBIT](DEBUG): Powering off loads.
2019-08-15T18:57:14.565Z,1565895434.565 [CBIT](DEBUG): Disabling WDT.
2019-08-15T18:57:14.577Z,1565895434.577 [CBIT](DEBUG): Opening all GF detection circuits.
2019-08-15T18:57:14.577Z,1565895434.577 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.614Z,1565895434.614 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.633Z,1565895434.633 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.696Z,1565895434.696 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.701Z,1565895434.701 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.750Z,1565895434.750 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-15T18:57:14.814Z,1565895434.814 [logger ThreadHandler](INFO): Thread cancelled.