2017-09-11T18:51:15.378Z,1505155875.378 [Supervisor](DEBUG): Initializing supervisor.
2017-09-11T18:51:15.382Z,1505155875.382 [SyncHandler](DEBUG): Created PCaller Thread at 4051A4E0
2017-09-11T18:51:15.383Z,1505155875.383 [SyncHandler](INFO): Protected caller Thread ID is 3009
2017-09-11T18:51:15.384Z,1505155875.384 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2017-09-11T18:51:15.385Z,1505155875.385 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4054A4E0
2017-09-11T18:51:15.385Z,1505155875.385 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3010
2017-09-11T18:51:15.390Z,1505155875.390 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2017-09-11T18:51:15.406Z,1505155875.406 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2017-09-11T18:51:15.407Z,1505155875.407 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4057A4E0
2017-09-11T18:51:15.408Z,1505155875.408 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3011
2017-09-11T18:51:15.408Z,1505155875.408 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2017-09-11T18:51:15.410Z,1505155875.410 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405AA4E0
2017-09-11T18:51:15.410Z,1505155875.410 [logger ThreadHandler](INFO): Protected caller Thread ID is 3012
2017-09-11T18:51:15.413Z,1505155875.413 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2017-09-11T18:51:15.413Z,1505155875.413 [Supervisor](INFO): Looking for Config files in directory: Config/
2017-09-11T18:51:15.415Z,1505155875.415 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2017-09-11T18:51:15.618Z,1505155875.618 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2017-09-11T18:51:15.618Z,1505155875.618 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2017-09-11T18:51:15.759Z,1505155875.759 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2017-09-11T18:51:15.759Z,1505155875.759 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2017-09-11T18:51:16.142Z,1505155876.142 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2017-09-11T18:51:16.143Z,1505155876.143 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2017-09-11T18:51:16.294Z,1505155876.294 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2017-09-11T18:51:16.295Z,1505155876.295 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2017-09-11T18:51:16.379Z,1505155876.379 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2017-09-11T18:51:16.603Z,1505155876.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2017-09-11T18:51:16.603Z,1505155876.603 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2017-09-11T18:51:16.712Z,1505155876.712 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2017-09-11T18:51:16.713Z,1505155876.713 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2017-09-11T18:51:17.046Z,1505155877.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2017-09-11T18:51:17.047Z,1505155877.047 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2017-09-11T18:51:17.471Z,1505155877.471 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2017-09-11T18:51:17.471Z,1505155877.471 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2017-09-11T18:51:17.826Z,1505155877.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2017-09-11T18:51:17.826Z,1505155877.826 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2017-09-11T18:51:18.530Z,1505155878.530 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2017-09-11T18:51:18.531Z,1505155878.531 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2017-09-11T18:51:18.742Z,1505155878.742 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2017-09-11T18:51:18.743Z,1505155878.743 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2017-09-11T18:51:18.849Z,1505155878.849 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2017-09-11T18:51:18.850Z,1505155878.850 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2017-09-11T18:51:19.399Z,1505155879.399 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2017-09-11T18:51:19.399Z,1505155879.399 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2017-09-11T18:51:19.515Z,1505155879.515 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2017-09-11T18:51:19.517Z,1505155879.517 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2017-09-11T18:51:19.518Z,1505155879.518 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2017-09-11T18:51:19.817Z,1505155879.817 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2017-09-11T18:51:19.818Z,1505155879.818 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2017-09-11T18:51:19.925Z,1505155879.925 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2017-09-11T18:51:20.020Z,1505155880.020 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2017-09-11T18:51:20.139Z,1505155880.139 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2017-09-11T18:51:20.245Z,1505155880.245 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2017-09-11T18:51:20.383Z,1505155880.383 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2017-09-11T18:51:20.553Z,1505155880.553 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2017-09-11T18:51:20.654Z,1505155880.654 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2017-09-11T18:51:20.752Z,1505155880.752 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2017-09-11T18:51:20.839Z,1505155880.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2017-09-11T18:51:21.069Z,1505155881.069 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2017-09-11T18:51:21.151Z,1505155881.151 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2017-09-11T18:51:21.151Z,1505155881.151 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2017-09-11T18:51:21.161Z,1505155881.161 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2017-09-11T18:51:21.309Z,1505155881.309 [SBIT](DEBUG): Construct Startup Built In Test.
2017-09-11T18:51:21.396Z,1505155881.396 [SBIT] Loaded
2017-09-11T18:51:21.396Z,1505155881.396 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2017-09-11T18:51:21.397Z,1505155881.397 [IBIT](DEBUG): Construct Initiated Built In Test.
2017-09-11T18:51:21.432Z,1505155881.432 [IBIT] Loaded
2017-09-11T18:51:21.432Z,1505155881.432 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2017-09-11T18:51:21.437Z,1505155881.437 [CBIT](DEBUG): Construct Continuous Built In Test.
2017-09-11T18:51:21.652Z,1505155881.652 [CBIT] Loaded
2017-09-11T18:51:21.652Z,1505155881.652 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2017-09-11T18:51:21.652Z,1505155881.652 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2017-09-11T18:51:21.653Z,1505155881.653 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2017-09-11T18:51:21.724Z,1505155881.724 [VerticalControl](DEBUG): Construct VerticalControl.
2017-09-11T18:51:21.845Z,1505155881.845 [VerticalControl] Loaded
2017-09-11T18:51:21.845Z,1505155881.845 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2017-09-11T18:51:21.846Z,1505155881.846 [HorizontalControl](DEBUG): Construct HorizontalControl.
2017-09-11T18:51:21.924Z,1505155881.924 [HorizontalControl] Loaded
2017-09-11T18:51:21.924Z,1505155881.924 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2017-09-11T18:51:21.925Z,1505155881.925 [SpeedControl](DEBUG): Construct SpeedControl.
2017-09-11T18:51:21.932Z,1505155881.932 [SpeedControl] Loaded
2017-09-11T18:51:21.932Z,1505155881.932 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2017-09-11T18:51:21.933Z,1505155881.933 [LoopControl](DEBUG): Construct LoopControl.
2017-09-11T18:51:21.934Z,1505155881.934 [LoopControl] Loaded
2017-09-11T18:51:21.934Z,1505155881.934 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2017-09-11T18:51:21.935Z,1505155881.935 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2017-09-11T18:51:21.935Z,1505155881.935 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2017-09-11T18:51:21.962Z,1505155881.962 [DepthRateCalculator] Loaded
2017-09-11T18:51:21.962Z,1505155881.962 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2017-09-11T18:51:21.968Z,1505155881.968 [PitchRateCalculator] Loaded
2017-09-11T18:51:21.969Z,1505155881.969 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2017-09-11T18:51:21.988Z,1505155881.988 [SpeedCalculator] Loaded
2017-09-11T18:51:21.988Z,1505155881.988 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2017-09-11T18:51:22.014Z,1505155882.014 [TempGradientCalculator] Loaded
2017-09-11T18:51:22.014Z,1505155882.014 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2017-09-11T18:51:22.033Z,1505155882.033 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2017-09-11T18:51:22.034Z,1505155882.034 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2017-09-11T18:51:22.040Z,1505155882.040 [YawRateCalculator] Loaded
2017-09-11T18:51:22.040Z,1505155882.040 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2017-09-11T18:51:22.041Z,1505155882.041 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2017-09-11T18:51:22.041Z,1505155882.041 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2017-09-11T18:51:22.127Z,1505155882.127 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC
2017-09-11T18:51:22.127Z,1505155882.127 [StratificationFrontDetector](DEBUG): (re)initializing
2017-09-11T18:51:22.128Z,1505155882.128 [StratificationFrontDetector] Loaded
2017-09-11T18:51:22.128Z,1505155882.128 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2017-09-11T18:51:22.129Z,1505155882.129 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2017-09-11T18:51:22.129Z,1505155882.129 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2017-09-11T18:51:22.364Z,1505155882.364 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2017-09-11T18:51:22.365Z,1505155882.365 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2017-09-11T18:51:22.478Z,1505155882.478 [DeadReckonUsingMultipleVelocitySources] Loaded
2017-09-11T18:51:22.479Z,1505155882.479 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2017-09-11T18:51:22.547Z,1505155882.547 [DeadReckonUsingSpeedCalculator] Loaded
2017-09-11T18:51:22.548Z,1505155882.548 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2017-09-11T18:51:22.569Z,1505155882.569 [NavChart] Loaded
2017-09-11T18:51:22.569Z,1505155882.569 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2017-09-11T18:51:22.574Z,1505155882.574 [UniversalFixResidualReporter] Loaded
2017-09-11T18:51:22.575Z,1505155882.575 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2017-09-11T18:51:22.575Z,1505155882.575 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2017-09-11T18:51:22.576Z,1505155882.576 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2017-09-11T18:51:22.591Z,1505155882.591 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2017-09-11T18:51:22.591Z,1505155882.591 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2017-09-11T18:51:22.751Z,1505155882.751 [Aanderaa_O2] Loaded
2017-09-11T18:51:22.752Z,1505155882.752 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2017-09-11T18:51:22.859Z,1505155882.859 [CTD_NeilBrown] Loaded
2017-09-11T18:51:22.859Z,1505155882.859 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2017-09-11T18:51:22.860Z,1505155882.860 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408154E0
2017-09-11T18:51:22.861Z,1505155882.861 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3095
2017-09-11T18:51:22.880Z,1505155882.880 [PAR_Licor] Loaded
2017-09-11T18:51:22.880Z,1505155882.880 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2017-09-11T18:51:22.938Z,1505155882.938 [WetLabsBB2FL] Loaded
2017-09-11T18:51:22.939Z,1505155882.939 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2017-09-11T18:51:22.940Z,1505155882.940 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408454E0
2017-09-11T18:51:22.940Z,1505155882.940 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 3096
2017-09-11T18:51:22.941Z,1505155882.941 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2017-09-11T18:51:22.942Z,1505155882.942 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2017-09-11T18:51:23.221Z,1505155883.221 [DataOverHttps] Loaded
2017-09-11T18:51:23.221Z,1505155883.221 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2017-09-11T18:51:23.238Z,1505155883.238 [Depth_Keller] Loaded
2017-09-11T18:51:23.238Z,1505155883.238 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2017-09-11T18:51:23.245Z,1505155883.245 [DropWeight] Loaded
2017-09-11T18:51:23.245Z,1505155883.245 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2017-09-11T18:51:23.358Z,1505155883.358 [NAL9602] Loaded
2017-09-11T18:51:23.358Z,1505155883.358 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2017-09-11T18:51:23.370Z,1505155883.370 [Onboard] Loaded
2017-09-11T18:51:23.370Z,1505155883.370 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2017-09-11T18:51:23.379Z,1505155883.379 [Radio_Surface] Loaded
2017-09-11T18:51:23.380Z,1505155883.380 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2017-09-11T18:51:23.381Z,1505155883.381 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40ACC4E0
2017-09-11T18:51:23.381Z,1505155883.381 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3097
2017-09-11T18:51:23.441Z,1505155883.441 [PNI_TCM] Loaded
2017-09-11T18:51:23.441Z,1505155883.441 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2017-09-11T18:51:25.980Z,1505155885.980 [BPC1] Loaded
2017-09-11T18:51:25.980Z,1505155885.980 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2017-09-11T18:51:25.981Z,1505155885.981 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2017-09-11T18:51:25.981Z,1505155885.981 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2017-09-11T18:51:26.084Z,1505155886.084 [BuoyancyServo] Loaded
2017-09-11T18:51:26.085Z,1505155886.085 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2017-09-11T18:51:26.100Z,1505155886.100 [ElevatorServo] Loaded
2017-09-11T18:51:26.100Z,1505155886.100 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2017-09-11T18:51:26.115Z,1505155886.115 [MassServo] Loaded
2017-09-11T18:51:26.115Z,1505155886.115 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2017-09-11T18:51:26.130Z,1505155886.130 [RudderServo] Loaded
2017-09-11T18:51:26.130Z,1505155886.130 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2017-09-11T18:51:26.145Z,1505155886.145 [ThrusterServo] Loaded
2017-09-11T18:51:26.145Z,1505155886.145 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2017-09-11T18:51:26.145Z,1505155886.145 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2017-09-11T18:51:26.146Z,1505155886.146 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2017-09-11T18:51:26.247Z,1505155886.247 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2017-09-11T18:51:26.248Z,1505155886.248 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2017-09-11T18:51:26.273Z,1505155886.273 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2017-09-11T18:51:26.279Z,1505155886.279 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2017-09-11T18:51:26.280Z,1505155886.280 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2017-09-11T18:51:26.291Z,1505155886.291 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2017-09-11T18:51:26.292Z,1505155886.292 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BA04E0
2017-09-11T18:51:26.293Z,1505155886.293 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3098
2017-09-11T18:51:26.300Z,1505155886.300 [Supervisor](INFO): Main Thread ID is 3008
2017-09-11T18:51:26.300Z,1505155886.300 [Supervisor](DEBUG): Running supervisor.
2017-09-11T18:51:26.301Z,1505155886.301 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3099
2017-09-11T18:51:26.304Z,1505155886.304 [controlThread ThreadHandler](INFO): Handler Thread ID is 3100
2017-09-11T18:51:26.305Z,1505155886.305 [controlThread](DEBUG): Initializing ControlThread
2017-09-11T18:51:26.306Z,1505155886.306 [SBIT](INFO): Initialize SBIT Component.
2017-09-11T18:51:26.306Z,1505155886.306 [SBIT](IMPORTANT): git: 2017-08-02-81-g2dedf71
2017-09-11T18:51:26.307Z,1505155886.307 [SBIT](INFO): git hash: 2dedf719d304b5c3f7e3acd061a0c8109ea4feed
2017-09-11T18:51:26.309Z,1505155886.309 [SBIT](INFO): Kernel Reporting Different Release From Configuration.
Kernel Expected: 2.6.27.8
Kernel Reported: 2.6.27.8-00011-g2bc81df-dirty
2017-09-11T18:51:26.309Z,1505155886.309 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
Kernel Reported: #646 PREEMPT Thu Feb 11 17:01:12 PST 2016
2017-09-11T18:51:26.310Z,1505155886.310 [SBIT](INFO): Beginning SBIT in 71.000000 seconds.
2017-09-11T18:51:26.311Z,1505155886.311 [IBIT](INFO): Initialize IBIT Component.
2017-09-11T18:51:26.312Z,1505155886.312 [CBIT](DEBUG): Initialize CBIT Component.
2017-09-11T18:51:26.312Z,1505155886.312 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2017-09-11T18:51:26.313Z,1505155886.313 [logger ThreadHandler](INFO): Handler Thread ID is 3101
2017-09-11T18:51:26.341Z,1505155886.341 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3102
2017-09-11T18:51:26.342Z,1505155886.342 [CTD_NeilBrown](INFO): Powering down
2017-09-11T18:51:26.376Z,1505155886.376 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 3103
2017-09-11T18:51:26.377Z,1505155886.377 [WetLabsBB2FL](INFO): Powering down
2017-09-11T18:51:26.397Z,1505155886.397 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2017-09-11T18:51:26.399Z,1505155886.399 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2017-09-11T18:51:26.400Z,1505155886.400 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2017-09-11T18:51:26.400Z,1505155886.400 [LoopControl](DEBUG): Initialize LoopControlComponent.
2017-09-11T18:51:26.401Z,1505155886.401 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2017-09-11T18:51:26.401Z,1505155886.401 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2017-09-11T18:51:26.402Z,1505155886.402 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2017-09-11T18:51:26.402Z,1505155886.402 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2017-09-11T18:51:26.403Z,1505155886.403 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2017-09-11T18:51:26.404Z,1505155886.404 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2017-09-11T18:51:26.405Z,1505155886.405 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-11T18:51:26.406Z,1505155886.406 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-11T18:51:26.406Z,1505155886.406 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-11T18:51:26.407Z,1505155886.407 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2017-09-11T18:51:26.407Z,1505155886.407 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2017-09-11T18:51:26.407Z,1505155886.407 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2017-09-11T18:51:26.408Z,1505155886.408 [NavChart](DEBUG): Initialize NavChart Navigation.
2017-09-11T18:51:26.408Z,1505155886.408 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2017-09-11T18:51:26.447Z,1505155886.447 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3104
2017-09-11T18:51:26.474Z,1505155886.474 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2017-09-11T18:51:26.488Z,1505155886.488 [Radio_Surface](INFO): Powering up
2017-09-11T18:51:26.497Z,1505155886.497 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3105
2017-09-11T18:51:26.502Z,1505155886.502 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2017-09-11T18:51:26.502Z,1505155886.502 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2017-09-11T18:51:26.503Z,1505155886.503 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2017-09-11T18:51:26.503Z,1505155886.503 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2017-09-11T18:51:26.503Z,1505155886.503 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2017-09-11T18:51:26.503Z,1505155886.503 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2017-09-11T18:51:26.503Z,1505155886.503 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2017-09-11T18:51:26.504Z,1505155886.504 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2017-09-11T18:51:26.504Z,1505155886.504 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2017-09-11T18:51:26.504Z,1505155886.504 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2017-09-11T18:51:26.504Z,1505155886.504 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2017-09-11T18:51:26.505Z,1505155886.505 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2017-09-11T18:51:26.505Z,1505155886.505 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2017-09-11T18:51:26.505Z,1505155886.505 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2017-09-11T18:51:26.506Z,1505155886.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2017-09-11T18:51:26.506Z,1505155886.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2017-09-11T18:51:26.547Z,1505155886.547 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2017-09-11T18:51:26.584Z,1505155886.584 [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>


2017-09-11T18:51:26.585Z,1505155886.585 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2017-09-11T18:51:26.661Z,1505155886.661 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2017-09-11T18:51:26.663Z,1505155886.663 [Default:A.Wait](DEBUG): Construct Wait.
2017-09-11T18:51:26.665Z,1505155886.665 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2017-09-11T18:51:26.714Z,1505155886.714 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2017-09-11T18:51:26.733Z,1505155886.733 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2017-09-11T18:51:26.741Z,1505155886.741 [Default:E.Execute](DEBUG): Construct Execute.
2017-09-11T18:51:26.745Z,1505155886.745 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
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/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="Default">

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

    <Guidance:Wait>
        <Sequence/>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <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">
            <Sequence/>
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Sequence/>
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn 300</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>


2017-09-11T18:51:26.766Z,1505155886.766 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2017-09-11T18:51:26.956Z,1505155886.956 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2017-09-11T18:51:26.982Z,1505155886.982 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2017-09-11T18:51:27.259Z,1505155887.259 [DepthRateCalculator](ERROR): Depth measurement is not active
2017-09-11T18:51:27.383Z,1505155887.383 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:27.410Z,1505155887.410 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:27.568Z,1505155887.568 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2017-09-11T18:51:27.575Z,1505155887.575 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2017-09-11T18:51:27.593Z,1505155887.593 [ElevatorServo](DEBUG): Initializing EZServoServo.
2017-09-11T18:51:27.599Z,1505155887.599 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2017-09-11T18:51:27.606Z,1505155887.606 [MassServo](DEBUG): Initializing EZServoServo.
2017-09-11T18:51:27.623Z,1505155887.623 [MassServo](DEBUG): Initializing MassServo.
2017-09-11T18:51:27.630Z,1505155887.630 [RudderServo](DEBUG): Initializing EZServoServo.
2017-09-11T18:51:27.635Z,1505155887.635 [RudderServo](DEBUG): Initializing RudderServo.
2017-09-11T18:51:27.641Z,1505155887.641 [ThrusterServo](DEBUG): Initializing EZServoServo.
2017-09-11T18:51:27.647Z,1505155887.647 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2017-09-11T18:51:27.942Z,1505155887.942 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2017-09-11T18:51:27.942Z,1505155887.942 [DropWeight] Hardware Fault, FailCount= 1
2017-09-11T18:51:27.942Z,1505155887.942 [DropWeight](ERROR): Hardware Fault
2017-09-11T18:51:28.029Z,1505155888.029 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:28.031Z,1505155888.031 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:28.076Z,1505155888.076 [CommandLine](FAULT): Scheduling is paused
2017-09-11T18:51:28.077Z,1505155888.077 [CBIT](INFO): Critical error at 20170911T185127
2017-09-11T18:51:28.077Z,1505155888.077 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2017-09-11T18:51:28.081Z,1505155888.081 [CBIT](ERROR): Hardware Fault in component: DropWeight
2017-09-11T18:51:28.082Z,1505155888.082 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2017-09-11T18:51:28.244Z,1505155888.244 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:28.246Z,1505155888.246 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:28.614Z,1505155888.614 [CBIT](INFO): Critical error at 20170911T185128
2017-09-11T18:51:28.666Z,1505155888.666 [NAL9602](INFO): Powering up NAL9602
2017-09-11T18:51:28.710Z,1505155888.710 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:28.711Z,1505155888.711 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:29.071Z,1505155889.071 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:29.074Z,1505155889.074 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:29.478Z,1505155889.478 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:29.479Z,1505155889.479 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:29.946Z,1505155889.946 [Aanderaa_O2](INFO): Powering down
2017-09-11T18:51:30.131Z,1505155890.131 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:30.132Z,1505155890.132 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:30.379Z,1505155890.379 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:30.381Z,1505155890.381 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-11T18:51:39.776Z,1505155899.776 [NAL9602](INFO): NAL9602 initialized
2017-09-11T18:51:57.402Z,1505155917.402 [BPC1](ERROR): Failed to receive battery data
2017-09-11T18:51:57.402Z,1505155917.402 [BPC1] Communications Fault, FailCount= 1
2017-09-11T18:51:57.402Z,1505155917.402 [BPC1](ERROR): Communications Fault
2017-09-11T18:51:57.496Z,1505155917.496 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-11T18:51:58.702Z,1505155918.702 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-11T18:51:58.702Z,1505155918.702 [BPC1] No Fault, FailCount= 1
2017-09-11T18:52:37.885Z,1505155957.885 [SBIT](IMPORTANT): Beginning Startup BIT
2017-09-11T18:52:37.906Z,1505155957.906 [CBIT](IMPORTANT): Beginning ground fault scan
2017-09-11T18:52:48.536Z,1505155968.536 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.003052
CHAN A1 (24V): 0.127083
CHAN A2 (12V): -0.002636
CHAN A3 (5V): 0.000180
CHAN B0 (3.3V): -0.000368
CHAN B1 (3.15aV): -0.000388
CHAN B2 (3.15bV): 4.767929
CHAN B3 (GND): 0.027570
OPEN: -0.000357
Full Scale Calc: 4.765 mA, -1.589 mA
2017-09-11T18:53:09.464Z,1505155989.464 [CommandLine](IMPORTANT): got command failComponent
2017-09-11T18:53:09.465Z,1505155989.465 [CommandLine](IMPORTANT): Failed components:
2017-09-11T18:53:09.465Z,1505155989.465 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2017-09-11T18:53:24.806Z,1505156004.806 [PNI_TCM](ERROR): CRC does not match. Expected:0x54692 got:0x0
2017-09-11T18:53:26.422Z,1505156006.422 [PNI_TCM](ERROR): CRC does not match. Expected:0x49868 got:0x100
2017-09-11T18:53:31.280Z,1505156011.280 [SBIT](IMPORTANT): SBIT PASSED
2017-09-11T18:53:31.552Z,1505156011.552 [MissionManager](IMPORTANT): Started mission Startup
2017-09-11T18:53:31.552Z,1505156011.552 [Startup] Running Loop=1
2017-09-11T18:53:31.553Z,1505156011.553 [Startup](DEBUG): Aggregate::initialize Startup
2017-09-11T18:53:31.553Z,1505156011.553 [Startup:A.GoToSurface] Running Loop=1
2017-09-11T18:53:31.553Z,1505156011.553 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2017-09-11T18:53:31.553Z,1505156011.553 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2017-09-11T18:53:31.554Z,1505156011.554 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2017-09-11T18:53:31.558Z,1505156011.558 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2017-09-11T18:53:31.559Z,1505156011.559 [Startup:A.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds.
2017-09-11T18:53:31.559Z,1505156011.559 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2017-09-11T18:53:31.575Z,1505156011.575 [Startup:StartupSatComms] Running Loop=1
2017-09-11T18:53:31.576Z,1505156011.576 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2017-09-11T18:53:31.576Z,1505156011.576 [Startup:StartupSatComms:A] Running Loop=1
2017-09-11T18:53:31.861Z,1505156011.861 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003606
2017-09-11T18:53:31.956Z,1505156011.956 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2017-09-11T18:54:26.709Z,1505156066.709 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-11T18:54:26.709Z,1505156066.709 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2017-09-11T18:54:26.709Z,1505156066.709 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-11T18:54:26.711Z,1505156066.711 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-11T18:54:26.711Z,1505156066.711 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2017-09-11T18:54:26.712Z,1505156066.712 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2017-09-11T18:54:26.746Z,1505156066.746 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-11T18:54:26.747Z,1505156066.747 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2017-09-11T18:54:27.152Z,1505156067.152 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-11T18:54:27.152Z,1505156067.152 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2017-09-11T18:54:27.153Z,1505156067.153 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2017-09-11T18:54:27.153Z,1505156067.153 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2017-09-11T18:54:27.522Z,1505156067.522 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-11T18:54:27.522Z,1505156067.522 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-11T18:54:27.522Z,1505156067.522 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-11T18:54:27.531Z,1505156067.531 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2017-09-11T18:54:27.532Z,1505156067.532 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2017-09-11T18:54:27.532Z,1505156067.532 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2017-09-11T18:54:27.916Z,1505156067.916 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.2 s old, using for 20.0 s.
2017-09-11T18:54:31.222Z,1505156071.222 [BPC1](ERROR): Failed to receive battery data
2017-09-11T18:54:31.223Z,1505156071.223 [BPC1] Communications Fault, FailCount= 1
2017-09-11T18:54:31.223Z,1505156071.223 [BPC1](ERROR): Communications Fault
2017-09-11T18:54:31.233Z,1505156071.233 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.5 s old, using for 20.0 s.
2017-09-11T18:54:31.249Z,1505156071.249 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-11T18:54:31.422Z,1505156071.422 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.7 s old, using for 20.0 s.
2017-09-11T18:54:31.753Z,1505156071.753 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.0 s old, using for 20.0 s.
2017-09-11T18:54:31.757Z,1505156071.757 [Startup:StartupSatComms:A](INFO): Timed out from 2017-09-11T18:53:31.6Z
2017-09-11T18:54:31.757Z,1505156071.757 [Startup:StartupSatComms:A] Stopped
2017-09-11T18:54:31.757Z,1505156071.757 [Startup:StartupSatComms:B] Running Loop=1
2017-09-11T18:54:32.140Z,1505156072.140 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.4 s old, using for 20.0 s.
2017-09-11T18:54:32.144Z,1505156072.144 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2017-09-11T18:54:32.172Z,1505156072.172 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-11T18:54:32.172Z,1505156072.172 [BPC1] No Fault, FailCount= 1
2017-09-11T18:54:32.777Z,1505156072.777 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.1 s old, using for 20.0 s.
2017-09-11T18:54:32.930Z,1505156072.930 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.2 s old, using for 20.0 s.
2017-09-11T18:54:36.238Z,1505156076.238 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.5 s old, using for 20.0 s.
2017-09-11T18:54:36.318Z,1505156076.318 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170908T234530/Courier0448.lzma
2017-09-11T18:54:36.410Z,1505156076.410 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.7 s old, using for 20.0 s.
2017-09-11T18:54:36.763Z,1505156076.763 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.1 s old, using for 20.0 s.
2017-09-11T18:54:37.156Z,1505156077.156 [DataOverHttps](INFO): Moved sent file to Logs/20170908T234530/Courier0448.lzma.bak
2017-09-11T18:54:37.157Z,1505156077.157 [DataOverHttps](INFO): SBD MOMSN=5085260
2017-09-11T18:54:37.256Z,1505156077.256 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.5 s old, using for 20.0 s.
2017-09-11T18:54:37.768Z,1505156077.768 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.1 s old, using for 20.0 s.
2017-09-11T18:54:37.973Z,1505156077.973 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.3 s old, using for 20.0 s.
2017-09-11T18:54:41.282Z,1505156081.282 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.6 s old, using for 20.0 s.
2017-09-11T18:54:41.448Z,1505156081.448 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.7 s old, using for 20.0 s.
2017-09-11T18:54:41.837Z,1505156081.837 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.1 s old, using for 20.0 s.
2017-09-11T18:54:42.231Z,1505156082.231 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.5 s old, using for 20.0 s.
2017-09-11T18:54:42.605Z,1505156082.605 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.9 s old, using for 20.0 s.
2017-09-11T18:54:43.014Z,1505156083.014 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.3 s old, using for 20.0 s.
2017-09-11T18:54:44.440Z,1505156084.440 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2017-09-11T18:54:44.440Z,1505156084.440 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tracking_on_surface.xml
2017-09-11T18:54:44.466Z,1505156084.466 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 10.000000 min
2017-09-11T18:54:44.515Z,1505156084.515 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 0.000000 count
2017-09-11T18:54:44.526Z,1505156084.526 [MissionManager](INFO): DefineArg tracking_on_surface.NumberOfPings = 1.000000 count
2017-09-11T18:54:44.530Z,1505156084.530 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 60.000000 s
2017-09-11T18:54:44.534Z,1505156084.534 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2017-09-11T18:54:44.555Z,1505156084.555 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = -1.300000 cm
2017-09-11T18:54:44.556Z,1505156084.556 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2017-09-11T18:54:45.002Z,1505156085.002 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Construct Wait.
2017-09-11T18:54:45.019Z,1505156085.019 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Derivation="Tethys/Derivation"
       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/Derivation http://okeanids.mbari.org/tethys/Xml/Derivation.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="tracking_on_surface">

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="ContactLabel"><Units:count/><Value>0</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>60</Value></DefineArg>

    <DefineArg Name="Repeat"><Units:count/><Value>13</Value></DefineArg>

    <DefineArg Name="MassDefault"><Control:VerticalControl.massDefault/></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

    <Derivation:Tracking>
        <Parallel/>
        <Setting><Derivation:Tracking.contactLabelSetting/><Arg Name="ContactLabel"/></Setting>
        <Setting><Derivation:Tracking.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Derivation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Derivation:Tracking>

    <Aggregate Id="TestDrive">

        <Sequence Repeat="Repeat"/>

        <Aggregate Id="Data">

            <When>
                <True/>
            </When>

            <SendData Service="Express">
                <Derivation:Tracking.contact_latitude/><Units:degree/>
                <Derivation:Tracking.contact_longitude/><Units:degree/>
                <Derivation:Tracking.contact_depth/><Units:meter/>
                <Derivation:Tracking.range_to_contact/><Units:meter/>
                <Derivation:Tracking.heading_to_contact/><Units:degree/>
            </SendData>

            <Syslog Severity="None">Pause a cycle</Syslog>

        </Aggregate>

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

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

    </Aggregate>

</Mission>


2017-09-11T18:54:45.022Z,1505156085.022 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2017-09-11T18:54:50.560Z,1505156090.560 [CommandLine](IMPORTANT): got command show variable DAT
2017-09-11T18:54:50.764Z,1505156090.764 [CommandLine](IMPORTANT): CBIT.loadAtStartup (bool)
2017-09-11T18:54:50.766Z,1505156090.766 [CommandLine](IMPORTANT): SBIT.loadAtStartup (bool)
2017-09-11T18:54:50.766Z,1505156090.766 [CommandLine](IMPORTANT): IBIT.loadAtStartup (bool)
2017-09-11T18:54:50.767Z,1505156090.767 [CommandLine](IMPORTANT): DepthRateCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.767Z,1505156090.767 [CommandLine](IMPORTANT): TempGradientCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.780Z,1505156090.780 [CommandLine](IMPORTANT): PitchRateCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.781Z,1505156090.781 [CommandLine](IMPORTANT): SpeedCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.781Z,1505156090.781 [CommandLine](IMPORTANT): VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.782Z,1505156090.782 [CommandLine](IMPORTANT): YawRateCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.782Z,1505156090.782 [CommandLine](IMPORTANT): BackSeatDriver.loadAtStartup (bool)
2017-09-11T18:54:50.783Z,1505156090.783 [CommandLine](IMPORTANT): HorizontalControl.loadAtStartup (bool)
2017-09-11T18:54:50.784Z,1505156090.784 [CommandLine](IMPORTANT): LoopControl.loadAtStartup (bool)
2017-09-11T18:54:50.784Z,1505156090.784 [CommandLine](IMPORTANT): SpeedControl.loadAtStartup (bool)
2017-09-11T18:54:50.785Z,1505156090.785 [CommandLine](IMPORTANT): VerticalControl.loadAtStartup (bool)
2017-09-11T18:54:50.788Z,1505156090.788 [CommandLine](IMPORTANT): HFRadarModelCalc.loadAtStartup (bool)
2017-09-11T18:54:50.788Z,1505156090.788 [CommandLine](IMPORTANT): HFRadarCompactModelForecaster.loadAtStartup (bool)
2017-09-11T18:54:50.789Z,1505156090.789 [CommandLine](IMPORTANT): HFRCMSpaceInterpolator.loadAtStartup (bool)
2017-09-11T18:54:50.789Z,1505156090.789 [CommandLine](IMPORTANT): HFRCMTimeInterpolator.loadAtStartup (bool)
2017-09-11T18:54:50.790Z,1505156090.790 [CommandLine](IMPORTANT): HFRCMReconstructedInterpolator.loadAtStartup (bool)
2017-09-11T18:54:50.790Z,1505156090.790 [CommandLine](IMPORTANT): HFRCMSurfaceCurrentAtVehicleLocation.loadAtStartup (bool)
2017-09-11T18:54:50.791Z,1505156090.791 [CommandLine](IMPORTANT): HFRCMVirtualSurfaceDrifter.loadAtStartup (bool)
2017-09-11T18:54:50.791Z,1505156090.791 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup (bool)
2017-09-11T18:54:50.851Z,1505156090.851 [CommandLine](IMPORTANT): DepAvgTempFrontDetector.loadAtStartup (bool)
2017-09-11T18:54:50.858Z,1505156090.858 [CommandLine](IMPORTANT): DeadReckonUsingMultipleVelocitySources.loadAtStartup (bool)
2017-09-11T18:54:50.860Z,1505156090.860 [CommandLine](IMPORTANT): DeadReckonUsingSpeedCalculator.loadAtStartup (bool)
2017-09-11T18:54:50.874Z,1505156090.874 [CommandLine](IMPORTANT): DeadReckonWithRespectToWater.loadAtStartup (bool)
2017-09-11T18:54:50.875Z,1505156090.875 [CommandLine](IMPORTANT): DeadReckonWithRespectToSeafloor.loadAtStartup (bool)
2017-09-11T18:54:50.876Z,1505156090.876 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.loadAtStartup (bool)
2017-09-11T18:54:50.896Z,1505156090.896 [CommandLine](IMPORTANT): DeadReckonUsingCompactModelForecast.loadAtStartup (bool)
2017-09-11T18:54:50.897Z,1505156090.897 [CommandLine](IMPORTANT): NavChart.loadAtStartup (bool)
2017-09-11T18:54:50.897Z,1505156090.897 [CommandLine](IMPORTANT): UniversalFixResidualReporter.loadAtStartup (bool)
2017-09-11T18:54:50.898Z,1505156090.898 [CommandLine](IMPORTANT): AsyncPiEstimator.loadAtStartup (bool)
2017-09-11T18:54:50.898Z,1505156090.898 [CommandLine](IMPORTANT): lcmLoadTest.loadAtStartup (bool)
2017-09-11T18:54:50.899Z,1505156090.899 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup (bool)
2017-09-11T18:54:50.909Z,1505156090.909 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup (bool)
2017-09-11T18:54:50.910Z,1505156090.910 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup (bool)
2017-09-11T18:54:50.911Z,1505156090.911 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup (bool)
2017-09-11T18:54:50.912Z,1505156090.912 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup (bool)
2017-09-11T18:54:50.925Z,1505156090.925 [CommandLine](IMPORTANT): ISUS.loadAtStartup (bool)
2017-09-11T18:54:50.926Z,1505156090.926 [CommandLine](IMPORTANT): PAR_Licor.loadAtStartup (bool)
2017-09-11T18:54:50.927Z,1505156090.927 [CommandLine](IMPORTANT): Turner_Cyclops_rhodamine.loadAtStartup (bool)
2017-09-11T18:54:50.937Z,1505156090.937 [CommandLine](IMPORTANT): Turbulence_NPS.loadAtStartup (bool)
2017-09-11T18:54:50.937Z,1505156090.937 [CommandLine](IMPORTANT): VemcoVR2C.loadAtStartup (bool)
2017-09-11T18:54:50.938Z,1505156090.938 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup (bool)
2017-09-11T18:54:50.939Z,1505156090.939 [CommandLine](IMPORTANT): AHRS_3DMGX3.loadAtStartup (bool)
2017-09-11T18:54:50.940Z,1505156090.940 [CommandLine](IMPORTANT): AHRS_sp3003D.loadAtStartup (bool)
2017-09-11T18:54:50.961Z,1505156090.961 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool)
2017-09-11T18:54:50.961Z,1505156090.961 [CommandLine](IMPORTANT): Batt_Ocean_Server.loadAtStartup (bool)
2017-09-11T18:54:50.962Z,1505156090.962 [CommandLine](IMPORTANT): BPC1.loadAtStartup (bool)
2017-09-11T18:54:50.962Z,1505156090.962 [CommandLine](IMPORTANT): DataOverHttps.loadAtStartup (bool)
2017-09-11T18:54:50.963Z,1505156090.963 [CommandLine](IMPORTANT): DataOverHttps.power (watt)
2017-09-11T18:54:50.963Z,1505156090.963 [CommandLine](IMPORTANT): DataOverHttps.connectionTimeout (second)
2017-09-11T18:54:50.964Z,1505156090.964 [CommandLine](IMPORTANT): DataOverHttps.period (second)
2017-09-11T18:54:50.964Z,1505156090.964 [CommandLine](IMPORTANT): DataOverHttps.timeout (minute)
2017-09-11T18:54:50.964Z,1505156090.964 [CommandLine](IMPORTANT): DataOverHttps.verbosity (count)
2017-09-11T18:54:50.965Z,1505156090.965 [CommandLine](IMPORTANT): DAT.loadAtStartup (bool)
2017-09-11T18:54:50.965Z,1505156090.965 [CommandLine](IMPORTANT): DAT.simulateHardware (bool)
2017-09-11T18:54:50.966Z,1505156090.966 [CommandLine](IMPORTANT): DAT.localAddress (count)
2017-09-11T18:54:50.966Z,1505156090.966 [CommandLine](IMPORTANT): Depth_Keller.loadAtStartup (bool)
2017-09-11T18:54:50.967Z,1505156090.967 [CommandLine](IMPORTANT): DropWeight.loadAtStartup (bool)
2017-09-11T18:54:50.967Z,1505156090.967 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup (bool)
2017-09-11T18:54:50.984Z,1505156090.984 [CommandLine](IMPORTANT): NAL9602.loadAtStartup (bool)
2017-09-11T18:54:50.985Z,1505156090.985 [CommandLine](IMPORTANT): Onboard.loadAtStartup (bool)
2017-09-11T18:54:50.986Z,1505156090.986 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup (bool)
2017-09-11T18:54:50.986Z,1505156090.986 [CommandLine](IMPORTANT): Radio_Surface.loadAtStartup (bool)
2017-09-11T18:54:50.987Z,1505156090.987 [CommandLine](IMPORTANT): Rowe_600.loadAtStartup (bool)
2017-09-11T18:54:50.988Z,1505156090.988 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup (bool)
2017-09-11T18:54:50.989Z,1505156090.989 [CommandLine](IMPORTANT): SCPI.loadAtStartup (bool)
2017-09-11T18:54:50.989Z,1505156090.989 [CommandLine](IMPORTANT): BuoyancyServo.loadAtStartup (bool)
2017-09-11T18:54:50.990Z,1505156090.990 [CommandLine](IMPORTANT): ElevatorServo.loadAtStartup (bool)
2017-09-11T18:54:50.991Z,1505156090.991 [CommandLine](IMPORTANT): MassServo.loadAtStartup (bool)
2017-09-11T18:54:51.006Z,1505156091.006 [CommandLine](IMPORTANT): RudderServo.loadAtStartup (bool)
2017-09-11T18:54:51.008Z,1505156091.008 [CommandLine](IMPORTANT): ThrusterServo.loadAtStartup (bool)
2017-09-11T18:54:51.009Z,1505156091.009 [CommandLine](IMPORTANT): ExternalSim.loadAtStartup (bool)
2017-09-11T18:54:51.009Z,1505156091.009 [CommandLine](IMPORTANT): InternalSim.loadAtStartup (bool)
2017-09-11T18:54:51.010Z,1505156091.010 [CommandLine](IMPORTANT): NavigationSim.loadAtStartup (bool)
2017-09-11T18:54:51.043Z,1505156091.043 [CommandLine](IMPORTANT): Config/Simulator.oceanModelData (none)
2017-09-11T18:54:51.044Z,1505156091.044 [CommandLine](IMPORTANT): Vehicle.sendDataToShore (bool)
2017-09-11T18:54:51.047Z,1505156091.047 [CommandLine](IMPORTANT): DAT.loadControl (none)
2017-09-11T18:54:51.047Z,1505156091.047 [CommandLine](IMPORTANT): DAT.uart (none)
2017-09-11T18:54:51.047Z,1505156091.047 [CommandLine](IMPORTANT): DAT.baud (bit_per_second)
2017-09-11T18:54:51.114Z,1505156091.114 [CommandLine](IMPORTANT): DataOverHttps.platform_communications (bool)
2017-09-11T18:54:51.191Z,1505156091.191 [CommandLine](IMPORTANT): DataOverHttps.durationOfLastRun (second)
2017-09-11T18:54:51.220Z,1505156091.220 [CommandLine](IMPORTANT): tracking_on_surface.TrackingUpdatePeriod (second)
2017-09-11T18:54:51.222Z,1505156091.222 [CommandLine](IMPORTANT): DAT.queryAddressRequested (count)
2017-09-11T18:54:51.223Z,1505156091.223 [CommandLine](IMPORTANT): DAT.numberOfPingsRequested (count)
2017-09-11T18:54:53.049Z,1505156093.049 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170909T185652/Courier0000.lzma
2017-09-11T18:54:53.824Z,1505156093.824 [DataOverHttps](INFO): Moved sent file to Logs/20170909T185652/Courier0000.lzma.bak
2017-09-11T18:54:53.824Z,1505156093.824 [DataOverHttps](INFO): SBD MOMSN=5085262
2017-09-11T18:55:03.573Z,1505156103.573 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170910T190606/Courier0000.lzma
2017-09-11T18:55:04.356Z,1505156104.356 [DataOverHttps](INFO): Moved sent file to Logs/20170910T190606/Courier0000.lzma.bak
2017-09-11T18:55:04.356Z,1505156104.356 [DataOverHttps](INFO): SBD MOMSN=5085265
2017-09-11T18:55:07.303Z,1505156107.303 [CommandLine](IMPORTANT): got command show stack
2017-09-11T18:55:07.303Z,1505156107.303 [CommandLine](IMPORTANT): Behavior Stack:

2017-09-11T18:55:07.303Z,1505156107.303 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2017-09-11T18:55:07.304Z,1505156107.304 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:B
2017-09-11T18:55:13.717Z,1505156113.717 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20170910T191320/Courier0000.lzma
2017-09-11T18:55:14.492Z,1505156114.492 [DataOverHttps](INFO): Moved sent file to Logs/20170910T191320/Courier0000.lzma.bak
2017-09-11T18:55:14.492Z,1505156114.492 [DataOverHttps](INFO): SBD MOMSN=5085268
2017-09-11T18:55:24.490Z,1505156124.490 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20170911T184748/Courier0000.lzma
2017-09-11T18:55:25.277Z,1505156125.277 [DataOverHttps](INFO): Moved sent file to Logs/20170911T184748/Courier0000.lzma.bak
2017-09-11T18:55:25.277Z,1505156125.277 [DataOverHttps](INFO): SBD MOMSN=5085273
2017-09-11T18:55:28.256Z,1505156128.256 [CommandLine](IMPORTANT): got command get longitude
2017-09-11T18:55:28.256Z,1505156128.256 [CommandLine](FAULT): Element has no value
2017-09-11T18:55:35.922Z,1505156135.922 [Startup:StartupSatComms:B](INFO): Timed out from 2017-09-11T18:54:31.8Z
2017-09-11T18:55:35.922Z,1505156135.922 [Startup:StartupSatComms:B] Stopped
2017-09-11T18:55:35.923Z,1505156135.923 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2017-09-11T18:55:35.923Z,1505156135.923 [Startup:StartupSatComms] Stopped
2017-09-11T18:55:35.923Z,1505156135.923 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2017-09-11T18:55:35.924Z,1505156135.924 [Startup](INFO): Completed Startup
2017-09-11T18:55:35.924Z,1505156135.924 [MissionManager](INFO): Startup is completed.
2017-09-11T18:55:35.924Z,1505156135.924 [MissionManager](INFO): Uninitializing Mission Startup
2017-09-11T18:55:35.925Z,1505156135.925 [Startup] Stopped
2017-09-11T18:55:35.925Z,1505156135.925 [Startup](DEBUG): Aggregate::uninitialize Startup
2017-09-11T18:55:35.925Z,1505156135.925 [Startup:A.GoToSurface] Stopped
2017-09-11T18:55:35.925Z,1505156135.925 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2017-09-11T18:55:36.003Z,1505156136.003 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20170911T185115/Courier0000.lzma
2017-09-11T18:55:36.113Z,1505156136.113 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2017-09-11T18:55:36.113Z,1505156136.113 [tracking_on_surface] Running Loop=1
2017-09-11T18:55:36.113Z,1505156136.113 [tracking_on_surface](DEBUG): Aggregate::initialize tracking_on_surface
2017-09-11T18:55:36.113Z,1505156136.113 [tracking_on_surface:A.Pitch] Running Loop=1
2017-09-11T18:55:36.113Z,1505156136.113 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2017-09-11T18:55:36.114Z,1505156136.114 [tracking_on_surface:B.] Running Loop=1
2017-09-11T18:55:36.114Z,1505156136.114 [tracking_on_surface:B.](INFO): Initializing Tracking.
2017-09-11T18:55:36.114Z,1505156136.114 [tracking_on_surface:TestDrive] Running Loop=1
2017-09-11T18:55:36.115Z,1505156136.115 [tracking_on_surface:TestDrive](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive
2017-09-11T18:55:36.115Z,1505156136.115 [tracking_on_surface:TestDrive:B] Running Loop=1
2017-09-11T18:55:36.124Z,1505156136.124 [tracking_on_surface:TestDrive:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2017-09-11T18:55:36.126Z,1505156136.126 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:36.126Z,1505156136.126 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:36.126Z,1505156136.126 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:36.152Z,1505156136.152 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:36.152Z,1505156136.152 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:36.152Z,1505156136.152 [tracking_on_surface:B.] Running Loop=1
2017-09-11T18:55:36.153Z,1505156136.153 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:36.162Z,1505156136.162 [tracking_on_surface:A.Pitch] Running Loop=1
2017-09-11T18:55:37.075Z,1505156137.075 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:37.075Z,1505156137.075 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:37.075Z,1505156137.075 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:37.075Z,1505156137.075 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:37.075Z,1505156137.075 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:37.376Z,1505156137.376 [DataOverHttps](INFO): Moved sent file to Logs/20170911T185115/Courier0000.lzma.bak
2017-09-11T18:55:37.376Z,1505156137.376 [DataOverHttps](INFO): SBD MOMSN=5085278
2017-09-11T18:55:37.503Z,1505156137.503 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:37.503Z,1505156137.503 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:37.503Z,1505156137.503 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:37.504Z,1505156137.504 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:37.505Z,1505156137.505 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:37.505Z,1505156137.505 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:38.053Z,1505156138.053 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:38.053Z,1505156138.053 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:38.053Z,1505156138.053 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:38.053Z,1505156138.053 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:38.053Z,1505156138.053 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:38.249Z,1505156138.249 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:38.249Z,1505156138.249 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:38.249Z,1505156138.249 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:38.250Z,1505156138.250 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:38.251Z,1505156138.251 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:38.251Z,1505156138.251 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:41.613Z,1505156141.613 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:41.613Z,1505156141.613 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:41.613Z,1505156141.613 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:41.613Z,1505156141.613 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:41.613Z,1505156141.613 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:41.783Z,1505156141.783 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:41.783Z,1505156141.783 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:41.783Z,1505156141.783 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:41.789Z,1505156141.789 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:41.789Z,1505156141.789 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:41.789Z,1505156141.789 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:42.139Z,1505156142.139 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:42.139Z,1505156142.139 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:42.139Z,1505156142.139 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:42.139Z,1505156142.139 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:42.140Z,1505156142.140 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:42.559Z,1505156142.559 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:42.559Z,1505156142.559 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:42.560Z,1505156142.560 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:42.561Z,1505156142.561 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:42.561Z,1505156142.561 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:42.561Z,1505156142.561 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:42.949Z,1505156142.949 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:42.949Z,1505156142.949 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:42.949Z,1505156142.949 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:42.949Z,1505156142.949 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:42.950Z,1505156142.950 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:43.312Z,1505156143.312 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:43.312Z,1505156143.312 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:43.313Z,1505156143.313 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:43.314Z,1505156143.314 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:43.314Z,1505156143.314 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:43.314Z,1505156143.314 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:47.704Z,1505156147.704 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:47.704Z,1505156147.704 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:47.704Z,1505156147.704 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:47.704Z,1505156147.704 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:47.704Z,1505156147.704 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:47.812Z,1505156147.812 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20170911T185115/Courier0004.lzma
2017-09-11T18:55:47.932Z,1505156147.932 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:47.932Z,1505156147.932 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:47.932Z,1505156147.932 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:47.934Z,1505156147.934 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:47.938Z,1505156147.938 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:47.938Z,1505156147.938 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:48.196Z,1505156148.196 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:48.197Z,1505156148.197 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:48.197Z,1505156148.197 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:48.197Z,1505156148.197 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:48.197Z,1505156148.197 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:48.542Z,1505156148.542 [DataOverHttps](INFO): Moved sent file to Logs/20170911T185115/Courier0004.lzma.bak
2017-09-11T18:55:48.542Z,1505156148.542 [DataOverHttps](INFO): SBD MOMSN=5085283
2017-09-11T18:55:48.651Z,1505156148.651 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:48.652Z,1505156148.652 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:48.652Z,1505156148.652 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:48.653Z,1505156148.653 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:48.653Z,1505156148.653 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:48.654Z,1505156148.654 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:49.283Z,1505156149.283 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:49.284Z,1505156149.284 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:49.284Z,1505156149.284 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:49.284Z,1505156149.284 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:49.284Z,1505156149.284 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:49.461Z,1505156149.461 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:49.461Z,1505156149.461 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:49.461Z,1505156149.461 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:49.463Z,1505156149.463 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:49.463Z,1505156149.463 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:49.464Z,1505156149.464 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:52.683Z,1505156152.683 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:52.683Z,1505156152.683 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:52.683Z,1505156152.683 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:52.683Z,1505156152.683 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:52.684Z,1505156152.684 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:52.844Z,1505156152.844 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:52.845Z,1505156152.845 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:52.845Z,1505156152.845 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:52.852Z,1505156152.852 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:52.852Z,1505156152.852 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:52.852Z,1505156152.852 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:53.200Z,1505156153.200 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:53.200Z,1505156153.200 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:53.200Z,1505156153.200 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:53.200Z,1505156153.200 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:53.201Z,1505156153.201 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:53.604Z,1505156153.604 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:53.605Z,1505156153.605 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:53.605Z,1505156153.605 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:53.606Z,1505156153.606 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:53.606Z,1505156153.606 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:53.606Z,1505156153.606 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:53.975Z,1505156153.975 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:53.975Z,1505156153.975 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:53.975Z,1505156153.975 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:53.975Z,1505156153.975 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:53.980Z,1505156153.980 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:54.424Z,1505156154.424 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:54.424Z,1505156154.424 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:54.424Z,1505156154.424 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:54.426Z,1505156154.426 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:54.426Z,1505156154.426 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:54.426Z,1505156154.426 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:56.517Z,1505156156.517 [CommandLine](IMPORTANT): got command set NAL9602.longitude_fix -121.800003 degree
2017-09-11T18:55:56.518Z,1505156156.518 [CommandLine](IMPORTANT): got command set NAL9602.latitude_fix 36.799999 degree
2017-09-11T18:55:58.443Z,1505156158.443 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:58.443Z,1505156158.443 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:58.443Z,1505156158.443 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:58.443Z,1505156158.443 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:58.443Z,1505156158.443 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:58.533Z,1505156158.533 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170908T234530/Express0449.lzma
2017-09-11T18:55:58.635Z,1505156158.635 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:58.635Z,1505156158.635 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:58.639Z,1505156158.639 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:58.641Z,1505156158.641 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:58.641Z,1505156158.641 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:58.641Z,1505156158.641 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:59.002Z,1505156159.002 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:55:59.002Z,1505156159.002 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:55:59.002Z,1505156159.002 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:55:59.002Z,1505156159.002 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:59.003Z,1505156159.003 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:59.308Z,1505156159.308 [DataOverHttps](INFO): Moved sent file to Logs/20170908T234530/Express0449.lzma.bak
2017-09-11T18:55:59.308Z,1505156159.308 [DataOverHttps](INFO): SBD MOMSN=5085285
2017-09-11T18:55:59.416Z,1505156159.416 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:55:59.417Z,1505156159.417 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:55:59.417Z,1505156159.417 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:55:59.418Z,1505156159.418 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:55:59.418Z,1505156159.418 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:55:59.418Z,1505156159.418 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:55:59.714Z,1505156159.714 [CommandLine](IMPORTANT): got command get longitude
2017-09-11T18:55:59.714Z,1505156159.714 [CommandLine](FAULT): Element has no value
2017-09-11T18:56:00.145Z,1505156160.145 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:00.145Z,1505156160.145 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:00.145Z,1505156160.145 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:00.150Z,1505156160.150 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:00.150Z,1505156160.150 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:00.283Z,1505156160.283 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:00.284Z,1505156160.284 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:00.284Z,1505156160.284 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:00.285Z,1505156160.285 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:00.285Z,1505156160.285 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:00.285Z,1505156160.285 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:03.355Z,1505156163.355 [CommandLine](IMPORTANT): got command show stack
2017-09-11T18:56:03.356Z,1505156163.356 [CommandLine](IMPORTANT): Behavior Stack:

2017-09-11T18:56:03.356Z,1505156163.356 [tracking_on_surface](IMPORTANT): Priority 0: tracking_on_surface:A.Pitch
2017-09-11T18:56:03.356Z,1505156163.356 [tracking_on_surface](IMPORTANT): Priority 1: tracking_on_surface:B.
2017-09-11T18:56:03.357Z,1505156163.357 [tracking_on_surface:TestDrive:Data](IMPORTANT): Priority 2: tracking_on_surface:TestDrive:Data:B
2017-09-11T18:56:03.357Z,1505156163.357 [tracking_on_surface:TestDrive](IMPORTANT): Priority 3: tracking_on_surface:TestDrive:B
2017-09-11T18:56:03.662Z,1505156163.662 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:03.662Z,1505156163.662 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:03.662Z,1505156163.662 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:03.662Z,1505156163.662 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:03.662Z,1505156163.662 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:03.819Z,1505156163.819 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:03.819Z,1505156163.819 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:03.819Z,1505156163.819 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:03.821Z,1505156163.821 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:03.821Z,1505156163.821 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:03.821Z,1505156163.821 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:04.175Z,1505156164.175 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:04.175Z,1505156164.175 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:04.175Z,1505156164.175 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:04.176Z,1505156164.176 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:04.176Z,1505156164.176 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:04.593Z,1505156164.593 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:04.594Z,1505156164.594 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:04.594Z,1505156164.594 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:04.595Z,1505156164.595 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:04.595Z,1505156164.595 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:04.595Z,1505156164.595 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:04.957Z,1505156164.957 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:04.957Z,1505156164.957 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:04.961Z,1505156164.961 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:04.961Z,1505156164.961 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:04.961Z,1505156164.961 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:05.356Z,1505156165.356 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:05.356Z,1505156165.356 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:05.356Z,1505156165.356 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:05.358Z,1505156165.358 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:05.358Z,1505156165.358 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:05.358Z,1505156165.358 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:07.510Z,1505156167.510 [CommandLine](IMPORTANT): got command failComponent
2017-09-11T18:56:07.510Z,1505156167.510 [CommandLine](IMPORTANT): Failed components:
2017-09-11T18:56:07.510Z,1505156167.510 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2017-09-11T18:56:08.708Z,1505156168.708 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:08.708Z,1505156168.708 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:08.709Z,1505156168.709 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:08.709Z,1505156168.709 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:08.709Z,1505156168.709 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:08.808Z,1505156168.808 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170909T185652/Express0001.lzma
2017-09-11T18:56:08.893Z,1505156168.893 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:08.894Z,1505156168.894 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:08.894Z,1505156168.894 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:08.899Z,1505156168.899 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:08.899Z,1505156168.899 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:08.900Z,1505156168.900 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:09.255Z,1505156169.255 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:09.255Z,1505156169.255 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:09.255Z,1505156169.255 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:09.255Z,1505156169.255 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:09.255Z,1505156169.255 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:09.575Z,1505156169.575 [DataOverHttps](INFO): Moved sent file to Logs/20170909T185652/Express0001.lzma.bak
2017-09-11T18:56:09.575Z,1505156169.575 [DataOverHttps](INFO): SBD MOMSN=5085287
2017-09-11T18:56:09.670Z,1505156169.670 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:09.670Z,1505156169.670 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:09.670Z,1505156169.670 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:09.672Z,1505156169.672 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:09.677Z,1505156169.677 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:09.677Z,1505156169.677 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:10.338Z,1505156170.338 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:10.338Z,1505156170.338 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:10.338Z,1505156170.338 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:10.338Z,1505156170.338 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:10.338Z,1505156170.338 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:10.480Z,1505156170.480 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:10.480Z,1505156170.480 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:10.480Z,1505156170.480 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:10.481Z,1505156170.481 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:10.486Z,1505156170.486 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:10.486Z,1505156170.486 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:13.768Z,1505156173.768 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:13.769Z,1505156173.769 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:13.769Z,1505156173.769 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:13.769Z,1505156173.769 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:13.769Z,1505156173.769 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:13.972Z,1505156173.972 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:13.972Z,1505156173.972 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:13.973Z,1505156173.973 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:13.974Z,1505156173.974 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:13.974Z,1505156173.974 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:13.974Z,1505156173.974 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:14.321Z,1505156174.321 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:14.321Z,1505156174.321 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:14.321Z,1505156174.321 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:14.322Z,1505156174.322 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:14.322Z,1505156174.322 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:14.699Z,1505156174.699 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:14.699Z,1505156174.699 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:14.699Z,1505156174.699 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:14.700Z,1505156174.700 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:14.700Z,1505156174.700 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:14.701Z,1505156174.701 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:15.112Z,1505156175.112 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:15.112Z,1505156175.112 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:15.112Z,1505156175.112 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:15.112Z,1505156175.112 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:15.113Z,1505156175.113 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:15.554Z,1505156175.554 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:15.554Z,1505156175.554 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:15.554Z,1505156175.554 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:15.556Z,1505156175.556 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:15.556Z,1505156175.556 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:15.556Z,1505156175.556 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:17.759Z,1505156177.759 [CommandLine](IMPORTANT): got command get DAT.loadAtStartup
2017-09-11T18:56:17.760Z,1505156177.760 [CommandLine](IMPORTANT): DAT.loadAtStartup 0 bool
2017-09-11T18:56:19.079Z,1505156179.079 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:19.079Z,1505156179.079 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:19.079Z,1505156179.079 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:19.079Z,1505156179.079 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:19.083Z,1505156179.083 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:19.156Z,1505156179.156 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170910T190606/Express0001.lzma
2017-09-11T18:56:19.237Z,1505156179.237 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:19.237Z,1505156179.237 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:19.238Z,1505156179.238 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:19.239Z,1505156179.239 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:19.239Z,1505156179.239 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:19.239Z,1505156179.239 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:19.605Z,1505156179.605 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:19.606Z,1505156179.606 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:19.606Z,1505156179.606 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:19.606Z,1505156179.606 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:19.606Z,1505156179.606 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:19.927Z,1505156179.927 [DataOverHttps](INFO): Moved sent file to Logs/20170910T190606/Express0001.lzma.bak
2017-09-11T18:56:19.927Z,1505156179.927 [DataOverHttps](INFO): SBD MOMSN=5085289
2017-09-11T18:56:20.028Z,1505156180.028 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:20.028Z,1505156180.028 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:20.028Z,1505156180.028 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:20.030Z,1505156180.030 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:20.030Z,1505156180.030 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:20.030Z,1505156180.030 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:20.633Z,1505156180.633 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:20.633Z,1505156180.633 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:20.633Z,1505156180.633 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:20.633Z,1505156180.633 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:20.633Z,1505156180.633 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:20.794Z,1505156180.794 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:20.795Z,1505156180.795 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:20.795Z,1505156180.795 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:20.797Z,1505156180.797 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:20.797Z,1505156180.797 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:20.797Z,1505156180.797 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:24.144Z,1505156184.144 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:24.144Z,1505156184.144 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:24.144Z,1505156184.144 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:24.144Z,1505156184.144 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:24.145Z,1505156184.145 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:24.291Z,1505156184.291 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:24.292Z,1505156184.292 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:24.292Z,1505156184.292 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:24.293Z,1505156184.293 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:24.293Z,1505156184.293 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:24.294Z,1505156184.294 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:24.660Z,1505156184.660 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:24.661Z,1505156184.661 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:24.661Z,1505156184.661 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:24.661Z,1505156184.661 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:24.661Z,1505156184.661 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:24.685Z,1505156184.685 [CommandLine](IMPORTANT): got command configSet list
2017-09-11T18:56:24.686Z,1505156184.686 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;

2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): Normal linearApproximation Rowe_600LCM.height_above_sea_floor 5.000000 meter;

2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=315 milliliter;

2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): VerticalControl.massDefault=-1.3 centimeter;

2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-35 millimeter;

2017-09-11T18:56:24.687Z,1505156184.687 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=26 millimeter;

2017-09-11T18:56:25.051Z,1505156185.051 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:25.051Z,1505156185.051 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:25.051Z,1505156185.051 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:25.052Z,1505156185.052 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:25.052Z,1505156185.052 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:25.053Z,1505156185.053 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:25.428Z,1505156185.428 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:25.429Z,1505156185.429 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:25.429Z,1505156185.429 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:25.429Z,1505156185.429 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:25.429Z,1505156185.429 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:25.839Z,1505156185.839 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:25.839Z,1505156185.839 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:25.839Z,1505156185.839 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:25.841Z,1505156185.841 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:25.841Z,1505156185.841 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:25.841Z,1505156185.841 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:29.117Z,1505156189.117 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:29.118Z,1505156189.118 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:29.118Z,1505156189.118 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:29.118Z,1505156189.118 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:29.118Z,1505156189.118 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:29.218Z,1505156189.218 [DataOverHttps](INFO): Sending 757 bytes from file Logs/20170910T191320/Express0001.lzma
2017-09-11T18:56:29.301Z,1505156189.301 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:29.301Z,1505156189.301 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:29.302Z,1505156189.302 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:29.308Z,1505156189.308 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:29.308Z,1505156189.308 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:29.309Z,1505156189.309 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:29.643Z,1505156189.643 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:29.643Z,1505156189.643 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:29.644Z,1505156189.644 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:29.644Z,1505156189.644 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:29.644Z,1505156189.644 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:29.977Z,1505156189.977 [DataOverHttps](INFO): Moved sent file to Logs/20170910T191320/Express0001.lzma.bak
2017-09-11T18:56:29.977Z,1505156189.977 [DataOverHttps](INFO): SBD MOMSN=5085291
2017-09-11T18:56:30.083Z,1505156190.083 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:30.083Z,1505156190.083 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:30.083Z,1505156190.083 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:30.084Z,1505156190.084 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:30.085Z,1505156190.085 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:30.085Z,1505156190.085 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:30.652Z,1505156190.652 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:30.652Z,1505156190.652 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:30.652Z,1505156190.652 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:30.652Z,1505156190.652 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:30.652Z,1505156190.652 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:30.836Z,1505156190.836 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:30.836Z,1505156190.836 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:30.836Z,1505156190.836 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:30.837Z,1505156190.837 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:30.837Z,1505156190.837 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:30.838Z,1505156190.838 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:34.319Z,1505156194.319 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:34.319Z,1505156194.319 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:34.319Z,1505156194.319 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:34.319Z,1505156194.319 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:34.319Z,1505156194.319 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:34.487Z,1505156194.487 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:34.487Z,1505156194.487 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:34.487Z,1505156194.487 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:34.493Z,1505156194.493 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:34.493Z,1505156194.493 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:34.493Z,1505156194.493 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:34.841Z,1505156194.841 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:34.841Z,1505156194.841 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:34.841Z,1505156194.841 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:34.841Z,1505156194.841 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:34.841Z,1505156194.841 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:35.279Z,1505156195.279 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:35.280Z,1505156195.280 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:35.280Z,1505156195.280 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:35.281Z,1505156195.281 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:35.281Z,1505156195.281 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:35.281Z,1505156195.281 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:35.625Z,1505156195.625 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:35.625Z,1505156195.625 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:35.625Z,1505156195.625 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:35.625Z,1505156195.625 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:35.633Z,1505156195.633 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:36.047Z,1505156196.047 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:36.047Z,1505156196.047 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:36.047Z,1505156196.047 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:36.048Z,1505156196.048 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:36.048Z,1505156196.048 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:36.049Z,1505156196.049 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:39.735Z,1505156199.735 [tracking_on_surface:TestDrive:B](INFO): Timed out from 2017-09-11T18:55:36.1Z
2017-09-11T18:56:39.735Z,1505156199.735 [tracking_on_surface:TestDrive:B] Stopped
2017-09-11T18:56:39.735Z,1505156199.735 [tracking_on_surface:TestDrive:C.Wait] Running Loop=1
2017-09-11T18:56:39.735Z,1505156199.735 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Initialize Wait Component.
2017-09-11T18:56:39.736Z,1505156199.736 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:39.740Z,1505156199.740 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:39.740Z,1505156199.740 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:39.740Z,1505156199.740 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:39.741Z,1505156199.741 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:39.741Z,1505156199.741 [tracking_on_surface:B.](INFO): *** querying DAT ***
2017-09-11T18:56:39.807Z,1505156199.807 [DataOverHttps](INFO): Sending 697 bytes from file Logs/20170911T184748/Express0001.lzma
2017-09-11T18:56:39.912Z,1505156199.912 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:39.913Z,1505156199.913 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:39.913Z,1505156199.913 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:39.914Z,1505156199.914 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:39.914Z,1505156199.914 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:39.914Z,1505156199.914 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:40.263Z,1505156200.263 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:40.264Z,1505156200.264 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:40.264Z,1505156200.264 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:40.264Z,1505156200.264 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:40.264Z,1505156200.264 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:40.581Z,1505156200.581 [DataOverHttps](INFO): Moved sent file to Logs/20170911T184748/Express0001.lzma.bak
2017-09-11T18:56:40.581Z,1505156200.581 [DataOverHttps](INFO): SBD MOMSN=5085309
2017-09-11T18:56:40.697Z,1505156200.697 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:40.697Z,1505156200.697 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:40.697Z,1505156200.697 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:40.698Z,1505156200.698 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:40.699Z,1505156200.699 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:40.699Z,1505156200.699 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:41.097Z,1505156201.097 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:41.097Z,1505156201.097 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:41.097Z,1505156201.097 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:41.097Z,1505156201.097 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:41.097Z,1505156201.097 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:41.449Z,1505156201.449 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:41.450Z,1505156201.450 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:41.450Z,1505156201.450 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:41.451Z,1505156201.451 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:41.451Z,1505156201.451 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:41.451Z,1505156201.451 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:44.751Z,1505156204.751 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2017-09-11T18:56:44.844Z,1505156204.844 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:44.844Z,1505156204.844 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:44.844Z,1505156204.844 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:44.844Z,1505156204.844 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:44.845Z,1505156204.845 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:45.011Z,1505156205.011 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:45.011Z,1505156205.011 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:45.011Z,1505156205.011 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:45.013Z,1505156205.013 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:45.013Z,1505156205.013 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:45.013Z,1505156205.013 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:45.360Z,1505156205.360 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:45.360Z,1505156205.360 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:45.360Z,1505156205.360 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:45.360Z,1505156205.360 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:45.360Z,1505156205.360 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:45.759Z,1505156205.759 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:45.759Z,1505156205.759 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:45.759Z,1505156205.759 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:45.761Z,1505156205.761 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:45.761Z,1505156205.761 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:45.761Z,1505156205.761 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:46.138Z,1505156206.138 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:46.138Z,1505156206.138 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:46.139Z,1505156206.139 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:46.139Z,1505156206.139 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:46.139Z,1505156206.139 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:46.536Z,1505156206.536 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:46.537Z,1505156206.537 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:46.537Z,1505156206.537 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:46.538Z,1505156206.538 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:46.538Z,1505156206.538 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:46.539Z,1505156206.539 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:46.941Z,1505156206.941 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:46.941Z,1505156206.941 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:46.941Z,1505156206.941 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:46.941Z,1505156206.941 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:46.941Z,1505156206.941 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:47.344Z,1505156207.344 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:47.344Z,1505156207.344 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:47.344Z,1505156207.344 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:47.346Z,1505156207.346 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:47.346Z,1505156207.346 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:47.346Z,1505156207.346 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:47.753Z,1505156207.753 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:47.753Z,1505156207.753 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:47.753Z,1505156207.753 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:47.753Z,1505156207.753 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:47.753Z,1505156207.753 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:48.150Z,1505156208.150 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:48.150Z,1505156208.150 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:48.150Z,1505156208.150 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:48.151Z,1505156208.151 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:48.151Z,1505156208.151 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:48.152Z,1505156208.152 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:48.543Z,1505156208.543 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:48.543Z,1505156208.543 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:48.544Z,1505156208.544 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:48.544Z,1505156208.544 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:48.544Z,1505156208.544 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:48.944Z,1505156208.944 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:48.945Z,1505156208.945 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:48.945Z,1505156208.945 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:48.951Z,1505156208.951 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:48.951Z,1505156208.951 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:48.951Z,1505156208.951 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:49.406Z,1505156209.406 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:49.406Z,1505156209.406 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:49.407Z,1505156209.407 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:49.407Z,1505156209.407 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:49.407Z,1505156209.407 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:49.737Z,1505156209.737 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:49.738Z,1505156209.738 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:49.738Z,1505156209.738 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:49.739Z,1505156209.739 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:49.739Z,1505156209.739 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:49.740Z,1505156209.740 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:50.160Z,1505156210.160 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:50.160Z,1505156210.160 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:50.160Z,1505156210.160 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:50.160Z,1505156210.160 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:50.160Z,1505156210.160 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:50.545Z,1505156210.545 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:50.545Z,1505156210.545 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:50.546Z,1505156210.546 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:50.547Z,1505156210.547 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:50.547Z,1505156210.547 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:50.547Z,1505156210.547 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:50.964Z,1505156210.964 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:50.965Z,1505156210.965 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:50.965Z,1505156210.965 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:50.965Z,1505156210.965 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:50.965Z,1505156210.965 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:51.339Z,1505156211.339 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:51.339Z,1505156211.339 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:51.339Z,1505156211.339 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:51.340Z,1505156211.340 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:51.340Z,1505156211.340 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:51.341Z,1505156211.341 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:51.738Z,1505156211.738 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:51.738Z,1505156211.738 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:51.739Z,1505156211.739 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:51.739Z,1505156211.739 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:51.743Z,1505156211.743 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:52.138Z,1505156212.138 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:52.139Z,1505156212.139 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:52.139Z,1505156212.139 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:52.144Z,1505156212.144 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:52.145Z,1505156212.145 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:52.145Z,1505156212.145 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:52.552Z,1505156212.552 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:52.553Z,1505156212.553 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:52.553Z,1505156212.553 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:52.553Z,1505156212.553 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:52.553Z,1505156212.553 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:52.924Z,1505156212.924 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:52.924Z,1505156212.924 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:52.925Z,1505156212.925 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:52.934Z,1505156212.934 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:52.934Z,1505156212.934 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:52.935Z,1505156212.935 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:53.331Z,1505156213.331 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:53.331Z,1505156213.331 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:53.331Z,1505156213.331 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:53.331Z,1505156213.331 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:53.331Z,1505156213.331 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:53.735Z,1505156213.735 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:53.735Z,1505156213.735 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:53.735Z,1505156213.735 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:53.737Z,1505156213.737 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:53.737Z,1505156213.737 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:53.737Z,1505156213.737 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:54.141Z,1505156214.141 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:54.141Z,1505156214.141 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:54.141Z,1505156214.141 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:54.142Z,1505156214.142 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:54.142Z,1505156214.142 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:54.378Z,1505156214.378 [CommandLine](IMPORTANT): got command restart application
2017-09-11T18:56:54.537Z,1505156214.537 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:54.537Z,1505156214.537 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:54.537Z,1505156214.537 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:54.539Z,1505156214.539 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:54.539Z,1505156214.539 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:54.539Z,1505156214.539 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:54.947Z,1505156214.947 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:54.947Z,1505156214.947 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:54.948Z,1505156214.948 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:54.948Z,1505156214.948 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:54.956Z,1505156214.956 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:55.346Z,1505156215.346 [tracking_on_surface:TestDrive:Data] Running Loop=1
2017-09-11T18:56:55.347Z,1505156215.347 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:55.347Z,1505156215.347 [tracking_on_surface:TestDrive:Data:A] Running Loop=1
2017-09-11T18:56:55.348Z,1505156215.348 [tracking_on_surface:TestDrive:Data:A] Stopped
2017-09-11T18:56:55.348Z,1505156215.348 [tracking_on_surface:TestDrive:Data:B] Running Loop=1
2017-09-11T18:56:55.348Z,1505156215.348 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:55.385Z,1505156215.385 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2017-09-11T18:56:55.390Z,1505156215.390 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:55.391Z,1505156215.391 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.561Z,1505156215.561 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2017-09-11T18:56:55.561Z,1505156215.561 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.562Z,1505156215.562 [CommandLine](INFO): Join timeout helper Thread ID is 3124
2017-09-11T18:56:55.563Z,1505156215.563 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2017-09-11T18:56:55.563Z,1505156215.563 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.563Z,1505156215.563 [NavChartDb](INFO): Join timeout helper Thread ID is 3125
2017-09-11T18:56:55.565Z,1505156215.565 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:55.566Z,1505156215.566 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.585Z,1505156215.585 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2017-09-11T18:56:55.585Z,1505156215.585 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.586Z,1505156215.586 [Radio_Surface](INFO): Join timeout helper Thread ID is 3126
2017-09-11T18:56:55.750Z,1505156215.750 [tracking_on_surface:TestDrive:Data:B] Stopped
2017-09-11T18:56:55.751Z,1505156215.751 [tracking_on_surface:TestDrive:Data](INFO): Completed tracking_on_surface:TestDrive:Data
2017-09-11T18:56:55.751Z,1505156215.751 [tracking_on_surface:TestDrive:Data] Stopped
2017-09-11T18:56:55.751Z,1505156215.751 [tracking_on_surface:TestDrive:Data](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive:Data
2017-09-11T18:56:55.751Z,1505156215.751 [tracking_on_surface:B.](DEBUG): Tracking...
2017-09-11T18:56:55.752Z,1505156215.752 [MissionManager](INFO): MissionManager is completed.
2017-09-11T18:56:55.752Z,1505156215.752 [MissionManager](INFO): Uninitializing Mission tracking_on_surface
2017-09-11T18:56:55.752Z,1505156215.752 [tracking_on_surface] Stopped
2017-09-11T18:56:55.752Z,1505156215.752 [tracking_on_surface](DEBUG): Aggregate::uninitialize tracking_on_surface
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:A.Pitch] Stopped
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:B.] Stopped
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:B.](DEBUG): Uninitializing Tracking.
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:TestDrive] Stopped
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:TestDrive](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:TestDrive:C.Wait] Stopped
2017-09-11T18:56:55.753Z,1505156215.753 [tracking_on_surface:TestDrive:C.Wait](DEBUG): Uninitialize Wait Component.
2017-09-11T18:56:55.754Z,1505156215.754 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:55.754Z,1505156215.754 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.758Z,1505156215.758 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2017-09-11T18:56:55.758Z,1505156215.758 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:55.758Z,1505156215.758 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3127
2017-09-11T18:56:55.998Z,1505156215.998 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:55.999Z,1505156215.999 [WetLabsBB2FL](INFO): Powering down
2017-09-11T18:56:55.000Z,1505156216.000 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.014Z,1505156216.014 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2017-09-11T18:56:56.014Z,1505156216.014 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.014Z,1505156216.014 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3128
2017-09-11T18:56:56.128Z,1505156216.128 [MissionManager](IMPORTANT): Started mission Default
2017-09-11T18:56:56.128Z,1505156216.128 [Default] Running Loop=1
2017-09-11T18:56:56.128Z,1505156216.128 [Default](DEBUG): Aggregate::initialize Default
2017-09-11T18:56:56.129Z,1505156216.129 [Default:B.GoToSurface] Running Loop=1
2017-09-11T18:56:56.129Z,1505156216.129 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2017-09-11T18:56:56.129Z,1505156216.129 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2017-09-11T18:56:56.129Z,1505156216.129 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2017-09-11T18:56:56.130Z,1505156216.130 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2017-09-11T18:56:56.130Z,1505156216.130 [Default:B.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds.
2017-09-11T18:56:56.130Z,1505156216.130 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2017-09-11T18:56:56.131Z,1505156216.131 [Default:A.Wait] Running Loop=1
2017-09-11T18:56:56.131Z,1505156216.131 [Default:A.Wait](DEBUG): Initialize Wait Component.
2017-09-11T18:56:56.275Z,1505156216.275 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:56.275Z,1505156216.275 [CTD_NeilBrown](INFO): Powering down
2017-09-11T18:56:56.276Z,1505156216.276 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.283Z,1505156216.283 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2017-09-11T18:56:56.283Z,1505156216.283 [logger ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.284Z,1505156216.284 [logger](INFO): Join timeout helper Thread ID is 3129
2017-09-11T18:56:56.298Z,1505156216.298 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:56.299Z,1505156216.299 [logger ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.303Z,1505156216.303 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2017-09-11T18:56:56.303Z,1505156216.303 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.303Z,1505156216.303 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2017-09-11T18:56:56.304Z,1505156216.304 [controlThread ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.304Z,1505156216.304 [controlThread](INFO): Join timeout helper Thread ID is 3130
2017-09-11T18:56:56.463Z,1505156216.463 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-11T18:56:56.463Z,1505156216.463 [controlThread](DEBUG): Uninitializing ControlThread
2017-09-11T18:56:56.463Z,1505156216.463 [Aanderaa_O2](INFO): Powering down
2017-09-11T18:56:56.465Z,1505156216.465 [NAL9602](INFO): Powering down
2017-09-11T18:56:56.467Z,1505156216.467 [PNI_TCM](INFO): Powering down
2017-09-11T18:56:56.556Z,1505156216.556 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2017-09-11T18:56:56.557Z,1505156216.557 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2017-09-11T18:56:56.558Z,1505156216.558 [MissionManager](INFO): Uninitializing Mission Default
2017-09-11T18:56:56.558Z,1505156216.558 [Default] Stopped
2017-09-11T18:56:56.558Z,1505156216.558 [Default](DEBUG): Aggregate::uninitialize Default
2017-09-11T18:56:56.558Z,1505156216.558 [Default:A.Wait] Stopped
2017-09-11T18:56:56.559Z,1505156216.559 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2017-09-11T18:56:56.559Z,1505156216.559 [Default:B.GoToSurface] Stopped
2017-09-11T18:56:56.559Z,1505156216.559 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2017-09-11T18:56:56.562Z,1505156216.562 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2017-09-11T18:56:56.562Z,1505156216.562 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2017-09-11T18:56:56.562Z,1505156216.562 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2017-09-11T18:56:56.563Z,1505156216.563 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2017-09-11T18:56:56.563Z,1505156216.563 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2017-09-11T18:56:56.563Z,1505156216.563 [BuoyancyServo](INFO): Powering down
2017-09-11T18:56:56.575Z,1505156216.575 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2017-09-11T18:56:56.575Z,1505156216.575 [ElevatorServo](INFO): Powering down
2017-09-11T18:56:56.576Z,1505156216.576 [MassServo](DEBUG): Uninitialize Mass Servo.
2017-09-11T18:56:56.576Z,1505156216.576 [MassServo](INFO): Powering down
2017-09-11T18:56:56.577Z,1505156216.577 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2017-09-11T18:56:56.577Z,1505156216.577 [RudderServo](INFO): Powering down
2017-09-11T18:56:56.578Z,1505156216.578 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2017-09-11T18:56:56.578Z,1505156216.578 [ThrusterServo](INFO): Powering down
2017-09-11T18:56:56.579Z,1505156216.579 [SBIT](DEBUG): Uninitialize SBIT Component.
2017-09-11T18:56:56.580Z,1505156216.580 [IBIT](DEBUG): Uninitialize IBIT Component.
2017-09-11T18:56:56.580Z,1505156216.580 [CBIT](DEBUG): Uninitialize CBIT Component.
2017-09-11T18:56:56.581Z,1505156216.581 [controlThread ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.643Z,1505156216.643 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.648Z,1505156216.648 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.764Z,1505156216.764 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.812Z,1505156216.812 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-11T18:56:56.895Z,1505156216.895 [logger ThreadHandler](INFO): Thread cancelled.