2018-08-20T16:55:43.353Z,1534784143.353 [Supervisor](DEBUG): Initializing supervisor. 2018-08-20T16:55:43.355Z,1534784143.355 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-08-20T16:55:43.356Z,1534784143.356 [SyncHandler](INFO): Protected caller Thread ID is 797 2018-08-20T16:55:43.357Z,1534784143.357 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-08-20T16:55:43.357Z,1534784143.357 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-08-20T16:55:43.358Z,1534784143.358 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 798 2018-08-20T16:55:43.361Z,1534784143.361 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-08-20T16:55:43.373Z,1534784143.373 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-08-20T16:55:43.374Z,1534784143.374 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-08-20T16:55:43.374Z,1534784143.374 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 799 2018-08-20T16:55:43.375Z,1534784143.375 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-08-20T16:55:43.376Z,1534784143.376 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-08-20T16:55:43.377Z,1534784143.377 [logger ThreadHandler](INFO): Protected caller Thread ID is 800 2018-08-20T16:55:43.379Z,1534784143.379 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-08-20T16:55:43.379Z,1534784143.379 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-08-20T16:55:43.383Z,1534784143.383 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-08-20T16:55:43.741Z,1534784143.741 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-08-20T16:55:43.742Z,1534784143.742 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-08-20T16:55:43.960Z,1534784143.960 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-08-20T16:55:43.961Z,1534784143.961 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-08-20T16:55:44.263Z,1534784144.263 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-08-20T16:55:44.265Z,1534784144.265 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-08-20T16:55:44.411Z,1534784144.411 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-08-20T16:55:44.413Z,1534784144.413 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-08-20T16:55:44.513Z,1534784144.513 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-08-20T16:55:44.515Z,1534784144.515 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-08-20T16:55:45.008Z,1534784145.008 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-08-20T16:55:45.010Z,1534784145.010 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-08-20T16:55:45.457Z,1534784145.457 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-08-20T16:55:45.459Z,1534784145.459 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-08-20T16:55:45.943Z,1534784145.943 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-08-20T16:55:45.944Z,1534784145.944 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-08-20T16:55:46.061Z,1534784146.061 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-08-20T16:55:46.062Z,1534784146.062 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-08-20T16:55:46.162Z,1534784146.162 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-08-20T16:55:46.163Z,1534784146.163 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-08-20T16:55:46.379Z,1534784146.379 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-08-20T16:55:46.381Z,1534784146.381 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-08-20T16:55:46.603Z,1534784146.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-08-20T16:55:46.603Z,1534784146.603 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-08-20T16:55:46.972Z,1534784146.972 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-08-20T16:55:46.973Z,1534784146.973 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-08-20T16:55:47.198Z,1534784147.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-08-20T16:55:47.199Z,1534784147.199 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-08-20T16:55:48.064Z,1534784148.064 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2018-08-20T16:55:48.066Z,1534784148.066 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2018-08-20T16:55:48.174Z,1534784148.174 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2018-08-20T16:55:48.298Z,1534784148.298 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2018-08-20T16:55:48.396Z,1534784148.396 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2018-08-20T16:55:48.485Z,1534784148.485 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2018-08-20T16:55:48.651Z,1534784148.651 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2018-08-20T16:55:48.839Z,1534784148.839 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2018-08-20T16:55:48.916Z,1534784148.916 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2018-08-20T16:55:49.153Z,1534784149.153 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2018-08-20T16:55:49.154Z,1534784149.154 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2018-08-20T16:55:49.239Z,1534784149.239 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2018-08-20T16:55:49.332Z,1534784149.332 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2018-08-20T16:55:49.438Z,1534784149.438 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2018-08-20T16:55:49.571Z,1534784149.571 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2018-08-20T16:55:49.580Z,1534784149.580 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-08-20T16:55:49.860Z,1534784149.860 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-08-20T16:55:49.861Z,1534784149.861 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-08-20T16:55:49.917Z,1534784149.917 [DepthRateCalculator] Loaded 2018-08-20T16:55:49.917Z,1534784149.917 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-08-20T16:55:49.923Z,1534784149.923 [PitchRateCalculator] Loaded 2018-08-20T16:55:49.924Z,1534784149.924 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-08-20T16:55:49.940Z,1534784149.940 [SpeedCalculator] Loaded 2018-08-20T16:55:49.940Z,1534784149.940 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-08-20T16:55:49.963Z,1534784149.963 [TempGradientCalculator] Loaded 2018-08-20T16:55:49.963Z,1534784149.963 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-08-20T16:55:49.980Z,1534784149.980 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2018-08-20T16:55:49.981Z,1534784149.981 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2018-08-20T16:55:49.987Z,1534784149.987 [YawRateCalculator] Loaded 2018-08-20T16:55:49.987Z,1534784149.987 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-08-20T16:55:50.028Z,1534784150.028 [ElevatorOffsetCalculator] Loaded 2018-08-20T16:55:50.028Z,1534784150.028 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-08-20T16:55:50.029Z,1534784150.029 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-08-20T16:55:50.031Z,1534784150.031 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-08-20T16:55:50.152Z,1534784150.152 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC 2018-08-20T16:55:50.152Z,1534784150.152 [StratificationFrontDetector](DEBUG): (re)initializing 2018-08-20T16:55:50.152Z,1534784150.152 [StratificationFrontDetector] Loaded 2018-08-20T16:55:50.153Z,1534784150.153 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2018-08-20T16:55:50.153Z,1534784150.153 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-08-20T16:55:50.155Z,1534784150.155 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-08-20T16:55:50.291Z,1534784150.291 [BuoyancyServo] Loaded 2018-08-20T16:55:50.291Z,1534784150.291 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-08-20T16:55:50.306Z,1534784150.306 [ElevatorServo] Loaded 2018-08-20T16:55:50.307Z,1534784150.307 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-08-20T16:55:50.322Z,1534784150.322 [MassServo] Loaded 2018-08-20T16:55:50.323Z,1534784150.323 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-08-20T16:55:50.338Z,1534784150.338 [RudderServo] Loaded 2018-08-20T16:55:50.339Z,1534784150.339 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-08-20T16:55:50.353Z,1534784150.353 [ThrusterServo] Loaded 2018-08-20T16:55:50.353Z,1534784150.353 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-08-20T16:55:50.354Z,1534784150.354 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-08-20T16:55:50.356Z,1534784150.356 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-08-20T16:55:50.380Z,1534784150.380 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-08-20T16:55:50.380Z,1534784150.380 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-08-20T16:55:50.505Z,1534784150.505 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-08-20T16:55:50.507Z,1534784150.507 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-08-20T16:55:51.071Z,1534784151.071 [DataOverHttps] Loaded 2018-08-20T16:55:51.072Z,1534784151.072 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-08-20T16:55:51.086Z,1534784151.086 [Depth_Keller] Loaded 2018-08-20T16:55:51.086Z,1534784151.086 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-08-20T16:55:51.092Z,1534784151.092 [DropWeight] Loaded 2018-08-20T16:55:51.092Z,1534784151.092 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2018-08-20T16:55:51.193Z,1534784151.193 [NAL9602] Loaded 2018-08-20T16:55:51.193Z,1534784151.193 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-08-20T16:55:51.210Z,1534784151.210 [Onboard] Loaded 2018-08-20T16:55:51.210Z,1534784151.210 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-08-20T16:55:51.221Z,1534784151.221 [Radio_Surface] Loaded 2018-08-20T16:55:51.221Z,1534784151.221 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-08-20T16:55:51.222Z,1534784151.222 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408854E0 2018-08-20T16:55:51.223Z,1534784151.223 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 882 2018-08-20T16:55:51.376Z,1534784151.376 [PNI_TCM] Loaded 2018-08-20T16:55:51.377Z,1534784151.377 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread. 2018-08-20T16:55:51.439Z,1534784151.439 [Rowe_600LCM] Loaded 2018-08-20T16:55:51.439Z,1534784151.439 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread. 2018-08-20T16:55:51.440Z,1534784151.440 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 408B54E0 2018-08-20T16:55:51.441Z,1534784151.441 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 883 2018-08-20T16:55:53.496Z,1534784153.496 [BPC1] Loaded 2018-08-20T16:55:53.496Z,1534784153.496 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2018-08-20T16:55:53.497Z,1534784153.497 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-08-20T16:55:53.497Z,1534784153.497 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-08-20T16:55:53.651Z,1534784153.651 [SBIT](DEBUG): Construct Startup Built In Test. 2018-08-20T16:55:53.674Z,1534784153.674 [SBIT] Loaded 2018-08-20T16:55:53.675Z,1534784153.675 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-08-20T16:55:53.675Z,1534784153.675 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-08-20T16:55:53.688Z,1534784153.688 [IBIT] Loaded 2018-08-20T16:55:53.688Z,1534784153.688 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-08-20T16:55:53.691Z,1534784153.691 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-08-20T16:55:53.845Z,1534784153.845 [CBIT] Loaded 2018-08-20T16:55:53.846Z,1534784153.846 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-08-20T16:55:53.846Z,1534784153.846 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-08-20T16:55:53.848Z,1534784153.848 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-08-20T16:55:54.038Z,1534784154.038 [Aanderaa_O2] Loaded 2018-08-20T16:55:54.038Z,1534784154.038 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2018-08-20T16:55:54.053Z,1534784154.053 [PAR_Licor] Loaded 2018-08-20T16:55:54.054Z,1534784154.054 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-08-20T16:55:54.104Z,1534784154.104 [WetLabsBB2FL] Loaded 2018-08-20T16:55:54.105Z,1534784154.105 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2018-08-20T16:55:54.106Z,1534784154.106 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409794E0 2018-08-20T16:55:54.106Z,1534784154.106 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 884 2018-08-20T16:55:54.107Z,1534784154.107 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-08-20T16:55:54.107Z,1534784154.107 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-08-20T16:55:54.196Z,1534784154.196 [VerticalControl](DEBUG): Construct VerticalControl. 2018-08-20T16:55:54.283Z,1534784154.283 [VerticalControl] Loaded 2018-08-20T16:55:54.283Z,1534784154.283 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-08-20T16:55:54.284Z,1534784154.284 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-08-20T16:55:54.342Z,1534784154.342 [HorizontalControl] Loaded 2018-08-20T16:55:54.343Z,1534784154.343 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-08-20T16:55:54.343Z,1534784154.343 [SpeedControl](DEBUG): Construct SpeedControl. 2018-08-20T16:55:54.345Z,1534784154.345 [SpeedControl] Loaded 2018-08-20T16:55:54.345Z,1534784154.345 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-08-20T16:55:54.346Z,1534784154.346 [LoopControl](DEBUG): Construct LoopControl. 2018-08-20T16:55:54.347Z,1534784154.347 [LoopControl] Loaded 2018-08-20T16:55:54.347Z,1534784154.347 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-08-20T16:55:54.348Z,1534784154.348 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-08-20T16:55:54.349Z,1534784154.349 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-08-20T16:55:54.387Z,1534784154.387 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-08-20T16:55:54.388Z,1534784154.388 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-08-20T16:55:54.495Z,1534784154.495 [DeadReckonUsingSpeedCalculator] Loaded 2018-08-20T16:55:54.496Z,1534784154.496 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-08-20T16:55:54.513Z,1534784154.513 [NavChart] Loaded 2018-08-20T16:55:54.513Z,1534784154.513 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-08-20T16:55:54.517Z,1534784154.517 [UniversalFixResidualReporter] Loaded 2018-08-20T16:55:54.518Z,1534784154.518 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-08-20T16:55:54.518Z,1534784154.518 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-08-20T16:55:54.522Z,1534784154.522 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-08-20T16:55:54.523Z,1534784154.523 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-08-20T16:55:54.530Z,1534784154.530 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-08-20T16:55:54.531Z,1534784154.531 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A054E0 2018-08-20T16:55:54.531Z,1534784154.531 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 885 2018-08-20T16:55:54.536Z,1534784154.536 [Supervisor](INFO): Main Thread ID is 796 2018-08-20T16:55:54.536Z,1534784154.536 [Supervisor](DEBUG): Running supervisor. 2018-08-20T16:55:54.537Z,1534784154.537 [CommandLine ThreadHandler](INFO): Handler Thread ID is 886 2018-08-20T16:55:54.539Z,1534784154.539 [controlThread ThreadHandler](INFO): Handler Thread ID is 887 2018-08-20T16:55:54.540Z,1534784154.540 [controlThread](DEBUG): Initializing ControlThread 2018-08-20T16:55:54.541Z,1534784154.541 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-08-20T16:55:54.541Z,1534784154.541 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-08-20T16:55:54.542Z,1534784154.542 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-08-20T16:55:54.542Z,1534784154.542 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-08-20T16:55:54.542Z,1534784154.542 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2018-08-20T16:55:54.543Z,1534784154.543 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-08-20T16:55:54.544Z,1534784154.544 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-08-20T16:55:54.551Z,1534784154.551 [SBIT](INFO): Initialize SBIT Component. 2018-08-20T16:55:54.552Z,1534784154.552 [SBIT](IMPORTANT): git: 2018-08-20 2018-08-20T16:55:54.552Z,1534784154.552 [SBIT](INFO): git hash: 695b514009632b0c9b638e65628c1e5f155de51b 2018-08-20T16:55:54.553Z,1534784154.553 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2018-08-20T16:55:54.554Z,1534784154.554 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2018-08-20T16:55:54.555Z,1534784154.555 [SBIT](INFO): Beginning SBIT in 23.000000 seconds. 2018-08-20T16:55:54.555Z,1534784154.555 [IBIT](INFO): Initialize IBIT Component. 2018-08-20T16:55:54.556Z,1534784154.556 [CBIT](DEBUG): Initialize CBIT Component. 2018-08-20T16:55:54.557Z,1534784154.557 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2018-08-20T16:55:54.558Z,1534784154.558 [logger ThreadHandler](INFO): Handler Thread ID is 888 2018-08-20T16:55:54.577Z,1534784154.577 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 889 2018-08-20T16:55:54.583Z,1534784154.583 [Radio_Surface](INFO): Powering up 2018-08-20T16:55:54.589Z,1534784154.589 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 890 2018-08-20T16:55:54.590Z,1534784154.590 [Rowe_600LCM](INFO): Initializing 2018-08-20T16:55:54.590Z,1534784154.590 [Rowe_600LCM](INFO): Checking LCM 2018-08-20T16:55:54.693Z,1534784154.693 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-08-20T16:55:54.695Z,1534784154.695 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-08-20T16:55:54.696Z,1534784154.696 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-08-20T16:55:54.696Z,1534784154.696 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-08-20T16:55:54.696Z,1534784154.696 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-08-20T16:55:54.697Z,1534784154.697 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-08-20T16:55:54.698Z,1534784154.698 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-08-20T16:55:54.698Z,1534784154.698 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-08-20T16:55:54.699Z,1534784154.699 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-08-20T16:55:54.700Z,1534784154.700 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-08-20T16:55:54.710Z,1534784154.710 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 891 2018-08-20T16:55:54.711Z,1534784154.711 [WetLabsBB2FL](INFO): Powering down 2018-08-20T16:55:54.833Z,1534784154.833 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-08-20T16:55:54.837Z,1534784154.837 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 892 2018-08-20T16:55:54.846Z,1534784154.846 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-08-20T16:55:54.846Z,1534784154.846 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-08-20T16:55:54.846Z,1534784154.846 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-08-20T16:55:54.847Z,1534784154.847 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-08-20T16:55:54.847Z,1534784154.847 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-08-20T16:55:54.847Z,1534784154.847 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-08-20T16:55:54.847Z,1534784154.847 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-08-20T16:55:54.847Z,1534784154.847 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-08-20T16:55:54.848Z,1534784154.848 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-08-20T16:55:54.848Z,1534784154.848 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-08-20T16:55:54.848Z,1534784154.848 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-08-20T16:55:54.848Z,1534784154.848 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-08-20T16:55:54.849Z,1534784154.849 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-08-20T16:55:54.849Z,1534784154.849 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-08-20T16:55:54.849Z,1534784154.849 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-08-20T16:55:54.849Z,1534784154.849 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-08-20T16:55:54.949Z,1534784154.949 [MissionManager](DEBUG): 2018-08-20T16:55:54.950Z,1534784154.950 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-08-20T16:55:55.041Z,1534784155.041 [Rowe_600LCM](INFO): LCM OK 2018-08-20T16:55:55.041Z,1534784155.041 [Rowe_600LCM](INFO): Powering up 2018-08-20T16:55:55.070Z,1534784155.070 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-08-20T16:55:55.071Z,1534784155.071 [Default:A.Wait](DEBUG): Construct Wait. 2018-08-20T16:55:55.094Z,1534784155.094 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-08-20T16:55:55.125Z,1534784155.125 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-08-20T16:55:55.127Z,1534784155.127 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-08-20T16:55:55.157Z,1534784155.157 [Default:E.Execute](DEBUG): Construct Execute. 2018-08-20T16:55:55.160Z,1534784155.160 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn 300 Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2018-08-20T16:55:55.172Z,1534784155.172 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-08-20T16:55:55.201Z,1534784155.201 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-08-20T16:55:55.762Z,1534784155.762 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:55.937Z,1534784155.937 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:55.941Z,1534784155.941 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-08-20T16:55:55.966Z,1534784155.966 [ElevatorServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:55.973Z,1534784155.973 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-08-20T16:55:55.987Z,1534784155.987 [MassServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:55.993Z,1534784155.993 [MassServo](DEBUG): Initializing MassServo. 2018-08-20T16:55:56.007Z,1534784156.007 [RudderServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:56.013Z,1534784156.013 [RudderServo](DEBUG): Initializing RudderServo. 2018-08-20T16:55:56.035Z,1534784156.035 [ThrusterServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:56.041Z,1534784156.041 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-08-20T16:55:56.259Z,1534784156.259 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:56.589Z,1534784156.589 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:56.937Z,1534784156.937 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2018-08-20T16:55:56.937Z,1534784156.937 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2018-08-20T16:55:56.937Z,1534784156.937 [BuoyancyServo] Communications Fault, FailCount= 1 2018-08-20T16:55:56.937Z,1534784156.937 [BuoyancyServo](ERROR): Communications Fault 2018-08-20T16:55:57.145Z,1534784157.145 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2018-08-20T16:55:57.203Z,1534784157.203 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:57.225Z,1534784157.225 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-08-20T16:55:57.226Z,1534784157.226 [BuoyancyServo](INFO): Powering down 2018-08-20T16:55:57.609Z,1534784157.609 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:58.025Z,1534784158.025 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:58.409Z,1534784158.409 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:58.805Z,1534784158.805 [Aanderaa_O2](INFO): Powering down 2018-08-20T16:55:58.916Z,1534784158.916 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-08-20T16:55:59.093Z,1534784159.093 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-20T16:55:59.204Z,1534784159.204 [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-08-20T16:55:59.431Z,1534784159.431 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-20T16:55:59.432Z,1534784159.432 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-20T16:55:59.442Z,1534784159.442 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2018-08-20T16:55:59.442Z,1534784159.442 [BuoyancyServo] No Fault, FailCount= 1 2018-08-20T16:55:59.445Z,1534784159.445 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-20T16:55:59.653Z,1534784159.653 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2018-08-20T16:55:59.654Z,1534784159.654 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-08-20T16:56:18.115Z,1534784178.115 [SBIT](IMPORTANT): Beginning Startup BIT 2018-08-20T16:56:18.130Z,1534784178.130 [CBIT](IMPORTANT): Beginning ground fault scan 2018-08-20T16:56:21.320Z,1534784181.320 [NAL9602](INFO): Powering up NAL9602 2018-08-20T16:56:29.023Z,1534784189.023 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 4.657929 CHAN A1 (24V): -0.009265 CHAN A2 (12V): 4.697929 CHAN A3 (5V): -0.001612 CHAN B0 (3.3V): 0.000226 CHAN B1 (3.15aV): -0.000096 CHAN B2 (3.15bV): -0.000045 CHAN B3 (GND): 0.000034 OPEN: -0.000242 Full Scale Calc: 4.765 mA, -1.589 mA 2018-08-20T16:56:32.515Z,1534784192.515 [NAL9602](INFO): NAL9602 initialized 2018-08-20T16:57:11.892Z,1534784231.892 [SBIT](IMPORTANT): SBIT PASSED 2018-08-20T16:57:11.983Z,1534784231.983 [CommandLine](IMPORTANT): got command configSet list 2018-08-20T16:57:11.983Z,1534784231.983 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2018-08-20T16:57:11.984Z,1534784231.984 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool; 2018-08-20T16:57:11.986Z,1534784231.986 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool; 2018-08-20T16:57:12.276Z,1534784232.276 [MissionManager](IMPORTANT): Started mission Startup 2018-08-20T16:57:12.285Z,1534784232.285 [Startup] Running Loop=1 2018-08-20T16:57:12.285Z,1534784232.285 [Startup](DEBUG): Aggregate::initialize Startup 2018-08-20T16:57:12.285Z,1534784232.285 [Startup:A.GoToSurface] Running Loop=1 2018-08-20T16:57:12.285Z,1534784232.285 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-08-20T16:57:12.286Z,1534784232.286 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-08-20T16:57:12.287Z,1534784232.287 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-08-20T16:57:12.287Z,1534784232.287 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-08-20T16:57:12.288Z,1534784232.288 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-08-20T16:57:12.288Z,1534784232.288 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-08-20T16:57:12.329Z,1534784232.329 [Startup:StartupSatComms] Running Loop=1 2018-08-20T16:57:12.329Z,1534784232.329 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2018-08-20T16:57:12.329Z,1534784232.329 [Startup:StartupSatComms:A] Running Loop=1 2018-08-20T16:57:12.653Z,1534784232.653 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2018-08-20T16:57:29.416Z,1534784249.416 [BPC1](ERROR): Failed to parse Bank B battery data 2018-08-20T16:57:55.757Z,1534784275.757 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-20T16:57:55.757Z,1534784275.757 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-08-20T16:57:55.757Z,1534784275.757 [Rowe_600LCM](ERROR): Communications Fault 2018-08-20T16:57:55.927Z,1534784275.927 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-20T16:57:56.161Z,1534784276.161 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-20T16:57:56.547Z,1534784276.547 [Rowe_600LCM](INFO): Powering down 2018-08-20T16:57:57.838Z,1534784277.838 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-20T16:57:57.839Z,1534784277.839 [Rowe_600LCM] No Fault, FailCount= 1 2018-08-20T16:57:58.173Z,1534784278.173 [Rowe_600LCM](INFO): Initializing 2018-08-20T16:57:58.173Z,1534784278.173 [Rowe_600LCM](INFO): Checking LCM 2018-08-20T16:57:58.173Z,1534784278.173 [Rowe_600LCM](INFO): LCM OK 2018-08-20T16:57:58.174Z,1534784278.174 [Rowe_600LCM](INFO): Powering up 2018-08-20T16:58:02.360Z,1534784282.360 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-20T16:58:02.420Z,1534784282.420 [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-08-20T16:58:02.422Z,1534784282.422 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-20T16:58:02.423Z,1534784282.423 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-20T16:58:02.424Z,1534784282.424 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-20T16:58:12.620Z,1534784292.620 [Startup:StartupSatComms:A](INFO): Timed out from 2018-08-20T16:57:12.3Z 2018-08-20T16:58:12.620Z,1534784292.620 [Startup:StartupSatComms:A] Stopped 2018-08-20T16:58:12.620Z,1534784292.620 [Startup:StartupSatComms:B] Running Loop=1 2018-08-20T16:58:13.023Z,1534784293.023 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2018-08-20T16:58:21.721Z,1534784301.721 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005088 2018-08-20T16:58:26.090Z,1534784306.090 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180820T164933/Courier0004.lzma 2018-08-20T16:58:26.876Z,1534784306.876 [DataOverHttps](INFO): Moved sent file to Logs/20180820T164933/Courier0004.lzma.bak 2018-08-20T16:58:26.877Z,1534784306.877 [DataOverHttps](INFO): SBD MOMSN=8430105 2018-08-20T16:58:42.762Z,1534784322.762 [DataOverHttps](INFO): Sending 102 bytes from file Logs/20180820T164933/Express0005.lzma 2018-08-20T16:58:43.548Z,1534784323.548 [DataOverHttps](INFO): Moved sent file to Logs/20180820T164933/Express0005.lzma.bak 2018-08-20T16:58:43.548Z,1534784323.548 [DataOverHttps](INFO): SBD MOMSN=8430107 2018-08-20T16:58:53.695Z,1534784333.695 [DataOverHttps](INFO): Sending 734 bytes from file Logs/20180820T165543/Express0001.lzma 2018-08-20T16:58:54.492Z,1534784334.492 [DataOverHttps](INFO): Moved sent file to Logs/20180820T165543/Express0001.lzma.bak 2018-08-20T16:58:54.492Z,1534784334.492 [DataOverHttps](INFO): SBD MOMSN=8430111 2018-08-20T16:58:55.329Z,1534784335.329 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-08-20T16:58:55.329Z,1534784335.329 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1 2018-08-20T16:58:55.329Z,1534784335.329 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2018-08-20T16:58:55.332Z,1534784335.332 [Startup:StartupSatComms:B] Stopped 2018-08-20T16:58:55.332Z,1534784335.332 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2018-08-20T16:58:55.332Z,1534784335.332 [Startup:StartupSatComms] Stopped 2018-08-20T16:58:55.332Z,1534784335.332 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2018-08-20T16:58:55.338Z,1534784335.338 [Startup](INFO): Completed Startup 2018-08-20T16:58:55.338Z,1534784335.338 [MissionManager](INFO): Startup is completed. 2018-08-20T16:58:55.338Z,1534784335.338 [MissionManager](INFO): Uninitializing Mission Startup 2018-08-20T16:58:55.338Z,1534784335.338 [Startup] Stopped 2018-08-20T16:58:55.338Z,1534784335.338 [Startup](DEBUG): Aggregate::uninitialize Startup 2018-08-20T16:58:55.338Z,1534784335.338 [Startup:A.GoToSurface] Stopped 2018-08-20T16:58:55.338Z,1534784335.338 [Startup:A.GoToSurface](DEBUG): Uninitialize G