2018-08-01T04:13:51.055Z,1533096831.055 [Supervisor](DEBUG): Initializing supervisor.
2018-08-01T04:13:51.057Z,1533096831.057 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-08-01T04:13:51.058Z,1533096831.058 [SyncHandler](INFO): Protected caller Thread ID is 799
2018-08-01T04:13:51.058Z,1533096831.058 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-08-01T04:13:51.059Z,1533096831.059 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-08-01T04:13:51.060Z,1533096831.060 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 800
2018-08-01T04:13:51.062Z,1533096831.062 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-08-01T04:13:51.074Z,1533096831.074 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-08-01T04:13:51.075Z,1533096831.075 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-08-01T04:13:51.075Z,1533096831.075 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 801
2018-08-01T04:13:51.076Z,1533096831.076 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-08-01T04:13:51.077Z,1533096831.077 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-08-01T04:13:51.077Z,1533096831.077 [logger ThreadHandler](INFO): Protected caller Thread ID is 802
2018-08-01T04:13:51.079Z,1533096831.079 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-08-01T04:13:51.080Z,1533096831.080 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-08-01T04:13:51.084Z,1533096831.084 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-08-01T04:13:51.182Z,1533096831.182 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-08-01T04:13:51.184Z,1533096831.184 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-08-01T04:13:51.288Z,1533096831.288 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-08-01T04:13:51.290Z,1533096831.290 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-08-01T04:13:51.497Z,1533096831.497 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-08-01T04:13:51.499Z,1533096831.499 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-08-01T04:13:51.835Z,1533096831.835 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-08-01T04:13:51.836Z,1533096831.836 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-08-01T04:13:52.187Z,1533096832.187 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-08-01T04:13:52.187Z,1533096832.187 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-08-01T04:13:52.663Z,1533096832.663 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-08-01T04:13:52.665Z,1533096832.665 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-08-01T04:13:53.096Z,1533096833.096 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-08-01T04:13:53.098Z,1533096833.098 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-08-01T04:13:53.582Z,1533096833.582 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-08-01T04:13:53.582Z,1533096833.582 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-08-01T04:13:53.665Z,1533096833.665 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-08-01T04:13:53.975Z,1533096833.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-08-01T04:13:53.976Z,1533096833.976 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-08-01T04:13:54.125Z,1533096834.125 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-08-01T04:13:54.126Z,1533096834.126 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-08-01T04:13:54.339Z,1533096834.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-08-01T04:13:54.340Z,1533096834.340 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-08-01T04:13:54.559Z,1533096834.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-08-01T04:13:54.559Z,1533096834.559 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-08-01T04:13:54.660Z,1533096834.660 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-08-01T04:13:54.662Z,1533096834.662 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-08-01T04:13:54.812Z,1533096834.812 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-08-01T04:13:54.814Z,1533096834.814 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2018-08-01T04:13:55.510Z,1533096835.510 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2018-08-01T04:13:55.747Z,1533096835.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-08-01T04:13:55.748Z,1533096835.748 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2018-08-01T04:13:55.855Z,1533096835.855 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2018-08-01T04:13:56.003Z,1533096836.003 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2018-08-01T04:13:56.097Z,1533096836.097 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2018-08-01T04:13:56.184Z,1533096836.184 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2018-08-01T04:13:56.331Z,1533096836.331 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2018-08-01T04:13:56.516Z,1533096836.516 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2018-08-01T04:13:56.616Z,1533096836.616 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2018-08-01T04:13:56.713Z,1533096836.713 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2018-08-01T04:13:56.812Z,1533096836.812 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2018-08-01T04:13:56.897Z,1533096836.897 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2018-08-01T04:13:56.901Z,1533096836.901 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-08-01T04:13:57.030Z,1533096837.030 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-08-01T04:13:57.032Z,1533096837.032 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-08-01T04:13:57.056Z,1533096837.056 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-08-01T04:13:57.058Z,1533096837.058 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-08-01T04:13:57.113Z,1533096837.113 [DepthRateCalculator] Loaded
2018-08-01T04:13:57.114Z,1533096837.114 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-08-01T04:13:57.119Z,1533096837.119 [PitchRateCalculator] Loaded
2018-08-01T04:13:57.120Z,1533096837.120 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-08-01T04:13:57.136Z,1533096837.136 [SpeedCalculator] Loaded
2018-08-01T04:13:57.136Z,1533096837.136 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-08-01T04:13:57.157Z,1533096837.157 [TempGradientCalculator] Loaded
2018-08-01T04:13:57.157Z,1533096837.157 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-08-01T04:13:57.173Z,1533096837.173 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2018-08-01T04:13:57.173Z,1533096837.173 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2018-08-01T04:13:57.179Z,1533096837.179 [YawRateCalculator] Loaded
2018-08-01T04:13:57.179Z,1533096837.179 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-08-01T04:13:57.219Z,1533096837.219 [ElevatorOffsetCalculator] Loaded
2018-08-01T04:13:57.219Z,1533096837.219 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-08-01T04:13:57.220Z,1533096837.220 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-08-01T04:13:57.221Z,1533096837.221 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-08-01T04:13:57.258Z,1533096837.258 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-08-01T04:13:57.258Z,1533096837.258 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-08-01T04:13:57.736Z,1533096837.736 [AcousticModem_Benthos_ATM900] Loaded
2018-08-01T04:13:57.736Z,1533096837.736 [ComponentRegistry](DEBUG): SyncComponent "AcousticModem_Benthos_ATM900" handled in the control thread.
2018-08-01T04:13:57.870Z,1533096837.870 [DataOverHttps] Loaded
2018-08-01T04:13:57.871Z,1533096837.871 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-08-01T04:13:57.885Z,1533096837.885 [Depth_Keller] Loaded
2018-08-01T04:13:57.885Z,1533096837.885 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-08-01T04:13:57.890Z,1533096837.890 [DropWeight] Loaded
2018-08-01T04:13:57.890Z,1533096837.890 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-08-01T04:13:57.988Z,1533096837.988 [NAL9602] Loaded
2018-08-01T04:13:57.988Z,1533096837.988 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-08-01T04:13:58.004Z,1533096838.004 [Onboard] Loaded
2018-08-01T04:13:58.005Z,1533096838.005 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-08-01T04:13:58.015Z,1533096838.015 [Radio_Surface] Loaded
2018-08-01T04:13:58.015Z,1533096838.015 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-08-01T04:13:58.016Z,1533096838.016 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407B74E0
2018-08-01T04:13:58.017Z,1533096838.017 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 881
2018-08-01T04:13:58.169Z,1533096838.169 [PNI_TCM] Loaded
2018-08-01T04:13:58.169Z,1533096838.169 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-08-01T04:13:58.230Z,1533096838.230 [Rowe_600LCM] Loaded
2018-08-01T04:13:58.231Z,1533096838.231 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-08-01T04:13:58.232Z,1533096838.232 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 407E74E0
2018-08-01T04:13:58.232Z,1533096838.232 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 882
2018-08-01T04:14:00.342Z,1533096840.342 [BPC1] Loaded
2018-08-01T04:14:00.342Z,1533096840.342 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-08-01T04:14:00.342Z,1533096840.342 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-08-01T04:14:00.343Z,1533096840.343 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-08-01T04:14:00.499Z,1533096840.499 [SBIT](DEBUG): Construct Startup Built In Test.
2018-08-01T04:14:00.522Z,1533096840.522 [SBIT] Loaded
2018-08-01T04:14:00.522Z,1533096840.522 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-08-01T04:14:00.523Z,1533096840.523 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-08-01T04:14:00.535Z,1533096840.535 [IBIT] Loaded
2018-08-01T04:14:00.535Z,1533096840.535 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-08-01T04:14:00.538Z,1533096840.538 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-08-01T04:14:00.689Z,1533096840.689 [CBIT] Loaded
2018-08-01T04:14:00.690Z,1533096840.690 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-08-01T04:14:00.690Z,1533096840.690 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-08-01T04:14:00.691Z,1533096840.691 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-08-01T04:14:00.881Z,1533096840.881 [Aanderaa_O2] Loaded
2018-08-01T04:14:00.881Z,1533096840.881 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-08-01T04:14:00.929Z,1533096840.929 [CTD_Seabird] Loaded
2018-08-01T04:14:00.929Z,1533096840.929 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-08-01T04:14:00.930Z,1533096840.930 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 408AA4E0
2018-08-01T04:14:00.931Z,1533096840.931 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 883
2018-08-01T04:14:00.949Z,1533096840.949 [ESPComponent] Loaded
2018-08-01T04:14:00.949Z,1533096840.949 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2018-08-01T04:14:00.963Z,1533096840.963 [PAR_Licor] Loaded
2018-08-01T04:14:00.964Z,1533096840.964 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-08-01T04:14:01.013Z,1533096841.013 [WetLabsBB2FL] Loaded
2018-08-01T04:14:01.013Z,1533096841.013 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-08-01T04:14:01.014Z,1533096841.014 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408DA4E0
2018-08-01T04:14:01.014Z,1533096841.014 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 884
2018-08-01T04:14:01.015Z,1533096841.015 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-08-01T04:14:01.016Z,1533096841.016 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-08-01T04:14:01.300Z,1533096841.300 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-08-01T04:14:01.301Z,1533096841.301 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-08-01T04:14:01.406Z,1533096841.406 [VerticalControl](DEBUG): Construct VerticalControl.
2018-08-01T04:14:01.570Z,1533096841.570 [VerticalControl] Loaded
2018-08-01T04:14:01.571Z,1533096841.571 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-08-01T04:14:01.571Z,1533096841.571 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-08-01T04:14:01.633Z,1533096841.633 [HorizontalControl] Loaded
2018-08-01T04:14:01.634Z,1533096841.634 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-08-01T04:14:01.634Z,1533096841.634 [SpeedControl](DEBUG): Construct SpeedControl.
2018-08-01T04:14:01.640Z,1533096841.640 [SpeedControl] Loaded
2018-08-01T04:14:01.640Z,1533096841.640 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-08-01T04:14:01.641Z,1533096841.641 [LoopControl](DEBUG): Construct LoopControl.
2018-08-01T04:14:01.641Z,1533096841.641 [LoopControl] Loaded
2018-08-01T04:14:01.641Z,1533096841.641 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-08-01T04:14:01.642Z,1533096841.642 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-08-01T04:14:01.643Z,1533096841.643 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-08-01T04:14:01.767Z,1533096841.767 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC
2018-08-01T04:14:01.767Z,1533096841.767 [StratificationFrontDetector](DEBUG): (re)initializing
2018-08-01T04:14:01.767Z,1533096841.767 [StratificationFrontDetector] Loaded
2018-08-01T04:14:01.768Z,1533096841.768 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2018-08-01T04:14:01.768Z,1533096841.768 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-08-01T04:14:01.769Z,1533096841.769 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-08-01T04:14:01.889Z,1533096841.889 [BuoyancyServo] Loaded
2018-08-01T04:14:01.889Z,1533096841.889 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-08-01T04:14:01.901Z,1533096841.901 [ElevatorServo] Loaded
2018-08-01T04:14:01.901Z,1533096841.901 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-08-01T04:14:01.912Z,1533096841.912 [MassServo] Loaded
2018-08-01T04:14:01.912Z,1533096841.912 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-08-01T04:14:01.923Z,1533096841.923 [RudderServo] Loaded
2018-08-01T04:14:01.924Z,1533096841.924 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-08-01T04:14:01.935Z,1533096841.935 [ThrusterServo] Loaded
2018-08-01T04:14:01.935Z,1533096841.935 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-08-01T04:14:01.936Z,1533096841.936 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-08-01T04:14:01.936Z,1533096841.936 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-08-01T04:14:02.044Z,1533096842.044 [DeadReckonUsingSpeedCalculator] Loaded
2018-08-01T04:14:02.045Z,1533096842.045 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-08-01T04:14:02.061Z,1533096842.061 [NavChart] Loaded
2018-08-01T04:14:02.061Z,1533096842.061 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-08-01T04:14:02.065Z,1533096842.065 [UniversalFixResidualReporter] Loaded
2018-08-01T04:14:02.066Z,1533096842.066 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-08-01T04:14:02.066Z,1533096842.066 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-08-01T04:14:02.070Z,1533096842.070 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-08-01T04:14:02.070Z,1533096842.070 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-08-01T04:14:02.077Z,1533096842.077 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-08-01T04:14:02.078Z,1533096842.078 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A334E0
2018-08-01T04:14:02.079Z,1533096842.079 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 886
2018-08-01T04:14:02.083Z,1533096842.083 [Supervisor](INFO): Main Thread ID is 798
2018-08-01T04:14:02.083Z,1533096842.083 [Supervisor](DEBUG): Running supervisor.
2018-08-01T04:14:02.084Z,1533096842.084 [CommandLine ThreadHandler](INFO): Handler Thread ID is 887
2018-08-01T04:14:02.086Z,1533096842.086 [controlThread ThreadHandler](INFO): Handler Thread ID is 888
2018-08-01T04:14:02.087Z,1533096842.087 [controlThread](DEBUG): Initializing ControlThread
2018-08-01T04:14:02.088Z,1533096842.088 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-08-01T04:14:02.088Z,1533096842.088 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-08-01T04:14:02.089Z,1533096842.089 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-08-01T04:14:02.089Z,1533096842.089 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-08-01T04:14:02.090Z,1533096842.090 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2018-08-01T04:14:02.090Z,1533096842.090 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-08-01T04:14:02.091Z,1533096842.091 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-08-01T04:14:02.095Z,1533096842.095 [SBIT](INFO): Initialize SBIT Component.
2018-08-01T04:14:02.096Z,1533096842.096 [SBIT](IMPORTANT): git: 2018-07-25
2018-08-01T04:14:02.096Z,1533096842.096 [SBIT](INFO): git hash: 2912d14d75d7acdc47d6eebe250915c9e75a6268
2018-08-01T04:14:02.096Z,1533096842.096 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-08-01T04:14:02.098Z,1533096842.098 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-08-01T04:14:02.099Z,1533096842.099 [SBIT](INFO): Beginning SBIT in 63.000000 seconds.
2018-08-01T04:14:02.099Z,1533096842.099 [IBIT](INFO): Initialize IBIT Component.
2018-08-01T04:14:02.100Z,1533096842.100 [CBIT](DEBUG): Initialize CBIT Component.
2018-08-01T04:14:02.100Z,1533096842.100 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2018-08-01T04:14:02.101Z,1533096842.101 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-08-01T04:14:02.101Z,1533096842.102 [logger ThreadHandler](INFO): Handler Thread ID is 889
2018-08-01T04:14:02.121Z,1533096842.121 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 890
2018-08-01T04:14:02.127Z,1533096842.127 [Radio_Surface](INFO): Powering up
2018-08-01T04:14:02.133Z,1533096842.133 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 891
2018-08-01T04:14:02.134Z,1533096842.134 [Rowe_600LCM](INFO): Initializing
2018-08-01T04:14:02.134Z,1533096842.134 [Rowe_600LCM](INFO): Checking LCM
2018-08-01T04:14:02.233Z,1533096842.233 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 892
2018-08-01T04:14:02.234Z,1533096842.234 [CTD_Seabird](INFO): Initializing
2018-08-01T04:14:02.234Z,1533096842.234 [CTD_Seabird](INFO): Checking LCM
2018-08-01T04:14:02.237Z,1533096842.237 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-08-01T04:14:02.239Z,1533096842.239 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-08-01T04:14:02.239Z,1533096842.239 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-08-01T04:14:02.240Z,1533096842.240 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-08-01T04:14:02.242Z,1533096842.242 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-08-01T04:14:02.242Z,1533096842.242 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-08-01T04:14:02.243Z,1533096842.243 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-08-01T04:14:02.243Z,1533096842.243 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-08-01T04:14:02.243Z,1533096842.243 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-08-01T04:14:02.244Z,1533096842.244 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-08-01T04:14:02.259Z,1533096842.259 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 893
2018-08-01T04:14:02.260Z,1533096842.260 [WetLabsBB2FL](INFO): Powering down
2018-08-01T04:14:02.373Z,1533096842.373 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 894
2018-08-01T04:14:02.380Z,1533096842.380 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-08-01T04:14:02.381Z,1533096842.381 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-08-01T04:14:02.381Z,1533096842.381 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-08-01T04:14:02.381Z,1533096842.381 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-08-01T04:14:02.381Z,1533096842.381 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-08-01T04:14:02.381Z,1533096842.381 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-08-01T04:14:02.382Z,1533096842.382 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-08-01T04:14:02.383Z,1533096842.383 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-08-01T04:14:02.383Z,1533096842.383 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-08-01T04:14:02.383Z,1533096842.383 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-08-01T04:14:02.383Z,1533096842.383 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-08-01T04:14:02.401Z,1533096842.401 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-08-01T04:14:02.458Z,1533096842.458 [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>


2018-08-01T04:14:02.523Z,1533096842.523 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-08-01T04:14:02.607Z,1533096842.607 [CTD_Seabird](INFO): LCM OK
2018-08-01T04:14:02.607Z,1533096842.607 [CTD_Seabird](INFO): Powering up
2018-08-01T04:14:02.607Z,1533096842.607 [Rowe_600LCM](INFO): LCM OK
2018-08-01T04:14:02.607Z,1533096842.607 [Rowe_600LCM](INFO): Powering up
2018-08-01T04:14:02.662Z,1533096842.662 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-08-01T04:14:02.663Z,1533096842.663 [Default:A.Wait](DEBUG): Construct Wait.
2018-08-01T04:14:02.679Z,1533096842.679 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-08-01T04:14:02.713Z,1533096842.713 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-08-01T04:14:02.715Z,1533096842.715 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-08-01T04:14:02.731Z,1533096842.731 [Default:E.Execute](DEBUG): Construct Execute.
2018-08-01T04:14:02.749Z,1533096842.749 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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


2018-08-01T04:14:02.769Z,1533096842.769 [controlThread](DEBUG): Component order: CycleStarter,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-08-01T04:14:02.797Z,1533096842.797 [AcousticModem_Benthos_ATM900](INFO): Powering up
2018-08-01T04:14:02.797Z,1533096842.797 [AcousticModem_Benthos_ATM900](DEBUG): Initializing AcousticModem_Benthos_ATM900.
2018-08-01T04:14:02.840Z,1533096842.840 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-08-01T04:14:03.283Z,1533096843.283 [ESPComponent](INFO): powering down ESP
2018-08-01T04:14:03.781Z,1533096843.781 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:03.977Z,1533096843.977 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:03.989Z,1533096843.989 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-08-01T04:14:04.021Z,1533096844.021 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:04.029Z,1533096844.029 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-08-01T04:14:04.052Z,1533096844.052 [MassServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:04.061Z,1533096844.061 [MassServo](DEBUG): Initializing MassServo.
2018-08-01T04:14:04.075Z,1533096844.075 [RudderServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:04.081Z,1533096844.081 [RudderServo](DEBUG): Initializing RudderServo.
2018-08-01T04:14:04.095Z,1533096844.095 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:04.101Z,1533096844.101 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-08-01T04:14:04.282Z,1533096844.282 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2018-08-01T04:14:04.282Z,1533096844.282 [DropWeight] Hardware Fault, FailCount= 1
2018-08-01T04:14:04.282Z,1533096844.282 [DropWeight](ERROR): Hardware Fault
2018-08-01T04:14:04.381Z,1533096844.381 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:04.399Z,1533096844.399 [CommandLine](FAULT): Scheduling is paused
2018-08-01T04:14:04.400Z,1533096844.400 [CBIT](INFO): Critical error at 20180801T041404
2018-08-01T04:14:04.400Z,1533096844.400 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-08-01T04:14:04.402Z,1533096844.402 [CBIT](ERROR): Hardware Fault in component: DropWeight
2018-08-01T04:14:04.403Z,1533096844.403 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2018-08-01T04:14:04.646Z,1533096844.646 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:04.985Z,1533096844.985 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-08-01T04:14:04.985Z,1533096844.985 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-08-01T04:14:04.985Z,1533096844.985 [BuoyancyServo] Communications Fault, FailCount= 1
2018-08-01T04:14:04.985Z,1533096844.985 [BuoyancyServo](ERROR): Communications Fault
2018-08-01T04:14:05.199Z,1533096845.199 [CBIT](INFO): Critical error at 20180801T041404
2018-08-01T04:14:05.201Z,1533096845.201 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-08-01T04:14:05.256Z,1533096845.256 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:05.282Z,1533096845.282 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-08-01T04:14:05.282Z,1533096845.282 [BuoyancyServo](INFO): Powering down
2018-08-01T04:14:05.657Z,1533096845.657 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:06.077Z,1533096846.077 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:06.434Z,1533096846.434 [Aanderaa_O2](INFO): Powering down
2018-08-01T04:14:06.576Z,1533096846.576 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:06.655Z,1533096846.655 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-08-01T04:14:06.775Z,1533096846.775 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-08-01T04:14:06.873Z,1533096846.873 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-08-01T04:14:06.941Z,1533096846.941 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-08-01T04:14:06.960Z,1533096846.960 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-08-01T04:14:06.974Z,1533096846.974 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-08-01T04:14:07.403Z,1533096847.403 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-08-01T04:14:07.404Z,1533096847.404 [BuoyancyServo] No Fault, FailCount= 1
2018-08-01T04:14:07.719Z,1533096847.719 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:07.719Z,1533096847.719 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-08-01T04:14:07.966Z,1533096847.966 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-08-01T04:14:08.126Z,1533096848.126 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null &
2018-08-01T04:14:08.128Z,1533096848.128 [CTD_Seabird](INFO): LCM subscribed to channel:ctd_t.seabird-gpctd
2018-08-01T04:14:08.729Z,1533096848.729 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-08-01T04:14:08.729Z,1533096848.729 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-08-01T04:14:08.729Z,1533096848.729 [BuoyancyServo] Communications Fault, FailCount= 2
2018-08-01T04:14:08.730Z,1533096848.730 [BuoyancyServo](ERROR): Communications Fault
2018-08-01T04:14:08.953Z,1533096848.953 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-08-01T04:14:08.970Z,1533096848.970 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-08-01T04:14:08.970Z,1533096848.970 [CTD_Seabird](INFO): Powering down
2018-08-01T04:14:09.107Z,1533096849.107 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-08-01T04:14:09.108Z,1533096849.108 [BuoyancyServo](INFO): Powering down
2018-08-01T04:14:10.566Z,1533096850.566 [AcousticModem_Benthos_ATM900](DEBUG): 
2018-08-01T04:14:11.487Z,1533096851.487 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-08-01T04:14:11.487Z,1533096851.487 [BuoyancyServo] No Fault, FailCount= 2
2018-08-01T04:14:11.771Z,1533096851.771 [AcousticModem_Benthos_ATM900](DEBUG): Teledyne Benthos ATM-900 Series OEM w/burn wire
2018-08-01T04:14:11.771Z,1533096851.771 [AcousticModem_Benthos_ATM900](DEBUG): MF Frequency Band
2018-08-01T04:14:11.772Z,1533096851.772 [AcousticModem_Benthos_ATM900](DEBUG): Standard version 8.6.3
2018-08-01T04:14:11.773Z,1533096851.773 [AcousticModem_Benthos_ATM900](DEBUG): Jan  1 2000 06:00:24 
2018-08-01T04:14:11.914Z,1533096851.914 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-08-01T04:14:11.914Z,1533096851.914 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-08-01T04:14:12.169Z,1533096852.169 [AcousticModem_Benthos_ATM900](DEBUG): WARNING: battery low
2018-08-01T04:14:12.966Z,1533096852.966 [AcousticModem_Benthos_ATM900](INFO): entering command mode
2018-08-01T04:14:13.366Z,1533096853.366 [AcousticModem_Benthos_ATM900](DEBUG): checking for command mode acknowledgment
2018-08-01T04:14:13.367Z,1533096853.367 [AcousticModem_Benthos_ATM900](DEBUG): read user prompt 1: user:1>
2018-08-01T04:14:13.367Z,1533096853.367 [AcousticModem_Benthos_ATM900](INFO): command mode acknowledged
2018-08-01T04:14:13.770Z,1533096853.770 [AcousticModem_Benthos_ATM900](INFO): setting local address to 3
2018-08-01T04:14:14.166Z,1533096854.166 [AcousticModem_Benthos_ATM900](DEBUG): checking for local address setting acknowledgment
2018-08-01T04:14:14.167Z,1533096854.167 [AcousticModem_Benthos_ATM900](INFO): set local address to 3
2018-08-01T04:14:14.567Z,1533096854.567 [AcousticModem_Benthos_ATM900](DEBUG): read user prompt 2: user:2>
2018-08-01T04:14:28.170Z,1533096868.170 [NAL9602](INFO): Powering up NAL9602
2018-08-01T04:14:39.370Z,1533096879.370 [NAL9602](INFO): NAL9602 initialized
2018-08-01T04:15:05.849Z,1533096905.849 [SBIT](IMPORTANT): Beginning Startup BIT
2018-08-01T04:15:05.862Z,1533096905.862 [CBIT](IMPORTANT): Beginning ground fault scan
2018-08-01T04:15:11.506Z,1533096911.506 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree
2018-08-01T04:15:11.508Z,1533096911.508 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2018-08-01T04:15:11.508Z,1533096911.508 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree
2018-08-01T04:15:11.510Z,1533096911.510 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2018-08-01T04:15:11.904Z,1533096911.904 [controlThread](DEBUG): Component order: CycleStarter,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-08-01T04:15:17.007Z,1533096917.007 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.009863
CHAN A1 (24V): -0.013667
CHAN A2 (12V): -0.003946
CHAN A3 (5V): -0.002681
CHAN B0 (3.3V): -0.000825
CHAN B1 (3.15aV): -0.001008
CHAN B2 (3.15bV): -0.001184
CHAN B3 (GND): 0.000062
OPEN: 0.004594
Full Scale Calc: 4.765 mA, -1.589 mA
2018-08-01T04:15:29.795Z,1533096929.795 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1533096576.000000 second
2018-08-01T04:15:41.610Z,1533096941.610 [CommandLine](IMPORTANT): got command get latitude
2018-08-01T04:15:41.611Z,1533096941.611 [CommandLine](IMPORTANT): latitude 36.799999 arcdeg
2018-08-01T04:15:59.675Z,1533096959.675 [SBIT](IMPORTANT): SBIT PASSED
2018-08-01T04:15:59.718Z,1533096959.718 [CommandLine](IMPORTANT): got command configSet list
2018-08-01T04:15:59.719Z,1533096959.719 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-08-01T04:15:59.722Z,1533096959.722 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup=0 bool;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): Express none Rowe_600LCM.height_above_sea_floor;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): IBIT.batteryHibernationTimeout=1 hour;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): IBIT.batteryMissingStickThreshold=15 count;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=200 cubic_centimeter;

2018-08-01T04:15:59.723Z,1533096959.723 [CommandLine](IMPORTANT): VerticalControl.massDefault=10 millimeter;

2018-08-01T04:16:00.123Z,1533096960.123 [MissionManager](IMPORTANT): Started mission Startup
2018-08-01T04:16:00.124Z,1533096960.124 [Startup] Running Loop=1
2018-08-01T04:16:00.124Z,1533096960.124 [Startup](DEBUG): Aggregate::initialize Startup
2018-08-01T04:16:00.130Z,1533096960.130 [Startup:A.GoToSurface] Running Loop=1
2018-08-01T04:16:00.130Z,1533096960.130 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-08-01T04:16:00.131Z,1533096960.131 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-08-01T04:16:00.138Z,1533096960.138 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-08-01T04:16:00.138Z,1533096960.138 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-08-01T04:16:00.140Z,1533096960.140 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-08-01T04:16:00.150Z,1533096960.150 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-08-01T04:16:00.188Z,1533096960.188 [Startup:StartupSatComms] Running Loop=1
2018-08-01T04:16:00.200Z,1533096960.200 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-08-01T04:16:00.200Z,1533096960.200 [Startup:StartupSatComms:A] Running Loop=1
2018-08-01T04:16:00.481Z,1533096960.481 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-08-01T04:16:00.483Z,1533096960.483 [Startup:StartupSatComms:A] Stopped
2018-08-01T04:16:00.483Z,1533096960.483 [Startup:StartupSatComms:B] Running Loop=1
2018-08-01T04:16:00.880Z,1533096960.880 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-08-01T04:16:03.377Z,1533096963.377 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-08-01T04:16:03.377Z,1533096963.377 [Rowe_600LCM] Communications Fault, FailCount= 1
2018-08-01T04:16:03.377Z,1533096963.377 [Rowe_600LCM](ERROR): Communications Fault
2018-08-01T04:16:03.689Z,1533096963.689 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-08-01T04:16:03.781Z,1533096963.781 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-08-01T04:16:03.878Z,1533096963.878 [Rowe_600LCM](INFO): Powering down
2018-08-01T04:16:05.282Z,1533096965.282 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-08-01T04:16:05.282Z,1533096965.282 [Rowe_600LCM] No Fault, FailCount= 1
2018-08-01T04:16:05.493Z,1533096965.493 [Rowe_600LCM](INFO): Initializing
2018-08-01T04:16:05.494Z,1533096965.494 [Rowe_600LCM](INFO): Checking LCM
2018-08-01T04:16:05.494Z,1533096965.494 [Rowe_600LCM](INFO): LCM OK
2018-08-01T04:16:05.494Z,1533096965.494 [Rowe_600LCM](INFO): Powering up
2018-08-01T04:16:09.719Z,1533096969.719 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-08-01T04:16:09.815Z,1533096969.815 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-08-01T04:16:09.817Z,1533096969.817 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-08-01T04:16:09.818Z,1533096969.818 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-08-01T04:16:09.818Z,1533096969.818 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-08-01T04:16:35.591Z,1533096995.591 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003910
2018-08-01T04:16:40.216Z,1533097000.216 [DataOverHttps](INFO): Sending 240 bytes from file Logs/20180801T041351/Courier0000.lzma
2018-08-01T04:16:41.016Z,1533097001.016 [DataOverHttps](INFO): Moved sent file to Logs/20180801T041351/Courier0000.lzma.bak
2018-08-01T04:16:41.016Z,1533097001.016 [DataOverHttps](INFO): SBD MOMSN=8389948
2018-08-01T04:16:47.529Z,1533097007.529 [DataOverHttps](IMPORTANT): SBD MTMSN=20180801T041055
2018-08-01T04:16:52.735Z,1533097012.735 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20180731T224756/Express0001.lzma
2018-08-01T04:16:52.755Z,1533097012.755 [DataOverHttps](INFO): Received command:sched asap "load Maintenance/sample.xml;set sample.MissionTimeout 5 hour;set sample.Depth 2 meter;set sample.NumberOfSamples 3 count;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 2 meter" 29sy6 1 2
2018-08-01T04:16:52.767Z,1533097012.767 [CommandLine](IMPORTANT): got command schedule asap "load Maintenance/sample.xml;set sample.MissionTimeout 5 hour;set sample.Depth 2 meter;set sample.NumberOfSamples 3 count;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 2 meter" 29sy6 1 2.000000
2018-08-01T04:16:52.767Z,1533097012.767 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=29sy6
2018-08-01T04:16:52.768Z,1533097012.768 [CommandLine](IMPORTANT): Scheduled #1 (#1 of 2 with id='29sy6'): "load Maintenance/sample.xml;set sample.MissionTimeout 5 hour;set sample.Depth 2 meter;set sample.NumberOfSamples 3 count;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 2 meter" ASAP
2018-08-01T04:16:53.664Z,1533097013.664 [DataOverHttps](INFO): Moved sent file to Logs/20180731T224756/Express0001.lzma.bak
2018-08-01T04:16:53.664Z,1533097013.664 [DataOverHttps](IMPORTANT): SBD MOMSN=8389954, MTMSN=20180801T041101
2018-08-01T04:16:58.000Z,1533097019.000 [DataOverHttps](INFO): Received command:sched asap "set sample:SampleAtDepth.SettleTime 3 second;run " 29sy6 2 2
2018-08-01T04:16:59.076Z,1533097019.076 [CommandLine](IMPORTANT): got command schedule asap "set sample:SampleAtDepth.SettleTime 3 second;run " 29sy6 2 2.000000
2018-08-01T04:16:59.077Z,1533097019.077 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=29sy6
2018-08-01T04:16:59.078Z,1533097019.078 [CommandLine](IMPORTANT): Scheduled #2 (#2 of 2 with id='29sy6'): "set sample:SampleAtDepth.SettleTime 3 second;run " ASAP
2018-08-01T04:16:59.275Z,1533097019.275 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2018-08-01T04:16:59.275Z,1533097019.275 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2018-08-01T04:16:59.319Z,1533097019.319 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2018-08-01T04:16:59.322Z,1533097019.322 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2018-08-01T04:16:59.325Z,1533097019.325 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2018-08-01T04:16:59.328Z,1533097019.328 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2018-08-01T04:16:59.330Z,1533097019.330 [sample:A.Pitch](DEBUG): Construct.
2018-08-01T04:16:59.336Z,1533097019.336 [sample:B.SetSpeed](DEBUG): Construct.
2018-08-01T04:16:59.374Z,1533097019.374 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2018-08-01T04:16:59.546Z,1533097019.546 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2018-08-01T04:16:59.558Z,1533097019.558 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 30.000000 s
2018-08-01T04:16:59.573Z,1533097019.573 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2018-08-01T04:16:59.597Z,1533097019.597 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2018-08-01T04:16:59.613Z,1533097019.613 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2018-08-01T04:16:59.622Z,1533097019.622 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2018-08-01T04:16:59.633Z,1533097019.633 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2018-08-01T04:16:59.649Z,1533097019.649 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2018-08-01T04:16:59.652Z,1533097019.652 [sample:SampleAtDepth:B.Pitch](DEBUG): Construct.
2018-08-01T04:16:59.675Z,1533097019.675 [sample:SampleAtDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2018-08-01T04:16:59.688Z,1533097019.688 [sample:SampleAtDepth:D.Wait](DEBUG): Construct Wait.
2018-08-01T04:16:59.726Z,1533097019.726 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2018-08-01T04:16:59.738Z,1533097019.738 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2018-08-01T04:16:59.738Z,1533097019.738 [MissionManager](ERROR): Slate does not contain celsius
2018-08-01T04:16:59.759Z,1533097019.759 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2018-08-01T04:16:59.768Z,1533097019.768 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2018-08-01T04:16:59.768Z,1533097019.768 [MissionManager](ERROR): Slate does not contain celsius
2018-08-01T04:16:59.816Z,1533097019.816 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target depth.
    </Description>
    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

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

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

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>
    <Timeout Duration="MissionTimeout"/>
    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

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

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

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

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

    <Aggregate Id="SampleRepeater">
        <Sequence Repeat="NumberOfSamples"/>

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

2018-08-01T04:16:59.816Z,1533097019.816 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2018-08-01T04:17:00.561Z,1533097020.561 [Startup:StartupSatComms:B](INFO): Timed out from 2018-08-01T04:16:00.5Z
2018-08-01T04:17:00.562Z,1533097020.562 [Startup:StartupSatComms:B] Stopped
2018-08-01T04:17:00.562Z,1533097020.562 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-08-01T04:17:00.562Z,1533097020.562 [Startup:StartupSatComms] Stopped
2018-08-01T04:17:00.562Z,1533097020.562 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-08-01T04:17:00.563Z,1533097020.563 [Startup](INFO): Completed Startup
2018-08-01T04:17:00.563Z,1533097020.563 [MissionManager](INFO): Startup is completed.
2018-08-01T04:17:00.563Z,1533097020.563 [MissionManager](INFO): Uninitializing Mission Startup
2018-08-01T04:17:00.563Z,1533097020.563 [Startup] Stopped
2018-08-01T04:17:00.564Z,1533097020.564 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-08-01T04:17:00.564Z,1533097020.564 [Startup:A.GoToSurface] Stopped
2018-08-01T04:17:00.564Z,1533097020.564 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-08-01T04:17:01.009Z,1533097021.009 [MissionManager](IMPORTANT): Started mission Default
2018-08-01T04:17:01.010Z,1533097021.010 [Default] Running Loop=1
2018-08-01T04:17:01.010Z,1533097021.010 [Default](DEBUG): Aggregate::initialize Default
2018-08-01T04:17:01.010Z,1533097021.010 [Default:B.GoToSurface] Running Loop=1
2018-08-01T04:17:01.010Z,1533097021.010 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-08-01T04:17:01.010Z,1533097021.010 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-08-01T04:17:01.011Z,1533097021.011 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-08-01T04:17:01.011Z,1533097021.011 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-08-01T04:17:01.012Z,1533097021.012 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-08-01T04:17:01.012Z,1533097021.012 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-08-01T04:17:01.013Z,1533097021.013 [Default:A.Wait] Running Loop=1
2018-08-01T04:17:01.013Z,1533097021.013 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-08-01T04:17:08.119Z,1533097028.119 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180801T041351/Courier0004.lzma
2018-08-01T04:17:08.896Z,1533097028.896 [DataOverHttps](INFO): Moved sent file to Logs/20180801T041351/Courier0004.lzma.bak
2018-08-01T04:17:08.896Z,1533097028.896 [DataOverHttps](INFO): SBD MOMSN=8389959
2018-08-01T04:17:12.862Z,1533097032.862 [CommandLine](IMPORTANT): got command set sample.MissionTimeout 5.000000 hour
2018-08-01T04:17:12.863Z,1533097032.863 [CommandLine](IMPORTANT): got command set sample.Depth 2.000000 meter
2018-08-01T04:17:12.864Z,1533097032.864 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 3.000000 count
2018-08-01T04:17:12.865Z,1533097032.865 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2018-08-01T04:17:12.866Z,1533097032.866 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 2.000000 meter
2018-08-01T04:17:14.172Z,1533097034.172 [Default:A.Wait](INFO): Done Waiting.
2018-08-01T04:17:14.172Z,1533097034.172 [Default:A.Wait] Stopped
2018-08-01T04:17:14.172Z,1533097034.172 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-08-01T04:17:14.603Z,1533097034.603 [Default:CheckIn] Running Loop=1
2018-08-01T04:17:14.603Z,1533097034.603 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-08-01T04:17:14.604Z,1533097034.604 [Default:CheckIn:Read_GPS] Running Loop=1
2018-08-01T04:17:15.043Z,1533097035.043 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-08-01T04:17:15.873Z,1533097035.873 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SettleTime 3.000000 second
2018-08-01T04:17:15.874Z,1533097035.874 [CommandLine](IMPORTANT): got command run 
2018-08-01T04:17:15.876Z,1533097035.876 [CommandLine](IMPORTANT): Running 
2018-08-01T04:17:16.157Z,1533097036.157 [Default] Stopped
2018-08-01T04:17:16.157Z,1533097036.157 [Default](DEBUG): Aggregate::uninitialize Default
2018-08-01T04:17:16.157Z,1533097036.157 [Default:B.GoToSurface] Stopped
2018-08-01T04:17:16.157Z,1533097036.157 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-08-01T04:17:16.158Z,1533097036.158 [Default:CheckIn] Stopped
2018-08-01T04:17:16.158Z,1533097036.158 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-08-01T04:17:16.158Z,1533097036.158 [Default:CheckIn:Read_GPS] Stopped
2018-08-01T04:17:16.158Z,1533097036.158 [MissionManager](IMPORTANT): Started mission sample
2018-08-01T04:17:16.158Z,1533097036.158 [sample] Running Loop=1
2018-08-01T04:17:16.158Z,1533097036.158 [sample](DEBUG): Aggregate::initialize sample
2018-08-01T04:17:16.159Z,1533097036.159 [sample:A.Pitch] Running Loop=1
2018-08-01T04:17:16.159Z,1533097036.159 [sample:A.Pitch](DEBUG): Initialize.
2018-08-01T04:17:16.159Z,1533097036.159 [sample:B.SetSpeed] Running Loop=1
2018-08-01T04:17:16.159Z,1533097036.159 [sample:B.SetSpeed](DEBUG): Initialize.
2018-08-01T04:17:16.159Z,1533097036.159 [sample:D] Running Loop=1
2018-08-01T04:17:16.161Z,1533097036.161 [sample:D] Stopped
2018-08-01T04:17:16.161Z,1533097036.161 [sample:E] Running Loop=1
2018-08-01T04:17:16.161Z,1533097036.161 [sample:B.SetSpeed] Running Loop=1
2018-08-01T04:17:16.174Z,1533097036.174 [sample:A.Pitch] Running Loop=1
2018-08-01T04:17:16.546Z,1533097036.546 [sample:E] Stopped
2018-08-01T04:17:16.546Z,1533097036.546 [sample:SampleRepeater] Running Loop=1
2018-08-01T04:17:16.546Z,1533097036.546 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2018-08-01T04:17:16.547Z,1533097036.547 [sample:SampleRepeater:Sample] Running Loop=1
2018-08-01T04:17:16.547Z,1533097036.547 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2018-08-01T04:17:16.965Z,1533097036.965 [sample:SampleAtDepth] Running Loop=1
2018-08-01T04:17:16.965Z,1533097036.965 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2018-08-01T04:17:16.965Z,1533097036.965 [sample:SampleAtDepth:B.Pitch] Running Loop=1
2018-08-01T04:17:16.966Z,1533097036.966 [sample:SampleAtDepth:B.Pitch](DEBUG): Initialize.
2018-08-01T04:17:16.966Z,1533097036.966 [sample:SampleAtDepth:A] Running Loop=1
2018-08-01T04:17:17.005Z,1533097037.005 [sample:SampleAtDepth:A](INFO): Moving to 2.000000 m 
2018-08-01T04:17:17.019Z,1533097037.019 [sample:SampleAtDepth:A] Stopped
2018-08-01T04:17:18.782Z,1533097038.782 [CommandLine](IMPORTANT): got command failComponent
2018-08-01T04:17:18.783Z,1533097038.783 [CommandLine](IMPORTANT): Failed components:
2018-08-01T04:17:18.783Z,1533097038.783 [CommandLine](IMPORTANT): DropWeight: Hardware Fault
2018-08-01T04:17:23.990Z,1533097043.990 [CommandLine](IMPORTANT): got command stop
2018-08-01T04:17:23.991Z,1533097043.991 [CommandLine](IMPORTANT): Scheduling is paused
2018-08-01T04:17:23.991Z,1533097043.991 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2018-08-01T04:17:24.172Z,1533097044.172 [MissionManager](INFO): MissionManager is completed.
2018-08-01T04:17:24.173Z,1533097044.173 [MissionManager](INFO): Uninitializing Mission sample
2018-08-01T04:17:24.173Z,1533097044.173 [sample] Stopped
2018-08-01T04:17:24.173Z,1533097044.173 [sample](DEBUG): Aggregate::uninitialize sample
2018-08-01T04:17:24.173Z,1533097044.173 [sample:A.Pitch] Stopped
2018-08-01T04:17:24.173Z,1533097044.173 [sample:B.SetSpeed] Stopped
2018-08-01T04:17:24.173Z,1533097044.173 [sample:B.SetSpeed](DEBUG): Uninitialize.
2018-08-01T04:17:24.173Z,1533097044.173 [sample:SampleAtDepth] Stopped
2018-08-01T04:17:24.173Z,1533097044.173 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2018-08-01T04:17:24.173Z,1533097044.173 [sample:SampleAtDepth:B.Pitch] Stopped
2018-08-01T04:17:24.174Z,1533097044.174 [sample:SampleRepeater] Stopped
2018-08-01T04:17:24.174Z,1533097044.174 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2018-08-01T04:17:24.174Z,1533097044.174 [sample:SampleRepeater:Sample] Stopped
2018-08-01T04:17:24.174Z,1533097044.174 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2018-08-01T04:17:24.560Z,1533097044.560 [MissionManager](IMPORTANT): Started mission Default
2018-08-01T04:17:24.560Z,1533097044.560 [Default] Running Loop=1
2018-08-01T04:17:24.560Z,1533097044.560 [Default](DEBUG): Aggregate::initialize Default
2018-08-01T04:17:24.560Z,1533097044.560 [Default:B.GoToSurface] Running Loop=1
2018-08-01T04:17:24.560Z,1533097044.560 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-08-01T04:17:24.561Z,1533097044.561 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-08-01T04:17:24.561Z,1533097044.561 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-08-01T04:17:24.562Z,1533097044.562 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-08-01T04:17:24.562Z,1533097044.562 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-08-01T04:17:24.562Z,1533097044.562 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-08-01T04:17:24.563Z,1533097044.563 [Default:A.Wait] Running Loop=1
2018-08-01T04:17:24.563Z,1533097044.563 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-08-01T04:17:37.793Z,1533097057.793 [Default:A.Wait](INFO): Done Waiting.
2018-08-01T04:17:37.793Z,1533097057.793 [Default:A.Wait] Stopped
2018-08-01T04:17:37.794Z,1533097057.794 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-08-01T04:17:38.149Z,1533097058.149 [Default:CheckIn] Running Loop=1
2018-08-01T04:17:38.149Z,1533097058.149 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-08-01T04:17:38.149Z,1533097058.149 [Default:CheckIn:Read_GPS] Running Loop=1
2018-08-01T04:17:40.035Z,1533097060.035 [CommandLine](IMPORTANT): got command configSet list
2018-08-01T04:17:40.035Z,1533097060.035 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-08-01T04:17:40.036Z,1533097060.036 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup=0 bool;

2018-08-01T04:17:40.036Z,1533097060.036 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2018-08-01T04:17:40.036Z,1533097060.036 [CommandLine](IMPORTANT): Express none Rowe_600LCM.height_above_sea_floor;

2018-08-01T04:17:40.037Z,1533097060.037 [CommandLine](IMPORTANT): IBIT.batteryHibernationTimeout=1 hour;

2018-08-01T04:17:40.037Z,1533097060.037 [CommandLine](IMPORTANT): IBIT.batteryMissingStickThreshold=15 count;

2018-08-01T04:17:40.037Z,1533097060.037 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;

2018-08-01T04:17:40.037Z,1533097060.037 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=200 cubic_centimeter;

2018-08-01T04:17:40.037Z,1533097060.037 [CommandLine](IMPORTANT): VerticalControl.massDefault=10 millimeter;

2018-08-01T04:18:05.767Z,1533097085.767 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-08-01T04:18:05.768Z,1533097085.768 [Rowe_600LCM] Communications Fault, FailCount= 2
2018-08-01T04:18:05.768Z,1533097085.768 [Rowe_600LCM](ERROR): Communications Fault
2018-08-01T04:18:05.797Z,1533097085.797 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-08-01T04:18:06.173Z,1533097086.173 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-08-01T04:18:06.262Z,1533097086.262 [Rowe_600LCM](INFO): Powering down
2018-08-01T04:18:07.735Z,1533097087.735 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-08-01T04:18:07.736Z,1533097087.736 [Rowe_600LCM] No Fault, FailCount= 2
2018-08-01T04:18:07.877Z,1533097087.877 [Rowe_600LCM](INFO): Initializing
2018-08-01T04:18:07.877Z,1533097087.877 [Rowe_600LCM](INFO): Checking LCM
2018-08-01T04:18:07.878Z,1533097087.878 [Rowe_600LCM](INFO): LCM OK
2018-08-01T04:18:07.878Z,1533097087.878 [Rowe_600LCM](INFO): Powering up
2018-08-01T04:18:12.133Z,1533097092.133 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-08-01T04:18:12.196Z,1533097092.196 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-08-01T04:18:12.197Z,1533097092.197 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-08-01T04:18:12.198Z,1533097092.198 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-08-01T04:18:12.199Z,1533097092.199 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-08-01T04:18:15.118Z,1533097095.118 [CommandLine](IMPORTANT): got command restart application
2018-08-01T04:18:16.128Z,1533097096.128 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:16.129Z,1533097096.129 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.153Z,1533097096.153 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-08-01T04:18:16.153Z,1533097096.153 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.154Z,1533097096.154 [CommandLine](INFO): Join timeout helper Thread ID is 936
2018-08-01T04:18:16.165Z,1533097096.165 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-08-01T04:18:16.165Z,1533097096.165 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.166Z,1533097096.166 [NavChartDb](INFO): Join timeout helper Thread ID is 937
2018-08-01T04:18:16.441Z,1533097096.441 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:16.441Z,1533097096.441 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.453Z,1533097096.453 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-08-01T04:18:16.453Z,1533097096.453 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.453Z,1533097096.453 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 938
2018-08-01T04:18:16.454Z,1533097096.454 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:16.454Z,1533097096.454 [WetLabsBB2FL](INFO): Powering down
2018-08-01T04:18:16.455Z,1533097096.455 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.455Z,1533097096.455 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-08-01T04:18:16.455Z,1533097096.455 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.456Z,1533097096.456 [CTD_Seabird](INFO): Join timeout helper Thread ID is 939
2018-08-01T04:18:16.825Z,1533097096.825 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:16.989Z,1533097096.989 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-08-01T04:18:16.989Z,1533097096.989 [CTD_Seabird](INFO): Powering down
2018-08-01T04:18:16.990Z,1533097096.990 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.997Z,1533097096.997 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-08-01T04:18:16.997Z,1533097096.997 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:16.997Z,1533097096.997 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 941
2018-08-01T04:18:17.377Z,1533097097.377 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:17.377Z,1533097097.377 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-08-01T04:18:17.463Z,1533097097.463 [Rowe_600LCM](INFO): Powering down
2018-08-01T04:18:17.464Z,1533097097.464 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.470Z,1533097097.470 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-08-01T04:18:17.470Z,1533097097.470 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.471Z,1533097097.471 [Radio_Surface](INFO): Join timeout helper Thread ID is 943
2018-08-01T04:18:17.721Z,1533097097.721 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:17.722Z,1533097097.722 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.742Z,1533097097.742 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-08-01T04:18:17.742Z,1533097097.742 [logger ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.742Z,1533097097.742 [logger](INFO): Join timeout helper Thread ID is 944
2018-08-01T04:18:17.777Z,1533097097.777 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:17.777Z,1533097097.777 [logger ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.781Z,1533097097.781 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-08-01T04:18:17.782Z,1533097097.782 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.782Z,1533097097.782 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-08-01T04:18:17.782Z,1533097097.782 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:17.782Z,1533097097.782 [controlThread](INFO): Join timeout helper Thread ID is 945
2018-08-01T04:18:17.961Z,1533097097.961 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-08-01T04:18:17.961Z,1533097097.961 [controlThread](DEBUG): Uninitializing ControlThread
2018-08-01T04:18:17.962Z,1533097097.962 [AcousticModem_Benthos_ATM900](INFO): Powering down
2018-08-01T04:18:18.082Z,1533097098.082 [NAL9602](INFO): Powering down
2018-08-01T04:18:18.083Z,1533097098.083 [PNI_TCM](INFO): Powering down
2018-08-01T04:18:18.170Z,1533097098.170 [Aanderaa_O2](INFO): Powering down
2018-08-01T04:18:18.173Z,1533097098.173 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-08-01T04:18:18.174Z,1533097098.174 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-08-01T04:18:18.175Z,1533097098.175 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-08-01T04:18:18.176Z,1533097098.176 [MissionManager](INFO): Uninitializing Mission Default
2018-08-01T04:18:18.176Z,1533097098.176 [Default] Stopped
2018-08-01T04:18:18.176Z,1533097098.176 [Default](DEBUG): Aggregate::uninitialize Default
2018-08-01T04:18:18.176Z,1533097098.176 [Default:B.GoToSurface] Stopped
2018-08-01T04:18:18.176Z,1533097098.176 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-08-01T04:18:18.176Z,1533097098.176 [Default:CheckIn] Stopped
2018-08-01T04:18:18.176Z,1533097098.176 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-08-01T04:18:18.177Z,1533097098.177 [Default:CheckIn:Read_GPS] Stopped
2018-08-01T04:18:18.180Z,1533097098.180 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-08-01T04:18:18.181Z,1533097098.181 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-08-01T04:18:18.181Z,1533097098.181 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-08-01T04:18:18.182Z,1533097098.182 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-08-01T04:18:18.182Z,1533097098.182 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-08-01T04:18:18.182Z,1533097098.182 [BuoyancyServo](INFO): Powering down
2018-08-01T04:18:18.197Z,1533097098.197 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-08-01T04:18:18.197Z,1533097098.197 [ElevatorServo](INFO): Powering down
2018-08-01T04:18:18.198Z,1533097098.198 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-08-01T04:18:18.198Z,1533097098.198 [MassServo](INFO): Powering down
2018-08-01T04:18:18.199Z,1533097098.199 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-08-01T04:18:18.199Z,1533097098.199 [RudderServo](INFO): Powering down
2018-08-01T04:18:18.200Z,1533097098.200 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-08-01T04:18:18.200Z,1533097098.200 [ThrusterServo](INFO): Powering down
2018-08-01T04:18:18.201Z,1533097098.201 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-08-01T04:18:18.202Z,1533097098.202 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-08-01T04:18:18.202Z,1533097098.202 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-08-01T04:18:18.203Z,1533097098.203 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.307Z,1533097098.307 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.314Z,1533097098.314 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.353Z,1533097098.353 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.358Z,1533097098.358 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.405Z,1533097098.405 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-08-01T04:18:18.471Z,1533097098.471 [logger ThreadHandler](INFO): Thread cancelled.