2018-11-04T23:47:23.842Z,1541375243.842 [Supervisor](DEBUG): Initializing supervisor.
2018-11-04T23:47:23.845Z,1541375243.845 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-11-04T23:47:23.845Z,1541375243.845 [SyncHandler](INFO): Protected caller Thread ID is 798
2018-11-04T23:47:23.846Z,1541375243.846 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-11-04T23:47:23.847Z,1541375243.847 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-11-04T23:47:23.847Z,1541375243.847 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 799
2018-11-04T23:47:23.850Z,1541375243.850 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-11-04T23:47:23.861Z,1541375243.861 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-11-04T23:47:23.862Z,1541375243.862 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-11-04T23:47:23.863Z,1541375243.863 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 800
2018-11-04T23:47:23.863Z,1541375243.863 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-11-04T23:47:23.864Z,1541375243.864 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-11-04T23:47:23.865Z,1541375243.865 [logger ThreadHandler](INFO): Protected caller Thread ID is 801
2018-11-04T23:47:23.867Z,1541375243.867 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-11-04T23:47:23.867Z,1541375243.867 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-11-04T23:47:23.871Z,1541375243.871 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-11-04T23:47:24.233Z,1541375244.233 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-11-04T23:47:24.235Z,1541375244.235 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-11-04T23:47:24.459Z,1541375244.459 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-11-04T23:47:24.461Z,1541375244.461 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-11-04T23:47:24.788Z,1541375244.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-11-04T23:47:24.790Z,1541375244.790 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-11-04T23:47:24.945Z,1541375244.945 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-11-04T23:47:24.946Z,1541375244.946 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-11-04T23:47:25.048Z,1541375245.048 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-11-04T23:47:25.049Z,1541375245.049 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-11-04T23:47:25.549Z,1541375245.549 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-11-04T23:47:25.551Z,1541375245.551 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-11-04T23:47:26.057Z,1541375246.057 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-11-04T23:47:26.058Z,1541375246.058 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-11-04T23:47:26.558Z,1541375246.558 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-11-04T23:47:26.560Z,1541375246.560 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-11-04T23:47:26.669Z,1541375246.669 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-11-04T23:47:26.670Z,1541375246.670 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-11-04T23:47:26.770Z,1541375246.770 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-11-04T23:47:26.771Z,1541375246.771 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-11-04T23:47:27.006Z,1541375247.006 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-11-04T23:47:27.008Z,1541375247.008 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-11-04T23:47:27.227Z,1541375247.227 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-11-04T23:47:27.228Z,1541375247.228 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-11-04T23:47:27.610Z,1541375247.610 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-11-04T23:47:27.610Z,1541375247.610 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-11-04T23:47:28.295Z,1541375248.295 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-11-04T23:47:28.297Z,1541375248.297 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-11-04T23:47:28.381Z,1541375248.381 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-11-04T23:47:28.385Z,1541375248.385 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-11-04T23:47:28.493Z,1541375248.493 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-11-04T23:47:28.621Z,1541375248.621 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-11-04T23:47:28.719Z,1541375248.719 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-11-04T23:47:28.807Z,1541375248.807 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-11-04T23:47:28.984Z,1541375248.984 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-11-04T23:47:29.181Z,1541375249.181 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-11-04T23:47:29.258Z,1541375249.258 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-11-04T23:47:29.500Z,1541375249.500 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-11-04T23:47:29.500Z,1541375249.500 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-11-04T23:47:29.586Z,1541375249.586 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-11-04T23:47:29.681Z,1541375249.681 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-11-04T23:47:29.787Z,1541375249.787 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-11-04T23:47:29.921Z,1541375249.921 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2018-11-04T23:47:29.925Z,1541375249.925 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-11-04T23:47:30.239Z,1541375250.239 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-11-04T23:47:30.239Z,1541375250.239 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-11-04T23:47:30.300Z,1541375250.300 [DepthRateCalculator] Loaded
2018-11-04T23:47:30.300Z,1541375250.300 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-11-04T23:47:30.307Z,1541375250.307 [PitchRateCalculator] Loaded
2018-11-04T23:47:30.307Z,1541375250.307 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-11-04T23:47:30.324Z,1541375250.324 [SpeedCalculator] Loaded
2018-11-04T23:47:30.325Z,1541375250.325 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-11-04T23:47:30.347Z,1541375250.347 [TempGradientCalculator] Loaded
2018-11-04T23:47:30.347Z,1541375250.347 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-11-04T23:47:30.353Z,1541375250.353 [YawRateCalculator] Loaded
2018-11-04T23:47:30.354Z,1541375250.354 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-11-04T23:47:30.396Z,1541375250.396 [ElevatorOffsetCalculator] Loaded
2018-11-04T23:47:30.397Z,1541375250.397 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-11-04T23:47:30.397Z,1541375250.397 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-11-04T23:47:30.398Z,1541375250.398 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-11-04T23:47:30.507Z,1541375250.507 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-11-04T23:47:30.507Z,1541375250.507 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-11-04T23:47:30.651Z,1541375250.651 [BuoyancyServo] Loaded
2018-11-04T23:47:30.651Z,1541375250.651 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-11-04T23:47:30.667Z,1541375250.667 [ElevatorServo] Loaded
2018-11-04T23:47:30.667Z,1541375250.667 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-11-04T23:47:30.682Z,1541375250.682 [MassServo] Loaded
2018-11-04T23:47:30.682Z,1541375250.682 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-11-04T23:47:30.699Z,1541375250.699 [RudderServo] Loaded
2018-11-04T23:47:30.699Z,1541375250.699 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-11-04T23:47:30.714Z,1541375250.714 [ThrusterServo] Loaded
2018-11-04T23:47:30.714Z,1541375250.714 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-11-04T23:47:30.715Z,1541375250.715 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-11-04T23:47:30.715Z,1541375250.715 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-11-04T23:47:30.740Z,1541375250.740 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-11-04T23:47:30.741Z,1541375250.741 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-11-04T23:47:30.880Z,1541375250.880 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-11-04T23:47:30.881Z,1541375250.881 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-11-04T23:47:31.477Z,1541375251.477 [DataOverHttps] Loaded
2018-11-04T23:47:31.478Z,1541375251.478 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-11-04T23:47:31.492Z,1541375251.492 [Depth_Keller] Loaded
2018-11-04T23:47:31.492Z,1541375251.492 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-11-04T23:47:31.497Z,1541375251.497 [DropWeight] Loaded
2018-11-04T23:47:31.498Z,1541375251.498 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-11-04T23:47:31.603Z,1541375251.603 [NAL9602] Loaded
2018-11-04T23:47:31.603Z,1541375251.603 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-11-04T23:47:31.620Z,1541375251.620 [Onboard] Loaded
2018-11-04T23:47:31.620Z,1541375251.620 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-11-04T23:47:31.632Z,1541375251.632 [Radio_Surface] Loaded
2018-11-04T23:47:31.632Z,1541375251.632 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-11-04T23:47:31.634Z,1541375251.634 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-11-04T23:47:31.634Z,1541375251.634 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 883
2018-11-04T23:47:31.789Z,1541375251.789 [PNI_TCM] Loaded
2018-11-04T23:47:31.790Z,1541375251.790 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-11-04T23:47:31.855Z,1541375251.855 [Rowe_600LCM] Loaded
2018-11-04T23:47:31.855Z,1541375251.855 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2018-11-04T23:47:31.856Z,1541375251.856 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408BF4E0
2018-11-04T23:47:31.856Z,1541375251.856 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 884
2018-11-04T23:47:34.177Z,1541375254.177 [BPC1] Loaded
2018-11-04T23:47:34.177Z,1541375254.177 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-11-04T23:47:34.178Z,1541375254.178 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-11-04T23:47:34.178Z,1541375254.178 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-11-04T23:47:34.349Z,1541375254.349 [SBIT](DEBUG): Construct Startup Built In Test.
2018-11-04T23:47:34.373Z,1541375254.373 [SBIT] Loaded
2018-11-04T23:47:34.373Z,1541375254.373 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-11-04T23:47:34.374Z,1541375254.374 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-11-04T23:47:34.385Z,1541375254.385 [IBIT] Loaded
2018-11-04T23:47:34.386Z,1541375254.386 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-11-04T23:47:34.389Z,1541375254.389 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-11-04T23:47:34.547Z,1541375254.547 [CBIT] Loaded
2018-11-04T23:47:34.547Z,1541375254.547 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-11-04T23:47:34.547Z,1541375254.547 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-11-04T23:47:34.548Z,1541375254.548 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-11-04T23:47:34.773Z,1541375254.773 [Aanderaa_O2] Loaded
2018-11-04T23:47:34.773Z,1541375254.773 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-11-04T23:47:34.861Z,1541375254.861 [CTD_NeilBrown] Loaded
2018-11-04T23:47:34.861Z,1541375254.861 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-11-04T23:47:34.863Z,1541375254.862 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4098A4E0
2018-11-04T23:47:34.863Z,1541375254.863 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 885
2018-11-04T23:47:34.922Z,1541375254.922 [CTD_Seabird] Loaded
2018-11-04T23:47:34.922Z,1541375254.922 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-11-04T23:47:34.923Z,1541375254.923 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409BA4E0
2018-11-04T23:47:34.924Z,1541375254.924 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 886
2018-11-04T23:47:34.939Z,1541375254.939 [PAR_Licor] Loaded
2018-11-04T23:47:34.939Z,1541375254.939 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-11-04T23:47:34.991Z,1541375254.991 [WetLabsBB2FL] Loaded
2018-11-04T23:47:34.992Z,1541375254.992 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-11-04T23:47:34.993Z,1541375254.993 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409EA4E0
2018-11-04T23:47:34.993Z,1541375254.993 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 887
2018-11-04T23:47:34.994Z,1541375254.994 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-11-04T23:47:34.996Z,1541375254.996 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-11-04T23:47:35.092Z,1541375255.092 [VerticalControl](DEBUG): Construct VerticalControl.
2018-11-04T23:47:35.180Z,1541375255.180 [VerticalControl] Loaded
2018-11-04T23:47:35.181Z,1541375255.181 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-11-04T23:47:35.181Z,1541375255.181 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-11-04T23:47:35.243Z,1541375255.243 [HorizontalControl] Loaded
2018-11-04T23:47:35.243Z,1541375255.243 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-11-04T23:47:35.244Z,1541375255.244 [SpeedControl](DEBUG): Construct SpeedControl.
2018-11-04T23:47:35.245Z,1541375255.245 [SpeedControl] Loaded
2018-11-04T23:47:35.246Z,1541375255.246 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-11-04T23:47:35.246Z,1541375255.246 [LoopControl](DEBUG): Construct LoopControl.
2018-11-04T23:47:35.247Z,1541375255.247 [LoopControl] Loaded
2018-11-04T23:47:35.247Z,1541375255.247 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-11-04T23:47:35.248Z,1541375255.248 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-11-04T23:47:35.249Z,1541375255.249 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-11-04T23:47:35.289Z,1541375255.289 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-11-04T23:47:35.290Z,1541375255.290 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-11-04T23:47:35.401Z,1541375255.401 [DeadReckonUsingSpeedCalculator] Loaded
2018-11-04T23:47:35.401Z,1541375255.401 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-11-04T23:47:35.418Z,1541375255.418 [NavChart] Loaded
2018-11-04T23:47:35.419Z,1541375255.419 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-11-04T23:47:35.423Z,1541375255.423 [UniversalFixResidualReporter] Loaded
2018-11-04T23:47:35.423Z,1541375255.423 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-11-04T23:47:35.423Z,1541375255.423 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-11-04T23:47:35.427Z,1541375255.427 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-11-04T23:47:35.428Z,1541375255.428 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-11-04T23:47:35.435Z,1541375255.435 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-11-04T23:47:35.436Z,1541375255.436 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A764E0
2018-11-04T23:47:35.436Z,1541375255.436 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 888
2018-11-04T23:47:35.441Z,1541375255.441 [Supervisor](INFO): Main Thread ID is 797
2018-11-04T23:47:35.441Z,1541375255.441 [Supervisor](DEBUG): Running supervisor.
2018-11-04T23:47:35.442Z,1541375255.442 [CommandLine ThreadHandler](INFO): Handler Thread ID is 889
2018-11-04T23:47:35.444Z,1541375255.444 [controlThread ThreadHandler](INFO): Handler Thread ID is 890
2018-11-04T23:47:35.444Z,1541375255.444 [controlThread](DEBUG): Initializing ControlThread
2018-11-04T23:47:35.445Z,1541375255.445 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-04T23:47:35.445Z,1541375255.445 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-11-04T23:47:35.446Z,1541375255.446 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-11-04T23:47:35.446Z,1541375255.446 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-11-04T23:47:35.447Z,1541375255.447 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-11-04T23:47:35.447Z,1541375255.447 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-11-04T23:47:35.455Z,1541375255.455 [SBIT](INFO): Initialize SBIT Component.
2018-11-04T23:47:35.456Z,1541375255.456 [SBIT](IMPORTANT): git: 2018-11-02
2018-11-04T23:47:35.456Z,1541375255.456 [SBIT](INFO): git hash: 766718804c5d96cf896f07eddb44b232c8585615
2018-11-04T23:47:35.457Z,1541375255.457 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-11-04T23:47:35.457Z,1541375255.457 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-11-04T23:47:35.458Z,1541375255.458 [SBIT](INFO): Beginning SBIT in 23.000000 seconds.
2018-11-04T23:47:35.459Z,1541375255.459 [IBIT](INFO): Initialize IBIT Component.
2018-11-04T23:47:35.459Z,1541375255.459 [CBIT](DEBUG): Initialize CBIT Component.
2018-11-04T23:47:35.460Z,1541375255.460 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2018-11-04T23:47:35.460Z,1541375255.460 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2018-11-04T23:47:35.461Z,1541375255.461 [logger ThreadHandler](INFO): Handler Thread ID is 891
2018-11-04T23:47:35.477Z,1541375255.477 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 892
2018-11-04T23:47:35.483Z,1541375255.483 [Radio_Surface](INFO): Powering up
2018-11-04T23:47:35.489Z,1541375255.489 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 893
2018-11-04T23:47:35.490Z,1541375255.490 [Rowe_600LCM](INFO): Initializing
2018-11-04T23:47:35.490Z,1541375255.490 [Rowe_600LCM](INFO): Checking LCM
2018-11-04T23:47:35.572Z,1541375255.572 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 894
2018-11-04T23:47:35.585Z,1541375255.585 [CTD_NeilBrown](INFO): Powering down
2018-11-04T23:47:35.609Z,1541375255.609 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-11-04T23:47:35.611Z,1541375255.611 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-11-04T23:47:35.612Z,1541375255.612 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-11-04T23:47:35.612Z,1541375255.612 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-11-04T23:47:35.613Z,1541375255.613 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 895
2018-11-04T23:47:35.614Z,1541375255.614 [CTD_Seabird](INFO): Initializing
2018-11-04T23:47:35.614Z,1541375255.615 [CTD_Seabird](INFO): Checking LCM
2018-11-04T23:47:35.616Z,1541375255.616 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-04T23:47:35.616Z,1541375255.616 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-04T23:47:35.621Z,1541375255.621 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-04T23:47:35.624Z,1541375255.624 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-11-04T23:47:35.625Z,1541375255.625 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-11-04T23:47:35.626Z,1541375255.626 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-11-04T23:47:35.717Z,1541375255.717 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 896
2018-11-04T23:47:35.730Z,1541375255.730 [WetLabsBB2FL](INFO): Powering down
2018-11-04T23:47:35.762Z,1541375255.762 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 897
2018-11-04T23:47:35.770Z,1541375255.770 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-11-04T23:47:35.771Z,1541375255.771 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-11-04T23:47:35.771Z,1541375255.771 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-11-04T23:47:35.771Z,1541375255.771 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-11-04T23:47:35.771Z,1541375255.771 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-11-04T23:47:35.771Z,1541375255.771 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-11-04T23:47:35.772Z,1541375255.772 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-11-04T23:47:35.772Z,1541375255.772 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-11-04T23:47:35.772Z,1541375255.772 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-11-04T23:47:35.772Z,1541375255.772 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-11-04T23:47:35.772Z,1541375255.772 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-11-04T23:47:35.773Z,1541375255.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-11-04T23:47:35.773Z,1541375255.773 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-11-04T23:47:35.773Z,1541375255.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-11-04T23:47:35.773Z,1541375255.773 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-11-04T23:47:35.773Z,1541375255.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-11-04T23:47:35.775Z,1541375255.775 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-04T23:47:35.873Z,1541375255.873 [MissionManager](DEBUG):
2018-11-04T23:47:35.886Z,1541375255.886 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-11-04T23:47:35.955Z,1541375255.955 [CTD_Seabird](INFO): LCM OK
2018-11-04T23:47:35.955Z,1541375255.955 [CTD_Seabird](INFO): Powering up
2018-11-04T23:47:35.955Z,1541375255.955 [Rowe_600LCM](INFO): LCM OK
2018-11-04T23:47:35.955Z,1541375255.955 [Rowe_600LCM](INFO): Powering up
2018-11-04T23:47:35.992Z,1541375255.992 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-11-04T23:47:35.994Z,1541375255.994 [Default:A.Wait](DEBUG): Construct Wait.
2018-11-04T23:47:35.995Z,1541375255.995 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-11-04T23:47:36.057Z,1541375256.057 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-11-04T23:47:36.059Z,1541375256.059 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-11-04T23:47:36.080Z,1541375256.080 [Default:E.Execute](DEBUG): Construct Execute.
2018-11-04T23:47:36.104Z,1541375256.104 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2018-11-04T23:47:36.109Z,1541375256.109 [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,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-11-04T23:47:36.142Z,1541375256.142 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-11-04T23:47:36.174Z,1541375256.174 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-11-04T23:47:36.332Z,1541375256.332 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-11-04T23:47:36.633Z,1541375256.633 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:36.637Z,1541375256.637 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-04T23:47:36.660Z,1541375256.660 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:36.665Z,1541375256.665 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-11-04T23:47:36.682Z,1541375256.682 [MassServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:36.689Z,1541375256.689 [MassServo](DEBUG): Initializing MassServo.
2018-11-04T23:47:36.711Z,1541375256.711 [RudderServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:36.717Z,1541375256.717 [RudderServo](DEBUG): Initializing RudderServo.
2018-11-04T23:47:36.742Z,1541375256.742 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:36.749Z,1541375256.749 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-11-04T23:47:36.767Z,1541375256.767 [CommandLine](FAULT): Scheduling is paused
2018-11-04T23:47:36.768Z,1541375256.768 [CBIT](INFO): Critical error at 20181104T234735
2018-11-04T23:47:36.768Z,1541375256.768 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-11-04T23:47:37.581Z,1541375257.581 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-11-04T23:47:37.581Z,1541375257.581 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-11-04T23:47:37.581Z,1541375257.581 [BuoyancyServo] Communications Fault, FailCount= 1
2018-11-04T23:47:37.581Z,1541375257.581 [BuoyancyServo](ERROR): Communications Fault
2018-11-04T23:47:37.796Z,1541375257.796 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-11-04T23:47:37.893Z,1541375257.893 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-04T23:47:37.894Z,1541375257.894 [BuoyancyServo](INFO): Powering down
2018-11-04T23:47:39.557Z,1541375259.557 [Aanderaa_O2](INFO): Powering down
2018-11-04T23:47:39.816Z,1541375259.816 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-11-04T23:47:39.968Z,1541375259.968 [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-11-04T23:47:40.114Z,1541375260.114 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-11-04T23:47:40.114Z,1541375260.114 [BuoyancyServo] No Fault, FailCount= 1
2018-11-04T23:47:40.143Z,1541375260.143 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-11-04T23:47:40.144Z,1541375260.144 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-11-04T23:47:40.144Z,1541375260.144 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-11-04T23:47:40.318Z,1541375260.318 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-11-04T23:47:40.319Z,1541375260.319 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-11-04T23:47:41.227Z,1541375261.227 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-04T23:47:41.547Z,1541375261.547 [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-11-04T23:47:41.549Z,1541375261.549 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd
2018-11-04T23:47:42.355Z,1541375262.355 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-04T23:47:42.355Z,1541375262.355 [CTD_Seabird](INFO): Powering down
2018-11-04T23:47:58.899Z,1541375278.899 [SBIT](IMPORTANT): Beginning Startup BIT
2018-11-04T23:47:58.904Z,1541375278.904 [CBIT](IMPORTANT): Beginning ground fault scan
2018-11-04T23:48:01.763Z,1541375281.763 [NAL9602](INFO): Powering up NAL9602
2018-11-04T23:48:09.850Z,1541375289.850 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.003944
CHAN A1 (24V): -0.009136
CHAN A2 (12V): -0.001804
CHAN A3 (5V): -0.001937
CHAN B0 (3.3V): 0.000228
CHAN B1 (3.15aV): -0.000608
CHAN B2 (3.15bV): 0.000064
CHAN B3 (GND): -0.000127
OPEN: -0.000438
Full Scale Calc: 4.765 mA, -1.589 mA
2018-11-04T23:48:12.975Z,1541375292.975 [NAL9602](INFO): NAL9602 initialized
2018-11-04T23:48:52.732Z,1541375332.732 [SBIT](IMPORTANT): SBIT PASSED
2018-11-04T23:48:52.785Z,1541375332.785 [CommandLine](IMPORTANT): got command configSet list
2018-11-04T23:48:52.785Z,1541375332.785 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-11-04T23:48:52.789Z,1541375332.789 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=28 count;
2018-11-04T23:48:52.789Z,1541375332.789 [CommandLine](IMPORTANT): BPC1.batteryMuxCycleTime=10 minute;
2018-11-04T23:48:52.789Z,1541375332.789 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=1 minute;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=1 bool;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=1 bool;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool;
2018-11-04T23:48:52.790Z,1541375332.790 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=213 cubic_centimeter;
2018-11-04T23:48:52.791Z,1541375332.791 [CommandLine](IMPORTANT): VerticalControl.massDefault=4 millimeter;
2018-11-04T23:48:53.106Z,1541375333.106 [MissionManager](IMPORTANT): Started mission Startup
2018-11-04T23:48:53.106Z,1541375333.106 [Startup] Running Loop=1
2018-11-04T23:48:53.106Z,1541375333.106 [Startup](DEBUG): Aggregate::initialize Startup
2018-11-04T23:48:53.106Z,1541375333.106 [Startup:A.GoToSurface] Running Loop=1
2018-11-04T23:48:53.106Z,1541375333.106 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-04T23:48:53.107Z,1541375333.107 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-04T23:48:53.107Z,1541375333.107 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-04T23:48:53.108Z,1541375333.108 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-04T23:48:53.108Z,1541375333.108 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-04T23:48:53.109Z,1541375333.109 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-04T23:48:53.123Z,1541375333.123 [Startup:StartupSatComms] Running Loop=1
2018-11-04T23:48:53.124Z,1541375333.124 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-11-04T23:48:53.124Z,1541375333.124 [Startup:StartupSatComms:A] Running Loop=1
2018-11-04T23:48:53.493Z,1541375333.493 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-11-04T23:49:53.511Z,1541375393.511 [Startup:StartupSatComms:A](INFO): Timed out from 2018-11-04T23:48:53.1Z
2018-11-04T23:49:53.511Z,1541375393.511 [Startup:StartupSatComms:A] Stopped
2018-11-04T23:49:53.511Z,1541375393.511 [Startup:StartupSatComms:B] Running Loop=1
2018-11-04T23:49:53.835Z,1541375393.835 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-04T23:50:08.788Z,1541375408.788 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005326
2018-11-04T23:50:13.515Z,1541375413.515 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181102T233339/Courier0010.lzma
2018-11-04T23:50:14.307Z,1541375414.307 [DataOverHttps](INFO): Moved sent file to Logs/20181102T233339/Courier0010.lzma.bak
2018-11-04T23:50:14.307Z,1541375414.307 [DataOverHttps](INFO): SBD MOMSN=8791213
2018-11-04T23:50:24.328Z,1541375424.328 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20181104T230822/Courier0000.lzma
2018-11-04T23:50:25.095Z,1541375425.095 [DataOverHttps](INFO): Moved sent file to Logs/20181104T230822/Courier0000.lzma.bak
2018-11-04T23:50:25.096Z,1541375425.096 [DataOverHttps](INFO): SBD MOMSN=8791215
2018-11-04T23:50:35.379Z,1541375435.379 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20181104T231058/Courier0000.lzma
2018-11-04T23:50:35.860Z,1541375435.860 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-11-04T23:50:35.865Z,1541375435.865 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-11-04T23:50:35.865Z,1541375435.865 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-11-04T23:50:35.895Z,1541375435.895 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-11-04T23:50:36.159Z,1541375436.159 [DataOverHttps](INFO): Moved sent file to Logs/20181104T231058/Courier0000.lzma.bak
2018-11-04T23:50:36.159Z,1541375436.159 [DataOverHttps](INFO): SBD MOMSN=8791222
2018-11-04T23:50:36.279Z,1541375436.279 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-11-04T23:50:36.279Z,1541375436.279 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-11-04T23:50:36.774Z,1541375436.774 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-11-04T23:50:36.775Z,1541375436.775 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-11-04T23:50:36.775Z,1541375436.775 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-11-04T23:50:37.094Z,1541375437.094 [CommandLine](IMPORTANT): got command failComponent
2018-11-04T23:50:37.095Z,1541375437.095 [CommandLine](IMPORTANT): Failed components:
2018-11-04T23:50:37.095Z,1541375437.095 [CommandLine](IMPORTANT): No failed Components.
2018-11-04T23:50:46.520Z,1541375446.520 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20181104T232750/Courier0000.lzma
2018-11-04T23:50:47.311Z,1541375447.311 [DataOverHttps](INFO): Moved sent file to Logs/20181104T232750/Courier0000.lzma.bak
2018-11-04T23:50:47.311Z,1541375447.311 [DataOverHttps](INFO): SBD MOMSN=8791229
2018-11-04T23:50:49.565Z,1541375449.565 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time.
2018-11-04T23:50:49.565Z,1541375449.565 [Rowe_600LCM] Communications Fault, FailCount= 1
2018-11-04T23:50:49.565Z,1541375449.565 [Rowe_600LCM](ERROR): Communications Fault
2018-11-04T23:50:49.969Z,1541375449.969 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-11-04T23:50:50.102Z,1541375450.102 [Rowe_600LCM](INFO): Powering down
2018-11-04T23:50:51.651Z,1541375451.651 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM
2018-11-04T23:50:51.651Z,1541375451.651 [CBIT](INFO): Clearing failed state for component Rowe_600LCM
2018-11-04T23:50:51.651Z,1541375451.651 [Rowe_600LCM] No Fault, FailCount= 1
2018-11-04T23:50:51.717Z,1541375451.717 [Rowe_600LCM](INFO): Initializing
2018-11-04T23:50:51.718Z,1541375451.718 [Rowe_600LCM](INFO): Checking LCM
2018-11-04T23:50:51.718Z,1541375451.718 [Rowe_600LCM](INFO): LCM OK
2018-11-04T23:50:51.718Z,1541375451.718 [Rowe_600LCM](INFO): Powering up
2018-11-04T23:50:55.903Z,1541375455.903 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2018-11-04T23:50:56.012Z,1541375456.012 [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-11-04T23:50:56.013Z,1541375456.013 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2018-11-04T23:50:56.014Z,1541375456.014 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2018-11-04T23:50:56.015Z,1541375456.015 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2018-11-04T23:50:56.823Z,1541375456.823 [Startup:StartupSatComms:B](INFO): Timed out from 2018-11-04T23:49:53.5Z
2018-11-04T23:50:56.823Z,1541375456.823 [Startup:StartupSatComms:B] Stopped
2018-11-04T23:50:56.823Z,1541375456.823 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-11-04T23:50:56.824Z,1541375456.824 [Startup:StartupSatComms] Stopped
2018-11-04T23:50:56.824Z,1541375456.824 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-11-04T23:50:56.849Z,1541375456.849 [Startup](INFO): Completed Startup
2018-11-04T23:50:56.850Z,1541375456.850 [MissionManager](INFO): Startup is completed.
2018-11-04T23:50:56.850Z,1541375456.850 [MissionManager](INFO): Uninitializing Mission Startup
2018-11-04T23:50:56.850Z,1541375456.850 [Startup] Stopped
2018-11-04T23:50:56.850Z,1541375456.850 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-11-04T23:50:56.850Z,1541375456.850 [Startup:A.GoToSurface] Stopped
2018-11-04T23:50:56.850Z,1541375456.850 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-04T23:50:56.921Z,1541375456.921 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20181104T232750/Courier0004.lzma
2018-11-04T23:50:56.999Z,1541375456.999 [MissionManager](IMPORTANT): Started mission Default
2018-11-04T23:50:56.999Z,1541375456.999 [Default] Running Loop=1
2018-11-04T23:50:56.000Z,1541375457.000 [Default](DEBUG): Aggregate::initialize Default
2018-11-04T23:50:56.000Z,1541375457.000 [Default:B.GoToSurface] Running Loop=1
2018-11-04T23:50:56.000Z,1541375457.000 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-11-04T23:50:57.000Z,1541375457.000 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-11-04T23:50:57.000Z,1541375457.000 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-11-04T23:50:57.005Z,1541375457.005 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-11-04T23:50:57.005Z,1541375457.005 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-11-04T23:50:57.006Z,1541375457.006 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-11-04T23:50:57.006Z,1541375457.006 [Default:A.Wait] Running Loop=1
2018-11-04T23:50:57.006Z,1541375457.006 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-11-04T23:50:57.721Z,1541375457.721 [DataOverHttps](INFO): Moved sent file to Logs/20181104T232750/Courier0004.lzma.bak
2018-11-04T23:50:57.722Z,1541375457.722 [DataOverHttps](INFO): SBD MOMSN=8791234
2018-11-04T23:51:10.383Z,1541375470.383 [Default:A.Wait](INFO): Done Waiting.
2018-11-04T23:51:10.383Z,1541375470.383 [Default:A.Wait] Stopped
2018-11-04T23:51:10.383Z,1541375470.383 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-11-04T23:51:10.795Z,1541375470.795 [Default:CheckIn] Running Loop=1
2018-11-04T23:51:10.795Z,1541375470.795 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-11-04T23:51:10.795Z,1541375470.795 [Default:CheckIn:Read_GPS] Running Loop=1
2018-11-04T23:51:11.183Z,1541375471.183 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-11-04T23:51:34.398Z,1541375494.398 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2018-11-04T23:53:16.303Z,1541375596.303 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-11-04T23:53:23.907Z,1541375603.907 [NAL9602](INFO): GPS fix at 20181104T235305: (36.802734, -121.787967)
2018-11-04T23:53:23.991Z,1541375603.991 [Default:CheckIn:Read_GPS] Stopped
2018-11-04T23:53:23.991Z,1541375603.991 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-11-04T23:53:24.368Z,1541375604.368 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-11-04T23:53:31.624Z,1541375611.624 [DataOverHttps](INFO): Sending 268 bytes from file Logs/20181104T233349/Courier0000.lzma
2018-11-04T23:53:32.424Z,1541375612.424 [DataOverHttps](INFO): Moved sent file to Logs/20181104T233349/Courier0000.lzma.bak
2018-11-04T23:53:32.424Z,1541375612.424 [DataOverHttps](INFO): SBD MOMSN=8791236
2018-11-04T23:53:43.178Z,1541375623.178 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20181104T233349/Courier0004.lzma
2018-11-04T23:53:43.948Z,1541375623.948 [DataOverHttps](INFO): Moved sent file to Logs/20181104T233349/Courier0004.lzma.bak
2018-11-04T23:53:43.948Z,1541375623.948 [DataOverHttps](INFO): SBD MOMSN=8791241
2018-11-04T23:53:54.529Z,1541375634.529 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20181104T234723/Courier0000.lzma
2018-11-04T23:53:55.299Z,1541375635.299 [DataOverHttps](INFO): Moved sent file to Logs/20181104T234723/Courier0000.lzma.bak
2018-11-04T23:53:55.299Z,1541375635.299 [DataOverHttps](INFO): SBD MOMSN=8791246
2018-11-04T23:54:05.142Z,1541375645.142 [NAL9602](INFO): Powering down
2018-11-04T23:54:05.320Z,1541375645.320 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20181104T234723/Courier0004.lzma
2018-11-04T23:54:06.083Z,1541375646.083 [DataOverHttps](INFO): Moved sent file to Logs/20181104T234723/Courier0004.lzma.bak
2018-11-04T23:54:06.083Z,1541375646.083 [DataOverHttps](INFO): SBD MOMSN=8791250
2018-11-04T23:54:16.278Z,1541375656.278 [DataOverHttps](INFO): Sending 166 bytes from file Logs/20181102T233339/Express0011.lzma
2018-11-04T23:54:17.075Z,1541375657.075 [DataOverHttps](INFO): Moved sent file to Logs/20181102T233339/Express0011.lzma.bak
2018-11-04T23:54:17.076Z,1541375657.076 [DataOverHttps](INFO): SBD MOMSN=8791253
2018-11-04T23:54:25.074Z,1541375665.074 [CommandLine](IMPORTANT): got command failComponent
2018-11-04T23:54:25.074Z,1541375665.074 [CommandLine](IMPORTANT): Failed components:
2018-11-04T23:54:25.074Z,1541375665.074 [CommandLine](IMPORTANT): No failed Components.
2018-11-04T23:54:27.219Z,1541375667.219 [DataOverHttps](INFO): Sending 387 bytes from file Logs/20181104T230119/Express0001.lzma
2018-11-04T23:54:28.019Z,1541375668.019 [DataOverHttps](INFO): Moved sent file to Logs/20181104T230119/Express0001.lzma.bak
2018-11-04T23:54:28.019Z,1541375668.019 [DataOverHttps](INFO): SBD MOMSN=8791257
2018-11-04T23:54:29.230Z,1541375669.230 [CommandLine](IMPORTANT): got command quit
2018-11-04T23:54:30.240Z,1541375670.240 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:30.240Z,1541375670.240 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.307Z,1541375670.307 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2018-11-04T23:54:30.307Z,1541375670.307 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.308Z,1541375670.308 [CommandLine](INFO): Join timeout helper Thread ID is 935
2018-11-04T23:54:30.321Z,1541375670.321 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-11-04T23:54:30.321Z,1541375670.321 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.322Z,1541375670.322 [NavChartDb](INFO): Join timeout helper Thread ID is 936
2018-11-04T23:54:30.701Z,1541375670.701 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:30.701Z,1541375670.701 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.705Z,1541375670.705 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-11-04T23:54:30.705Z,1541375670.705 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.706Z,1541375670.706 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 937
2018-11-04T23:54:30.897Z,1541375670.897 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:30.897Z,1541375670.897 [WetLabsBB2FL](INFO): Powering down
2018-11-04T23:54:30.898Z,1541375670.898 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.917Z,1541375670.917 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-11-04T23:54:30.917Z,1541375670.917 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:30.917Z,1541375670.917 [CTD_Seabird](INFO): Join timeout helper Thread ID is 938
2018-11-04T23:54:31.073Z,1541375671.073 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:31.228Z,1541375671.228 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-11-04T23:54:31.229Z,1541375671.229 [CTD_Seabird](INFO): Powering down
2018-11-04T23:54:31.230Z,1541375671.230 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:31.249Z,1541375671.249 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-11-04T23:54:31.249Z,1541375671.249 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:31.250Z,1541375671.250 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 940
2018-11-04T23:54:31.625Z,1541375671.625 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:31.625Z,1541375671.625 [CTD_NeilBrown](INFO): Powering down
2018-11-04T23:54:31.626Z,1541375671.626 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:31.630Z,1541375671.630 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2018-11-04T23:54:31.630Z,1541375671.630 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:31.631Z,1541375671.631 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 941
2018-11-04T23:54:31.833Z,1541375671.833 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:31.833Z,1541375671.833 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2018-11-04T23:54:32.000Z,1541375672.000 [Rowe_600LCM](INFO): Powering down
2018-11-04T23:54:32.002Z,1541375672.002 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.012Z,1541375672.012 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-11-04T23:54:32.012Z,1541375672.012 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.013Z,1541375672.013 [Radio_Surface](INFO): Join timeout helper Thread ID is 943
2018-11-04T23:54:32.301Z,1541375672.301 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:32.301Z,1541375672.301 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.314Z,1541375672.314 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-11-04T23:54:32.314Z,1541375672.314 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.314Z,1541375672.314 [logger](INFO): Join timeout helper Thread ID is 944
2018-11-04T23:54:32.357Z,1541375672.357 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:32.357Z,1541375672.357 [logger ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.366Z,1541375672.366 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-11-04T23:54:32.366Z,1541375672.366 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.366Z,1541375672.366 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-11-04T23:54:32.366Z,1541375672.366 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.367Z,1541375672.367 [controlThread](INFO): Join timeout helper Thread ID is 945
2018-11-04T23:54:32.733Z,1541375672.733 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-11-04T23:54:32.733Z,1541375672.733 [controlThread](DEBUG): Uninitializing ControlThread
2018-11-04T23:54:32.739Z,1541375672.739 [NAL9602](INFO): Powering down
2018-11-04T23:54:32.741Z,1541375672.741 [PNI_TCM](INFO): Powering down
2018-11-04T23:54:32.830Z,1541375672.830 [Aanderaa_O2](INFO): Powering down
2018-11-04T23:54:32.831Z,1541375672.831 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-11-04T23:54:32.832Z,1541375672.832 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-11-04T23:54:32.833Z,1541375672.833 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-11-04T23:54:32.833Z,1541375672.833 [MissionManager](INFO): Uninitializing Mission Default
2018-11-04T23:54:32.833Z,1541375672.833 [Default] Stopped
2018-11-04T23:54:32.834Z,1541375672.834 [Default](DEBUG): Aggregate::uninitialize Default
2018-11-04T23:54:32.834Z,1541375672.834 [Default:B.GoToSurface] Stopped
2018-11-04T23:54:32.834Z,1541375672.834 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-11-04T23:54:32.834Z,1541375672.834 [Default:CheckIn] Stopped
2018-11-04T23:54:32.834Z,1541375672.834 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-11-04T23:54:32.834Z,1541375672.834 [Default:CheckIn:Read_Iridium] Stopped
2018-11-04T23:54:32.838Z,1541375672.838 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-11-04T23:54:32.838Z,1541375672.838 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-11-04T23:54:32.838Z,1541375672.838 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-11-04T23:54:32.839Z,1541375672.839 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-11-04T23:54:32.839Z,1541375672.839 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-11-04T23:54:32.839Z,1541375672.839 [BuoyancyServo](INFO): Powering down
2018-11-04T23:54:32.853Z,1541375672.853 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2018-11-04T23:54:32.853Z,1541375672.853 [ElevatorServo](INFO): Powering down
2018-11-04T23:54:32.854Z,1541375672.854 [MassServo](DEBUG): Uninitialize Mass Servo.
2018-11-04T23:54:32.854Z,1541375672.854 [MassServo](INFO): Powering down
2018-11-04T23:54:32.855Z,1541375672.855 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2018-11-04T23:54:32.855Z,1541375672.855 [RudderServo](INFO): Powering down
2018-11-04T23:54:32.856Z,1541375672.856 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2018-11-04T23:54:32.856Z,1541375672.856 [ThrusterServo](INFO): Powering down
2018-11-04T23:54:32.857Z,1541375672.857 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-11-04T23:54:32.857Z,1541375672.857 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-11-04T23:54:32.858Z,1541375672.858 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-11-04T23:54:32.859Z,1541375672.859 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.978Z,1541375672.978 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:32.984Z,1541375672.984 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:33.023Z,1541375673.023 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:33.027Z,1541375673.027 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:33.029Z,1541375673.029 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:33.056Z,1541375673.056 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-11-04T23:54:33.128Z,1541375673.128 [logger ThreadHandler](INFO): Thread cancelled.