2018-07-30T15:31:17.945Z,1532964677.945 [Supervisor](DEBUG): Initializing supervisor.
2018-07-30T15:31:17.948Z,1532964677.948 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-07-30T15:31:17.949Z,1532964677.949 [SyncHandler](INFO): Protected caller Thread ID is 797
2018-07-30T15:31:17.949Z,1532964677.949 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-07-30T15:31:17.950Z,1532964677.950 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-07-30T15:31:17.951Z,1532964677.951 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 798
2018-07-30T15:31:17.953Z,1532964677.953 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-07-30T15:31:17.965Z,1532964677.965 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-07-30T15:31:17.966Z,1532964677.966 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-07-30T15:31:17.966Z,1532964677.966 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 799
2018-07-30T15:31:17.967Z,1532964677.967 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-07-30T15:31:17.968Z,1532964677.968 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-07-30T15:31:17.968Z,1532964677.968 [logger ThreadHandler](INFO): Protected caller Thread ID is 800
2018-07-30T15:31:17.970Z,1532964677.970 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-07-30T15:31:17.971Z,1532964677.971 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-07-30T15:31:17.975Z,1532964677.975 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-07-30T15:31:18.320Z,1532964678.320 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-07-30T15:31:18.322Z,1532964678.322 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-07-30T15:31:18.529Z,1532964678.529 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-07-30T15:31:18.530Z,1532964678.530 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-07-30T15:31:18.829Z,1532964678.829 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-07-30T15:31:18.831Z,1532964678.831 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-07-30T15:31:18.974Z,1532964678.974 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-07-30T15:31:18.975Z,1532964678.975 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-07-30T15:31:19.074Z,1532964679.074 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-07-30T15:31:19.075Z,1532964679.075 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-07-30T15:31:19.557Z,1532964679.557 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-07-30T15:31:19.559Z,1532964679.559 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-07-30T15:31:19.960Z,1532964679.960 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-07-30T15:31:19.962Z,1532964679.962 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-07-30T15:31:20.423Z,1532964680.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-07-30T15:31:20.425Z,1532964680.425 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-07-30T15:31:20.531Z,1532964680.531 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-07-30T15:31:20.532Z,1532964680.532 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-07-30T15:31:20.631Z,1532964680.631 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-07-30T15:31:20.632Z,1532964680.632 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-07-30T15:31:20.843Z,1532964680.843 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-07-30T15:31:20.843Z,1532964680.843 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-07-30T15:31:21.060Z,1532964681.060 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-07-30T15:31:21.061Z,1532964681.061 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-07-30T15:31:21.778Z,1532964681.778 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-07-30T15:31:21.779Z,1532964681.779 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-07-30T15:31:21.925Z,1532964681.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-07-30T15:31:21.926Z,1532964681.926 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-07-30T15:31:22.009Z,1532964682.009 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-07-30T15:31:22.013Z,1532964682.013 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-07-30T15:31:22.118Z,1532964682.118 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-07-30T15:31:22.239Z,1532964682.239 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-07-30T15:31:22.336Z,1532964682.336 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-07-30T15:31:22.423Z,1532964682.423 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-07-30T15:31:22.578Z,1532964682.578 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-07-30T15:31:22.761Z,1532964682.761 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-07-30T15:31:22.838Z,1532964682.838 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-07-30T15:31:23.071Z,1532964683.071 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-07-30T15:31:23.071Z,1532964683.071 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-07-30T15:31:23.156Z,1532964683.156 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-07-30T15:31:23.247Z,1532964683.247 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-07-30T15:31:23.349Z,1532964683.349 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-07-30T15:31:23.477Z,1532964683.477 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2018-07-30T15:31:23.482Z,1532964683.482 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-07-30T15:31:23.768Z,1532964683.768 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-07-30T15:31:23.770Z,1532964683.770 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-07-30T15:31:23.826Z,1532964683.826 [DepthRateCalculator] Loaded
2018-07-30T15:31:23.826Z,1532964683.826 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-07-30T15:31:23.832Z,1532964683.832 [PitchRateCalculator] Loaded
2018-07-30T15:31:23.832Z,1532964683.832 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-07-30T15:31:23.849Z,1532964683.849 [SpeedCalculator] Loaded
2018-07-30T15:31:23.849Z,1532964683.849 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-07-30T15:31:23.871Z,1532964683.871 [TempGradientCalculator] Loaded
2018-07-30T15:31:23.871Z,1532964683.871 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-07-30T15:31:23.887Z,1532964683.887 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2018-07-30T15:31:23.887Z,1532964683.887 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2018-07-30T15:31:23.893Z,1532964683.893 [YawRateCalculator] Loaded
2018-07-30T15:31:23.893Z,1532964683.893 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-07-30T15:31:23.934Z,1532964683.934 [ElevatorOffsetCalculator] Loaded
2018-07-30T15:31:23.934Z,1532964683.934 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-07-30T15:31:23.934Z,1532964683.934 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-07-30T15:31:23.935Z,1532964683.935 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-07-30T15:31:24.057Z,1532964684.057 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC
2018-07-30T15:31:24.057Z,1532964684.057 [StratificationFrontDetector](DEBUG): (re)initializing
2018-07-30T15:31:24.057Z,1532964684.057 [StratificationFrontDetector] Loaded
2018-07-30T15:31:24.057Z,1532964684.057 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2018-07-30T15:31:24.058Z,1532964684.058 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-07-30T15:31:24.059Z,1532964684.059 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-07-30T15:31:24.196Z,1532964684.196 [BuoyancyServo] Loaded
2018-07-30T15:31:24.196Z,1532964684.196 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-07-30T15:31:24.211Z,1532964684.211 [ElevatorServo] Loaded
2018-07-30T15:31:24.212Z,1532964684.212 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-07-30T15:31:24.226Z,1532964684.226 [MassServo] Loaded
2018-07-30T15:31:24.227Z,1532964684.227 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-07-30T15:31:24.242Z,1532964684.242 [RudderServo] Loaded
2018-07-30T15:31:24.243Z,1532964684.243 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-07-30T15:31:24.257Z,1532964684.257 [ThrusterServo] Loaded
2018-07-30T15:31:24.258Z,1532964684.258 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-07-30T15:31:24.258Z,1532964684.258 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-07-30T15:31:24.259Z,1532964684.259 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-07-30T15:31:24.283Z,1532964684.283 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-07-30T15:31:24.284Z,1532964684.284 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-07-30T15:31:24.411Z,1532964684.411 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-07-30T15:31:24.412Z,1532964684.412 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-07-30T15:31:24.973Z,1532964684.973 [DataOverHttps] Loaded
2018-07-30T15:31:24.974Z,1532964684.974 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-07-30T15:31:24.988Z,1532964684.988 [Depth_Keller] Loaded
2018-07-30T15:31:24.988Z,1532964684.988 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-07-30T15:31:24.993Z,1532964684.993 [DropWeight] Loaded
2018-07-30T15:31:24.993Z,1532964684.993 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-07-30T15:31:25.092Z,1532964685.092 [NAL9602] Loaded
2018-07-30T15:31:25.092Z,1532964685.092 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-07-30T15:31:25.109Z,1532964685.109 [Onboard] Loaded
2018-07-30T15:31:25.109Z,1532964685.109 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-07-30T15:31:25.119Z,1532964685.119 [Radio_Surface] Loaded
2018-07-30T15:31:25.119Z,1532964685.119 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-07-30T15:31:25.120Z,1532964685.120 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408844E0
2018-07-30T15:31:25.121Z,1532964685.121 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 882
2018-07-30T15:31:25.275Z,1532964685.275 [PNI_TCM] Loaded
2018-07-30T15:31:25.275Z,1532964685.275 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-07-30T15:31:25.337Z,1532964685.337 [Rowe_600LCM] Loaded
2018-07-30T15:31:25.337Z,1532964685.337 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-07-30T15:31:25.338Z,1532964685.338 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408B44E0
2018-07-30T15:31:25.339Z,1532964685.339 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 883
2018-07-30T15:31:27.464Z,1532964687.464 [BPC1] Loaded
2018-07-30T15:31:27.465Z,1532964687.465 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-07-30T15:31:27.465Z,1532964687.465 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-07-30T15:31:27.466Z,1532964687.466 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-07-30T15:31:27.624Z,1532964687.624 [SBIT](DEBUG): Construct Startup Built In Test.
2018-07-30T15:31:27.647Z,1532964687.647 [SBIT] Loaded
2018-07-30T15:31:27.647Z,1532964687.647 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-07-30T15:31:27.648Z,1532964687.648 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-07-30T15:31:27.659Z,1532964687.659 [IBIT] Loaded
2018-07-30T15:31:27.660Z,1532964687.660 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-07-30T15:31:27.663Z,1532964687.663 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-07-30T15:31:27.815Z,1532964687.815 [CBIT] Loaded
2018-07-30T15:31:27.815Z,1532964687.815 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-07-30T15:31:27.815Z,1532964687.815 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-07-30T15:31:27.816Z,1532964687.816 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-07-30T15:31:28.006Z,1532964688.006 [Aanderaa_O2] Loaded
2018-07-30T15:31:28.007Z,1532964688.007 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-07-30T15:31:28.086Z,1532964688.086 [CTD_NeilBrown] Loaded
2018-07-30T15:31:28.086Z,1532964688.086 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-07-30T15:31:28.087Z,1532964688.087 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409754E0
2018-07-30T15:31:28.087Z,1532964688.087 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 884
2018-07-30T15:31:28.135Z,1532964688.135 [CTD_Seabird] Loaded
2018-07-30T15:31:28.135Z,1532964688.135 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-07-30T15:31:28.136Z,1532964688.136 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409A54E0
2018-07-30T15:31:28.136Z,1532964688.136 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 885
2018-07-30T15:31:28.151Z,1532964688.151 [PAR_Licor] Loaded
2018-07-30T15:31:28.151Z,1532964688.151 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-07-30T15:31:28.202Z,1532964688.202 [WetLabsBB2FL] Loaded
2018-07-30T15:31:28.202Z,1532964688.202 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-07-30T15:31:28.203Z,1532964688.203 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409D54E0
2018-07-30T15:31:28.204Z,1532964688.204 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 886
2018-07-30T15:31:28.204Z,1532964688.204 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-07-30T15:31:28.205Z,1532964688.205 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-07-30T15:31:28.294Z,1532964688.294 [VerticalControl](DEBUG): Construct VerticalControl.
2018-07-30T15:31:28.380Z,1532964688.380 [VerticalControl] Loaded
2018-07-30T15:31:28.380Z,1532964688.380 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-07-30T15:31:28.381Z,1532964688.381 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-07-30T15:31:28.439Z,1532964688.439 [HorizontalControl] Loaded
2018-07-30T15:31:28.439Z,1532964688.439 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-07-30T15:31:28.440Z,1532964688.440 [SpeedControl](DEBUG): Construct SpeedControl.
2018-07-30T15:31:28.442Z,1532964688.442 [SpeedControl] Loaded
2018-07-30T15:31:28.442Z,1532964688.442 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-07-30T15:31:28.443Z,1532964688.443 [LoopControl](DEBUG): Construct LoopControl.
2018-07-30T15:31:28.443Z,1532964688.443 [LoopControl] Loaded
2018-07-30T15:31:28.444Z,1532964688.444 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-07-30T15:31:28.444Z,1532964688.444 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-07-30T15:31:28.445Z,1532964688.445 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-07-30T15:31:28.482Z,1532964688.482 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-07-30T15:31:28.483Z,1532964688.483 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-07-30T15:31:28.592Z,1532964688.592 [DeadReckonUsingSpeedCalculator] Loaded
2018-07-30T15:31:28.592Z,1532964688.592 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-07-30T15:31:28.609Z,1532964688.609 [NavChart] Loaded
2018-07-30T15:31:28.609Z,1532964688.609 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-07-30T15:31:28.613Z,1532964688.613 [UniversalFixResidualReporter] Loaded
2018-07-30T15:31:28.613Z,1532964688.613 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-07-30T15:31:28.614Z,1532964688.614 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-07-30T15:31:28.617Z,1532964688.617 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-07-30T15:31:28.618Z,1532964688.618 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-07-30T15:31:28.625Z,1532964688.625 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-07-30T15:31:28.626Z,1532964688.626 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A614E0
2018-07-30T15:31:28.627Z,1532964688.627 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 887
2018-07-30T15:31:28.631Z,1532964688.631 [Supervisor](INFO): Main Thread ID is 796
2018-07-30T15:31:28.631Z,1532964688.631 [Supervisor](DEBUG): Running supervisor.
2018-07-30T15:31:28.632Z,1532964688.632 [CommandLine ThreadHandler](INFO): Handler Thread ID is 888
2018-07-30T15:31:28.634Z,1532964688.634 [controlThread ThreadHandler](INFO): Handler Thread ID is 889
2018-07-30T15:31:28.635Z,1532964688.635 [controlThread](DEBUG): Initializing ControlThread
2018-07-30T15:31:28.636Z,1532964688.636 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-07-30T15:31:28.636Z,1532964688.636 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-07-30T15:31:28.636Z,1532964688.636 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-07-30T15:31:28.637Z,1532964688.637 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-07-30T15:31:28.637Z,1532964688.637 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2018-07-30T15:31:28.638Z,1532964688.638 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-07-30T15:31:28.638Z,1532964688.638 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-07-30T15:31:28.645Z,1532964688.645 [SBIT](INFO): Initialize SBIT Component.
2018-07-30T15:31:28.645Z,1532964688.645 [SBIT](IMPORTANT): git: 2018-06-03
2018-07-30T15:31:28.645Z,1532964688.645 [SBIT](INFO): git hash: e89e4219fcae2edd415aee450018ea5d8b44159b
2018-07-30T15:31:28.646Z,1532964688.646 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-07-30T15:31:28.647Z,1532964688.647 [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-07-30T15:31:28.648Z,1532964688.648 [SBIT](INFO): Beginning SBIT in 23.000000 seconds.
2018-07-30T15:31:28.649Z,1532964688.649 [IBIT](INFO): Initialize IBIT Component.
2018-07-30T15:31:28.649Z,1532964688.649 [CBIT](DEBUG): Initialize CBIT Component.
2018-07-30T15:31:28.650Z,1532964688.650 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2018-07-30T15:31:28.650Z,1532964688.650 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2018-07-30T15:31:28.651Z,1532964688.651 [logger ThreadHandler](INFO): Handler Thread ID is 890
2018-07-30T15:31:28.671Z,1532964688.671 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 891
2018-07-30T15:31:28.677Z,1532964688.677 [Radio_Surface](INFO): Powering up
2018-07-30T15:31:28.683Z,1532964688.683 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 892
2018-07-30T15:31:28.683Z,1532964688.683 [Rowe_600LCM](INFO): Initializing
2018-07-30T15:31:28.684Z,1532964688.684 [Rowe_600LCM](INFO): Checking LCM
2018-07-30T15:31:28.769Z,1532964688.769 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 893
2018-07-30T15:31:28.769Z,1532964688.769 [CTD_NeilBrown](INFO): Powering down
2018-07-30T15:31:28.795Z,1532964688.795 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-07-30T15:31:28.797Z,1532964688.797 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-07-30T15:31:28.798Z,1532964688.798 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-07-30T15:31:28.803Z,1532964688.803 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 894
2018-07-30T15:31:28.803Z,1532964688.803 [CTD_Seabird](INFO): Initializing
2018-07-30T15:31:28.804Z,1532964688.804 [CTD_Seabird](INFO): Checking LCM
2018-07-30T15:31:28.807Z,1532964688.807 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-07-30T15:31:28.807Z,1532964688.807 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-07-30T15:31:28.808Z,1532964688.808 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-07-30T15:31:28.808Z,1532964688.808 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-07-30T15:31:28.809Z,1532964688.809 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-07-30T15:31:28.809Z,1532964688.809 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-07-30T15:31:28.814Z,1532964688.814 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-07-30T15:31:28.918Z,1532964688.918 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 895
2018-07-30T15:31:28.919Z,1532964688.919 [WetLabsBB2FL](INFO): Powering down
2018-07-30T15:31:29.032Z,1532964689.032 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 896
2018-07-30T15:31:29.037Z,1532964689.037 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-07-30T15:31:29.049Z,1532964689.049 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-07-30T15:31:29.049Z,1532964689.049 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-07-30T15:31:29.049Z,1532964689.049 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-07-30T15:31:29.049Z,1532964689.049 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-07-30T15:31:29.050Z,1532964689.050 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-07-30T15:31:29.050Z,1532964689.050 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-07-30T15:31:29.050Z,1532964689.050 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-07-30T15:31:29.050Z,1532964689.050 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-07-30T15:31:29.051Z,1532964689.051 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-07-30T15:31:29.051Z,1532964689.051 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-07-30T15:31:29.051Z,1532964689.051 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-07-30T15:31:29.051Z,1532964689.051 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-07-30T15:31:29.051Z,1532964689.051 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-07-30T15:31:29.052Z,1532964689.052 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-07-30T15:31:29.052Z,1532964689.052 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-07-30T15:31:29.052Z,1532964689.052 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-07-30T15:31:29.121Z,1532964689.121 [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-07-30T15:31:29.121Z,1532964689.121 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-07-30T15:31:29.150Z,1532964689.150 [CTD_Seabird](INFO): LCM OK
2018-07-30T15:31:29.150Z,1532964689.150 [CTD_Seabird](INFO): Powering up
2018-07-30T15:31:29.151Z,1532964689.151 [Rowe_600LCM](INFO): LCM OK
2018-07-30T15:31:29.151Z,1532964689.151 [Rowe_600LCM](INFO): Powering up
2018-07-30T15:31:29.229Z,1532964689.229 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-07-30T15:31:29.239Z,1532964689.239 [Default:A.Wait](DEBUG): Construct Wait.
2018-07-30T15:31:29.240Z,1532964689.240 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-07-30T15:31:29.260Z,1532964689.260 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-07-30T15:31:29.291Z,1532964689.291 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-07-30T15:31:29.297Z,1532964689.297 [Default:E.Execute](DEBUG): Construct Execute.
2018-07-30T15:31:29.317Z,1532964689.317 [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-07-30T15:31:29.322Z,1532964689.322 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,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-07-30T15:31:29.346Z,1532964689.346 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-07-30T15:31:29.374Z,1532964689.374 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-07-30T15:31:29.712Z,1532964689.712 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-07-30T15:31:29.811Z,1532964689.811 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:30.015Z,1532964690.015 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:30.023Z,1532964690.023 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-07-30T15:31:30.034Z,1532964690.034 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:30.043Z,1532964690.043 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-07-30T15:31:30.065Z,1532964690.065 [MassServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:30.071Z,1532964690.071 [MassServo](DEBUG): Initializing MassServo.
2018-07-30T15:31:30.077Z,1532964690.077 [RudderServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:30.083Z,1532964690.083 [RudderServo](DEBUG): Initializing RudderServo.
2018-07-30T15:31:30.089Z,1532964690.089 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:30.095Z,1532964690.095 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-07-30T15:31:30.120Z,1532964690.120 [CommandLine](FAULT): Scheduling is paused
2018-07-30T15:31:30.120Z,1532964690.120 [CBIT](INFO): Critical error at 20180730T153128
2018-07-30T15:31:30.121Z,1532964690.121 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-07-30T15:31:30.372Z,1532964690.372 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:30.631Z,1532964690.631 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:30.978Z,1532964690.978 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-07-30T15:31:30.979Z,1532964690.979 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-07-30T15:31:30.979Z,1532964690.979 [BuoyancyServo] Communications Fault, FailCount= 1
2018-07-30T15:31:30.979Z,1532964690.979 [BuoyancyServo](ERROR): Communications Fault
2018-07-30T15:31:31.190Z,1532964691.190 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-07-30T15:31:31.253Z,1532964691.253 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:31.267Z,1532964691.267 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-07-30T15:31:31.268Z,1532964691.268 [BuoyancyServo](INFO): Powering down
2018-07-30T15:31:31.702Z,1532964691.702 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:32.055Z,1532964692.055 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:32.471Z,1532964692.471 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:32.889Z,1532964692.889 [Aanderaa_O2](INFO): Powering down
2018-07-30T15:31:33.079Z,1532964693.079 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-07-30T15:31:33.228Z,1532964693.228 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-07-30T15:31:33.418Z,1532964693.418 [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-07-30T15:31:33.464Z,1532964693.464 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-07-30T15:31:33.464Z,1532964693.464 [BuoyancyServo] No Fault, FailCount= 1
2018-07-30T15:31:33.544Z,1532964693.544 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-07-30T15:31:33.545Z,1532964693.545 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-07-30T15:31:33.545Z,1532964693.545 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-07-30T15:31:33.674Z,1532964693.674 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:33.686Z,1532964693.686 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-07-30T15:31:34.594Z,1532964694.594 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-07-30T15:31:34.595Z,1532964694.595 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-07-30T15:31:34.595Z,1532964694.595 [BuoyancyServo] Communications Fault, FailCount= 2
2018-07-30T15:31:34.595Z,1532964694.595 [BuoyancyServo](ERROR): Communications Fault
2018-07-30T15:31:34.621Z,1532964694.621 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-07-30T15:31:34.710Z,1532964694.710 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-07-30T15:31:34.738Z,1532964694.738 [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-07-30T15:31:34.740Z,1532964694.740 [CTD_Seabird](INFO): LCM subscribed to channel:ctd_t.seabird-gpctd
2018-07-30T15:31:35.216Z,1532964695.216 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-07-30T15:31:35.221Z,1532964695.221 [BuoyancyServo](INFO): Powering down
2018-07-30T15:31:35.635Z,1532964695.635 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-07-30T15:31:35.635Z,1532964695.635 [CTD_Seabird](INFO): Powering down
2018-07-30T15:31:37.504Z,1532964697.504 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-07-30T15:31:37.504Z,1532964697.504 [BuoyancyServo] No Fault, FailCount= 2
2018-07-30T15:31:37.856Z,1532964697.856 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-07-30T15:31:37.857Z,1532964697.857 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-07-30T15:31:52.252Z,1532964712.252 [SBIT](IMPORTANT): Beginning Startup BIT
2018-07-30T15:31:52.278Z,1532964712.278 [CBIT](IMPORTANT): Beginning ground fault scan
2018-07-30T15:31:55.180Z,1532964715.180 [NAL9602](INFO): Powering up NAL9602
2018-07-30T15:32:03.683Z,1532964723.683 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005362
CHAN A1 (24V): -0.009544
CHAN A2 (12V): -0.002426
CHAN A3 (5V): -0.001980
CHAN B0 (3.3V): 0.000302
CHAN B1 (3.15aV): -0.000425
CHAN B2 (3.15bV): -0.000413
CHAN B3 (GND): -0.000042
OPEN: -0.000186
Full Scale Calc: 4.765 mA, -1.589 mA
2018-07-30T15:32:06.380Z,1532964726.380 [NAL9602](INFO): NAL9602 initialized
2018-07-30T15:32:44.230Z,1532964764.230 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:32:44.230Z,1532964764.230 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:32:45.151Z,1532964765.151 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:32:45.947Z,1532964765.947 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:32:46.318Z,1532964766.318 [SBIT](IMPORTANT): SBIT PASSED
2018-07-30T15:32:46.379Z,1532964766.379 [CommandLine](IMPORTANT): got command configSet list
2018-07-30T15:32:46.379Z,1532964766.379 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-07-30T15:32:46.387Z,1532964766.387 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;

2018-07-30T15:32:46.387Z,1532964766.387 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=0 bool;

2018-07-30T15:32:46.387Z,1532964766.387 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=5 minute;

2018-07-30T15:32:46.387Z,1532964766.387 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=0 bool;

2018-07-30T15:32:46.388Z,1532964766.388 [CommandLine](IMPORTANT): Express none Rowe_600LCM.height_above_sea_floor;

2018-07-30T15:32:46.388Z,1532964766.388 [CommandLine](IMPORTANT): IBIT.batteryMissingStickThreshold=5 count;

2018-07-30T15:32:46.388Z,1532964766.388 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=1 bool;

2018-07-30T15:32:46.388Z,1532964766.388 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=132 cubic_centimeter;

2018-07-30T15:32:46.388Z,1532964766.388 [CommandLine](IMPORTANT): VerticalControl.massDefault=5.3 millimeter;

2018-07-30T15:32:46.677Z,1532964766.677 [MissionManager](IMPORTANT): Started mission Startup
2018-07-30T15:32:46.677Z,1532964766.677 [Startup] Running Loop=1
2018-07-30T15:32:46.677Z,1532964766.677 [Startup](DEBUG): Aggregate::initialize Startup
2018-07-30T15:32:46.677Z,1532964766.677 [Startup:A.GoToSurface] Running Loop=1
2018-07-30T15:32:46.677Z,1532964766.677 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-07-30T15:32:46.682Z,1532964766.682 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-07-30T15:32:46.683Z,1532964766.683 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-07-30T15:32:46.683Z,1532964766.683 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-07-30T15:32:46.684Z,1532964766.684 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-07-30T15:32:46.684Z,1532964766.684 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-07-30T15:32:46.718Z,1532964766.718 [Startup:StartupSatComms] Running Loop=1
2018-07-30T15:32:46.719Z,1532964766.719 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-07-30T15:32:46.719Z,1532964766.719 [Startup:StartupSatComms:A] Running Loop=1
2018-07-30T15:32:47.104Z,1532964767.104 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-07-30T15:32:59.159Z,1532964779.159 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:32:59.955Z,1532964779.955 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:33:01.856Z,1532964781.856 [BPC1](ERROR): Failed to parse Bank B battery data
2018-07-30T15:33:05.829Z,1532964785.829 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:33:05.830Z,1532964785.830 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:33:29.874Z,1532964809.874 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-07-30T15:33:29.874Z,1532964809.874 [Rowe_600LCM] Communications Fault, FailCount= 1
2018-07-30T15:33:29.874Z,1532964809.874 [Rowe_600LCM](ERROR): Communications Fault
2018-07-30T15:33:29.920Z,1532964809.920 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-07-30T15:33:30.282Z,1532964810.282 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-07-30T15:33:30.440Z,1532964810.440 [Rowe_600LCM](INFO): Powering down
2018-07-30T15:33:31.904Z,1532964811.904 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-07-30T15:33:31.904Z,1532964811.904 [Rowe_600LCM] No Fault, FailCount= 1
2018-07-30T15:33:32.054Z,1532964812.054 [Rowe_600LCM](INFO): Initializing
2018-07-30T15:33:32.055Z,1532964812.055 [Rowe_600LCM](INFO): Checking LCM
2018-07-30T15:33:32.055Z,1532964812.055 [Rowe_600LCM](INFO): LCM OK
2018-07-30T15:33:32.055Z,1532964812.055 [Rowe_600LCM](INFO): Powering up
2018-07-30T15:33:36.178Z,1532964816.178 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-07-30T15:33:36.293Z,1532964816.293 [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-07-30T15:33:36.294Z,1532964816.294 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-07-30T15:33:36.295Z,1532964816.295 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-07-30T15:33:36.295Z,1532964816.295 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-07-30T15:33:47.092Z,1532964827.092 [Startup:StartupSatComms:A](INFO): Timed out from 2018-07-30T15:32:46.7Z
2018-07-30T15:33:47.092Z,1532964827.092 [Startup:StartupSatComms:A] Stopped
2018-07-30T15:33:47.093Z,1532964827.093 [Startup:StartupSatComms:B] Running Loop=1
2018-07-30T15:33:47.513Z,1532964827.513 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-07-30T15:34:00.064Z,1532964840.064 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003794
2018-07-30T15:34:04.432Z,1532964844.432 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20180730T152644/Courier0004.lzma
2018-07-30T15:34:05.185Z,1532964845.185 [DataOverHttps](INFO): Moved sent file to Logs/20180730T152644/Courier0004.lzma.bak
2018-07-30T15:34:05.185Z,1532964845.185 [DataOverHttps](INFO): SBD MOMSN=8385267
2018-07-30T15:34:14.457Z,1532964854.457 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20180730T153117/Courier0000.lzma
2018-07-30T15:34:15.241Z,1532964855.241 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Courier0000.lzma.bak
2018-07-30T15:34:15.241Z,1532964855.241 [DataOverHttps](INFO): SBD MOMSN=8385269
2018-07-30T15:34:24.568Z,1532964864.568 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20180730T152644/Express0005.lzma
2018-07-30T15:34:25.342Z,1532964865.342 [DataOverHttps](INFO): Moved sent file to Logs/20180730T152644/Express0005.lzma.bak
2018-07-30T15:34:25.342Z,1532964865.342 [DataOverHttps](INFO): SBD MOMSN=8385273
2018-07-30T15:34:29.652Z,1532964869.652 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-07-30T15:34:29.653Z,1532964869.653 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-07-30T15:34:29.653Z,1532964869.653 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-07-30T15:34:29.666Z,1532964869.666 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-07-30T15:34:29.829Z,1532964869.829 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-07-30T15:34:29.829Z,1532964869.829 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-07-30T15:34:30.141Z,1532964870.141 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-07-30T15:34:30.141Z,1532964870.141 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-07-30T15:34:30.141Z,1532964870.141 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-07-30T15:34:34.708Z,1532964874.708 [DataOverHttps](INFO): Sending 954 bytes from file Logs/20180730T153117/Express0001.lzma
2018-07-30T15:34:35.505Z,1532964875.505 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Express0001.lzma.bak
2018-07-30T15:34:35.505Z,1532964875.505 [DataOverHttps](INFO): SBD MOMSN=8385275
2018-07-30T15:34:36.016Z,1532964876.016 [Startup:StartupSatComms:B] Stopped
2018-07-30T15:34:36.017Z,1532964876.017 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-07-30T15:34:36.017Z,1532964876.017 [Startup:StartupSatComms] Stopped
2018-07-30T15:34:36.017Z,1532964876.017 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-07-30T15:34:36.020Z,1532964876.020 [Startup](INFO): Completed Startup
2018-07-30T15:34:36.020Z,1532964876.020 [MissionManager](INFO): Startup is completed.
2018-07-30T15:34:36.021Z,1532964876.021 [MissionManager](INFO): Uninitializing Mission Startup
2018-07-30T15:34:36.021Z,1532964876.021 [Startup] Stopped
2018-07-30T15:34:36.021Z,1532964876.021 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-07-30T15:34:36.022Z,1532964876.022 [Startup:A.GoToSurface] Stopped
2018-07-30T15:34:36.022Z,1532964876.022 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-07-30T15:34:36.369Z,1532964876.369 [MissionManager](IMPORTANT): Started mission Default
2018-07-30T15:34:36.369Z,1532964876.369 [Default] Running Loop=1
2018-07-30T15:34:36.369Z,1532964876.369 [Default](DEBUG): Aggregate::initialize Default
2018-07-30T15:34:36.369Z,1532964876.369 [Default:B.GoToSurface] Running Loop=1
2018-07-30T15:34:36.369Z,1532964876.369 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-07-30T15:34:36.369Z,1532964876.369 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-07-30T15:34:36.370Z,1532964876.370 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-07-30T15:34:36.374Z,1532964876.374 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-07-30T15:34:36.375Z,1532964876.375 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-07-30T15:34:36.375Z,1532964876.375 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-07-30T15:34:36.375Z,1532964876.375 [Default:A.Wait] Running Loop=1
2018-07-30T15:34:36.375Z,1532964876.375 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-07-30T15:34:48.151Z,1532964888.151 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:34:48.947Z,1532964888.947 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:34:49.496Z,1532964889.496 [Default:A.Wait](INFO): Done Waiting.
2018-07-30T15:34:49.496Z,1532964889.496 [Default:A.Wait] Stopped
2018-07-30T15:34:49.497Z,1532964889.497 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-07-30T15:34:50.008Z,1532964890.008 [Default:CheckIn] Running Loop=1
2018-07-30T15:34:50.008Z,1532964890.008 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-07-30T15:34:50.008Z,1532964890.008 [Default:CheckIn:Read_GPS] Running Loop=1
2018-07-30T15:34:50.283Z,1532964890.283 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-07-30T15:36:40.155Z,1532965000.155 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:36:40.951Z,1532965000.951 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:37:07.764Z,1532965027.764 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-07-30T15:37:07.765Z,1532965027.765 [Rowe_600LCM] Communications Fault, FailCount= 2
2018-07-30T15:37:07.765Z,1532965027.765 [Rowe_600LCM](ERROR): Communications Fault
2018-07-30T15:37:07.843Z,1532965027.843 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-07-30T15:37:08.167Z,1532965028.167 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-07-30T15:37:08.315Z,1532965028.315 [Rowe_600LCM](INFO): Powering down
2018-07-30T15:37:09.308Z,1532965029.308 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-07-30T15:37:09.775Z,1532965029.775 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-07-30T15:37:09.775Z,1532965029.775 [Rowe_600LCM] No Fault, FailCount= 2
2018-07-30T15:37:09.932Z,1532965029.932 [Rowe_600LCM](INFO): Initializing
2018-07-30T15:37:09.933Z,1532965029.933 [Rowe_600LCM](INFO): Checking LCM
2018-07-30T15:37:09.933Z,1532965029.933 [Rowe_600LCM](INFO): LCM OK
2018-07-30T15:37:09.933Z,1532965029.933 [Rowe_600LCM](INFO): Powering up
2018-07-30T15:37:14.056Z,1532965034.056 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-07-30T15:37:14.171Z,1532965034.171 [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-07-30T15:37:14.172Z,1532965034.172 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-07-30T15:37:14.173Z,1532965034.173 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-07-30T15:37:14.173Z,1532965034.173 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-07-30T15:37:30.179Z,1532965050.179 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-07-30T15:37:30.179Z,1532965050.179 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2018-07-30T15:37:30.179Z,1532965050.179 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-07-30T15:37:30.193Z,1532965050.193 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-07-30T15:37:30.610Z,1532965050.610 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-07-30T15:37:30.610Z,1532965050.610 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2018-07-30T15:37:30.982Z,1532965050.982 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-07-30T15:37:30.986Z,1532965050.986 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-07-30T15:37:30.987Z,1532965050.987 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-07-30T15:38:26.151Z,1532965106.151 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:38:26.947Z,1532965106.947 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:38:42.551Z,1532965122.551 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.386030 seconds old.
2018-07-30T15:38:42.955Z,1532965122.955 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.790644 seconds old.
2018-07-30T15:38:43.339Z,1532965123.339 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.174265 seconds old.
2018-07-30T15:38:50.885Z,1532965130.885 [NAL9602](INFO): GPS fix at 20180730T153850: (36.802744, -121.787927)
2018-07-30T15:38:50.954Z,1532965130.954 [Default:CheckIn:Read_GPS] Stopped
2018-07-30T15:38:50.954Z,1532965130.954 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-07-30T15:38:51.412Z,1532965131.412 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-07-30T15:38:57.781Z,1532965137.781 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20180730T153117/Courier0004.lzma
2018-07-30T15:38:58.581Z,1532965138.581 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Courier0004.lzma.bak
2018-07-30T15:38:58.581Z,1532965138.581 [DataOverHttps](INFO): SBD MOMSN=8385307
2018-07-30T15:39:09.015Z,1532965149.015 [DataOverHttps](INFO): Sending 359 bytes from file Logs/20180730T153117/Express0005.lzma
2018-07-30T15:39:09.777Z,1532965149.777 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Express0005.lzma.bak
2018-07-30T15:39:09.777Z,1532965149.777 [DataOverHttps](INFO): SBD MOMSN=8385310
2018-07-30T15:39:10.257Z,1532965150.257 [Default:CheckIn:Read_Iridium] Stopped
2018-07-30T15:39:10.257Z,1532965150.257 [Default:CheckIn:C.Wait] Running Loop=1
2018-07-30T15:39:10.257Z,1532965150.257 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-07-30T15:39:28.128Z,1532965168.128 [NAL9602](INFO): Powering down
2018-07-30T15:39:28.278Z,1532965168.278 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-07-30T15:39:28.278Z,1532965168.278 [Rowe_600LCM] Communications Fault, FailCount= 3
2018-07-30T15:39:28.278Z,1532965168.278 [Rowe_600LCM](ERROR): Communications Fault
2018-07-30T15:39:28.641Z,1532965168.641 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-07-30T15:39:28.682Z,1532965168.682 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-07-30T15:39:28.776Z,1532965168.776 [Rowe_600LCM](INFO): Powering down
2018-07-30T15:39:30.275Z,1532965170.275 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-07-30T15:39:30.275Z,1532965170.275 [Rowe_600LCM] No Fault, FailCount= 3
2018-07-30T15:39:30.390Z,1532965170.390 [Rowe_600LCM](INFO): Initializing
2018-07-30T15:39:30.391Z,1532965170.391 [Rowe_600LCM](INFO): Checking LCM
2018-07-30T15:39:30.391Z,1532965170.391 [Rowe_600LCM](INFO): LCM OK
2018-07-30T15:39:30.391Z,1532965170.391 [Rowe_600LCM](INFO): Powering up
2018-07-30T15:39:34.513Z,1532965174.513 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-07-30T15:39:34.705Z,1532965174.705 [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-07-30T15:39:34.706Z,1532965174.706 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-07-30T15:39:34.707Z,1532965174.707 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-07-30T15:39:34.707Z,1532965174.707 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-07-30T15:40:18.147Z,1532965218.147 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:40:18.943Z,1532965218.943 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:41:30.850Z,1532965290.850 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-07-30T15:41:30.850Z,1532965290.850 [Rowe_600LCM] Communications Fault, FailCount= 4
2018-07-30T15:41:30.850Z,1532965290.850 [Rowe_600LCM](ERROR): Communications Fault
2018-07-30T15:41:30.944Z,1532965290.944 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-07-30T15:41:31.262Z,1532965291.262 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-07-30T15:41:31.425Z,1532965291.425 [Rowe_600LCM](INFO): Powering down
2018-07-30T15:41:32.888Z,1532965292.888 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-07-30T15:41:32.888Z,1532965292.888 [Rowe_600LCM] No Fault, FailCount= 4
2018-07-30T15:41:33.038Z,1532965293.038 [Rowe_600LCM](INFO): Initializing
2018-07-30T15:41:33.039Z,1532965293.039 [Rowe_600LCM](INFO): Checking LCM
2018-07-30T15:41:33.039Z,1532965293.039 [Rowe_600LCM](INFO): LCM OK
2018-07-30T15:41:33.039Z,1532965293.039 [Rowe_600LCM](INFO): Powering up
2018-07-30T15:41:37.164Z,1532965297.164 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-07-30T15:41:37.309Z,1532965297.309 [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-07-30T15:41:37.310Z,1532965297.310 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-07-30T15:41:37.311Z,1532965297.311 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-07-30T15:41:37.311Z,1532965297.311 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-07-30T15:42:07.147Z,1532965327.147 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:42:07.943Z,1532965327.943 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:43:59.139Z,1532965439.139 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:43:59.935Z,1532965439.935 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:44:10.928Z,1532965450.928 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-07-30T15:44:10.928Z,1532965450.928 [Default:CheckIn:C.Wait] Stopped
2018-07-30T15:44:10.929Z,1532965450.929 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-07-30T15:44:10.929Z,1532965450.929 [Default:CheckIn:D] Running Loop=1
2018-07-30T15:44:11.332Z,1532965451.332 [Default:CheckIn:D] Stopped
2018-07-30T15:44:11.332Z,1532965451.332 [Default:CheckIn:E] Running Loop=1
2018-07-30T15:44:11.726Z,1532965451.726 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.582682 min 
2018-07-30T15:44:11.728Z,1532965451.728 [Default:CheckIn:E] Stopped
2018-07-30T15:44:11.728Z,1532965451.728 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-07-30T15:44:11.728Z,1532965451.728 [Default:CheckIn] Stopped
2018-07-30T15:44:11.728Z,1532965451.728 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-07-30T15:44:11.728Z,1532965451.728 [Default:CheckIn](INFO): Running loop #2
2018-07-30T15:44:11.729Z,1532965451.729 [Default:CheckIn] Running Loop=2
2018-07-30T15:44:11.729Z,1532965451.729 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-07-30T15:44:11.729Z,1532965451.729 [Default:CheckIn:Read_GPS] Running Loop=1
2018-07-30T15:44:15.580Z,1532965455.580 [NAL9602](INFO): Powering up
2018-07-30T15:44:26.456Z,1532965466.456 [NAL9602](INFO): NAL9602 initialized
2018-07-30T15:44:58.460Z,1532965498.460 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2018-07-30T15:44:58.538Z,1532965498.538 [NAL9602](FAULT): received: 
+CSQ:0

OK99, 2, 0, 0, 0

OK
2018-07-30T15:44:58.539Z,1532965498.539 [NAL9602] Data Fault, FailCount= 1
2018-07-30T15:44:58.539Z,1532965498.539 [NAL9602](ERROR): Data Fault
2018-07-30T15:44:58.657Z,1532965498.657 [CBIT](ERROR): Data Fault in component: NAL9602
2018-07-30T15:44:58.860Z,1532965498.860 [NAL9602](INFO): Powering down
2018-07-30T15:44:59.742Z,1532965499.742 [CBIT](INFO): Clearing failed state for component NAL9602
2018-07-30T15:44:59.742Z,1532965499.742 [NAL9602] No Fault, FailCount= 1
2018-07-30T15:45:23.151Z,1532965523.151 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:23.947Z,1532965523.947 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:24.743Z,1532965524.743 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:25.455Z,1532965525.455 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:26.251Z,1532965526.251 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:27.049Z,1532965527.049 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:27.455Z,1532965527.455 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:45:29.260Z,1532965529.260 [NAL9602](INFO): Powering up NAL9602
2018-07-30T15:45:40.460Z,1532965540.460 [NAL9602](INFO): NAL9602 initialized
2018-07-30T15:46:05.143Z,1532965565.143 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:46:05.941Z,1532965565.941 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:47:36.693Z,1532965656.693 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:47:36.694Z,1532965656.694 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:47:57.151Z,1532965677.151 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:47:57.947Z,1532965677.947 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:48:02.677Z,1532965682.677 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:48:02.677Z,1532965682.677 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:48:29.933Z,1532965709.933 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:48:29.933Z,1532965709.933 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:49:11.977Z,1532965751.977 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-07-30T15:44:11.7Z
2018-07-30T15:49:11.977Z,1532965751.977 [Default:CheckIn:Read_GPS] Stopped
2018-07-30T15:49:11.977Z,1532965751.977 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-07-30T15:49:16.657Z,1532965756.657 [NAL9602](INFO): SBD MO Status=2, MOMSN=7599, MT Status=2, MTMSN=0
2018-07-30T15:49:16.658Z,1532965756.658 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-07-30T15:49:16.773Z,1532965756.773 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180730T153117/Courier0007.lzma
2018-07-30T15:49:17.565Z,1532965757.565 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Courier0007.lzma.bak
2018-07-30T15:49:17.565Z,1532965757.565 [DataOverHttps](INFO): SBD MOMSN=8385325
2018-07-30T15:49:27.129Z,1532965767.129 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20180730T153117/Express0008.lzma
2018-07-30T15:49:27.913Z,1532965767.913 [DataOverHttps](INFO): Moved sent file to Logs/20180730T153117/Express0008.lzma.bak
2018-07-30T15:49:27.913Z,1532965767.913 [DataOverHttps](INFO): SBD MOMSN=8385327
2018-07-30T15:49:28.421Z,1532965768.421 [Default:CheckIn:Read_Iridium] Stopped
2018-07-30T15:49:28.421Z,1532965768.421 [Default:CheckIn:C.Wait] Running Loop=1
2018-07-30T15:49:28.421Z,1532965768.421 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-07-30T15:49:32.061Z,1532965772.061 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-07-30T15:49:49.139Z,1532965789.139 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:49:49.935Z,1532965789.935 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-07-30T15:50:02.571Z,1532965802.571 [NAL9602](INFO): Powering down
2018-07-30T15:50:42.605Z,1532965842.605 [CommandLine](IMPORTANT): got command restart system
2018-07-30T15:50:44.926Z,1532965844.926 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:44.926Z,1532965844.926 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.014Z,1532965845.014 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-07-30T15:50:45.014Z,1532965845.014 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.015Z,1532965845.015 [CommandLine](INFO): Join timeout helper Thread ID is 1026
2018-07-30T15:50:45.016Z,1532965845.016 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-07-30T15:50:45.016Z,1532965845.016 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.016Z,1532965845.016 [NavChartDb](INFO): Join timeout helper Thread ID is 1027
2018-07-30T15:50:45.046Z,1532965845.046 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:45.047Z,1532965845.047 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.054Z,1532965845.054 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-07-30T15:50:45.054Z,1532965845.054 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.055Z,1532965845.055 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1028
2018-07-30T15:50:45.215Z,1532965845.215 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:45.215Z,1532965845.215 [WetLabsBB2FL](INFO): Powering down
2018-07-30T15:50:45.216Z,1532965845.216 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.226Z,1532965845.226 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-07-30T15:50:45.226Z,1532965845.226 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.227Z,1532965845.227 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1029
2018-07-30T15:50:45.287Z,1532965845.287 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:45.437Z,1532965845.437 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-07-30T15:50:45.437Z,1532965845.437 [CTD_Seabird](INFO): Powering down
2018-07-30T15:50:45.438Z,1532965845.438 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.450Z,1532965845.450 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-07-30T15:50:45.450Z,1532965845.450 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.451Z,1532965845.451 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1031
2018-07-30T15:50:45.528Z,1532965845.528 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:45.529Z,1532965845.529 [CTD_NeilBrown](INFO): Powering down
2018-07-30T15:50:45.530Z,1532965845.530 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.531Z,1532965845.531 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-07-30T15:50:45.532Z,1532965845.532 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:45.532Z,1532965845.532 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 1032
2018-07-30T15:50:45.939Z,1532965845.939 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:45.939Z,1532965845.939 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-07-30T15:50:46.136Z,1532965846.136 [Rowe_600LCM](INFO): Powering down
2018-07-30T15:50:46.137Z,1532965846.137 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.139Z,1532965846.139 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-07-30T15:50:46.139Z,1532965846.139 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.140Z,1532965846.140 [Radio_Surface](INFO): Join timeout helper Thread ID is 1034
2018-07-30T15:50:46.395Z,1532965846.395 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:46.395Z,1532965846.395 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.410Z,1532965846.410 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-07-30T15:50:46.410Z,1532965846.410 [logger ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.422Z,1532965846.422 [logger](INFO): Join timeout helper Thread ID is 1035
2018-07-30T15:50:46.455Z,1532965846.455 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:46.455Z,1532965846.455 [logger ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.471Z,1532965846.471 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-07-30T15:50:46.471Z,1532965846.471 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.471Z,1532965846.471 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-07-30T15:50:46.471Z,1532965846.471 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:46.472Z,1532965846.472 [controlThread](INFO): Join timeout helper Thread ID is 1036
2018-07-30T15:50:46.790Z,1532965846.790 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-07-30T15:50:46.791Z,1532965846.791 [controlThread](DEBUG): Uninitializing ControlThread
2018-07-30T15:50:46.792Z,1532965846.792 [NAL9602](INFO): Powering down
2018-07-30T15:50:46.793Z,1532965846.793 [PNI_TCM](INFO): Powering down
2018-07-30T15:50:46.879Z,1532965846.879 [Aanderaa_O2](INFO): Powering down
2018-07-30T15:50:46.881Z,1532965846.881 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-07-30T15:50:46.882Z,1532965846.882 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-07-30T15:50:46.883Z,1532965846.883 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-07-30T15:50:46.884Z,1532965846.884 [MissionManager](INFO): Uninitializing Mission Default
2018-07-30T15:50:46.884Z,1532965846.884 [Default] Stopped
2018-07-30T15:50:46.884Z,1532965846.884 [Default](DEBUG): Aggregate::uninitialize Default
2018-07-30T15:50:46.884Z,1532965846.884 [Default:B.GoToSurface] Stopped
2018-07-30T15:50:46.884Z,1532965846.884 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-07-30T15:50:46.884Z,1532965846.884 [Default:CheckIn] Stopped
2018-07-30T15:50:46.884Z,1532965846.884 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-07-30T15:50:46.885Z,1532965846.885 [Default:CheckIn:C.Wait] Stopped
2018-07-30T15:50:46.885Z,1532965846.885 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-07-30T15:50:46.888Z,1532965846.888 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-07-30T15:50:46.889Z,1532965846.889 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-07-30T15:50:46.889Z,1532965846.889 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-07-30T15:50:46.889Z,1532965846.889 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-07-30T15:50:46.890Z,1532965846.890 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-07-30T15:50:46.890Z,1532965846.890 [BuoyancyServo](INFO): Powering down
2018-07-30T15:50:46.902Z,1532965846.902 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-07-30T15:50:46.902Z,1532965846.902 [ElevatorServo](INFO): Powering down
2018-07-30T15:50:46.904Z,1532965846.904 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-07-30T15:50:46.904Z,1532965846.904 [MassServo](INFO): Powering down
2018-07-30T15:50:46.905Z,1532965846.905 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-07-30T15:50:46.905Z,1532965846.905 [RudderServo](INFO): Powering down
2018-07-30T15:50:46.906Z,1532965846.906 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-07-30T15:50:46.906Z,1532965846.906 [ThrusterServo](INFO): Powering down
2018-07-30T15:50:46.907Z,1532965846.907 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-07-30T15:50:46.907Z,1532965846.907 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-07-30T15:50:46.908Z,1532965846.908 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-07-30T15:50:46.909Z,1532965846.909 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.014Z,1532965847.014 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.021Z,1532965847.021 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.058Z,1532965847.058 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.061Z,1532965847.061 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.064Z,1532965847.064 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.091Z,1532965847.091 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-07-30T15:50:47.162Z,1532965847.162 [logger ThreadHandler](INFO): Thread cancelled.