2019-05-18T20:27:27.343Z,1558211247.343 [Supervisor](DEBUG): Initializing supervisor.
2019-05-18T20:27:27.346Z,1558211247.346 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-18T20:27:27.347Z,1558211247.347 [SyncHandler](INFO): Protected caller Thread ID is 1265
2019-05-18T20:27:27.348Z,1558211247.348 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-18T20:27:27.349Z,1558211247.349 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-18T20:27:27.349Z,1558211247.349 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1266
2019-05-18T20:27:27.352Z,1558211247.352 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-18T20:27:27.364Z,1558211247.364 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-18T20:27:27.365Z,1558211247.365 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-18T20:27:27.366Z,1558211247.366 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1267
2019-05-18T20:27:27.367Z,1558211247.367 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-18T20:27:27.368Z,1558211247.368 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-18T20:27:27.368Z,1558211247.368 [logger ThreadHandler](INFO): Protected caller Thread ID is 1268
2019-05-18T20:27:27.370Z,1558211247.370 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-18T20:27:27.370Z,1558211247.370 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-18T20:27:27.372Z,1558211247.372 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-18T20:27:27.573Z,1558211247.573 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-18T20:27:27.573Z,1558211247.573 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-18T20:27:27.653Z,1558211247.653 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-18T20:27:28.088Z,1558211248.088 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-18T20:27:28.089Z,1558211248.089 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-18T20:27:28.424Z,1558211248.424 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-18T20:27:28.425Z,1558211248.425 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-18T20:27:28.521Z,1558211248.521 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-18T20:27:28.522Z,1558211248.522 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-18T20:27:28.820Z,1558211248.820 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-18T20:27:28.821Z,1558211248.821 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-18T20:27:29.016Z,1558211249.016 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-18T20:27:29.016Z,1558211249.016 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-18T20:27:29.469Z,1558211249.469 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-18T20:27:29.469Z,1558211249.469 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-18T20:27:29.574Z,1558211249.574 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-18T20:27:29.575Z,1558211249.575 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-18T20:27:29.675Z,1558211249.675 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-18T20:27:29.675Z,1558211249.675 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-18T20:27:30.251Z,1558211250.251 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-18T20:27:30.252Z,1558211250.252 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-18T20:27:30.639Z,1558211250.639 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-18T20:27:30.639Z,1558211250.639 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-18T20:27:30.834Z,1558211250.834 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-18T20:27:30.835Z,1558211250.835 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-18T20:27:30.979Z,1558211250.979 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-18T20:27:30.980Z,1558211250.980 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-18T20:27:31.129Z,1558211251.129 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-18T20:27:31.131Z,1558211251.131 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2019-05-18T20:27:31.132Z,1558211251.132 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2019-05-18T20:27:31.222Z,1558211251.222 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2019-05-18T20:27:31.307Z,1558211251.307 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2019-05-18T20:27:31.409Z,1558211251.409 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2019-05-18T20:27:31.491Z,1558211251.491 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2019-05-18T20:27:31.586Z,1558211251.586 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2019-05-18T20:27:31.685Z,1558211251.685 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2019-05-18T20:27:31.934Z,1558211251.934 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2019-05-18T20:27:32.061Z,1558211252.061 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2019-05-18T20:27:32.232Z,1558211252.232 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2019-05-18T20:27:32.692Z,1558211252.692 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2019-05-18T20:27:32.964Z,1558211252.964 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2019-05-18T20:27:33.463Z,1558211253.463 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-18T20:27:33.465Z,1558211253.465 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2019-05-18T20:27:33.465Z,1558211253.465 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-18T20:27:33.479Z,1558211253.479 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-18T20:27:33.577Z,1558211253.577 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-18T20:27:33.885Z,1558211253.885 [VerticalControl] Loaded
2019-05-18T20:27:33.885Z,1558211253.885 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-18T20:27:33.886Z,1558211253.886 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-18T20:27:33.955Z,1558211253.955 [HorizontalControl] Loaded
2019-05-18T20:27:33.955Z,1558211253.955 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-18T20:27:33.956Z,1558211253.956 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-18T20:27:33.961Z,1558211253.961 [SpeedControl] Loaded
2019-05-18T20:27:33.962Z,1558211253.962 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-18T20:27:33.962Z,1558211253.962 [LoopControl](DEBUG): Construct LoopControl.
2019-05-18T20:27:33.963Z,1558211253.963 [LoopControl] Loaded
2019-05-18T20:27:33.963Z,1558211253.963 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-18T20:27:33.964Z,1558211253.964 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-18T20:27:33.964Z,1558211253.964 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-18T20:27:33.977Z,1558211253.977 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-18T20:27:33.978Z,1558211253.978 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-18T20:27:34.075Z,1558211254.075 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-18T20:27:34.076Z,1558211254.076 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-18T20:27:34.203Z,1558211254.203 [BuoyancyServo] Loaded
2019-05-18T20:27:34.203Z,1558211254.203 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-18T20:27:34.214Z,1558211254.214 [ElevatorServo] Loaded
2019-05-18T20:27:34.215Z,1558211254.215 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-18T20:27:34.226Z,1558211254.226 [MassServo] Loaded
2019-05-18T20:27:34.226Z,1558211254.226 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-18T20:27:34.237Z,1558211254.237 [RudderServo] Loaded
2019-05-18T20:27:34.237Z,1558211254.237 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-18T20:27:34.248Z,1558211254.248 [ThrusterServo] Loaded
2019-05-18T20:27:34.249Z,1558211254.249 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-18T20:27:34.249Z,1558211254.249 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-18T20:27:34.250Z,1558211254.250 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-18T20:27:34.357Z,1558211254.357 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-18T20:27:34.357Z,1558211254.357 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-18T20:27:34.377Z,1558211254.377 [NavChart] Loaded
2019-05-18T20:27:34.378Z,1558211254.378 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-18T20:27:34.382Z,1558211254.382 [UniversalFixResidualReporter] Loaded
2019-05-18T20:27:34.382Z,1558211254.382 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-18T20:27:34.382Z,1558211254.382 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-18T20:27:34.383Z,1558211254.383 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-18T20:27:34.452Z,1558211254.452 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-18T20:27:34.453Z,1558211254.453 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-18T20:27:34.779Z,1558211254.779 [DataOverHttps] Loaded
2019-05-18T20:27:34.779Z,1558211254.779 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-18T20:27:34.781Z,1558211254.781 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087B4E0
2019-05-18T20:27:34.781Z,1558211254.781 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1350
2019-05-18T20:27:34.794Z,1558211254.794 [Depth_Keller] Loaded
2019-05-18T20:27:34.795Z,1558211254.795 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-18T20:27:34.891Z,1558211254.891 [NAL9602] Loaded
2019-05-18T20:27:34.892Z,1558211254.892 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-18T20:27:34.908Z,1558211254.908 [Onboard] Loaded
2019-05-18T20:27:34.908Z,1558211254.908 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-18T20:27:34.912Z,1558211254.912 [Radio_Surface] Loaded
2019-05-18T20:27:34.912Z,1558211254.912 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-18T20:27:34.913Z,1558211254.913 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AB4E0
2019-05-18T20:27:34.913Z,1558211254.913 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1351
2019-05-18T20:27:35.042Z,1558211255.042 [DAT] Loaded
2019-05-18T20:27:35.042Z,1558211255.042 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-05-18T20:27:35.043Z,1558211255.043 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-18T20:27:35.044Z,1558211255.044 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-18T20:27:35.084Z,1558211255.084 [DepthRateCalculator] Loaded
2019-05-18T20:27:35.084Z,1558211255.084 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-18T20:27:35.090Z,1558211255.090 [PitchRateCalculator] Loaded
2019-05-18T20:27:35.090Z,1558211255.090 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-18T20:27:35.102Z,1558211255.102 [SpeedCalculator] Loaded
2019-05-18T20:27:35.102Z,1558211255.102 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-18T20:27:35.123Z,1558211255.123 [TempGradientCalculator] Loaded
2019-05-18T20:27:35.124Z,1558211255.124 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-18T20:27:35.129Z,1558211255.129 [YawRateCalculator] Loaded
2019-05-18T20:27:35.129Z,1558211255.129 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-18T20:27:35.159Z,1558211255.159 [ElevatorOffsetCalculator] Loaded
2019-05-18T20:27:35.159Z,1558211255.159 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-18T20:27:35.159Z,1558211255.159 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-18T20:27:35.160Z,1558211255.160 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-18T20:27:35.418Z,1558211255.418 [CTD_NeilBrown] Loaded
2019-05-18T20:27:35.418Z,1558211255.418 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-18T20:27:35.419Z,1558211255.419 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409AD4E0
2019-05-18T20:27:35.420Z,1558211255.420 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1352
2019-05-18T20:27:35.450Z,1558211255.450 [ESPComponent] Loaded
2019-05-18T20:27:35.450Z,1558211255.450 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-05-18T20:27:35.465Z,1558211255.465 [PAR_Licor] Loaded
2019-05-18T20:27:35.465Z,1558211255.465 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-05-18T20:27:35.513Z,1558211255.513 [WetLabsBB2FL] Loaded
2019-05-18T20:27:35.514Z,1558211255.514 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-05-18T20:27:35.515Z,1558211255.515 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DD4E0
2019-05-18T20:27:35.515Z,1558211255.515 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1353
2019-05-18T20:27:35.516Z,1558211255.516 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-18T20:27:35.516Z,1558211255.516 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-18T20:27:35.547Z,1558211255.547 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-18T20:27:35.547Z,1558211255.547 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-18T20:27:35.841Z,1558211255.841 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-18T20:27:35.841Z,1558211255.841 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-18T20:27:35.974Z,1558211255.974 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-18T20:27:35.985Z,1558211255.985 [SBIT] Loaded
2019-05-18T20:27:35.985Z,1558211255.985 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-18T20:27:35.986Z,1558211255.986 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-18T20:27:35.999Z,1558211255.999 [IBIT] Loaded
2019-05-18T20:27:35.999Z,1558211255.999 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-18T20:27:36.003Z,1558211256.003 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-18T20:27:36.391Z,1558211256.391 [CBIT] Loaded
2019-05-18T20:27:36.392Z,1558211256.392 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-18T20:27:36.392Z,1558211256.392 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-18T20:27:36.396Z,1558211256.396 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-18T20:27:36.397Z,1558211256.397 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-18T20:27:36.403Z,1558211256.403 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-18T20:27:36.405Z,1558211256.405 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADC4E0
2019-05-18T20:27:36.405Z,1558211256.405 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1354
2019-05-18T20:27:36.410Z,1558211256.410 [Supervisor](INFO): Main Thread ID is 802
2019-05-18T20:27:36.410Z,1558211256.410 [Supervisor](DEBUG): Running supervisor.
2019-05-18T20:27:36.411Z,1558211256.411 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1355
2019-05-18T20:27:36.413Z,1558211256.413 [controlThread ThreadHandler](INFO): Handler Thread ID is 1356
2019-05-18T20:27:36.414Z,1558211256.414 [controlThread](DEBUG): Initializing ControlThread
2019-05-18T20:27:36.414Z,1558211256.414 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-18T20:27:36.416Z,1558211256.416 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-18T20:27:36.417Z,1558211256.417 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-18T20:27:36.417Z,1558211256.417 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-18T20:27:36.419Z,1558211256.419 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-18T20:27:36.419Z,1558211256.419 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-18T20:27:36.422Z,1558211256.422 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-18T20:27:36.422Z,1558211256.422 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-18T20:27:36.422Z,1558211256.422 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-18T20:27:36.423Z,1558211256.423 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-18T20:27:36.423Z,1558211256.423 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-18T20:27:36.423Z,1558211256.423 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-18T20:27:36.425Z,1558211256.425 [SBIT](INFO): Initialize SBIT Component.
2019-05-18T20:27:36.425Z,1558211256.425 [SBIT](IMPORTANT): git: 2019-05-01-18-gebccc08
2019-05-18T20:27:36.426Z,1558211256.426 [SBIT](INFO): git hash: ebccc08b74c64e8c330b6ee85a06f50705035b59
2019-05-18T20:27:36.426Z,1558211256.426 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-18T20:27:36.427Z,1558211256.427 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
2019-05-18T20:27:36.428Z,1558211256.428 [SBIT](INFO): Beginning SBIT in 59.000000 seconds.
2019-05-18T20:27:36.429Z,1558211256.429 [IBIT](INFO): Initialize IBIT Component.
2019-05-18T20:27:36.430Z,1558211256.430 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-18T20:27:36.431Z,1558211256.431 [logger ThreadHandler](INFO): Handler Thread ID is 1357
2019-05-18T20:27:36.441Z,1558211256.441 [CBIT](DEBUG): Initialized mux pins.
2019-05-18T20:27:36.441Z,1558211256.441 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-18T20:27:36.449Z,1558211256.449 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1358
2019-05-18T20:27:36.450Z,1558211256.450 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-18T20:27:36.461Z,1558211256.461 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1359
2019-05-18T20:27:36.465Z,1558211256.465 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-18T20:27:36.465Z,1558211256.465 [CBIT](DEBUG): Initializing heartbeat.
2019-05-18T20:27:36.473Z,1558211256.473 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1360
2019-05-18T20:27:36.474Z,1558211256.474 [CTD_NeilBrown](INFO): Powering down
2019-05-18T20:27:36.501Z,1558211256.501 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1361
2019-05-18T20:27:36.502Z,1558211256.502 [WetLabsBB2FL](INFO): Powering down
2019-05-18T20:27:36.529Z,1558211256.529 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1362
2019-05-18T20:27:36.532Z,1558211256.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-18T20:27:36.533Z,1558211256.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-18T20:27:36.533Z,1558211256.533 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-18T20:27:36.533Z,1558211256.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-18T20:27:36.533Z,1558211256.533 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-18T20:27:36.533Z,1558211256.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-18T20:27:36.534Z,1558211256.534 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-18T20:27:36.534Z,1558211256.534 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-18T20:27:36.534Z,1558211256.534 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-18T20:27:36.534Z,1558211256.534 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-18T20:27:36.534Z,1558211256.534 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-18T20:27:36.535Z,1558211256.535 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-18T20:27:36.535Z,1558211256.535 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-18T20:27:36.535Z,1558211256.535 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-18T20:27:36.535Z,1558211256.535 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-18T20:27:36.535Z,1558211256.535 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-18T20:27:36.537Z,1558211256.537 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-18T20:27:36.537Z,1558211256.537 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-18T20:27:36.573Z,1558211256.573 [CBIT](DEBUG): Backplane powered.
2019-05-18T20:27:36.574Z,1558211256.574 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-18T20:27:36.583Z,1558211256.583 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-18T20:27:36.594Z,1558211256.594 [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-05-18T20:27:36.595Z,1558211256.595 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-18T20:27:36.667Z,1558211256.667 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-18T20:27:36.668Z,1558211256.668 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-18T20:27:36.686Z,1558211256.686 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-18T20:27:36.713Z,1558211256.713 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-18T20:27:36.715Z,1558211256.715 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-18T20:27:36.741Z,1558211256.741 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-18T20:27:36.744Z,1558211256.744 [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-05-18T20:27:36.748Z,1558211256.748 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-18T20:27:36.771Z,1558211256.771 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2019-05-18T20:27:36.801Z,1558211256.801 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-05-18T20:27:36.801Z,1558211256.801 [DAT](INFO): Powering up
2019-05-18T20:27:36.801Z,1558211256.801 [DAT](DEBUG): Initializing DAT.
2019-05-18T20:27:36.809Z,1558211256.809 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-05-18T20:27:36.865Z,1558211256.865 [Radio_Surface](INFO): Powering up
2019-05-18T20:27:36.943Z,1558211256.943 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-18T20:27:37.027Z,1558211257.027 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:37.033Z,1558211257.033 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-18T20:27:37.034Z,1558211257.034 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:37.045Z,1558211257.045 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-18T20:27:37.046Z,1558211257.046 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:37.053Z,1558211257.053 [MassServo](DEBUG): Initializing MassServo.
2019-05-18T20:27:37.054Z,1558211257.054 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:37.069Z,1558211257.069 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-18T20:27:37.070Z,1558211257.070 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:37.077Z,1558211257.077 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-18T20:27:37.945Z,1558211257.945 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-18T20:27:37.945Z,1558211257.945 [RudderServo](FAULT): Rudder failed to initialize
2019-05-18T20:27:37.945Z,1558211257.945 [RudderServo] Communications Fault, FailCount= 1
2019-05-18T20:27:37.945Z,1558211257.945 [RudderServo](ERROR): Communications Fault
2019-05-18T20:27:38.056Z,1558211258.056 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-18T20:27:38.234Z,1558211258.234 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-18T20:27:38.234Z,1558211258.234 [RudderServo](INFO): Powering down
2019-05-18T20:27:38.943Z,1558211258.943 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-18T20:27:39.062Z,1558211259.062 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-18T20:27:39.066Z,1558211259.066 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-18T20:27:39.066Z,1558211259.066 [RudderServo] No Fault, FailCount= 1
2019-05-18T20:27:46.665Z,1558211266.665 [CBIT](CRITICAL): Environmental Failure. Press:14.766173 PSI. Humidity:28%. Temp:26 C. ABORTING MISSION
2019-05-18T20:27:46.666Z,1558211266.666 [Supervisor](INFO): Stop Mission called by CBIT::monitorEnvironmentals
2019-05-18T20:27:47.067Z,1558211267.067 [CommandLine](FAULT): Scheduling is paused
2019-05-18T20:27:47.067Z,1558211267.067 [CBIT](INFO): Critical error at 20190518T202746
2019-05-18T20:28:05.155Z,1558211285.155 [NAL9602](INFO): Powering up NAL9602
2019-05-18T20:28:16.063Z,1558211296.063 [NAL9602](INFO): NAL9602 initialized
2019-05-18T20:28:16.885Z,1558211296.885 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:28:35.903Z,1558211315.903 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-18T20:28:35.907Z,1558211315.907 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-18T20:28:37.090Z,1558211317.090 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: 50ms MGP

user:1>, available: 
2019-05-18T20:28:37.091Z,1558211317.091 [DAT] Communications Fault, FailCount= 1
2019-05-18T20:28:37.091Z,1558211317.091 [DAT](ERROR): Communications Fault
2019-05-18T20:28:37.142Z,1558211317.142 [CBIT](ERROR): Communications Fault in component: DAT
2019-05-18T20:28:37.500Z,1558211317.500 [DAT](INFO): Powering down
2019-05-18T20:28:38.537Z,1558211318.537 [CBIT](INFO): Clearing failed state for component DAT
2019-05-18T20:28:38.537Z,1558211318.537 [DAT] No Fault, FailCount= 1
2019-05-18T20:28:40.841Z,1558211320.841 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-05-18T20:28:40.841Z,1558211320.841 [DAT](INFO): Powering up
2019-05-18T20:28:40.841Z,1558211320.841 [DAT](DEBUG): Initializing DAT.
2019-05-18T20:28:40.902Z,1558211320.902 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-05-18T20:28:46.908Z,1558211326.908 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.012979
CHAN A1 (24V): -0.013164
CHAN A2 (12V): 4.697929
CHAN A3 (5V): -0.026667
CHAN B0 (3.3V): 0.000317
CHAN B1 (3.15aV): -0.000036
CHAN B2 (3.15bV): 0.000570
CHAN B3 (GND): -0.000130
OPEN: 0.005330
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-18T20:28:53.937Z,1558211333.937 [DAT](INFO): setting local address to 2
2019-05-18T20:28:54.338Z,1558211334.338 [DAT](INFO): set local address to 2
2019-05-18T20:29:29.180Z,1558211369.180 [SBIT](IMPORTANT): SBIT PASSED
2019-05-18T20:29:29.273Z,1558211369.273 [CommandLine](IMPORTANT): got command configSet list
2019-05-18T20:29:29.274Z,1558211369.274 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=8 count;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-05-18T20:29:29.275Z,1558211369.275 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): Express none DVL_micro.height_above_sea_floor;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=90 cubic_centimeter;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): VerticalControl.massDefault=-1 centimeter;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-33 millimeter;

2019-05-18T20:29:29.276Z,1558211369.276 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=27 millimeter;

2019-05-18T20:29:29.589Z,1558211369.589 [MissionManager](IMPORTANT): Started mission Startup
2019-05-18T20:29:29.590Z,1558211369.590 [Startup] Running Loop=1
2019-05-18T20:29:29.590Z,1558211369.590 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-18T20:29:29.590Z,1558211369.590 [Startup:A.GoToSurface] Running Loop=1
2019-05-18T20:29:29.590Z,1558211369.590 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-18T20:29:29.591Z,1558211369.591 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-18T20:29:29.591Z,1558211369.591 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-18T20:29:29.591Z,1558211369.591 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-18T20:29:29.592Z,1558211369.592 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-18T20:29:29.592Z,1558211369.592 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-18T20:29:29.594Z,1558211369.594 [Startup:StartupSatComms] Running Loop=1
2019-05-18T20:29:29.595Z,1558211369.595 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-18T20:29:29.595Z,1558211369.595 [Startup:StartupSatComms:A] Running Loop=1
2019-05-18T20:29:29.991Z,1558211369.991 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-18T20:29:36.453Z,1558211376.453 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:29:36.453Z,1558211376.453 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-18T20:29:36.453Z,1558211376.453 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:29:36.464Z,1558211376.464 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:29:36.871Z,1558211376.871 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:29:36.871Z,1558211376.871 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-18T20:29:39.450Z,1558211379.450 [CommandLine](IMPORTANT): got command gfscan
2019-05-18T20:29:39.695Z,1558211379.695 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-18T20:29:50.604Z,1558211390.604 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.012628
CHAN A1 (24V): -0.012981
CHAN A2 (12V): -0.000409
CHAN A3 (5V): -0.001000
CHAN B0 (3.3V): 0.000263
CHAN B1 (3.15aV): -0.000448
CHAN B2 (3.15bV): -0.000102
CHAN B3 (GND): -0.000521
OPEN: 0.005186
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-18T20:30:15.115Z,1558211415.115 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004791
2019-05-18T20:30:29.790Z,1558211429.790 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-18T20:29:29.6Z
2019-05-18T20:30:29.790Z,1558211429.790 [Startup:StartupSatComms:A] Stopped
2019-05-18T20:30:29.790Z,1558211429.790 [Startup:StartupSatComms:B] Running Loop=1
2019-05-18T20:30:30.195Z,1558211430.195 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-18T20:30:39.524Z,1558211439.524 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190518T153213/Courier0082.lzma
2019-05-18T20:30:40.331Z,1558211440.331 [DataOverHttps](INFO): Moved sent file to Logs/20190518T153213/Courier0082.lzma.bak
2019-05-18T20:30:40.331Z,1558211440.331 [DataOverHttps](INFO): SBD MOMSN=11105959
2019-05-18T20:30:57.048Z,1558211457.048 [DataOverHttps](INFO): Sending 143 bytes from file Logs/20190518T202727/Courier0000.lzma
2019-05-18T20:30:57.855Z,1558211457.855 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Courier0000.lzma.bak
2019-05-18T20:30:57.855Z,1558211457.855 [DataOverHttps](IMPORTANT): SBD MOMSN=11105962, MTMSN=20190518T203021
2019-05-18T20:31:08.331Z,1558211468.331 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-18T20:31:08.373Z,1558211468.373 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-18T20:31:08.373Z,1558211468.373 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-18T20:31:08.455Z,1558211468.455 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-18T20:31:08.462Z,1558211468.462 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-18T20:31:08.478Z,1558211468.478 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-18T20:31:08.480Z,1558211468.480 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-18T20:31:08.491Z,1558211468.491 [sample:A.AbortSample](DEBUG): Construct.
2019-05-18T20:31:08.492Z,1558211468.492 [sample:B.Pitch](DEBUG): Construct.
2019-05-18T20:31:08.527Z,1558211468.527 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-18T20:31:08.538Z,1558211468.538 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-18T20:31:08.701Z,1558211468.701 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-18T20:31:08.704Z,1558211468.704 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-18T20:31:08.716Z,1558211468.716 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-18T20:31:08.744Z,1558211468.744 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-18T20:31:08.784Z,1558211468.784 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-18T20:31:08.830Z,1558211468.830 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-18T20:31:08.837Z,1558211468.837 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-18T20:31:08.840Z,1558211468.840 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-18T20:31:08.852Z,1558211468.852 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-18T20:31:08.867Z,1558211468.867 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-18T20:31:08.903Z,1558211468.903 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:31:08.914Z,1558211468.914 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-18T20:31:08.942Z,1558211468.942 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-18T20:31:08.982Z,1558211468.982 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:31:09.015Z,1558211469.015 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:31:09.074Z,1558211469.074 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

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

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

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

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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

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

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

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

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

    </Aggregate>

</Mission>


2019-05-18T20:31:09.074Z,1558211469.074 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-18T20:31:13.706Z,1558211473.706 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-18T20:31:13.707Z,1558211473.707 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-18T20:31:13.708Z,1558211473.708 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-18T20:31:13.708Z,1558211473.708 [CommandLine](IMPORTANT): got command run 
2019-05-18T20:31:13.710Z,1558211473.710 [CommandLine](IMPORTANT): Running 
2019-05-18T20:31:19.316Z,1558211479.316 [DataOverHttps](INFO): Sending 261 bytes from file Logs/20190518T153213/Express0083.lzma
2019-05-18T20:31:20.340Z,1558211480.340 [DataOverHttps](INFO): Moved sent file to Logs/20190518T153213/Express0083.lzma.bak
2019-05-18T20:31:20.340Z,1558211480.340 [DataOverHttps](INFO): SBD MOMSN=11105967
2019-05-18T20:31:29.800Z,1558211489.800 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-18T20:30:29.8Z
2019-05-18T20:31:29.800Z,1558211489.800 [Startup:StartupSatComms:B] Stopped
2019-05-18T20:31:29.800Z,1558211489.800 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-18T20:31:29.800Z,1558211489.800 [Startup:StartupSatComms] Stopped
2019-05-18T20:31:29.800Z,1558211489.800 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-18T20:31:29.801Z,1558211489.801 [Startup](INFO): Completed Startup
2019-05-18T20:31:29.801Z,1558211489.801 [MissionManager](INFO): Startup is completed.
2019-05-18T20:31:29.801Z,1558211489.801 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-18T20:31:29.801Z,1558211489.801 [Startup] Stopped
2019-05-18T20:31:29.801Z,1558211489.801 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-18T20:31:29.802Z,1558211489.802 [Startup:A.GoToSurface] Stopped
2019-05-18T20:31:29.802Z,1558211489.802 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-18T20:31:30.177Z,1558211490.177 [MissionManager](IMPORTANT): Started mission sample
2019-05-18T20:31:30.178Z,1558211490.178 [sample] Running Loop=1
2019-05-18T20:31:30.178Z,1558211490.178 [sample](DEBUG): Aggregate::initialize sample
2019-05-18T20:31:30.178Z,1558211490.178 [sample:A.AbortSample] Running Loop=1
2019-05-18T20:31:30.178Z,1558211490.178 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-18T20:31:30.178Z,1558211490.178 [sample:B.Pitch] Running Loop=1
2019-05-18T20:31:30.178Z,1558211490.178 [sample:B.Pitch](DEBUG): Initialize.
2019-05-18T20:31:30.178Z,1558211490.178 [sample:C.SetSpeed] Running Loop=1
2019-05-18T20:31:30.178Z,1558211490.178 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-18T20:31:30.179Z,1558211490.179 [sample:E] Running Loop=1
2019-05-18T20:31:30.179Z,1558211490.179 [sample:E] Stopped
2019-05-18T20:31:30.179Z,1558211490.179 [sample:F] Running Loop=1
2019-05-18T20:31:30.179Z,1558211490.179 [sample:C.SetSpeed] Running Loop=1
2019-05-18T20:31:30.179Z,1558211490.179 [sample:B.Pitch] Running Loop=1
2019-05-18T20:31:30.180Z,1558211490.180 [sample:A.AbortSample] Running Loop=1
2019-05-18T20:31:30.578Z,1558211490.578 [sample:F] Stopped
2019-05-18T20:31:30.578Z,1558211490.578 [sample:SampleRepeater] Running Loop=1
2019-05-18T20:31:30.578Z,1558211490.578 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-18T20:31:30.578Z,1558211490.578 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-18T20:31:30.578Z,1558211490.578 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-18T20:31:31.005Z,1558211491.005 [sample:SampleAtDepth] Running Loop=1
2019-05-18T20:31:31.005Z,1558211491.005 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-18T20:31:31.005Z,1558211491.005 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-18T20:31:31.005Z,1558211491.005 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-18T20:31:31.005Z,1558211491.005 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-18T20:31:31.006Z,1558211491.006 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-18T20:31:31.006Z,1558211491.006 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-18T20:31:31.006Z,1558211491.006 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-18T20:31:31.006Z,1558211491.006 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-18T20:31:31.696Z,1558211491.696 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190518T202727/Courier0004.lzma
2019-05-18T20:31:32.502Z,1558211492.502 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Courier0004.lzma.bak
2019-05-18T20:31:32.502Z,1558211492.502 [DataOverHttps](INFO): SBD MOMSN=11105977
2019-05-18T20:31:37.433Z,1558211497.433 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:31:37.434Z,1558211497.434 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-18T20:31:37.434Z,1558211497.434 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:31:37.503Z,1558211497.503 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:31:37.552Z,1558211497.552 [CommandLine](IMPORTANT): got command get depth
2019-05-18T20:31:37.552Z,1558211497.552 [CommandLine](IMPORTANT): depth 0.151258 m
2019-05-18T20:31:37.929Z,1558211497.929 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:31:37.929Z,1558211497.929 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-18T20:31:45.903Z,1558211505.903 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.000000 meter
2019-05-18T20:31:45.904Z,1558211505.904 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-05-18T20:31:46.023Z,1558211506.023 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-18T20:31:46.327Z,1558211506.327 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-18T20:31:46.328Z,1558211506.328 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-18T20:31:46.739Z,1558211506.739 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-18T20:31:46.739Z,1558211506.739 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-18T20:31:46.739Z,1558211506.739 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-18T20:31:46.739Z,1558211506.739 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-18T20:31:46.739Z,1558211506.739 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-18T20:31:50.367Z,1558211510.367 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-18T20:31:50.367Z,1558211510.367 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-18T20:31:50.367Z,1558211510.367 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-18T20:31:50.367Z,1558211510.367 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-18T20:31:50.368Z,1558211510.368 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-18T20:31:50.368Z,1558211510.368 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-18T20:31:50.368Z,1558211510.368 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-18T20:31:50.368Z,1558211510.368 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-18T20:31:50.774Z,1558211510.774 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-18T20:31:50.775Z,1558211510.775 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-18T20:31:51.187Z,1558211511.187 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-18T20:31:51.978Z,1558211511.978 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'
2019-05-18T20:31:51.980Z,1558211511.980 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"
2019-05-18T20:31:52.384Z,1558211512.384 [ESPComponent](INFO): powering up ESP
2019-05-18T20:31:52.384Z,1558211512.384 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-18T20:31:52.401Z,1558211512.401 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.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-05-18T20:31:52.525Z,1558211512.525 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-18T20:32:00.888Z,1558211520.888 [ESPComponent](INFO): console:[    0.55] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-18T20:32:08.651Z,1558211528.651 [CommandLine](IMPORTANT): got command show variable stopSamp
2019-05-18T20:32:08.748Z,1558211528.748 [CommandLine](IMPORTANT): ESPComponent.stopSampling (bool)
2019-05-18T20:32:17.924Z,1558211537.924 [CommandLine](IMPORTANT): got command report touch ESPComponent.stopSampling
2019-05-18T20:32:23.775Z,1558211543.775 [CommandLine](IMPORTANT): got command get ESPComponent.stopSampling
2019-05-18T20:32:23.776Z,1558211543.776 [CommandLine](IMPORTANT): ESPComponent.stopSampling 0 bool
2019-05-18T20:32:25.931Z,1558211545.931 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-18T20:32:26.730Z,1558211546.730 [ESPComponent](IMPORTANT): [sample #1] Explicit cartridge argument not given
2019-05-18T20:32:26.731Z,1558211546.731 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-18T20:32:26.732Z,1558211546.732 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2019-05-18T20:32:26.738Z,1558211546.738 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-18T20:32:26.739Z,1558211546.739 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-18T20:32:27.139Z,1558211547.139 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-18T20:32:27.139Z,1558211547.139 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-18T20:32:27.140Z,1558211547.140 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-18T20:32:27.140Z,1558211547.140 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-18T20:32:27.140Z,1558211547.140 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-18T20:32:27.547Z,1558211547.547 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-18T20:32:27.938Z,1558211547.938 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2019-05-18T20:32:28.338Z,1558211548.338 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-05-18T20:32:29.953Z,1558211549.953 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2019-05-18T20:32:45.739Z,1558211565.739 [CommandLine](IMPORTANT): got command stop
2019-05-18T20:32:45.739Z,1558211565.739 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-18T20:32:45.739Z,1558211565.739 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-18T20:32:46.143Z,1558211566.143 [MissionManager](INFO): MissionManager is completed.
2019-05-18T20:32:46.143Z,1558211566.143 [MissionManager](INFO): Uninitializing Mission sample
2019-05-18T20:32:46.144Z,1558211566.144 [sample] Stopped
2019-05-18T20:32:46.144Z,1558211566.144 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-18T20:32:46.144Z,1558211566.144 [sample:A.AbortSample] Stopped
2019-05-18T20:32:46.144Z,1558211566.144 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-18T20:32:46.144Z,1558211566.144 [sample:B.Pitch] Stopped
2019-05-18T20:32:46.144Z,1558211566.144 [sample:C.SetSpeed] Stopped
2019-05-18T20:32:46.144Z,1558211566.144 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-18T20:32:46.144Z,1558211566.144 [sample:SampleAtDepth] Stopped
2019-05-18T20:32:46.144Z,1558211566.144 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-18T20:32:46.144Z,1558211566.144 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleRepeater] Stopped
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-18T20:32:46.145Z,1558211566.145 [sample:SampleRepeater:Sample] Stopped
2019-05-18T20:32:46.146Z,1558211566.146 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-18T20:32:46.230Z,1558211566.230 [Reporter](INFO): ESPComponent.stopSampling 1 bool
2019-05-18T20:32:46.540Z,1558211566.540 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:32:46.540Z,1558211566.540 [ESPComponent](IMPORTANT): [sample #1] Stop sampling requested.
2019-05-18T20:32:46.554Z,1558211566.554 [MissionManager](IMPORTANT): Started mission Default
2019-05-18T20:32:46.554Z,1558211566.554 [Default] Running Loop=1
2019-05-18T20:32:46.554Z,1558211566.554 [Default](DEBUG): Aggregate::initialize Default
2019-05-18T20:32:46.555Z,1558211566.555 [Default:B.GoToSurface] Running Loop=1
2019-05-18T20:32:46.555Z,1558211566.555 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-18T20:32:46.555Z,1558211566.555 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-18T20:32:46.555Z,1558211566.555 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-18T20:32:46.556Z,1558211566.556 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-18T20:32:46.556Z,1558211566.556 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-18T20:32:46.556Z,1558211566.556 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-18T20:32:46.557Z,1558211566.557 [Default:A.Wait] Running Loop=1
2019-05-18T20:32:46.557Z,1558211566.557 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-18T20:32:46.630Z,1558211566.630 [Reporter](INFO): ESPComponent.stopSampling 0 bool
2019-05-18T20:32:46.942Z,1558211566.942 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.stop
2019-05-18T20:32:47.341Z,1558211567.341 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING
2019-05-18T20:32:59.863Z,1558211579.863 [Default:A.Wait](INFO): Done Waiting.
2019-05-18T20:32:59.863Z,1558211579.863 [Default:A.Wait] Stopped
2019-05-18T20:32:59.863Z,1558211579.863 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-18T20:33:00.271Z,1558211580.271 [Default:CheckIn] Running Loop=1
2019-05-18T20:33:00.271Z,1558211580.271 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-18T20:33:00.271Z,1558211580.271 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-18T20:33:00.675Z,1558211580.675 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-18T20:33:19.638Z,1558211599.638 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-18T20:33:20.453Z,1558211600.453 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:24.901Z,1558211604.901 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:26.917Z,1558211606.917 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:30.153Z,1558211610.153 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:32.981Z,1558211612.981 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:36.209Z,1558211616.209 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:38.649Z,1558211618.649 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:33:38.649Z,1558211618.649 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-05-18T20:33:38.649Z,1558211618.649 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:33:38.660Z,1558211618.660 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:33:39.045Z,1558211619.045 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:39.157Z,1558211619.157 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:33:39.157Z,1558211619.157 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-05-18T20:33:42.273Z,1558211622.273 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:45.097Z,1558211625.097 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:47.929Z,1558211627.929 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:49.949Z,1558211629.949 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:53.177Z,1558211633.177 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:56.009Z,1558211636.009 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:33:59.237Z,1558211639.237 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:02.065Z,1558211642.065 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:05.297Z,1558211645.297 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:08.125Z,1558211648.125 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:10.957Z,1558211650.957 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:12.977Z,1558211652.977 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:14.993Z,1558211654.993 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:18.225Z,1558211658.225 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:21.057Z,1558211661.057 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:22.019Z,1558211662.019 [CommandLine](IMPORTANT): got command show variable vehicleOpen
2019-05-18T20:34:22.046Z,1558211662.046 [CommandLine](IMPORTANT): CBIT.vehicleOpen (bool)
2019-05-18T20:34:24.289Z,1558211664.289 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:27.114Z,1558211667.114 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:30.349Z,1558211670.349 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:33.173Z,1558211673.173 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:36.001Z,1558211676.001 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:38.021Z,1558211678.021 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:40.045Z,1558211680.045 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:41.120Z,1558211681.120 [CommandLine](IMPORTANT): got command configSet CBIT.vehicleOpen 1.000000 bool persist
2019-05-18T20:34:43.273Z,1558211683.273 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:46.105Z,1558211686.105 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:47.318Z,1558211687.318 [ESPComponent](FAULT): Timeout while awaiting result for cmd='Cmd.stop'
2019-05-18T20:34:47.318Z,1558211687.318 [ESPComponent](CRITICAL): [sample #1] ESP sampling sequence terminated with error: Timeout while awaiting result for cmd='Cmd.stop'
2019-05-18T20:34:47.318Z,1558211687.318 [ESPComponent] Communications Fault, FailCount= 1
2019-05-18T20:34:47.318Z,1558211687.318 [ESPComponent](ERROR): Communications Fault
2019-05-18T20:34:47.337Z,1558211687.337 [CommandLine](FAULT): Scheduling is paused
2019-05-18T20:34:47.337Z,1558211687.337 [CBIT](INFO): Critical error at 20190518T203447
2019-05-18T20:34:47.339Z,1558211687.339 [CBIT](ERROR): Communications Fault in component: ESPComponent
2019-05-18T20:34:47.727Z,1558211687.727 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:34:47.727Z,1558211687.727 [ESPComponent](IMPORTANT): [sample #1] No ESP summary messages.
2019-05-18T20:34:47.728Z,1558211687.728 [ESPComponent](INFO): powering down ESP
2019-05-18T20:34:47.729Z,1558211687.729 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-18T20:34:47.884Z,1558211687.884 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-18T20:34:48.562Z,1558211688.562 [CBIT](INFO): Clearing failed state for component ESPComponent
2019-05-18T20:34:48.562Z,1558211688.562 [ESPComponent] No Fault, FailCount= 1
2019-05-18T20:34:49.333Z,1558211689.333 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:49.348Z,1558211689.348 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:34:49.348Z,1558211689.348 [ESPComponent](INFO): powering down ESP
2019-05-18T20:34:49.349Z,1558211689.349 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-18T20:34:49.496Z,1558211689.496 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-18T20:34:52.165Z,1558211692.165 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:55.393Z,1558211695.393 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:34:58.225Z,1558211698.225 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:01.053Z,1558211701.053 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:03.073Z,1558211703.073 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:06.301Z,1558211706.301 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:09.133Z,1558211709.133 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:12.361Z,1558211712.361 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:15.193Z,1558211715.193 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:18.425Z,1558211718.425 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:21.253Z,1558211721.253 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:24.081Z,1558211724.081 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:26.101Z,1558211726.101 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:29.329Z,1558211729.329 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:32.161Z,1558211732.161 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:35.393Z,1558211735.393 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:38.217Z,1558211738.217 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:39.500Z,1558211739.500 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:35:39.500Z,1558211739.500 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-05-18T20:35:39.500Z,1558211739.500 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:35:39.535Z,1558211739.535 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:35:39.874Z,1558211739.874 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:35:39.874Z,1558211739.874 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-05-18T20:35:40.778Z,1558211740.778 [DataOverHttps](IMPORTANT): SBD MTMSN=20190518T203504
2019-05-18T20:35:41.453Z,1558211741.453 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:44.281Z,1558211744.281 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:47.113Z,1558211747.113 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:49.129Z,1558211749.129 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:49.717Z,1558211749.717 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-18T20:35:49.731Z,1558211749.731 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-18T20:35:49.732Z,1558211749.732 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-18T20:35:49.763Z,1558211749.763 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-18T20:35:49.765Z,1558211749.765 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-18T20:35:49.767Z,1558211749.767 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-18T20:35:49.769Z,1558211749.769 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-18T20:35:49.770Z,1558211749.770 [sample:A.AbortSample](DEBUG): Construct.
2019-05-18T20:35:49.771Z,1558211749.771 [sample:B.Pitch](DEBUG): Construct.
2019-05-18T20:35:49.775Z,1558211749.775 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-18T20:35:49.777Z,1558211749.777 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-18T20:35:49.911Z,1558211749.911 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-18T20:35:49.914Z,1558211749.914 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-18T20:35:49.916Z,1558211749.916 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-18T20:35:49.957Z,1558211749.957 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-18T20:35:49.959Z,1558211749.959 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-18T20:35:49.962Z,1558211749.962 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-18T20:35:49.964Z,1558211749.964 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-18T20:35:49.966Z,1558211749.966 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-18T20:35:49.969Z,1558211749.969 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-18T20:35:49.983Z,1558211749.983 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-18T20:35:50.008Z,1558211750.008 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:35:50.019Z,1558211750.019 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-18T20:35:50.043Z,1558211750.043 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-18T20:35:50.101Z,1558211750.101 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:35:50.125Z,1558211750.125 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-18T20:35:50.161Z,1558211750.161 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

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

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

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

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

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

    <Timeout Duration="MissionTimeout"/>

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

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

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

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

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

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

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

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

    </Aggregate>

</Mission>


2019-05-18T20:35:50.162Z,1558211750.162 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-18T20:35:52.361Z,1558211752.361 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:55.189Z,1558211755.189 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:35:56.348Z,1558211756.348 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-18T20:35:56.348Z,1558211756.348 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-18T20:35:56.350Z,1558211756.350 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-18T20:35:56.350Z,1558211756.350 [CommandLine](IMPORTANT): got command run 
2019-05-18T20:35:56.352Z,1558211756.352 [CommandLine](IMPORTANT): Running 
2019-05-18T20:35:56.410Z,1558211756.410 [Default] Stopped
2019-05-18T20:35:56.410Z,1558211756.410 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-18T20:35:56.411Z,1558211756.411 [Default:B.GoToSurface] Stopped
2019-05-18T20:35:56.411Z,1558211756.411 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-18T20:35:56.411Z,1558211756.411 [Default:CheckIn] Stopped
2019-05-18T20:35:56.411Z,1558211756.411 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-18T20:35:56.411Z,1558211756.411 [Default:CheckIn:Read_GPS] Stopped
2019-05-18T20:35:56.411Z,1558211756.411 [MissionManager](IMPORTANT): Started mission sample
2019-05-18T20:35:56.411Z,1558211756.411 [sample] Running Loop=1
2019-05-18T20:35:56.411Z,1558211756.411 [sample](DEBUG): Aggregate::initialize sample
2019-05-18T20:35:56.412Z,1558211756.412 [sample:A.AbortSample] Running Loop=1
2019-05-18T20:35:56.412Z,1558211756.412 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-18T20:35:56.412Z,1558211756.412 [sample:B.Pitch] Running Loop=1
2019-05-18T20:35:56.412Z,1558211756.412 [sample:B.Pitch](DEBUG): Initialize.
2019-05-18T20:35:56.412Z,1558211756.412 [sample:C.SetSpeed] Running Loop=1
2019-05-18T20:35:56.412Z,1558211756.412 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-18T20:35:56.412Z,1558211756.412 [sample:E] Running Loop=1
2019-05-18T20:35:56.413Z,1558211756.413 [sample:E] Stopped
2019-05-18T20:35:56.413Z,1558211756.413 [sample:F] Running Loop=1
2019-05-18T20:35:56.413Z,1558211756.413 [sample:C.SetSpeed] Running Loop=1
2019-05-18T20:35:56.413Z,1558211756.413 [sample:B.Pitch] Running Loop=1
2019-05-18T20:35:56.413Z,1558211756.413 [sample:A.AbortSample] Running Loop=1
2019-05-18T20:35:56.422Z,1558211756.422 [Reporter](INFO): ESPComponent.stopSampling 0 bool
2019-05-18T20:35:56.815Z,1558211756.815 [sample:F] Stopped
2019-05-18T20:35:56.815Z,1558211756.815 [sample:SampleRepeater] Running Loop=1
2019-05-18T20:35:56.815Z,1558211756.815 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-18T20:35:56.815Z,1558211756.815 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-18T20:35:56.815Z,1558211756.815 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-18T20:35:57.230Z,1558211757.230 [sample:SampleAtDepth] Running Loop=1
2019-05-18T20:35:57.230Z,1558211757.230 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-18T20:35:57.230Z,1558211757.230 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-18T20:35:57.230Z,1558211757.230 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-18T20:35:57.231Z,1558211757.231 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-18T20:35:57.231Z,1558211757.231 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-18T20:35:57.231Z,1558211757.231 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-18T20:35:57.231Z,1558211757.231 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-18T20:35:57.231Z,1558211757.231 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-18T20:35:57.630Z,1558211757.630 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-18T20:35:57.631Z,1558211757.631 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-18T20:35:58.035Z,1558211758.035 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-18T20:35:58.035Z,1558211758.035 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-18T20:35:58.035Z,1558211758.035 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-18T20:35:58.035Z,1558211758.035 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-18T20:35:58.035Z,1558211758.035 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-18T20:35:58.429Z,1558211758.429 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:01.249Z,1558211761.249 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:01.677Z,1558211761.677 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-18T20:36:01.678Z,1558211761.678 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-18T20:36:02.121Z,1558211762.121 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-18T20:36:02.121Z,1558211762.121 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-18T20:36:02.121Z,1558211762.121 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-18T20:36:02.121Z,1558211762.121 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-18T20:36:02.121Z,1558211762.121 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-18T20:36:02.122Z,1558211762.122 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-18T20:36:02.122Z,1558211762.122 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-18T20:36:02.122Z,1558211762.122 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-18T20:36:02.483Z,1558211762.483 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-18T20:36:03.679Z,1558211763.679 [ESPComponent](INFO): powering up ESP
2019-05-18T20:36:03.679Z,1558211763.679 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-18T20:36:03.697Z,1558211763.697 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.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-05-18T20:36:03.803Z,1558211763.803 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-18T20:36:04.485Z,1558211764.485 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:07.309Z,1558211767.309 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:09.778Z,1558211769.778 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-05-18T20:36:10.137Z,1558211770.137 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:10.983Z,1558211770.983 [ESPComponent](INFO): console:[   PU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-05-18T20:36:12.173Z,1558211772.173 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:12.194Z,1558211772.194 [ESPComponent](INFO): console: timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-18T20:36:14.180Z,1558211774.180 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:14.198Z,1558211774.198 [ESPComponent](INFO): console: ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-18T20:36:17.409Z,1558211777.409 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:20.241Z,1558211780.241 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:23.469Z,1558211783.469 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:24.692Z,1558211784.692 [ESPComponent](INFO): console:ork unavailable:  Local time is Sat May 18 13:35:50 PDT 2019
2019-05-18T20:36:26.297Z,1558211786.297 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:29.529Z,1558211789.529 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:32.361Z,1558211792.361 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:35.189Z,1558211795.189 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:37.207Z,1558211797.207 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:37.222Z,1558211797.222 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-18T20:36:38.047Z,1558211798.047 [ESPComponent](IMPORTANT): [sample #2] Explicit cartridge argument not given
2019-05-18T20:36:38.047Z,1558211798.047 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-18T20:36:38.048Z,1558211798.048 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2
2019-05-18T20:36:38.054Z,1558211798.054 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-18T20:36:38.055Z,1558211798.055 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-18T20:36:38.439Z,1558211798.439 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-18T20:36:38.440Z,1558211798.440 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-18T20:36:38.440Z,1558211798.440 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-18T20:36:38.440Z,1558211798.440 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-18T20:36:38.440Z,1558211798.440 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-18T20:36:38.839Z,1558211798.839 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-18T20:36:39.225Z,1558211799.225 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:39.240Z,1558211799.240 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG
2019-05-18T20:36:39.648Z,1558211799.648 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS
2019-05-18T20:36:41.254Z,1558211801.254 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE
2019-05-18T20:36:42.465Z,1558211802.465 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:45.305Z,1558211805.305 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:48.521Z,1558211808.521 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:51.345Z,1558211811.345 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:54.293Z,1558211814.293 [CommandLine](IMPORTANT): got command stop
2019-05-18T20:36:54.294Z,1558211814.294 [CommandLine](IMPORTANT): Scheduling is paused
2019-05-18T20:36:54.294Z,1558211814.294 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-18T20:36:54.577Z,1558211814.577 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:36:54.611Z,1558211814.611 [MissionManager](INFO): MissionManager is completed.
2019-05-18T20:36:54.612Z,1558211814.612 [MissionManager](INFO): Uninitializing Mission sample
2019-05-18T20:36:54.612Z,1558211814.612 [sample] Stopped
2019-05-18T20:36:54.612Z,1558211814.612 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-18T20:36:54.612Z,1558211814.612 [sample:A.AbortSample] Stopped
2019-05-18T20:36:54.612Z,1558211814.612 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-18T20:36:54.612Z,1558211814.612 [sample:B.Pitch] Stopped
2019-05-18T20:36:54.612Z,1558211814.612 [sample:C.SetSpeed] Stopped
2019-05-18T20:36:54.612Z,1558211814.612 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-18T20:36:54.612Z,1558211814.612 [sample:SampleAtDepth] Stopped
2019-05-18T20:36:54.612Z,1558211814.612 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleRepeater] Stopped
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-18T20:36:54.613Z,1558211814.613 [sample:SampleRepeater:Sample] Stopped
2019-05-18T20:36:54.614Z,1558211814.614 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-18T20:36:54.658Z,1558211814.658 [Reporter](INFO): ESPComponent.stopSampling 1 bool
2019-05-18T20:36:55.003Z,1558211815.003 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:36:55.004Z,1558211815.004 [ESPComponent](IMPORTANT): [sample #2] Stop sampling requested.
2019-05-18T20:36:55.029Z,1558211815.029 [MissionManager](IMPORTANT): Started mission Default
2019-05-18T20:36:55.029Z,1558211815.029 [Default] Running Loop=1
2019-05-18T20:36:55.029Z,1558211815.029 [Default](DEBUG): Aggregate::initialize Default
2019-05-18T20:36:55.029Z,1558211815.029 [Default:B.GoToSurface] Running Loop=1
2019-05-18T20:36:55.030Z,1558211815.030 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-18T20:36:55.030Z,1558211815.030 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-18T20:36:55.030Z,1558211815.030 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-18T20:36:55.030Z,1558211815.030 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-18T20:36:55.031Z,1558211815.031 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-18T20:36:55.031Z,1558211815.031 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-18T20:36:55.032Z,1558211815.032 [Default:A.Wait] Running Loop=1
2019-05-18T20:36:55.032Z,1558211815.032 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-18T20:36:55.107Z,1558211815.107 [Reporter](INFO): ESPComponent.stopSampling 0 bool
2019-05-18T20:36:55.411Z,1558211815.411 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.stop
2019-05-18T20:36:55.798Z,1558211815.798 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPING
2019-05-18T20:36:57.410Z,1558211817.410 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:00.237Z,1558211820.237 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:02.253Z,1558211822.253 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:05.489Z,1558211825.489 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:08.313Z,1558211828.313 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:08.351Z,1558211828.351 [Default:A.Wait](INFO): Done Waiting.
2019-05-18T20:37:08.351Z,1558211828.351 [Default:A.Wait] Stopped
2019-05-18T20:37:08.351Z,1558211828.351 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-18T20:37:08.754Z,1558211828.754 [Default:CheckIn] Running Loop=1
2019-05-18T20:37:08.754Z,1558211828.754 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-18T20:37:08.754Z,1558211828.754 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-18T20:37:11.549Z,1558211831.549 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:14.377Z,1558211834.377 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:17.605Z,1558211837.605 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:20.433Z,1558211840.433 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:23.265Z,1558211843.265 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:25.286Z,1558211845.286 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:28.513Z,1558211848.513 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:31.341Z,1558211851.341 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:34.573Z,1558211854.573 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:37.401Z,1558211857.401 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:40.637Z,1558211860.637 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:40.665Z,1558211860.665 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:37:40.665Z,1558211860.665 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-05-18T20:37:40.665Z,1558211860.665 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:37:40.709Z,1558211860.709 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:37:41.113Z,1558211861.113 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:37:41.113Z,1558211861.113 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-05-18T20:37:43.461Z,1558211863.461 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:46.289Z,1558211866.289 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:48.309Z,1558211868.309 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:50.329Z,1558211870.329 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:53.565Z,1558211873.565 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:56.389Z,1558211876.389 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:37:59.632Z,1558211879.632 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:02.453Z,1558211882.453 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:05.689Z,1558211885.689 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:08.509Z,1558211888.509 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:11.337Z,1558211891.337 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:13.357Z,1558211893.357 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:16.589Z,1558211896.589 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:38:16.986Z,1558211896.986 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-18T20:38:16.986Z,1558211896.986 [NAL9602] Data Fault, FailCount= 1
2019-05-18T20:38:16.986Z,1558211896.986 [NAL9602](ERROR): Data Fault
2019-05-18T20:38:17.041Z,1558211897.041 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-18T20:38:17.386Z,1558211897.386 [NAL9602](INFO): Powering down
2019-05-18T20:38:18.230Z,1558211898.230 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-18T20:38:18.230Z,1558211898.230 [NAL9602] No Fault, FailCount= 1
2019-05-18T20:38:47.690Z,1558211927.690 [NAL9602](INFO): Powering up NAL9602
2019-05-18T20:38:55.790Z,1558211935.790 [ESPComponent](FAULT): Timeout while awaiting result for cmd='Cmd.stop'
2019-05-18T20:38:55.790Z,1558211935.790 [ESPComponent](CRITICAL): [sample #2] ESP sampling sequence terminated with error: Timeout while awaiting result for cmd='Cmd.stop'
2019-05-18T20:38:55.790Z,1558211935.790 [ESPComponent] Communications Fault, FailCount= 2
2019-05-18T20:38:55.790Z,1558211935.790 [ESPComponent](ERROR): Communications Fault
2019-05-18T20:38:55.802Z,1558211935.802 [CommandLine](FAULT): Scheduling is paused
2019-05-18T20:38:55.803Z,1558211935.803 [CBIT](INFO): Critical error at 20190518T203855
2019-05-18T20:38:55.805Z,1558211935.805 [CBIT](ERROR): Communications Fault in component: ESPComponent
2019-05-18T20:38:56.184Z,1558211936.184 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:38:56.185Z,1558211936.185 [ESPComponent](IMPORTANT): [sample #2] No ESP summary messages.
2019-05-18T20:38:56.185Z,1558211936.185 [ESPComponent](INFO): powering down ESP
2019-05-18T20:38:56.186Z,1558211936.186 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-18T20:38:56.350Z,1558211936.350 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-18T20:38:57.015Z,1558211937.015 [CBIT](INFO): Clearing failed state for component ESPComponent
2019-05-18T20:38:57.015Z,1558211937.015 [ESPComponent] No Fault, FailCount= 2
2019-05-18T20:38:57.806Z,1558211937.806 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-18T20:38:57.807Z,1558211937.807 [ESPComponent](INFO): powering down ESP
2019-05-18T20:38:57.807Z,1558211937.807 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-18T20:38:57.940Z,1558211937.940 [Reporter](INFO): ESPComponent.stopSampling no_value
2019-05-18T20:38:58.595Z,1558211938.595 [NAL9602](INFO): NAL9602 initialized
2019-05-18T20:39:02.245Z,1558211942.245 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:05.071Z,1558211945.071 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:08.305Z,1558211948.305 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:11.133Z,1558211951.133 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:13.957Z,1558211953.957 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:15.977Z,1558211955.977 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:18.001Z,1558211958.001 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:21.229Z,1558211961.229 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:24.061Z,1558211964.061 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:27.293Z,1558211967.293 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:30.121Z,1558211970.121 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:33.353Z,1558211973.353 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:36.177Z,1558211976.177 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:39.009Z,1558211979.009 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:41.025Z,1558211981.025 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:41.857Z,1558211981.857 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:39:41.857Z,1558211981.857 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-05-18T20:39:41.857Z,1558211981.857 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:39:41.867Z,1558211981.867 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:39:42.256Z,1558211982.256 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:39:42.256Z,1558211982.256 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-05-18T20:39:43.053Z,1558211983.053 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:46.277Z,1558211986.277 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:49.109Z,1558211989.109 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:52.341Z,1558211992.341 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:55.165Z,1558211995.165 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:39:58.397Z,1558211998.397 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:01.229Z,1558212001.229 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:04.057Z,1558212004.057 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:06.077Z,1558212006.077 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:09.309Z,1558212009.309 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:12.133Z,1558212012.133 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:15.365Z,1558212015.365 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:18.197Z,1558212018.197 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:21.429Z,1558212021.429 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:24.257Z,1558212024.257 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:27.085Z,1558212027.085 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:29.105Z,1558212029.105 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:31.125Z,1558212031.125 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:34.353Z,1558212034.353 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:37.181Z,1558212037.181 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:40.413Z,1558212040.413 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:43.241Z,1558212043.241 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:46.473Z,1558212046.473 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:49.301Z,1558212049.301 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:52.129Z,1558212052.129 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:54.149Z,1558212054.149 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:40:57.381Z,1558212057.381 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:00.213Z,1558212060.213 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:03.441Z,1558212063.441 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:06.273Z,1558212066.273 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:09.501Z,1558212069.501 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:12.333Z,1558212072.333 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:15.157Z,1558212075.157 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:17.177Z,1558212077.177 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:19.201Z,1558212079.201 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:22.433Z,1558212082.433 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:25.265Z,1558212085.265 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:28.493Z,1558212088.493 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:31.321Z,1558212091.321 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:34.553Z,1558212094.553 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:37.381Z,1558212097.381 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:40.209Z,1558212100.209 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:42.229Z,1558212102.229 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:42.661Z,1558212102.661 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:41:42.661Z,1558212102.661 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-05-18T20:41:42.661Z,1558212102.661 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:41:42.672Z,1558212102.672 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:41:43.073Z,1558212103.073 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:41:43.074Z,1558212103.074 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-05-18T20:41:45.457Z,1558212105.457 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:48.285Z,1558212108.285 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:51.517Z,1558212111.517 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:54.345Z,1558212114.345 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:41:57.581Z,1558212117.581 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:00.405Z,1558212120.405 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:03.241Z,1558212123.241 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:05.257Z,1558212125.257 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:08.485Z,1558212128.485 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:08.914Z,1558212128.914 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-18T20:37:08.8Z
2019-05-18T20:42:08.915Z,1558212128.915 [Default:CheckIn:Read_GPS] Stopped
2019-05-18T20:42:08.915Z,1558212128.915 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-18T20:42:09.327Z,1558212129.327 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-18T20:42:11.313Z,1558212131.313 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:14.545Z,1558212134.545 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:17.377Z,1558212137.377 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:20.605Z,1558212140.605 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:23.437Z,1558212143.437 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:26.285Z,1558212146.285 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:28.281Z,1558212148.281 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:30.301Z,1558212150.301 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:33.537Z,1558212153.537 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:36.361Z,1558212156.361 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:39.597Z,1558212159.597 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:42.425Z,1558212162.425 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:43.376Z,1558212163.376 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20190518T202727/Courier0007.lzma
2019-05-18T20:42:44.182Z,1558212164.182 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Courier0007.lzma.bak
2019-05-18T20:42:44.182Z,1558212164.182 [DataOverHttps](INFO): SBD MOMSN=11106037
2019-05-18T20:42:45.653Z,1558212165.653 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:48.481Z,1558212168.481 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:51.313Z,1558212171.313 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:53.329Z,1558212173.329 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:55.349Z,1558212175.349 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:42:55.640Z,1558212175.640 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190518T202727/Courier0010.lzma
2019-05-18T20:42:56.446Z,1558212176.446 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Courier0010.lzma.bak
2019-05-18T20:42:56.446Z,1558212176.446 [DataOverHttps](INFO): SBD MOMSN=11106041
2019-05-18T20:42:58.581Z,1558212178.581 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:01.409Z,1558212181.409 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:04.641Z,1558212184.641 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:07.469Z,1558212187.469 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:09.162Z,1558212189.162 [DataOverHttps](INFO): Sending 1215 bytes from file Logs/20190518T202727/Express0001.lzma
2019-05-18T20:43:09.966Z,1558212189.966 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Express0001.lzma.bak
2019-05-18T20:43:09.966Z,1558212189.966 [DataOverHttps](INFO): SBD MOMSN=11106043
2019-05-18T20:43:10.701Z,1558212190.701 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:13.529Z,1558212193.529 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:16.357Z,1558212196.357 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:18.381Z,1558212198.381 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:21.609Z,1558212201.609 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:22.541Z,1558212202.541 [DataOverHttps](INFO): Sending 279 bytes from file Logs/20190518T202727/Express0005.lzma
2019-05-18T20:43:23.346Z,1558212203.346 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Express0005.lzma.bak
2019-05-18T20:43:23.346Z,1558212203.346 [DataOverHttps](INFO): SBD MOMSN=11106080
2019-05-18T20:43:24.445Z,1558212204.445 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:27.669Z,1558212207.669 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:30.501Z,1558212210.501 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:33.733Z,1558212213.733 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:35.951Z,1558212215.951 [DataOverHttps](INFO): Sending 1622 bytes from file Logs/20190518T202727/Express0008.lzma
2019-05-18T20:43:36.557Z,1558212216.557 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:36.754Z,1558212216.754 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Express0008.lzma.bak
2019-05-18T20:43:36.754Z,1558212216.754 [DataOverHttps](INFO): SBD MOMSN=11106090
2019-05-18T20:43:39.389Z,1558212219.389 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:41.405Z,1558212221.405 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:43.425Z,1558212223.425 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:43.449Z,1558212223.449 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:43:43.449Z,1558212223.449 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-05-18T20:43:43.449Z,1558212223.449 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:43:43.460Z,1558212223.460 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:43:43.870Z,1558212223.870 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:43:43.870Z,1558212223.870 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-05-18T20:43:46.657Z,1558212226.657 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:49.356Z,1558212229.356 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20190518T202727/Express0011.lzma
2019-05-18T20:43:49.485Z,1558212229.485 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:50.162Z,1558212230.162 [DataOverHttps](INFO): Moved sent file to Logs/20190518T202727/Express0011.lzma.bak
2019-05-18T20:43:50.162Z,1558212230.162 [DataOverHttps](INFO): SBD MOMSN=11106164
2019-05-18T20:43:52.717Z,1558212232.717 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:53.157Z,1558212233.157 [Default:CheckIn:Read_Iridium] Stopped
2019-05-18T20:43:53.158Z,1558212233.158 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-18T20:43:53.158Z,1558212233.158 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-18T20:43:55.545Z,1558212235.545 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:43:58.777Z,1558212238.777 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:01.605Z,1558212241.605 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:04.433Z,1558212244.433 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:06.453Z,1558212246.453 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:09.689Z,1558212249.689 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:12.517Z,1558212252.517 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:15.745Z,1558212255.745 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:18.573Z,1558212258.573 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:21.809Z,1558212261.809 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:24.633Z,1558212264.633 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:27.465Z,1558212267.465 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:29.481Z,1558212269.481 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:32.713Z,1558212272.713 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:35.541Z,1558212275.541 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:38.773Z,1558212278.773 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:41.605Z,1558212281.605 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:44.837Z,1558212284.837 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:47.665Z,1558212287.665 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:50.493Z,1558212290.493 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:52.509Z,1558212292.509 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:54.533Z,1558212294.533 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:44:57.765Z,1558212297.765 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:00.589Z,1558212300.589 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:03.821Z,1558212303.821 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:06.653Z,1558212306.653 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:09.885Z,1558212309.885 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:12.713Z,1558212312.713 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:15.537Z,1558212315.537 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:17.557Z,1558212317.557 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:20.789Z,1558212320.789 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:23.621Z,1558212323.621 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:26.853Z,1558212326.853 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:29.681Z,1558212329.681 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:32.909Z,1558212332.909 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:35.737Z,1558212335.737 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:38.565Z,1558212338.565 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:40.585Z,1558212340.585 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:42.605Z,1558212342.605 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:44.682Z,1558212344.682 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:45:44.682Z,1558212344.682 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2019-05-18T20:45:44.682Z,1558212344.682 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:45:44.700Z,1558212344.700 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:45:45.103Z,1558212345.103 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:45:45.103Z,1558212345.103 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2019-05-18T20:45:45.837Z,1558212345.837 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:48.685Z,1558212348.685 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:51.897Z,1558212351.897 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:54.729Z,1558212354.729 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:45:57.957Z,1558212357.957 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:00.789Z,1558212360.789 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:03.613Z,1558212363.613 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:05.649Z,1558212365.649 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:08.865Z,1558212368.865 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:11.693Z,1558212371.693 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:14.925Z,1558212374.925 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:17.757Z,1558212377.757 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:20.985Z,1558212380.985 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:23.815Z,1558212383.815 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:26.649Z,1558212386.649 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:28.661Z,1558212388.661 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:30.684Z,1558212390.684 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:33.941Z,1558212393.941 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:36.757Z,1558212396.757 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:39.989Z,1558212399.989 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:42.817Z,1558212402.817 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:45.645Z,1558212405.645 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:47.665Z,1558212407.665 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:49.685Z,1558212409.685 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:51.705Z,1558212411.705 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:54.937Z,1558212414.937 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:46:57.769Z,1558212417.769 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:00.997Z,1558212420.997 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:03.825Z,1558212423.825 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:07.061Z,1558212427.061 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:09.885Z,1558212429.885 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:12.717Z,1558212432.717 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:14.737Z,1558212434.737 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:16.753Z,1558212436.753 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:19.989Z,1558212439.989 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:22.813Z,1558212442.813 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:26.049Z,1558212446.049 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:28.873Z,1558212448.873 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:32.109Z,1558212452.109 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:34.933Z,1558212454.933 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:37.765Z,1558212457.765 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:39.785Z,1558212459.785 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:43.013Z,1558212463.013 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:45.841Z,1558212465.841 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:45.872Z,1558212465.872 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:47:45.872Z,1558212465.872 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2019-05-18T20:47:45.872Z,1558212465.872 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:47:45.883Z,1558212465.883 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:47:46.294Z,1558212466.294 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:47:46.294Z,1558212466.294 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2019-05-18T20:47:49.077Z,1558212469.077 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:51.901Z,1558212471.901 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:55.137Z,1558212475.137 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:47:57.961Z,1558212477.961 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:00.789Z,1558212480.789 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:02.809Z,1558212482.809 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:04.829Z,1558212484.829 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:08.065Z,1558212488.065 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:10.893Z,1558212490.893 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:14.125Z,1558212494.125 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:16.957Z,1558212496.957 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:19.785Z,1558212499.785 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:21.805Z,1558212501.805 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:23.825Z,1558212503.825 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:25.845Z,1558212505.845 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:27.869Z,1558212507.869 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:31.101Z,1558212511.101 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:33.925Z,1558212513.925 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:37.161Z,1558212517.161 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:39.989Z,1558212519.989 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:43.225Z,1558212523.225 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:46.045Z,1558212526.045 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:48.873Z,1558212528.873 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:50.897Z,1558212530.897 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:53.730Z,1558212533.730 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-18T20:48:53.730Z,1558212533.730 [Default:CheckIn:C.Wait] Stopped
2019-05-18T20:48:53.730Z,1558212533.730 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-18T20:48:53.731Z,1558212533.731 [Default:CheckIn:D] Running Loop=1
2019-05-18T20:48:54.125Z,1558212534.125 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:48:54.150Z,1558212534.150 [Default:CheckIn:D] Stopped
2019-05-18T20:48:54.151Z,1558212534.151 [Default:CheckIn:E] Running Loop=1
2019-05-18T20:48:54.566Z,1558212534.566 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.985350 min 
2019-05-18T20:48:54.566Z,1558212534.566 [Default:CheckIn:E] Stopped
2019-05-18T20:48:54.566Z,1558212534.566 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn] Stopped
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn](INFO): Running loop #2
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn] Running Loop=2
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-18T20:48:54.567Z,1558212534.567 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-18T20:48:56.957Z,1558212536.957 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:00.178Z,1558212540.178 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-05-18T20:49:00.178Z,1558212540.178 [NAL9602] Data Fault, FailCount= 2
2019-05-18T20:49:00.178Z,1558212540.178 [NAL9602](ERROR): Data Fault
2019-05-18T20:49:00.208Z,1558212540.208 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-18T20:49:00.580Z,1558212540.580 [NAL9602](INFO): Powering down
2019-05-18T20:49:01.426Z,1558212541.426 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-18T20:49:01.426Z,1558212541.426 [NAL9602] No Fault, FailCount= 2
2019-05-18T20:49:30.878Z,1558212570.878 [NAL9602](INFO): Powering up NAL9602
2019-05-18T20:49:41.790Z,1558212581.790 [NAL9602](INFO): NAL9602 initialized
2019-05-18T20:49:42.609Z,1558212582.609 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:45.437Z,1558212585.437 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:47.058Z,1558212587.058 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-18T20:49:47.058Z,1558212587.058 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2019-05-18T20:49:47.058Z,1558212587.058 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-18T20:49:47.068Z,1558212587.068 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-18T20:49:47.482Z,1558212587.482 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-18T20:49:47.482Z,1558212587.482 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2019-05-18T20:49:48.261Z,1558212588.261 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:51.501Z,1558212591.501 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:54.325Z,1558212594.325 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:57.149Z,1558212597.149 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:49:59.173Z,1558212599.173 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:01.193Z,1558212601.193 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:04.429Z,1558212604.429 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:07.249Z,1558212607.249 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:10.485Z,1558212610.485 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:13.309Z,1558212613.309 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:16.545Z,1558212616.545 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:19.373Z,1558212619.373 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:22.201Z,1558212622.201 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:24.221Z,1558212624.221 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:26.241Z,1558212626.241 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:29.473Z,1558212629.473 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:32.301Z,1558212632.301 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:35.529Z,1558212635.529 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:38.361Z,1558212638.361 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:41.589Z,1558212641.589 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:44.425Z,1558212644.425 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:47.245Z,1558212647.245 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:49.265Z,1558212649.265 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:52.497Z,1558212652.497 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:55.329Z,1558212655.329 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:50:58.565Z,1558212658.565 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:01.389Z,1558212661.389 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:04.617Z,1558212664.617 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:07.445Z,1558212667.445 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:10.273Z,1558212670.273 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:12.297Z,1558212672.297 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:14.313Z,1558212674.313 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:16.155Z,1558212676.155 [CommandLine](IMPORTANT): got command restart application
2019-05-18T20:51:17.169Z,1558212677.169 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:17.169Z,1558212677.169 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.297Z,1558212677.297 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-18T20:51:17.297Z,1558212677.297 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.298Z,1558212677.298 [CommandLine](INFO): Join timeout helper Thread ID is 1468
2019-05-18T20:51:17.298Z,1558212677.298 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-18T20:51:17.298Z,1558212677.298 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.299Z,1558212677.299 [NavChartDb](INFO): Join timeout helper Thread ID is 1469
2019-05-18T20:51:17.305Z,1558212677.305 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:17.305Z,1558212677.305 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.317Z,1558212677.317 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-18T20:51:17.317Z,1558212677.317 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.317Z,1558212677.317 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1470
2019-05-18T20:51:17.545Z,1558212677.545 [NAL9602](DEBUG): Fix Requested
2019-05-18T20:51:17.725Z,1558212677.725 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:17.725Z,1558212677.725 [WetLabsBB2FL](INFO): Powering down
2019-05-18T20:51:17.726Z,1558212677.726 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.729Z,1558212677.729 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-18T20:51:17.729Z,1558212677.729 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.729Z,1558212677.729 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1471
2019-05-18T20:51:17.797Z,1558212677.797 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:17.797Z,1558212677.797 [CTD_NeilBrown](INFO): Powering down
2019-05-18T20:51:17.809Z,1558212677.809 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.809Z,1558212677.809 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-18T20:51:17.809Z,1558212677.809 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.810Z,1558212677.810 [Radio_Surface](INFO): Join timeout helper Thread ID is 1472
2019-05-18T20:51:17.849Z,1558212677.849 [Radio_Surface](INFO): Powering down
2019-05-18T20:51:17.850Z,1558212677.850 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:17.850Z,1558212677.850 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.858Z,1558212677.858 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-18T20:51:17.858Z,1558212677.858 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:17.858Z,1558212677.858 [DataOverHttps](INFO): Join timeout helper Thread ID is 1473
2019-05-18T20:51:18.169Z,1558212678.169 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:18.169Z,1558212678.169 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.182Z,1558212678.181 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-18T20:51:18.182Z,1558212678.182 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.182Z,1558212678.182 [logger](INFO): Join timeout helper Thread ID is 1474
2019-05-18T20:51:18.217Z,1558212678.217 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:18.217Z,1558212678.217 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.221Z,1558212678.221 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-18T20:51:18.222Z,1558212678.222 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.222Z,1558212678.222 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-18T20:51:18.222Z,1558212678.222 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.222Z,1558212678.222 [controlThread](INFO): Join timeout helper Thread ID is 1475
2019-05-18T20:51:18.333Z,1558212678.333 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-18T20:51:18.333Z,1558212678.333 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-18T20:51:18.334Z,1558212678.334 [NAL9602](INFO): Powering down
2019-05-18T20:51:18.335Z,1558212678.335 [DAT](INFO): Powering down
2019-05-18T20:51:18.455Z,1558212678.455 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-18T20:51:18.456Z,1558212678.456 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-18T20:51:18.456Z,1558212678.456 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-18T20:51:18.457Z,1558212678.457 [MissionManager](INFO): Uninitializing Mission Default
2019-05-18T20:51:18.457Z,1558212678.457 [Default] Stopped
2019-05-18T20:51:18.457Z,1558212678.457 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-18T20:51:18.457Z,1558212678.457 [Default:B.GoToSurface] Stopped
2019-05-18T20:51:18.457Z,1558212678.457 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-18T20:51:18.457Z,1558212678.457 [Default:CheckIn] Stopped
2019-05-18T20:51:18.457Z,1558212678.457 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-18T20:51:18.458Z,1558212678.458 [Default:CheckIn:Read_GPS] Stopped
2019-05-18T20:51:18.460Z,1558212678.460 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-18T20:51:18.460Z,1558212678.460 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-18T20:51:18.460Z,1558212678.460 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-18T20:51:18.461Z,1558212678.461 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-18T20:51:18.461Z,1558212678.461 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-18T20:51:18.461Z,1558212678.461 [BuoyancyServo](INFO): Powering down
2019-05-18T20:51:18.473Z,1558212678.473 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-18T20:51:18.473Z,1558212678.473 [ElevatorServo](INFO): Powering down
2019-05-18T20:51:18.474Z,1558212678.474 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-18T20:51:18.474Z,1558212678.474 [MassServo](INFO): Powering down
2019-05-18T20:51:18.475Z,1558212678.475 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-18T20:51:18.475Z,1558212678.475 [RudderServo](INFO): Powering down
2019-05-18T20:51:18.476Z,1558212678.476 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-18T20:51:18.476Z,1558212678.476 [ThrusterServo](INFO): Powering down
2019-05-18T20:51:18.476Z,1558212678.476 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-18T20:51:18.477Z,1558212678.477 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-18T20:51:18.477Z,1558212678.477 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-18T20:51:18.477Z,1558212678.477 [CBIT](DEBUG): Powering off loads.
2019-05-18T20:51:18.489Z,1558212678.489 [CBIT](DEBUG): Disabling WDT.
2019-05-18T20:51:18.501Z,1558212678.501 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-18T20:51:18.501Z,1558212678.501 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.540Z,1558212678.540 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.546Z,1558212678.546 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.574Z,1558212678.574 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.698Z,1558212678.698 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.741Z,1558212678.741 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-18T20:51:18.795Z,1558212678.795 [logger ThreadHandler](INFO): Thread cancelled.