2018-06-03T21:02:51.665Z,1528059771.665 [Supervisor](DEBUG): Initializing supervisor.
2018-06-03T21:02:51.668Z,1528059771.668 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-06-03T21:02:51.668Z,1528059771.668 [SyncHandler](INFO): Protected caller Thread ID is 1431
2018-06-03T21:02:51.669Z,1528059771.669 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-06-03T21:02:51.670Z,1528059771.670 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-06-03T21:02:51.670Z,1528059771.670 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1432
2018-06-03T21:02:51.673Z,1528059771.673 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-06-03T21:02:51.684Z,1528059771.684 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-06-03T21:02:51.685Z,1528059771.685 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-06-03T21:02:51.686Z,1528059771.686 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1433
2018-06-03T21:02:51.686Z,1528059771.686 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-06-03T21:02:51.687Z,1528059771.687 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-06-03T21:02:51.688Z,1528059771.688 [logger ThreadHandler](INFO): Protected caller Thread ID is 1434
2018-06-03T21:02:51.690Z,1528059771.690 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-06-03T21:02:51.690Z,1528059771.690 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-06-03T21:02:51.691Z,1528059771.691 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-06-03T21:02:52.035Z,1528059772.035 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-06-03T21:02:52.036Z,1528059772.036 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-06-03T21:02:52.247Z,1528059772.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-06-03T21:02:52.247Z,1528059772.247 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-06-03T21:02:52.545Z,1528059772.545 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-06-03T21:02:52.546Z,1528059772.546 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-06-03T21:02:52.688Z,1528059772.688 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-06-03T21:02:52.688Z,1528059772.688 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-06-03T21:02:52.788Z,1528059772.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-06-03T21:02:52.788Z,1528059772.788 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-06-03T21:02:53.269Z,1528059773.269 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-06-03T21:02:53.270Z,1528059773.270 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-06-03T21:02:53.670Z,1528059773.670 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-06-03T21:02:53.670Z,1528059773.670 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-06-03T21:02:54.130Z,1528059774.130 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-06-03T21:02:54.130Z,1528059774.130 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-06-03T21:02:54.236Z,1528059774.236 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-06-03T21:02:54.237Z,1528059774.237 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-06-03T21:02:54.335Z,1528059774.335 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-06-03T21:02:54.335Z,1528059774.335 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-06-03T21:02:54.546Z,1528059774.546 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-06-03T21:02:54.547Z,1528059774.547 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-06-03T21:02:54.760Z,1528059774.760 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-06-03T21:02:54.761Z,1528059774.761 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-06-03T21:02:55.120Z,1528059775.120 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-06-03T21:02:55.120Z,1528059775.120 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-06-03T21:02:55.263Z,1528059775.263 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-06-03T21:02:55.264Z,1528059775.264 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-06-03T21:02:55.347Z,1528059775.347 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-06-03T21:02:55.348Z,1528059775.348 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-06-03T21:02:55.452Z,1528059775.452 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-06-03T21:02:55.573Z,1528059775.573 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-06-03T21:02:55.668Z,1528059775.668 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-06-03T21:02:55.795Z,1528059775.795 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-06-03T21:02:56.242Z,1528059776.242 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-06-03T21:02:56.563Z,1528059776.563 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-06-03T21:02:56.694Z,1528059776.694 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-06-03T21:02:56.987Z,1528059776.987 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-06-03T21:02:56.987Z,1528059776.987 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-06-03T21:02:57.071Z,1528059777.071 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-06-03T21:02:57.161Z,1528059777.161 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-06-03T21:02:57.263Z,1528059777.263 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-06-03T21:02:57.390Z,1528059777.390 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-06-03T21:02:57.393Z,1528059777.393 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-06-03T21:02:57.630Z,1528059777.630 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-06-03T21:02:57.631Z,1528059777.631 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-06-03T21:02:57.672Z,1528059777.672 [DepthRateCalculator] Loaded
2018-06-03T21:02:57.672Z,1528059777.672 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-06-03T21:02:57.678Z,1528059777.678 [PitchRateCalculator] Loaded
2018-06-03T21:02:57.678Z,1528059777.678 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-06-03T21:02:57.694Z,1528059777.694 [SpeedCalculator] Loaded
2018-06-03T21:02:57.695Z,1528059777.695 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-06-03T21:02:57.716Z,1528059777.716 [TempGradientCalculator] Loaded
2018-06-03T21:02:57.716Z,1528059777.716 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-06-03T21:02:57.732Z,1528059777.732 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2018-06-03T21:02:57.732Z,1528059777.732 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2018-06-03T21:02:57.738Z,1528059777.738 [YawRateCalculator] Loaded
2018-06-03T21:02:57.738Z,1528059777.738 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-06-03T21:02:57.778Z,1528059777.778 [ElevatorOffsetCalculator] Loaded
2018-06-03T21:02:57.778Z,1528059777.778 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-06-03T21:02:57.779Z,1528059777.779 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-06-03T21:02:57.779Z,1528059777.779 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-06-03T21:02:57.860Z,1528059777.860 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC
2018-06-03T21:02:57.860Z,1528059777.860 [StratificationFrontDetector](DEBUG): (re)initializing
2018-06-03T21:02:57.861Z,1528059777.861 [StratificationFrontDetector] Loaded
2018-06-03T21:02:57.861Z,1528059777.861 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2018-06-03T21:02:57.861Z,1528059777.861 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-06-03T21:02:57.862Z,1528059777.862 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-06-03T21:02:57.974Z,1528059777.974 [BuoyancyServo] Loaded
2018-06-03T21:02:57.974Z,1528059777.974 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-06-03T21:02:57.989Z,1528059777.989 [ElevatorServo] Loaded
2018-06-03T21:02:57.990Z,1528059777.990 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-06-03T21:02:58.004Z,1528059778.004 [MassServo] Loaded
2018-06-03T21:02:58.005Z,1528059778.005 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-06-03T21:02:58.020Z,1528059778.020 [RudderServo] Loaded
2018-06-03T21:02:58.020Z,1528059778.020 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-06-03T21:02:58.035Z,1528059778.035 [ThrusterServo] Loaded
2018-06-03T21:02:58.035Z,1528059778.035 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-06-03T21:02:58.035Z,1528059778.035 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-06-03T21:02:58.036Z,1528059778.036 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-06-03T21:02:58.049Z,1528059778.049 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-06-03T21:02:58.049Z,1528059778.049 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-06-03T21:02:58.146Z,1528059778.146 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-06-03T21:02:58.147Z,1528059778.147 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-06-03T21:02:58.426Z,1528059778.426 [DataOverHttps] Loaded
2018-06-03T21:02:58.426Z,1528059778.426 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-06-03T21:02:58.440Z,1528059778.440 [Depth_Keller] Loaded
2018-06-03T21:02:58.440Z,1528059778.440 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-06-03T21:02:58.445Z,1528059778.445 [DropWeight] Loaded
2018-06-03T21:02:58.445Z,1528059778.445 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-06-03T21:02:58.544Z,1528059778.544 [NAL9602] Loaded
2018-06-03T21:02:58.544Z,1528059778.544 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-06-03T21:02:58.560Z,1528059778.560 [Onboard] Loaded
2018-06-03T21:02:58.560Z,1528059778.560 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-06-03T21:02:58.571Z,1528059778.571 [Radio_Surface] Loaded
2018-06-03T21:02:58.571Z,1528059778.571 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-06-03T21:02:58.572Z,1528059778.572 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408844E0
2018-06-03T21:02:58.572Z,1528059778.572 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1516
2018-06-03T21:02:58.701Z,1528059778.701 [DAT] Loaded
2018-06-03T21:02:58.701Z,1528059778.701 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2018-06-03T21:02:58.749Z,1528059778.749 [PNI_TCM] Loaded
2018-06-03T21:02:58.750Z,1528059778.750 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-06-03T21:02:58.810Z,1528059778.810 [Rowe_600LCM] Loaded
2018-06-03T21:02:58.811Z,1528059778.811 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-06-03T21:02:58.812Z,1528059778.812 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408B44E0
2018-06-03T21:02:58.812Z,1528059778.812 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 1517
2018-06-03T21:03:00.600Z,1528059780.600 [BPC1] Loaded
2018-06-03T21:03:00.600Z,1528059780.600 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-06-03T21:03:00.600Z,1528059780.600 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-06-03T21:03:00.601Z,1528059780.601 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-06-03T21:03:00.729Z,1528059780.729 [SBIT](DEBUG): Construct Startup Built In Test.
2018-06-03T21:03:00.752Z,1528059780.752 [SBIT] Loaded
2018-06-03T21:03:00.752Z,1528059780.752 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-06-03T21:03:00.753Z,1528059780.753 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-06-03T21:03:00.764Z,1528059780.764 [IBIT] Loaded
2018-06-03T21:03:00.765Z,1528059780.765 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-06-03T21:03:00.768Z,1528059780.768 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-06-03T21:03:00.919Z,1528059780.919 [CBIT] Loaded
2018-06-03T21:03:00.920Z,1528059780.920 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-06-03T21:03:00.920Z,1528059780.920 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-06-03T21:03:00.921Z,1528059780.921 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-06-03T21:03:01.237Z,1528059781.237 [Aanderaa_O2] Loaded
2018-06-03T21:03:01.237Z,1528059781.237 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-06-03T21:03:01.321Z,1528059781.321 [CTD_NeilBrown] Loaded
2018-06-03T21:03:01.322Z,1528059781.322 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-06-03T21:03:01.323Z,1528059781.323 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409754E0
2018-06-03T21:03:01.323Z,1528059781.323 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1518
2018-06-03T21:03:01.370Z,1528059781.370 [CTD_Seabird] Loaded
2018-06-03T21:03:01.370Z,1528059781.370 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-06-03T21:03:01.371Z,1528059781.371 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409A54E0
2018-06-03T21:03:01.372Z,1528059781.372 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1519
2018-06-03T21:03:01.386Z,1528059781.386 [PAR_Licor] Loaded
2018-06-03T21:03:01.386Z,1528059781.386 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-06-03T21:03:01.436Z,1528059781.436 [WetLabsBB2FL] Loaded
2018-06-03T21:03:01.436Z,1528059781.436 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-06-03T21:03:01.437Z,1528059781.437 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409D54E0
2018-06-03T21:03:01.438Z,1528059781.438 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1520
2018-06-03T21:03:01.438Z,1528059781.438 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-06-03T21:03:01.439Z,1528059781.439 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-06-03T21:03:01.506Z,1528059781.506 [VerticalControl](DEBUG): Construct VerticalControl.
2018-06-03T21:03:01.591Z,1528059781.591 [VerticalControl] Loaded
2018-06-03T21:03:01.592Z,1528059781.592 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-06-03T21:03:01.592Z,1528059781.592 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-06-03T21:03:01.650Z,1528059781.650 [HorizontalControl] Loaded
2018-06-03T21:03:01.650Z,1528059781.650 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-06-03T21:03:01.651Z,1528059781.651 [SpeedControl](DEBUG): Construct SpeedControl.
2018-06-03T21:03:01.652Z,1528059781.652 [SpeedControl] Loaded
2018-06-03T21:03:01.653Z,1528059781.653 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-06-03T21:03:01.653Z,1528059781.653 [LoopControl](DEBUG): Construct LoopControl.
2018-06-03T21:03:01.654Z,1528059781.654 [LoopControl] Loaded
2018-06-03T21:03:01.654Z,1528059781.654 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-06-03T21:03:01.655Z,1528059781.655 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-06-03T21:03:01.655Z,1528059781.655 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-06-03T21:03:01.680Z,1528059781.680 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-06-03T21:03:01.681Z,1528059781.681 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-06-03T21:03:01.772Z,1528059781.772 [DeadReckonUsingSpeedCalculator] Loaded
2018-06-03T21:03:01.772Z,1528059781.772 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-06-03T21:03:01.788Z,1528059781.788 [NavChart] Loaded
2018-06-03T21:03:01.789Z,1528059781.789 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-06-03T21:03:01.793Z,1528059781.793 [UniversalFixResidualReporter] Loaded
2018-06-03T21:03:01.793Z,1528059781.793 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-06-03T21:03:01.793Z,1528059781.793 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-06-03T21:03:01.797Z,1528059781.797 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-06-03T21:03:01.798Z,1528059781.798 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-06-03T21:03:01.804Z,1528059781.804 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-06-03T21:03:01.806Z,1528059781.806 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A614E0
2018-06-03T21:03:01.806Z,1528059781.806 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1521
2018-06-03T21:03:01.810Z,1528059781.810 [Supervisor](INFO): Main Thread ID is 797
2018-06-03T21:03:01.811Z,1528059781.811 [Supervisor](DEBUG): Running supervisor.
2018-06-03T21:03:01.811Z,1528059781.811 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1522
2018-06-03T21:03:01.814Z,1528059781.814 [controlThread ThreadHandler](INFO): Handler Thread ID is 1523
2018-06-03T21:03:01.814Z,1528059781.814 [controlThread](DEBUG): Initializing ControlThread
2018-06-03T21:03:01.815Z,1528059781.815 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-06-03T21:03:01.815Z,1528059781.815 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-06-03T21:03:01.816Z,1528059781.816 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-06-03T21:03:01.816Z,1528059781.816 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-06-03T21:03:01.817Z,1528059781.817 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2018-06-03T21:03:01.817Z,1528059781.817 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-06-03T21:03:01.818Z,1528059781.818 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-06-03T21:03:01.824Z,1528059781.824 [SBIT](INFO): Initialize SBIT Component.
2018-06-03T21:03:01.824Z,1528059781.824 [SBIT](IMPORTANT): git: 2018-06-03
2018-06-03T21:03:01.825Z,1528059781.825 [SBIT](INFO): git hash: e89e4219fcae2edd415aee450018ea5d8b44159b
2018-06-03T21:03:01.825Z,1528059781.825 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-06-03T21:03:01.826Z,1528059781.826 [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-06-03T21:03:01.827Z,1528059781.827 [SBIT](INFO): Beginning SBIT in 23.000000 seconds.
2018-06-03T21:03:01.828Z,1528059781.828 [IBIT](INFO): Initialize IBIT Component.
2018-06-03T21:03:01.829Z,1528059781.829 [CBIT](DEBUG): Initialize CBIT Component.
2018-06-03T21:03:01.829Z,1528059781.829 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-06-03T21:03:01.830Z,1528059781.830 [logger ThreadHandler](INFO): Handler Thread ID is 1524
2018-06-03T21:03:01.849Z,1528059781.849 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1525
2018-06-03T21:03:01.855Z,1528059781.855 [Radio_Surface](INFO): Powering up
2018-06-03T21:03:01.861Z,1528059781.861 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 1526
2018-06-03T21:03:01.862Z,1528059781.862 [Rowe_600LCM](INFO): Initializing
2018-06-03T21:03:01.862Z,1528059781.862 [Rowe_600LCM](INFO): Checking LCM
2018-06-03T21:03:01.871Z,1528059781.871 [Rowe_600LCM](INFO): LCM OK
2018-06-03T21:03:01.871Z,1528059781.871 [Rowe_600LCM](INFO): Powering up
2018-06-03T21:03:01.877Z,1528059781.877 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1527
2018-06-03T21:03:01.878Z,1528059781.878 [CTD_NeilBrown](INFO): Powering down
2018-06-03T21:03:01.909Z,1528059781.909 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1528
2018-06-03T21:03:01.910Z,1528059781.910 [CTD_Seabird](INFO): Initializing
2018-06-03T21:03:01.910Z,1528059781.910 [CTD_Seabird](INFO): Checking LCM
2018-06-03T21:03:01.911Z,1528059781.911 [CTD_Seabird](INFO): LCM OK
2018-06-03T21:03:01.911Z,1528059781.911 [CTD_Seabird](INFO): Powering up
2018-06-03T21:03:01.921Z,1528059781.921 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1529
2018-06-03T21:03:01.922Z,1528059781.922 [WetLabsBB2FL](INFO): Powering down
2018-06-03T21:03:01.945Z,1528059781.945 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-06-03T21:03:01.947Z,1528059781.947 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-06-03T21:03:01.948Z,1528059781.948 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-06-03T21:03:01.948Z,1528059781.948 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-06-03T21:03:01.949Z,1528059781.949 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-06-03T21:03:01.950Z,1528059781.950 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-06-03T21:03:01.950Z,1528059781.950 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-06-03T21:03:01.951Z,1528059781.951 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-06-03T21:03:01.951Z,1528059781.951 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-06-03T21:03:01.952Z,1528059781.952 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-06-03T21:03:01.973Z,1528059781.973 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1530
2018-06-03T21:03:01.976Z,1528059781.976 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-06-03T21:03:01.977Z,1528059781.977 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-06-03T21:03:01.977Z,1528059781.977 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-06-03T21:03:01.977Z,1528059781.977 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-06-03T21:03:01.978Z,1528059781.978 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-06-03T21:03:01.978Z,1528059781.978 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-06-03T21:03:01.978Z,1528059781.978 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-06-03T21:03:01.978Z,1528059781.978 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-06-03T21:03:01.978Z,1528059781.978 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-06-03T21:03:01.979Z,1528059781.979 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-06-03T21:03:01.979Z,1528059781.979 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-06-03T21:03:01.979Z,1528059781.979 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-06-03T21:03:01.979Z,1528059781.979 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-06-03T21:03:01.979Z,1528059781.979 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-06-03T21:03:01.980Z,1528059781.980 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-06-03T21:03:01.980Z,1528059781.980 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-06-03T21:03:01.999Z,1528059781.999 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-06-03T21:03:02.035Z,1528059782.035 [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-06-03T21:03:02.036Z,1528059782.036 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-06-03T21:03:02.127Z,1528059782.127 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-06-03T21:03:02.128Z,1528059782.128 [Default:A.Wait](DEBUG): Construct Wait.
2018-06-03T21:03:02.130Z,1528059782.130 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-06-03T21:03:02.177Z,1528059782.177 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-06-03T21:03:02.179Z,1528059782.179 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-06-03T21:03:02.201Z,1528059782.201 [Default:E.Execute](DEBUG): Construct Execute.
2018-06-03T21:03:02.205Z,1528059782.205 [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-06-03T21:03:02.215Z,1528059782.215 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,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-06-03T21:03:02.246Z,1528059782.246 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-06-03T21:03:02.468Z,1528059782.468 [DAT](INFO): Powering up
2018-06-03T21:03:02.469Z,1528059782.469 [DAT](DEBUG): Initializing DAT.
2018-06-03T21:03:02.849Z,1528059782.849 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:02.961Z,1528059782.961 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:02.969Z,1528059782.969 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-06-03T21:03:02.992Z,1528059782.992 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:02.997Z,1528059782.997 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-06-03T21:03:03.011Z,1528059783.011 [MassServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:03.017Z,1528059783.017 [MassServo](DEBUG): Initializing MassServo.
2018-06-03T21:03:03.031Z,1528059783.031 [RudderServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:03.037Z,1528059783.037 [RudderServo](DEBUG): Initializing RudderServo.
2018-06-03T21:03:03.066Z,1528059783.066 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:03.073Z,1528059783.073 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-06-03T21:03:03.283Z,1528059783.283 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:03.610Z,1528059783.610 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:04.129Z,1528059784.129 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:04.492Z,1528059784.492 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:04.901Z,1528059784.901 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:05.317Z,1528059785.317 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:05.801Z,1528059785.801 [Aanderaa_O2](INFO): Powering down
2018-06-03T21:03:05.949Z,1528059785.949 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-06-03T21:03:06.200Z,1528059786.200 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-06-03T21:03:06.428Z,1528059786.428 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -cfg /mnt/mmc/LRAUV/lrauv-framework/onboard/devices/rowe/default-dvl-9600.cfg -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-06-03T21:03:06.460Z,1528059786.460 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-06-03T21:03:06.471Z,1528059786.471 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-06-03T21:03:06.497Z,1528059786.497 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-06-03T21:03:07.521Z,1528059787.521 [MassServo](ERROR): isCommunicating uart error serial timeout
2018-06-03T21:03:07.522Z,1528059787.522 [MassServo](FAULT): Invalid EZ Servo response:"\377"
2018-06-03T21:03:07.522Z,1528059787.522 [MassServo] Communications Fault, FailCount= 1
2018-06-03T21:03:07.522Z,1528059787.522 [MassServo](ERROR): Communications Fault
2018-06-03T21:03:07.522Z,1528059787.522 [MassServo](FAULT): Mass Shifter error waiting for homing. Uart error: serial timeout
2018-06-03T21:03:07.523Z,1528059787.523 [MassServo] Hardware Fault, FailCount= 1
2018-06-03T21:03:07.523Z,1528059787.523 [MassServo](ERROR): Hardware Fault
2018-06-03T21:03:07.538Z,1528059787.538 [MassServo](FAULT): Invalid EZ Servo response:"4271"
2018-06-03T21:03:07.538Z,1528059787.538 [MassServo] Communications Fault, FailCount= 1
2018-06-03T21:03:07.538Z,1528059787.538 [MassServo](ERROR): Communications Fault
2018-06-03T21:03:07.602Z,1528059787.602 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-06-03T21:03:07.647Z,1528059787.647 [CBIT](ERROR): Communications Fault in component: MassServo
2018-06-03T21:03:07.780Z,1528059787.780 [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-06-03T21:03:07.783Z,1528059787.783 [CTD_Seabird](INFO): LCM subscribed to channel:ctd_t.seabird-gpctd
2018-06-03T21:03:07.980Z,1528059787.980 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-06-03T21:03:07.980Z,1528059787.980 [MassServo](INFO): Powering down
2018-06-03T21:03:08.230Z,1528059788.230 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-06-03T21:03:08.230Z,1528059788.230 [CTD_Seabird](INFO): Powering down
2018-06-03T21:03:08.779Z,1528059788.779 [MassServo](DEBUG): Initializing EZServoServo.
2018-06-03T21:03:08.779Z,1528059788.779 [MassServo](DEBUG): Initializing MassServo.
2018-06-03T21:03:08.802Z,1528059788.802 [CBIT](INFO): Clearing failed state for component MassServo
2018-06-03T21:03:08.802Z,1528059788.802 [MassServo] No Fault, FailCount= 1
2018-06-03T21:03:15.520Z,1528059795.520 [DAT](INFO): setting local address to 2
2018-06-03T21:03:15.912Z,1528059795.912 [DAT](INFO): set local address to 2
2018-06-03T21:03:25.760Z,1528059805.760 [SBIT](IMPORTANT): Beginning Startup BIT
2018-06-03T21:03:25.799Z,1528059805.799 [CBIT](IMPORTANT): Beginning ground fault scan
2018-06-03T21:03:28.823Z,1528059808.823 [NAL9602](INFO): Powering up NAL9602
2018-06-03T21:03:36.508Z,1528059816.508 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004080
CHAN A1 (24V): -0.008141
CHAN A2 (12V): -0.002386
CHAN A3 (5V): -0.001072
CHAN B0 (3.3V): 0.000007
CHAN B1 (3.15aV): -0.000308
CHAN B2 (3.15bV): -0.000208
CHAN B3 (GND): 0.000123
OPEN: -0.000298
Full Scale Calc: 4.765 mA, -1.589 mA
2018-06-03T21:03:40.023Z,1528059820.023 [NAL9602](INFO): NAL9602 initialized
2018-06-03T21:03:45.058Z,1528059825.058 [CommandLine](IMPORTANT): got command failComponent
2018-06-03T21:03:45.058Z,1528059825.058 [CommandLine](IMPORTANT): Failed components:
2018-06-03T21:03:45.058Z,1528059825.058 [CommandLine](IMPORTANT): No failed Components.
2018-06-03T21:04:04.454Z,1528059844.454 [CommandLine](IMPORTANT): got command failComponent
2018-06-03T21:04:04.454Z,1528059844.454 [CommandLine](IMPORTANT): Failed components:
2018-06-03T21:04:04.454Z,1528059844.454 [CommandLine](IMPORTANT): No failed Components.
2018-06-03T21:04:14.674Z,1528059854.674 [CommandLine](IMPORTANT): got command show variable rowe600_lcm
2018-06-03T21:04:19.260Z,1528059859.260 [SBIT](IMPORTANT): SBIT PASSED
2018-06-03T21:04:19.355Z,1528059859.355 [CommandLine](IMPORTANT): got command configSet list
2018-06-03T21:04:19.356Z,1528059859.356 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-06-03T21:04:19.357Z,1528059859.357 [CommandLine](IMPORTANT): DAT.loadAtStartup=1 bool;

2018-06-03T21:04:19.670Z,1528059859.670 [MissionManager](IMPORTANT): Started mission Startup
2018-06-03T21:04:19.670Z,1528059859.670 [Startup] Running Loop=1
2018-06-03T21:04:19.671Z,1528059859.671 [Startup](DEBUG): Aggregate::initialize Startup
2018-06-03T21:04:19.671Z,1528059859.671 [Startup:A.GoToSurface] Running Loop=1
2018-06-03T21:04:19.671Z,1528059859.671 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-06-03T21:04:19.671Z,1528059859.671 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-06-03T21:04:19.672Z,1528059859.672 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-06-03T21:04:19.672Z,1528059859.672 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-06-03T21:04:19.681Z,1528059859.681 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-06-03T21:04:19.681Z,1528059859.681 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-06-03T21:04:19.701Z,1528059859.701 [Startup:StartupSatComms] Running Loop=1
2018-06-03T21:04:19.701Z,1528059859.701 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-06-03T21:04:19.705Z,1528059859.705 [Startup:StartupSatComms:A] Running Loop=1
2018-06-03T21:04:20.070Z,1528059860.070 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-06-03T21:04:25.750Z,1528059865.750 [CommandLine](IMPORTANT): got command show variable rowe_600lcm
2018-06-03T21:04:25.828Z,1528059865.828 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup (bool)
2018-06-03T21:04:25.830Z,1528059865.830 [CommandLine](IMPORTANT): Rowe_600LCM.simulateHardware (bool)
2018-06-03T21:04:25.831Z,1528059865.831 [CommandLine](IMPORTANT): Rowe_600LCM.bottomTrackVelocityAccuracy (meter_per_second)
2018-06-03T21:04:25.833Z,1528059865.833 [CommandLine](IMPORTANT): Rowe_600LCM.waterTrackVelocityAccuracy (meter_per_second)
2018-06-03T21:04:25.835Z,1528059865.835 [CommandLine](IMPORTANT): Rowe_600LCM.altitudeAccuracy (meter)
2018-06-03T21:04:25.861Z,1528059865.861 [CommandLine](IMPORTANT): Rowe_600LCM.loadControl (none)
2018-06-03T21:04:25.862Z,1528059865.862 [CommandLine](IMPORTANT): Rowe_600LCM.uart (none)
2018-06-03T21:04:25.864Z,1528059865.864 [CommandLine](IMPORTANT): Rowe_600LCM.baud (bit_per_second)
2018-06-03T21:04:25.866Z,1528059865.866 [CommandLine](IMPORTANT): Rowe_600LCM.maxSpeed (meter_per_second)
2018-06-03T21:04:25.867Z,1528059865.867 [CommandLine](IMPORTANT): Rowe_600LCM.lcmChannelBottom (none)
2018-06-03T21:04:25.868Z,1528059865.868 [CommandLine](IMPORTANT): Rowe_600LCM.lcmChannelWater (none)
2018-06-03T21:04:25.870Z,1528059865.870 [CommandLine](IMPORTANT): Rowe_600LCM.lcmChannelDVL (none)
2018-06-03T21:04:25.871Z,1528059865.871 [CommandLine](IMPORTANT): Rowe_600LCM.lcmApplication (none)
2018-06-03T21:04:26.162Z,1528059866.162 [CommandLine](IMPORTANT): Rowe_600LCM.height_above_sea_floor (meter)
2018-06-03T21:04:26.162Z,1528059866.162 [CommandLine](IMPORTANT): Rowe_600LCM.platform_x_velocity_wrt_ground (meter_per_second)
2018-06-03T21:04:26.163Z,1528059866.163 [CommandLine](IMPORTANT): Rowe_600LCM.platform_y_velocity_wrt_ground (meter_per_second)
2018-06-03T21:04:26.163Z,1528059866.163 [CommandLine](IMPORTANT): Rowe_600LCM.platform_z_velocity_wrt_ground (meter_per_second)
2018-06-03T21:04:26.164Z,1528059866.164 [CommandLine](IMPORTANT): Rowe_600LCM.platform_x_velocity_wrt_sea_water (meter_per_second)
2018-06-03T21:04:26.164Z,1528059866.164 [CommandLine](IMPORTANT): Rowe_600LCM.platform_y_velocity_wrt_sea_water (meter_per_second)
2018-06-03T21:04:26.164Z,1528059866.164 [CommandLine](IMPORTANT): Rowe_600LCM.platform_z_velocity_wrt_sea_water (meter_per_second)
2018-06-03T21:04:26.169Z,1528059866.169 [CommandLine](IMPORTANT): Rowe_600LCM.platform_velocity_wrt_ground (meter_per_second)
2018-06-03T21:04:26.170Z,1528059866.170 [CommandLine](IMPORTANT): Rowe_600LCM.platform_velocity_wrt_sea_water (meter_per_second)
2018-06-03T21:04:26.170Z,1528059866.170 [CommandLine](IMPORTANT): Rowe_600LCM.Altitude1 (meter)
2018-06-03T21:04:26.170Z,1528059866.170 [CommandLine](IMPORTANT): Rowe_600LCM.Altitude2 (meter)
2018-06-03T21:04:26.171Z,1528059866.171 [CommandLine](IMPORTANT): Rowe_600LCM.Altitude3 (meter)
2018-06-03T21:04:26.171Z,1528059866.171 [CommandLine](IMPORTANT): Rowe_600LCM.Altitude4 (meter)
2018-06-03T21:04:26.249Z,1528059866.249 [CommandLine](IMPORTANT): Rowe_600LCM.durationOfLastRun (second)
2018-06-03T21:04:26.277Z,1528059866.277 [CommandLine](IMPORTANT): Rowe_600LCM.component_voltage (volt)
2018-06-03T21:04:26.278Z,1528059866.278 [CommandLine](IMPORTANT): Rowe_600LCM.component_avgVoltage (volt)
2018-06-03T21:04:26.280Z,1528059866.280 [CommandLine](IMPORTANT): Rowe_600LCM.component_current (milliampere)
2018-06-03T21:04:26.280Z,1528059866.280 [CommandLine](IMPORTANT): Rowe_600LCM.component_avgCurrent (milliampere)
2018-06-03T21:04:36.162Z,1528059876.162 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:04:36.957Z,1528059876.957 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:05:02.361Z,1528059902.361 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-06-03T21:05:02.361Z,1528059902.361 [Rowe_600LCM] Communications Fault, FailCount= 1
2018-06-03T21:05:02.361Z,1528059902.361 [Rowe_600LCM](ERROR): Communications Fault
2018-06-03T21:05:02.477Z,1528059902.477 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-06-03T21:05:02.765Z,1528059902.765 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:05:02.989Z,1528059902.989 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:05:04.458Z,1528059904.458 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-06-03T21:05:04.458Z,1528059904.458 [Rowe_600LCM] No Fault, FailCount= 1
2018-06-03T21:05:04.605Z,1528059904.605 [Rowe_600LCM](INFO): Initializing
2018-06-03T21:05:04.605Z,1528059904.605 [Rowe_600LCM](INFO): Checking LCM
2018-06-03T21:05:04.606Z,1528059904.606 [Rowe_600LCM](INFO): LCM OK
2018-06-03T21:05:04.606Z,1528059904.606 [Rowe_600LCM](INFO): Powering up
2018-06-03T21:05:08.731Z,1528059908.731 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-06-03T21:05:08.840Z,1528059908.840 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -cfg /mnt/mmc/LRAUV/lrauv-framework/onboard/devices/rowe/default-dvl-9600.cfg -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-06-03T21:05:08.842Z,1528059908.842 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-06-03T21:05:08.843Z,1528059908.843 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-06-03T21:05:08.843Z,1528059908.843 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-06-03T21:05:20.031Z,1528059920.031 [Startup:StartupSatComms:A](INFO): Timed out from 2018-06-03T21:04:19.7Z
2018-06-03T21:05:20.031Z,1528059920.031 [Startup:StartupSatComms:A] Stopped
2018-06-03T21:05:20.031Z,1528059920.031 [Startup:StartupSatComms:B] Running Loop=1
2018-06-03T21:05:20.436Z,1528059920.436 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-06-03T21:06:02.047Z,1528059962.047 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-06-03T21:06:02.047Z,1528059962.047 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-06-03T21:06:02.047Z,1528059962.047 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-06-03T21:06:02.072Z,1528059962.072 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-06-03T21:06:02.458Z,1528059962.458 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-06-03T21:06:02.458Z,1528059962.458 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-06-03T21:06:02.830Z,1528059962.830 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-06-03T21:06:02.831Z,1528059962.831 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-06-03T21:06:02.831Z,1528059962.831 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-06-03T21:06:07.803Z,1528059967.803 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003891
2018-06-03T21:06:12.220Z,1528059972.220 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180603T192854/Courier0031.lzma
2018-06-03T21:06:13.020Z,1528059973.020 [DataOverHttps](INFO): Moved sent file to Logs/20180603T192854/Courier0031.lzma.bak
2018-06-03T21:06:13.021Z,1528059973.021 [DataOverHttps](INFO): SBD MOMSN=8310093
2018-06-03T21:06:23.777Z,1528059983.777 [Startup:StartupSatComms:B](INFO): Timed out from 2018-06-03T21:05:20.0Z
2018-06-03T21:06:23.777Z,1528059983.777 [Startup:StartupSatComms:B] Stopped
2018-06-03T21:06:23.777Z,1528059983.777 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-06-03T21:06:23.778Z,1528059983.778 [Startup:StartupSatComms] Stopped
2018-06-03T21:06:23.778Z,1528059983.778 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-06-03T21:06:23.779Z,1528059983.779 [Startup](INFO): Completed Startup
2018-06-03T21:06:23.779Z,1528059983.779 [MissionManager](INFO): Startup is completed.
2018-06-03T21:06:23.779Z,1528059983.779 [MissionManager](INFO): Uninitializing Mission Startup
2018-06-03T21:06:23.779Z,1528059983.779 [Startup] Stopped
2018-06-03T21:06:23.780Z,1528059983.780 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-06-03T21:06:23.780Z,1528059983.780 [Startup:A.GoToSurface] Stopped
2018-06-03T21:06:23.780Z,1528059983.780 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-06-03T21:06:23.866Z,1528059983.866 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20180603T192854/Express0032.lzma
2018-06-03T21:06:23.964Z,1528059983.964 [MissionManager](IMPORTANT): Started mission Default
2018-06-03T21:06:23.964Z,1528059983.964 [Default] Running Loop=1
2018-06-03T21:06:23.964Z,1528059983.964 [Default](DEBUG): Aggregate::initialize Default
2018-06-03T21:06:23.964Z,1528059983.964 [Default:B.GoToSurface] Running Loop=1
2018-06-03T21:06:23.964Z,1528059983.964 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-06-03T21:06:23.964Z,1528059983.964 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-06-03T21:06:23.965Z,1528059983.965 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-06-03T21:06:23.965Z,1528059983.965 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-06-03T21:06:23.966Z,1528059983.966 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-06-03T21:06:23.966Z,1528059983.966 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-06-03T21:06:23.967Z,1528059983.967 [Default:A.Wait] Running Loop=1
2018-06-03T21:06:23.967Z,1528059983.967 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-06-03T21:06:24.162Z,1528059984.162 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:06:24.655Z,1528059984.655 [DataOverHttps](INFO): Moved sent file to Logs/20180603T192854/Express0032.lzma.bak
2018-06-03T21:06:24.656Z,1528059984.656 [DataOverHttps](INFO): SBD MOMSN=8310095
2018-06-03T21:06:24.957Z,1528059984.957 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:06:37.096Z,1528059997.096 [Default:A.Wait](INFO): Done Waiting.
2018-06-03T21:06:37.096Z,1528059997.096 [Default:A.Wait] Stopped
2018-06-03T21:06:37.097Z,1528059997.097 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-06-03T21:06:37.458Z,1528059997.458 [Default:CheckIn] Running Loop=1
2018-06-03T21:06:37.458Z,1528059997.458 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-06-03T21:06:37.458Z,1528059997.458 [Default:CheckIn:Read_GPS] Running Loop=1
2018-06-03T21:06:37.855Z,1528059997.855 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-06-03T21:07:05.153Z,1528060025.153 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-06-03T21:07:05.153Z,1528060025.153 [Rowe_600LCM] Communications Fault, FailCount= 2
2018-06-03T21:07:05.153Z,1528060025.153 [Rowe_600LCM](ERROR): Communications Fault
2018-06-03T21:07:05.482Z,1528060025.482 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-06-03T21:07:05.557Z,1528060025.557 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:07:05.777Z,1528060025.777 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:07:07.056Z,1528060027.056 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-06-03T21:07:07.056Z,1528060027.056 [Rowe_600LCM] No Fault, FailCount= 2
2018-06-03T21:07:07.406Z,1528060027.406 [Rowe_600LCM](INFO): Initializing
2018-06-03T21:07:07.406Z,1528060027.406 [Rowe_600LCM](INFO): Checking LCM
2018-06-03T21:07:07.406Z,1528060027.406 [Rowe_600LCM](INFO): LCM OK
2018-06-03T21:07:07.407Z,1528060027.407 [Rowe_600LCM](INFO): Powering up
2018-06-03T21:07:11.600Z,1528060031.600 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-06-03T21:07:11.668Z,1528060031.668 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -cfg /mnt/mmc/LRAUV/lrauv-framework/onboard/devices/rowe/default-dvl-9600.cfg -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-06-03T21:07:11.669Z,1528060031.669 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-06-03T21:07:11.671Z,1528060031.671 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-06-03T21:07:11.671Z,1528060031.671 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-06-03T21:07:27.010Z,1528060047.010 [CommandLine](IMPORTANT): got command failComponent
2018-06-03T21:07:27.011Z,1528060047.011 [CommandLine](IMPORTANT): Failed components:
2018-06-03T21:07:27.011Z,1528060047.011 [CommandLine](IMPORTANT): No failed Components.
2018-06-03T21:08:44.179Z,1528060124.179 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-06-03T21:09:03.028Z,1528060143.028 [BPC1](ERROR): Failed to receive data from both battery packs
2018-06-03T21:09:03.028Z,1528060143.028 [BPC1] Communications Fault, FailCount= 1
2018-06-03T21:09:03.028Z,1528060143.028 [BPC1](ERROR): Communications Fault
2018-06-03T21:09:03.039Z,1528060143.039 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-06-03T21:09:03.039Z,1528060143.039 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2018-06-03T21:09:03.039Z,1528060143.039 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-06-03T21:09:03.076Z,1528060143.076 [CBIT](ERROR): Communications Fault in component: BPC1
2018-06-03T21:09:03.081Z,1528060143.081 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-06-03T21:09:03.451Z,1528060143.451 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-06-03T21:09:03.451Z,1528060143.451 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2018-06-03T21:09:03.833Z,1528060143.833 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-06-03T21:09:03.834Z,1528060143.834 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-06-03T21:09:03.834Z,1528060143.834 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-06-03T21:09:04.239Z,1528060144.239 [CBIT](INFO): Clearing failed state for component BPC1
2018-06-03T21:09:04.239Z,1528060144.239 [BPC1] No Fault, FailCount= 1
2018-06-03T21:09:08.157Z,1528060148.157 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-06-03T21:09:08.157Z,1528060148.157 [Rowe_600LCM] Communications Fault, FailCount= 3
2018-06-03T21:09:08.157Z,1528060148.157 [Rowe_600LCM](ERROR): Communications Fault
2018-06-03T21:09:08.265Z,1528060148.265 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-06-03T21:09:08.561Z,1528060148.561 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:09:08.852Z,1528060148.852 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:09:09.661Z,1528060149.661 [Rowe_600LCM](FAULT): LCB fault:  Software Overcurrent.
2018-06-03T21:09:09.662Z,1528060149.662 [Rowe_600LCM] Hardware Fault, FailCount= 3
2018-06-03T21:09:09.662Z,1528060149.662 [Rowe_600LCM](ERROR): Hardware Fault
2018-06-03T21:09:10.265Z,1528060150.265 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-06-03T21:09:10.265Z,1528060150.265 [Rowe_600LCM] No Fault, FailCount= 3
2018-06-03T21:09:10.469Z,1528060150.469 [Rowe_600LCM](INFO): Initializing
2018-06-03T21:09:10.469Z,1528060150.469 [Rowe_600LCM](INFO): Checking LCM
2018-06-03T21:09:10.470Z,1528060150.470 [Rowe_600LCM](INFO): LCM OK
2018-06-03T21:09:10.470Z,1528060150.470 [Rowe_600LCM](INFO): Powering up
2018-06-03T21:09:14.667Z,1528060154.667 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-06-03T21:09:14.784Z,1528060154.784 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -cfg /mnt/mmc/LRAUV/lrauv-framework/onboard/devices/rowe/default-dvl-9600.cfg -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-06-03T21:09:14.785Z,1528060154.785 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-06-03T21:09:14.786Z,1528060154.786 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-06-03T21:09:14.787Z,1528060154.787 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-06-03T21:11:11.153Z,1528060271.153 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-06-03T21:11:11.153Z,1528060271.153 [Rowe_600LCM] Communications Fault, FailCount= 4
2018-06-03T21:11:11.153Z,1528060271.153 [Rowe_600LCM](ERROR): Communications Fault
2018-06-03T21:11:11.388Z,1528060271.388 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-06-03T21:11:11.558Z,1528060271.558 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:11:11.843Z,1528060271.843 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:11:12.649Z,1528060272.649 [Rowe_600LCM](FAULT): LCB fault:  Software Overcurrent.
2018-06-03T21:11:12.650Z,1528060272.650 [Rowe_600LCM] Hardware Fault, FailCount= 4
2018-06-03T21:11:12.650Z,1528060272.650 [Rowe_600LCM](ERROR): Hardware Fault
2018-06-03T21:11:13.351Z,1528060273.351 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-06-03T21:11:13.351Z,1528060273.351 [Rowe_600LCM] No Fault, FailCount= 4
2018-06-03T21:11:13.457Z,1528060273.457 [Rowe_600LCM](INFO): Initializing
2018-06-03T21:11:13.457Z,1528060273.457 [Rowe_600LCM](INFO): Checking LCM
2018-06-03T21:11:13.458Z,1528060273.458 [Rowe_600LCM](INFO): LCM OK
2018-06-03T21:11:13.458Z,1528060273.458 [Rowe_600LCM](INFO): Powering up
2018-06-03T21:11:17.583Z,1528060277.583 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-06-03T21:11:17.644Z,1528060277.644 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -cfg /mnt/mmc/LRAUV/lrauv-framework/onboard/devices/rowe/default-dvl-9600.cfg -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null &
2018-06-03T21:11:17.646Z,1528060277.646 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-06-03T21:11:17.647Z,1528060277.647 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-06-03T21:11:17.647Z,1528060277.647 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-06-03T21:11:37.746Z,1528060297.746 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-06-03T21:06:37.5Z
2018-06-03T21:11:37.746Z,1528060297.746 [Default:CheckIn:Read_GPS] Stopped
2018-06-03T21:11:37.746Z,1528060297.746 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-06-03T21:11:38.146Z,1528060298.146 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-06-03T21:11:42.720Z,1528060302.720 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180603T210251/Courier0004.lzma
2018-06-03T21:11:43.519Z,1528060303.519 [DataOverHttps](INFO): Moved sent file to Logs/20180603T210251/Courier0004.lzma.bak
2018-06-03T21:11:43.519Z,1528060303.519 [DataOverHttps](INFO): SBD MOMSN=8310098
2018-06-03T21:11:51.154Z,1528060311.154 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:11:51.950Z,1528060311.950 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2018-06-03T21:11:53.616Z,1528060313.616 [DataOverHttps](INFO): Sending 1239 bytes from file Logs/20180603T210251/Express0001.lzma
2018-06-03T21:11:54.395Z,1528060314.395 [DataOverHttps](INFO): Moved sent file to Logs/20180603T210251/Express0001.lzma.bak
2018-06-03T21:11:54.396Z,1528060314.396 [DataOverHttps](INFO): SBD MOMSN=8310101
2018-06-03T21:12:04.379Z,1528060324.379 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-06-03T21:12:04.379Z,1528060324.379 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2018-06-03T21:12:04.379Z,1528060324.379 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-06-03T21:12:04.392Z,1528060324.392 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-06-03T21:12:04.428Z,1528060324.428 [DataOverHttps](INFO): Sending 339 bytes from file Logs/20180603T210251/Express0005.lzma
2018-06-03T21:12:04.604Z,1528060324.604 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-06-03T21:12:04.605Z,1528060324.605 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2018-06-03T21:12:04.891Z,1528060324.891 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-06-03T21:12:04.892Z,1528060324.892 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-06-03T21:12:04.892Z,1528060324.892 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-06-03T21:12:05.203Z,1528060325.203 [DataOverHttps](INFO): Moved sent file to Logs/20180603T210251/Express0005.lzma.bak
2018-06-03T21:12:05.203Z,1528060325.203 [DataOverHttps](INFO): SBD MOMSN=8310157
2018-06-03T21:12:06.504Z,1528060326.504 [Default:CheckIn:Read_Iridium] Stopped
2018-06-03T21:12:06.504Z,1528060326.504 [Default:CheckIn:C.Wait] Running Loop=1
2018-06-03T21:12:06.504Z,1528060326.504 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-06-03T21:13:14.145Z,1528060394.145 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-06-03T21:13:14.145Z,1528060394.145 [Rowe_600LCM] Communications Fault, FailCount= 5
2018-06-03T21:13:14.145Z,1528060394.145 [Rowe_600LCM](ERROR): Communications Fault
2018-06-03T21:13:14.166Z,1528060394.166 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-06-03T21:13:14.166Z,1528060394.166 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM
2018-06-03T21:13:14.550Z,1528060394.550 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:13:14.847Z,1528060394.847 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:13:40.538Z,1528060420.538 [CommandLine](IMPORTANT): got command restart application
2018-06-03T21:13:40.863Z,1528060420.863 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-06-03T21:13:40.863Z,1528060420.863 [NAL9602] Data Fault, FailCount= 1
2018-06-03T21:13:40.863Z,1528060420.863 [NAL9602](ERROR): Data Fault
2018-06-03T21:13:40.949Z,1528060420.949 [CBIT](ERROR): Data Fault in component: NAL9602
2018-06-03T21:13:41.263Z,1528060421.263 [NAL9602](INFO): Powering down
2018-06-03T21:13:41.541Z,1528060421.541 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2018-06-03T21:13:41.544Z,1528060421.544 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:41.545Z,1528060421.545 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:41.725Z,1528060421.725 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2018-06-03T21:13:41.726Z,1528060421.726 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:41.726Z,1528060421.726 [CommandLine](INFO): Join timeout helper Thread ID is 1598
2018-06-03T21:13:41.745Z,1528060421.745 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-06-03T21:13:41.745Z,1528060421.745 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:41.745Z,1528060421.745 [NavChartDb](INFO): Join timeout helper Thread ID is 1599
2018-06-03T21:13:41.949Z,1528060421.949 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:41.949Z,1528060421.949 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:41.957Z,1528060421.957 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-06-03T21:13:41.957Z,1528060421.957 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:41.957Z,1528060421.957 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1600
2018-06-03T21:13:42.017Z,1528060422.017 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.017Z,1528060422.017 [WetLabsBB2FL](INFO): Powering down
2018-06-03T21:13:42.018Z,1528060422.018 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.040Z,1528060422.040 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-06-03T21:13:42.040Z,1528060422.040 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.041Z,1528060422.041 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1601
2018-06-03T21:13:42.081Z,1528060422.081 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.221Z,1528060422.221 [CBIT](INFO): Clearing failed state for component NAL9602
2018-06-03T21:13:42.222Z,1528060422.222 [NAL9602] No Fault, FailCount= 1
2018-06-03T21:13:42.279Z,1528060422.279 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-06-03T21:13:42.279Z,1528060422.279 [CTD_Seabird](INFO): Powering down
2018-06-03T21:13:42.280Z,1528060422.280 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.297Z,1528060422.297 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-06-03T21:13:42.297Z,1528060422.297 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.298Z,1528060422.298 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1603
2018-06-03T21:13:42.533Z,1528060422.533 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.534Z,1528060422.534 [CTD_NeilBrown](INFO): Powering down
2018-06-03T21:13:42.535Z,1528060422.535 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.550Z,1528060422.550 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-06-03T21:13:42.550Z,1528060422.550 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.551Z,1528060422.551 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 1604
2018-06-03T21:13:42.733Z,1528060422.733 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.733Z,1528060422.733 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-06-03T21:13:42.818Z,1528060422.818 [Rowe_600LCM](INFO): Powering down
2018-06-03T21:13:42.819Z,1528060422.819 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.826Z,1528060422.826 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-06-03T21:13:42.826Z,1528060422.826 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.827Z,1528060422.827 [Radio_Surface](INFO): Join timeout helper Thread ID is 1606
2018-06-03T21:13:42.929Z,1528060422.929 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.930Z,1528060422.930 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.938Z,1528060422.938 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-06-03T21:13:42.938Z,1528060422.938 [logger ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.938Z,1528060422.938 [logger](INFO): Join timeout helper Thread ID is 1607
2018-06-03T21:13:42.949Z,1528060422.949 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:42.949Z,1528060422.949 [logger ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.962Z,1528060422.962 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-06-03T21:13:42.962Z,1528060422.962 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.962Z,1528060422.962 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-06-03T21:13:42.962Z,1528060422.962 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:42.963Z,1528060422.963 [controlThread](INFO): Join timeout helper Thread ID is 1608
2018-06-03T21:13:43.253Z,1528060423.253 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-06-03T21:13:43.253Z,1528060423.253 [controlThread](DEBUG): Uninitializing ControlThread
2018-06-03T21:13:43.254Z,1528060423.254 [NAL9602](INFO): Powering down
2018-06-03T21:13:43.255Z,1528060423.255 [DAT](INFO): Powering down
2018-06-03T21:13:43.373Z,1528060423.373 [PNI_TCM](INFO): Powering down
2018-06-03T21:13:43.462Z,1528060423.462 [Aanderaa_O2](INFO): Powering down
2018-06-03T21:13:43.463Z,1528060423.463 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-06-03T21:13:43.464Z,1528060423.464 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-06-03T21:13:43.465Z,1528060423.465 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-06-03T21:13:43.466Z,1528060423.466 [MissionManager](INFO): Uninitializing Mission Default
2018-06-03T21:13:43.466Z,1528060423.466 [Default] Stopped
2018-06-03T21:13:43.466Z,1528060423.466 [Default](DEBUG): Aggregate::uninitialize Default
2018-06-03T21:13:43.466Z,1528060423.466 [Default:B.GoToSurface] Stopped
2018-06-03T21:13:43.466Z,1528060423.466 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-06-03T21:13:43.467Z,1528060423.467 [Default:CheckIn] Stopped
2018-06-03T21:13:43.467Z,1528060423.467 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-06-03T21:13:43.467Z,1528060423.467 [Default:CheckIn:C.Wait] Stopped
2018-06-03T21:13:43.467Z,1528060423.467 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-06-03T21:13:43.471Z,1528060423.471 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-06-03T21:13:43.471Z,1528060423.471 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-06-03T21:13:43.471Z,1528060423.471 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-06-03T21:13:43.472Z,1528060423.472 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-06-03T21:13:43.472Z,1528060423.472 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-06-03T21:13:43.472Z,1528060423.472 [BuoyancyServo](INFO): Powering down
2018-06-03T21:13:43.485Z,1528060423.485 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-06-03T21:13:43.485Z,1528060423.485 [ElevatorServo](INFO): Powering down
2018-06-03T21:13:43.486Z,1528060423.486 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-06-03T21:13:43.486Z,1528060423.486 [MassServo](INFO): Powering down
2018-06-03T21:13:43.487Z,1528060423.487 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-06-03T21:13:43.487Z,1528060423.487 [RudderServo](INFO): Powering down
2018-06-03T21:13:43.488Z,1528060423.488 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-06-03T21:13:43.488Z,1528060423.488 [ThrusterServo](INFO): Powering down
2018-06-03T21:13:43.490Z,1528060423.490 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-06-03T21:13:43.490Z,1528060423.490 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-06-03T21:13:43.490Z,1528060423.490 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-06-03T21:13:43.491Z,1528060423.491 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.604Z,1528060423.604 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.613Z,1528060423.613 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.650Z,1528060423.650 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.653Z,1528060423.653 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.656Z,1528060423.656 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.682Z,1528060423.682 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-06-03T21:13:43.743Z,1528060423.743 [logger ThreadHandler](INFO): Thread cancelled.