2018-10-09T16:22:11.096Z,1539102131.096 [Supervisor](DEBUG): Initializing supervisor. 2018-10-09T16:22:11.098Z,1539102131.098 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-10-09T16:22:11.099Z,1539102131.099 [SyncHandler](INFO): Protected caller Thread ID is 798 2018-10-09T16:22:11.099Z,1539102131.099 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-10-09T16:22:11.100Z,1539102131.100 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-10-09T16:22:11.101Z,1539102131.101 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 799 2018-10-09T16:22:11.103Z,1539102131.103 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-10-09T16:22:11.115Z,1539102131.115 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-10-09T16:22:11.116Z,1539102131.116 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-10-09T16:22:11.116Z,1539102131.116 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 800 2018-10-09T16:22:11.117Z,1539102131.117 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-10-09T16:22:11.118Z,1539102131.118 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-10-09T16:22:11.118Z,1539102131.118 [logger ThreadHandler](INFO): Protected caller Thread ID is 801 2018-10-09T16:22:11.120Z,1539102131.120 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-10-09T16:22:11.120Z,1539102131.120 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-10-09T16:22:11.124Z,1539102131.124 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-10-09T16:22:11.481Z,1539102131.481 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-10-09T16:22:11.483Z,1539102131.483 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-10-09T16:22:11.690Z,1539102131.690 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-10-09T16:22:11.692Z,1539102131.692 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-10-09T16:22:12.006Z,1539102132.006 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-10-09T16:22:12.007Z,1539102132.007 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-10-09T16:22:12.159Z,1539102132.159 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-10-09T16:22:12.160Z,1539102132.160 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-10-09T16:22:12.260Z,1539102132.260 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-10-09T16:22:12.262Z,1539102132.262 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-10-09T16:22:12.740Z,1539102132.740 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-10-09T16:22:12.742Z,1539102132.742 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-10-09T16:22:13.217Z,1539102133.217 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-10-09T16:22:13.218Z,1539102133.218 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-10-09T16:22:13.697Z,1539102133.697 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-10-09T16:22:13.698Z,1539102133.698 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-10-09T16:22:13.804Z,1539102133.804 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-10-09T16:22:13.805Z,1539102133.805 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-10-09T16:22:13.903Z,1539102133.903 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-10-09T16:22:13.905Z,1539102133.905 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-10-09T16:22:14.127Z,1539102134.127 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-10-09T16:22:14.128Z,1539102134.128 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-10-09T16:22:14.338Z,1539102134.338 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-10-09T16:22:14.339Z,1539102134.339 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-10-09T16:22:14.699Z,1539102134.699 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-10-09T16:22:14.699Z,1539102134.699 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-10-09T16:22:14.857Z,1539102134.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-10-09T16:22:14.857Z,1539102134.857 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-10-09T16:22:15.034Z,1539102135.034 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2018-10-09T16:22:15.862Z,1539102135.862 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2018-10-09T16:22:15.970Z,1539102135.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2018-10-09T16:22:16.091Z,1539102136.091 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2018-10-09T16:22:16.188Z,1539102136.188 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2018-10-09T16:22:16.274Z,1539102136.274 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2018-10-09T16:22:16.445Z,1539102136.445 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2018-10-09T16:22:16.632Z,1539102136.632 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2018-10-09T16:22:16.709Z,1539102136.709 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2018-10-09T16:22:16.943Z,1539102136.943 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2018-10-09T16:22:16.944Z,1539102136.944 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2018-10-09T16:22:17.029Z,1539102137.029 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2018-10-09T16:22:17.122Z,1539102137.122 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2018-10-09T16:22:17.226Z,1539102137.226 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2018-10-09T16:22:17.356Z,1539102137.356 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2018-10-09T16:22:17.359Z,1539102137.359 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-10-09T16:22:17.664Z,1539102137.664 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-10-09T16:22:17.666Z,1539102137.666 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-10-09T16:22:17.772Z,1539102137.772 [DepthRateCalculator] Loaded 2018-10-09T16:22:17.772Z,1539102137.772 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-10-09T16:22:17.778Z,1539102137.778 [PitchRateCalculator] Loaded 2018-10-09T16:22:17.778Z,1539102137.778 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-10-09T16:22:17.794Z,1539102137.794 [SpeedCalculator] Loaded 2018-10-09T16:22:17.795Z,1539102137.795 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-10-09T16:22:17.816Z,1539102137.816 [TempGradientCalculator] Loaded 2018-10-09T16:22:17.816Z,1539102137.816 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-10-09T16:22:17.821Z,1539102137.821 [YawRateCalculator] Loaded 2018-10-09T16:22:17.822Z,1539102137.822 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-10-09T16:22:17.861Z,1539102137.861 [ElevatorOffsetCalculator] Loaded 2018-10-09T16:22:17.861Z,1539102137.861 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-10-09T16:22:17.861Z,1539102137.861 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-10-09T16:22:17.862Z,1539102137.862 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-10-09T16:22:17.965Z,1539102137.965 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-10-09T16:22:17.966Z,1539102137.966 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-10-09T16:22:18.097Z,1539102138.097 [BuoyancyServo] Loaded 2018-10-09T16:22:18.097Z,1539102138.097 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-10-09T16:22:18.111Z,1539102138.111 [ElevatorServo] Loaded 2018-10-09T16:22:18.112Z,1539102138.112 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-10-09T16:22:18.126Z,1539102138.126 [MassServo] Loaded 2018-10-09T16:22:18.126Z,1539102138.126 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-10-09T16:22:18.141Z,1539102138.141 [RudderServo] Loaded 2018-10-09T16:22:18.142Z,1539102138.142 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-10-09T16:22:18.156Z,1539102138.156 [ThrusterServo] Loaded 2018-10-09T16:22:18.156Z,1539102138.156 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-10-09T16:22:18.156Z,1539102138.156 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-10-09T16:22:18.157Z,1539102138.157 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-10-09T16:22:18.181Z,1539102138.181 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-10-09T16:22:18.181Z,1539102138.181 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-10-09T16:22:18.305Z,1539102138.305 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-10-09T16:22:18.306Z,1539102138.306 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-10-09T16:22:18.873Z,1539102138.873 [DataOverHttps] Loaded 2018-10-09T16:22:18.873Z,1539102138.873 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-10-09T16:22:18.886Z,1539102138.886 [Depth_Keller] Loaded 2018-10-09T16:22:18.886Z,1539102138.886 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-10-09T16:22:18.891Z,1539102138.891 [DropWeight] Loaded 2018-10-09T16:22:18.891Z,1539102138.891 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2018-10-09T16:22:18.988Z,1539102138.988 [NAL9602] Loaded 2018-10-09T16:22:18.988Z,1539102138.988 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-10-09T16:22:19.004Z,1539102139.004 [Onboard] Loaded 2018-10-09T16:22:19.004Z,1539102139.004 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-10-09T16:22:19.014Z,1539102139.014 [Radio_Surface] Loaded 2018-10-09T16:22:19.014Z,1539102139.014 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-10-09T16:22:19.016Z,1539102139.016 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0 2018-10-09T16:22:19.016Z,1539102139.016 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 884 2018-10-09T16:22:19.168Z,1539102139.168 [PNI_TCM] Loaded 2018-10-09T16:22:19.168Z,1539102139.168 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread. 2018-10-09T16:22:19.227Z,1539102139.227 [Rowe_600LCM] Loaded 2018-10-09T16:22:19.228Z,1539102139.228 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread. 2018-10-09T16:22:19.229Z,1539102139.229 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408BF4E0 2018-10-09T16:22:19.229Z,1539102139.229 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 885 2018-10-09T16:22:21.242Z,1539102141.242 [BPC1] Loaded 2018-10-09T16:22:21.242Z,1539102141.242 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2018-10-09T16:22:21.242Z,1539102141.242 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-10-09T16:22:21.244Z,1539102141.244 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-10-09T16:22:21.395Z,1539102141.395 [SBIT](DEBUG): Construct Startup Built In Test. 2018-10-09T16:22:21.417Z,1539102141.417 [SBIT] Loaded 2018-10-09T16:22:21.417Z,1539102141.417 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-10-09T16:22:21.418Z,1539102141.418 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-10-09T16:22:21.429Z,1539102141.429 [IBIT] Loaded 2018-10-09T16:22:21.429Z,1539102141.429 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-10-09T16:22:21.432Z,1539102141.432 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-10-09T16:22:21.579Z,1539102141.579 [CBIT] Loaded 2018-10-09T16:22:21.579Z,1539102141.579 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-10-09T16:22:21.580Z,1539102141.580 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-10-09T16:22:21.580Z,1539102141.580 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-10-09T16:22:21.783Z,1539102141.783 [Aanderaa_O2] Loaded 2018-10-09T16:22:21.783Z,1539102141.783 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2018-10-09T16:22:21.859Z,1539102141.859 [CTD_NeilBrown] Loaded 2018-10-09T16:22:21.859Z,1539102141.859 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2018-10-09T16:22:21.860Z,1539102141.860 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409894E0 2018-10-09T16:22:21.861Z,1539102141.861 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 886 2018-10-09T16:22:21.911Z,1539102141.911 [CTD_Seabird] Loaded 2018-10-09T16:22:21.911Z,1539102141.911 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2018-10-09T16:22:21.912Z,1539102141.912 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409B94E0 2018-10-09T16:22:21.912Z,1539102141.912 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 887 2018-10-09T16:22:21.926Z,1539102141.926 [PAR_Licor] Loaded 2018-10-09T16:22:21.927Z,1539102141.927 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-10-09T16:22:21.975Z,1539102141.975 [WetLabsBB2FL] Loaded 2018-10-09T16:22:21.975Z,1539102141.975 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2018-10-09T16:22:21.976Z,1539102141.976 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409E94E0 2018-10-09T16:22:21.976Z,1539102141.976 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 888 2018-10-09T16:22:21.977Z,1539102141.977 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-10-09T16:22:21.979Z,1539102141.979 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-10-09T16:22:22.065Z,1539102142.065 [VerticalControl](DEBUG): Construct VerticalControl. 2018-10-09T16:22:22.148Z,1539102142.148 [VerticalControl] Loaded 2018-10-09T16:22:22.148Z,1539102142.148 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-10-09T16:22:22.149Z,1539102142.149 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-10-09T16:22:22.205Z,1539102142.205 [HorizontalControl] Loaded 2018-10-09T16:22:22.205Z,1539102142.205 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-10-09T16:22:22.206Z,1539102142.206 [SpeedControl](DEBUG): Construct SpeedControl. 2018-10-09T16:22:22.208Z,1539102142.208 [SpeedControl] Loaded 2018-10-09T16:22:22.208Z,1539102142.208 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-10-09T16:22:22.209Z,1539102142.209 [LoopControl](DEBUG): Construct LoopControl. 2018-10-09T16:22:22.209Z,1539102142.209 [LoopControl] Loaded 2018-10-09T16:22:22.210Z,1539102142.210 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-10-09T16:22:22.210Z,1539102142.210 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-10-09T16:22:22.211Z,1539102142.211 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-10-09T16:22:22.247Z,1539102142.247 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-10-09T16:22:22.248Z,1539102142.248 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-10-09T16:22:22.353Z,1539102142.353 [DeadReckonUsingSpeedCalculator] Loaded 2018-10-09T16:22:22.353Z,1539102142.353 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-10-09T16:22:22.370Z,1539102142.370 [NavChart] Loaded 2018-10-09T16:22:22.370Z,1539102142.370 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-10-09T16:22:22.374Z,1539102142.374 [UniversalFixResidualReporter] Loaded 2018-10-09T16:22:22.374Z,1539102142.374 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-10-09T16:22:22.375Z,1539102142.375 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-10-09T16:22:22.378Z,1539102142.378 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-10-09T16:22:22.379Z,1539102142.379 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-10-09T16:22:22.386Z,1539102142.386 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-10-09T16:22:22.387Z,1539102142.387 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A754E0 2018-10-09T16:22:22.387Z,1539102142.387 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 889 2018-10-09T16:22:22.392Z,1539102142.392 [Supervisor](INFO): Main Thread ID is 797 2018-10-09T16:22:22.392Z,1539102142.392 [Supervisor](DEBUG): Running supervisor. 2018-10-09T16:22:22.392Z,1539102142.392 [CommandLine ThreadHandler](INFO): Handler Thread ID is 890 2018-10-09T16:22:22.395Z,1539102142.395 [controlThread ThreadHandler](INFO): Handler Thread ID is 891 2018-10-09T16:22:22.395Z,1539102142.395 [controlThread](DEBUG): Initializing ControlThread 2018-10-09T16:22:22.396Z,1539102142.396 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-10-09T16:22:22.397Z,1539102142.397 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-10-09T16:22:22.397Z,1539102142.397 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-10-09T16:22:22.397Z,1539102142.397 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-10-09T16:22:22.398Z,1539102142.398 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-10-09T16:22:22.398Z,1539102142.398 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-10-09T16:22:22.406Z,1539102142.406 [SBIT](INFO): Initialize SBIT Component. 2018-10-09T16:22:22.406Z,1539102142.406 [SBIT](IMPORTANT): git: 2018-10-09 2018-10-09T16:22:22.406Z,1539102142.406 [SBIT](INFO): git hash: e647870a3e94d94bcb418e3013bcadd95d09d9aa 2018-10-09T16:22:22.407Z,1539102142.407 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2018-10-09T16:22:22.407Z,1539102142.407 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2018-10-09T16:22:22.408Z,1539102142.408 [SBIT](INFO): Beginning SBIT in 23.000000 seconds. 2018-10-09T16:22:22.409Z,1539102142.409 [IBIT](INFO): Initialize IBIT Component. 2018-10-09T16:22:22.410Z,1539102142.410 [CBIT](DEBUG): Initialize CBIT Component. 2018-10-09T16:22:22.410Z,1539102142.410 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2018-10-09T16:22:22.410Z,1539102142.410 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2018-10-09T16:22:22.411Z,1539102142.411 [logger ThreadHandler](INFO): Handler Thread ID is 892 2018-10-09T16:22:22.428Z,1539102142.428 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 893 2018-10-09T16:22:22.433Z,1539102142.433 [Radio_Surface](INFO): Powering up 2018-10-09T16:22:22.440Z,1539102142.440 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 894 2018-10-09T16:22:22.440Z,1539102142.440 [Rowe_600LCM](INFO): Initializing 2018-10-09T16:22:22.441Z,1539102142.441 [Rowe_600LCM](INFO): Checking LCM 2018-10-09T16:22:22.522Z,1539102142.522 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-10-09T16:22:22.528Z,1539102142.528 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-10-09T16:22:22.537Z,1539102142.537 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-10-09T16:22:22.539Z,1539102142.539 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-10-09T16:22:22.540Z,1539102142.540 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-10-09T16:22:22.541Z,1539102142.541 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-10-09T16:22:22.541Z,1539102142.541 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-10-09T16:22:22.553Z,1539102142.553 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-10-09T16:22:22.554Z,1539102142.554 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 895 2018-10-09T16:22:22.555Z,1539102142.555 [CTD_NeilBrown](INFO): Powering down 2018-10-09T16:22:22.556Z,1539102142.556 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-10-09T16:22:22.571Z,1539102142.571 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-10-09T16:22:22.672Z,1539102142.672 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 896 2018-10-09T16:22:22.674Z,1539102142.674 [CTD_Seabird](INFO): Initializing 2018-10-09T16:22:22.674Z,1539102142.674 [CTD_Seabird](INFO): Checking LCM 2018-10-09T16:22:22.688Z,1539102142.688 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 897 2018-10-09T16:22:22.689Z,1539102142.689 [WetLabsBB2FL](INFO): Powering down 2018-10-09T16:22:22.717Z,1539102142.717 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-10-09T16:22:22.786Z,1539102142.786 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 898 2018-10-09T16:22:22.794Z,1539102142.794 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-10-09T16:22:22.794Z,1539102142.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-10-09T16:22:22.794Z,1539102142.794 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-10-09T16:22:22.794Z,1539102142.794 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-10-09T16:22:22.795Z,1539102142.795 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-10-09T16:22:22.795Z,1539102142.795 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-10-09T16:22:22.795Z,1539102142.795 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-10-09T16:22:22.796Z,1539102142.796 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-10-09T16:22:22.797Z,1539102142.797 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-10-09T16:22:22.797Z,1539102142.797 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-10-09T16:22:22.797Z,1539102142.797 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-10-09T16:22:22.814Z,1539102142.814 [MissionManager](DEBUG): 2018-10-09T16:22:22.820Z,1539102142.820 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-10-09T16:22:22.901Z,1539102142.901 [CTD_Seabird](INFO): LCM OK 2018-10-09T16:22:22.901Z,1539102142.901 [CTD_Seabird](INFO): Powering up 2018-10-09T16:22:22.901Z,1539102142.901 [Rowe_600LCM](INFO): LCM OK 2018-10-09T16:22:22.902Z,1539102142.902 [Rowe_600LCM](INFO): Powering up 2018-10-09T16:22:22.926Z,1539102142.926 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-10-09T16:22:22.928Z,1539102142.928 [Default:A.Wait](DEBUG): Construct Wait. 2018-10-09T16:22:22.929Z,1539102142.929 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-10-09T16:22:22.972Z,1539102142.972 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-10-09T16:22:22.975Z,1539102142.975 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-10-09T16:22:22.997Z,1539102142.997 [Default:E.Execute](DEBUG): Construct Execute. 2018-10-09T16:22:23.010Z,1539102143.010 [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-10-09T16:22:23.015Z,1539102143.015 [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-10-09T16:22:23.049Z,1539102143.049 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-10-09T16:22:23.073Z,1539102143.073 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar 2018-10-09T16:22:23.364Z,1539102143.364 [DepthRateCalculator](ERROR): Depth measurement is not active 2018-10-09T16:22:23.453Z,1539102143.453 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:23.679Z,1539102143.679 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:23.687Z,1539102143.687 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-10-09T16:22:23.706Z,1539102143.706 [ElevatorServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:23.712Z,1539102143.712 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-10-09T16:22:23.726Z,1539102143.726 [MassServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:23.731Z,1539102143.731 [MassServo](DEBUG): Initializing MassServo. 2018-10-09T16:22:23.753Z,1539102143.753 [RudderServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:23.759Z,1539102143.759 [RudderServo](DEBUG): Initializing RudderServo. 2018-10-09T16:22:23.773Z,1539102143.773 [ThrusterServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:23.779Z,1539102143.779 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-10-09T16:22:24.138Z,1539102144.138 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:24.329Z,1539102144.329 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:24.675Z,1539102144.675 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2018-10-09T16:22:24.675Z,1539102144.675 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2018-10-09T16:22:24.675Z,1539102144.675 [BuoyancyServo] Communications Fault, FailCount= 1 2018-10-09T16:22:24.676Z,1539102144.676 [BuoyancyServo](ERROR): Communications Fault 2018-10-09T16:22:24.887Z,1539102144.887 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2018-10-09T16:22:24.949Z,1539102144.949 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:24.971Z,1539102144.971 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-10-09T16:22:24.971Z,1539102144.971 [BuoyancyServo](INFO): Powering down 2018-10-09T16:22:25.343Z,1539102145.343 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:25.755Z,1539102145.755 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:26.162Z,1539102146.162 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:26.655Z,1539102146.655 [Aanderaa_O2](INFO): Powering down 2018-10-09T16:22:26.756Z,1539102146.756 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-10-09T16:22:26.822Z,1539102146.822 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-10-09T16:22:26.934Z,1539102146.934 [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-10-09T16:22:27.113Z,1539102147.113 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-10-09T16:22:27.114Z,1539102147.114 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-10-09T16:22:27.114Z,1539102147.114 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-10-09T16:22:27.148Z,1539102147.148 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2018-10-09T16:22:27.148Z,1539102147.148 [BuoyancyServo] No Fault, FailCount= 1 2018-10-09T16:22:27.405Z,1539102147.405 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:27.406Z,1539102147.406 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-10-09T16:22:28.273Z,1539102148.273 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-10-09T16:22:28.295Z,1539102148.295 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2018-10-09T16:22:28.296Z,1539102148.296 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2018-10-09T16:22:28.296Z,1539102148.296 [BuoyancyServo] Communications Fault, FailCount= 2 2018-10-09T16:22:28.296Z,1539102148.296 [BuoyancyServo](ERROR): Communications Fault 2018-10-09T16:22:28.448Z,1539102148.448 [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-10-09T16:22:28.449Z,1539102148.449 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd 2018-10-09T16:22:28.539Z,1539102148.539 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2018-10-09T16:22:29.057Z,1539102149.057 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-10-09T16:22:29.079Z,1539102149.079 [BuoyancyServo](INFO): Powering down 2018-10-09T16:22:29.352Z,1539102149.352 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-10-09T16:22:29.352Z,1539102149.352 [CTD_Seabird](INFO): Powering down 2018-10-09T16:22:31.373Z,1539102151.373 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2018-10-09T16:22:31.373Z,1539102151.373 [BuoyancyServo] No Fault, FailCount= 2 2018-10-09T16:22:31.837Z,1539102151.837 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-10-09T16:22:31.837Z,1539102151.837 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-10-09T16:22:46.181Z,1539102166.181 [SBIT](IMPORTANT): Beginning Startup BIT 2018-10-09T16:22:46.186Z,1539102166.186 [CBIT](IMPORTANT): Beginning ground fault scan 2018-10-09T16:22:49.281Z,1539102169.281 [NAL9602](INFO): Powering up NAL9602 2018-10-09T16:22:57.040Z,1539102177.040 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.005157 CHAN A1 (24V): 4.657929 CHAN A2 (12V): -0.002407 CHAN A3 (5V): -0.001291 CHAN B0 (3.3V): 0.000043 CHAN B1 (3.15aV): -0.000020 CHAN B2 (3.15bV): -0.000585 CHAN B3 (GND): 0.000327 OPEN: -0.000457 Full Scale Calc: 4.765 mA, -1.589 mA 2018-10-09T16:22:59.402Z,1539102179.402 [SBIT](ERROR): Could not read massPosReader_. 2018-10-09T16:23:00.481Z,1539102180.481 [NAL9602](INFO): NAL9602 initialized 2018-10-09T16:23:01.567Z,1539102181.567 [CommandLine](IMPORTANT): got command restart system 2018-10-09T16:23:03.923Z,1539102183.923 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2018-10-09T16:23:03.927Z,1539102183.927 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:03.927Z,1539102183.927 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:04.047Z,1539102184.047 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-10-09T16:23:04.047Z,1539102184.047 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:04.048Z,1539102184.048 [CommandLine](INFO): Join timeout helper Thread ID is 919 2018-10-09T16:23:04.063Z,1539102184.063 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-10-09T16:23:04.063Z,1539102184.063 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:04.064Z,1539102184.064 [NavChartDb](INFO): Join timeout helper Thread ID is 920 2018-10-09T16:23:04.623Z,1539102184.623 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:04.623Z,1539102184.623 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:04.632Z,1539102184.632 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-10-09T16:23:04.632Z,1539102184.632 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:04.633Z,1539102184.633 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 921 2018-10-09T16:23:05.047Z,1539102185.047 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:05.048Z,1539102185.048 [WetLabsBB2FL](INFO): Powering down 2018-10-09T16:23:05.048Z,1539102185.048 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.063Z,1539102185.063 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-10-09T16:23:05.063Z,1539102185.063 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.064Z,1539102185.064 [CTD_Seabird](INFO): Join timeout helper Thread ID is 922 2018-10-09T16:23:05.359Z,1539102185.359 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:05.552Z,1539102185.552 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-10-09T16:23:05.552Z,1539102185.552 [CTD_Seabird](INFO): Powering down 2018-10-09T16:23:05.553Z,1539102185.553 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.571Z,1539102185.571 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2018-10-09T16:23:05.571Z,1539102185.571 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.572Z,1539102185.572 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 924 2018-10-09T16:23:05.947Z,1539102185.947 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:05.948Z,1539102185.948 [CTD_NeilBrown](INFO): Powering down 2018-10-09T16:23:05.948Z,1539102185.948 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.964Z,1539102185.964 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler 2018-10-09T16:23:05.964Z,1539102185.964 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:05.965Z,1539102185.965 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 925 2018-10-09T16:23:06.361Z,1539102186.361 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:06.361Z,1539102186.361 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-10-09T16:23:06.724Z,1539102186.724 [Rowe_600LCM](INFO): Powering down 2018-10-09T16:23:06.726Z,1539102186.726 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:06.744Z,1539102186.744 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-10-09T16:23:06.744Z,1539102186.744 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-10-09T16:23:06.745Z,1539102186.745 [Radio_Surface](INFO): Join timeout helper Thread ID is 927 2018-10-09T16:23:06.968Z,1539102186.968 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-10-09T16:23:06.969Z,1