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.