2017-09-11T23:05:21.149Z,1505171121.149 [Supervisor](DEBUG): Initializing supervisor. 2017-09-11T23:05:21.153Z,1505171121.153 [SyncHandler](DEBUG): Created PCaller Thread at 4051A4E0 2017-09-11T23:05:21.153Z,1505171121.153 [SyncHandler](INFO): Protected caller Thread ID is 1353 2017-09-11T23:05:21.154Z,1505171121.154 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2017-09-11T23:05:21.155Z,1505171121.155 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4054A4E0 2017-09-11T23:05:21.156Z,1505171121.156 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1354 2017-09-11T23:05:21.161Z,1505171121.161 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2017-09-11T23:05:21.176Z,1505171121.176 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2017-09-11T23:05:21.178Z,1505171121.178 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4057A4E0 2017-09-11T23:05:21.178Z,1505171121.178 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1355 2017-09-11T23:05:21.179Z,1505171121.179 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2017-09-11T23:05:21.180Z,1505171121.180 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405AA4E0 2017-09-11T23:05:21.181Z,1505171121.181 [logger ThreadHandler](INFO): Protected caller Thread ID is 1356 2017-09-11T23:05:21.183Z,1505171121.183 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2017-09-11T23:05:21.184Z,1505171121.184 [Supervisor](INFO): Looking for Config files in directory: Config/ 2017-09-11T23:05:21.186Z,1505171121.186 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2017-09-11T23:05:21.391Z,1505171121.391 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2017-09-11T23:05:21.391Z,1505171121.391 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2017-09-11T23:05:21.533Z,1505171121.533 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2017-09-11T23:05:21.533Z,1505171121.533 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2017-09-11T23:05:21.923Z,1505171121.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2017-09-11T23:05:21.923Z,1505171121.923 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2017-09-11T23:05:22.076Z,1505171122.076 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2017-09-11T23:05:22.077Z,1505171122.077 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2017-09-11T23:05:22.161Z,1505171122.161 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2017-09-11T23:05:22.385Z,1505171122.385 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2017-09-11T23:05:22.385Z,1505171122.385 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2017-09-11T23:05:22.494Z,1505171122.494 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2017-09-11T23:05:22.494Z,1505171122.494 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2017-09-11T23:05:22.828Z,1505171122.828 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2017-09-11T23:05:22.829Z,1505171122.829 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2017-09-11T23:05:23.257Z,1505171123.257 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2017-09-11T23:05:23.257Z,1505171123.257 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2017-09-11T23:05:23.689Z,1505171123.689 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2017-09-11T23:05:23.689Z,1505171123.689 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2017-09-11T23:05:24.324Z,1505171124.324 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2017-09-11T23:05:24.325Z,1505171124.325 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2017-09-11T23:05:24.539Z,1505171124.539 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2017-09-11T23:05:24.540Z,1505171124.540 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2017-09-11T23:05:24.647Z,1505171124.647 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2017-09-11T23:05:24.648Z,1505171124.648 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2017-09-11T23:05:25.201Z,1505171125.201 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2017-09-11T23:05:25.202Z,1505171125.202 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2017-09-11T23:05:25.318Z,1505171125.318 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2017-09-11T23:05:25.320Z,1505171125.320 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2017-09-11T23:05:25.321Z,1505171125.321 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2017-09-11T23:05:25.621Z,1505171125.621 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2017-09-11T23:05:25.622Z,1505171125.622 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2017-09-11T23:05:25.730Z,1505171125.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2017-09-11T23:05:25.827Z,1505171125.827 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2017-09-11T23:05:25.936Z,1505171125.936 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2017-09-11T23:05:26.027Z,1505171126.027 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2017-09-11T23:05:26.165Z,1505171126.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2017-09-11T23:05:26.336Z,1505171126.336 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2017-09-11T23:05:26.438Z,1505171126.438 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2017-09-11T23:05:26.536Z,1505171126.536 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2017-09-11T23:05:26.624Z,1505171126.624 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2017-09-11T23:05:26.855Z,1505171126.855 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2017-09-11T23:05:26.936Z,1505171126.936 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/ 2017-09-11T23:05:26.937Z,1505171126.937 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2017-09-11T23:05:26.938Z,1505171126.938 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2017-09-11T23:05:27.067Z,1505171127.067 [SBIT](DEBUG): Construct Startup Built In Test. 2017-09-11T23:05:27.105Z,1505171127.105 [SBIT] Loaded 2017-09-11T23:05:27.105Z,1505171127.105 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2017-09-11T23:05:27.106Z,1505171127.106 [IBIT](DEBUG): Construct Initiated Built In Test. 2017-09-11T23:05:27.141Z,1505171127.141 [IBIT] Loaded 2017-09-11T23:05:27.141Z,1505171127.141 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2017-09-11T23:05:27.146Z,1505171127.146 [CBIT](DEBUG): Construct Continuous Built In Test. 2017-09-11T23:05:27.343Z,1505171127.343 [CBIT] Loaded 2017-09-11T23:05:27.343Z,1505171127.343 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2017-09-11T23:05:27.344Z,1505171127.344 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2017-09-11T23:05:27.344Z,1505171127.344 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2017-09-11T23:05:27.417Z,1505171127.417 [VerticalControl](DEBUG): Construct VerticalControl. 2017-09-11T23:05:27.539Z,1505171127.539 [VerticalControl] Loaded 2017-09-11T23:05:27.540Z,1505171127.540 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2017-09-11T23:05:27.540Z,1505171127.540 [HorizontalControl](DEBUG): Construct HorizontalControl. 2017-09-11T23:05:27.619Z,1505171127.619 [HorizontalControl] Loaded 2017-09-11T23:05:27.620Z,1505171127.620 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2017-09-11T23:05:27.620Z,1505171127.620 [SpeedControl](DEBUG): Construct SpeedControl. 2017-09-11T23:05:27.628Z,1505171127.628 [SpeedControl] Loaded 2017-09-11T23:05:27.628Z,1505171127.628 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2017-09-11T23:05:27.629Z,1505171127.629 [LoopControl](DEBUG): Construct LoopControl. 2017-09-11T23:05:27.629Z,1505171127.629 [LoopControl] Loaded 2017-09-11T23:05:27.630Z,1505171127.630 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2017-09-11T23:05:27.630Z,1505171127.630 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2017-09-11T23:05:27.631Z,1505171127.631 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2017-09-11T23:05:27.657Z,1505171127.657 [DepthRateCalculator] Loaded 2017-09-11T23:05:27.658Z,1505171127.658 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2017-09-11T23:05:27.664Z,1505171127.664 [PitchRateCalculator] Loaded 2017-09-11T23:05:27.664Z,1505171127.664 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2017-09-11T23:05:27.684Z,1505171127.684 [SpeedCalculator] Loaded 2017-09-11T23:05:27.684Z,1505171127.684 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2017-09-11T23:05:27.710Z,1505171127.710 [TempGradientCalculator] Loaded 2017-09-11T23:05:27.710Z,1505171127.710 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2017-09-11T23:05:27.729Z,1505171127.729 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2017-09-11T23:05:27.730Z,1505171127.730 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2017-09-11T23:05:27.736Z,1505171127.736 [YawRateCalculator] Loaded 2017-09-11T23:05:27.736Z,1505171127.736 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2017-09-11T23:05:27.737Z,1505171127.737 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2017-09-11T23:05:27.738Z,1505171127.738 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2017-09-11T23:05:27.824Z,1505171127.824 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC 2017-09-11T23:05:27.824Z,1505171127.824 [StratificationFrontDetector](DEBUG): (re)initializing 2017-09-11T23:05:27.825Z,1505171127.825 [StratificationFrontDetector] Loaded 2017-09-11T23:05:27.825Z,1505171127.825 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2017-09-11T23:05:27.826Z,1505171127.826 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2017-09-11T23:05:27.826Z,1505171127.826 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2017-09-11T23:05:28.241Z,1505171128.241 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2017-09-11T23:05:28.241Z,1505171128.241 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2017-09-11T23:05:28.355Z,1505171128.355 [DeadReckonUsingMultipleVelocitySources] Loaded 2017-09-11T23:05:28.356Z,1505171128.356 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2017-09-11T23:05:28.425Z,1505171128.425 [DeadReckonUsingSpeedCalculator] Loaded 2017-09-11T23:05:28.426Z,1505171128.426 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2017-09-11T23:05:28.447Z,1505171128.447 [NavChart] Loaded 2017-09-11T23:05:28.447Z,1505171128.447 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2017-09-11T23:05:28.452Z,1505171128.452 [UniversalFixResidualReporter] Loaded 2017-09-11T23:05:28.453Z,1505171128.453 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2017-09-11T23:05:28.453Z,1505171128.453 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2017-09-11T23:05:28.454Z,1505171128.454 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2017-09-11T23:05:28.469Z,1505171128.469 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2017-09-11T23:05:28.470Z,1505171128.470 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2017-09-11T23:05:28.629Z,1505171128.629 [Aanderaa_O2] Loaded 2017-09-11T23:05:28.630Z,1505171128.630 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread. 2017-09-11T23:05:28.737Z,1505171128.737 [CTD_NeilBrown] Loaded 2017-09-11T23:05:28.737Z,1505171128.737 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2017-09-11T23:05:28.739Z,1505171128.739 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408154E0 2017-09-11T23:05:28.739Z,1505171128.739 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1439 2017-09-11T23:05:28.758Z,1505171128.758 [PAR_Licor] Loaded 2017-09-11T23:05:28.758Z,1505171128.758 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2017-09-11T23:05:28.817Z,1505171128.817 [WetLabsBB2FL] Loaded 2017-09-11T23:05:28.818Z,1505171128.818 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2017-09-11T23:05:28.819Z,1505171128.819 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408454E0 2017-09-11T23:05:28.819Z,1505171128.819 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1440 2017-09-11T23:05:28.820Z,1505171128.820 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2017-09-11T23:05:28.820Z,1505171128.820 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2017-09-11T23:05:29.245Z,1505171129.245 [DataOverHttps] Loaded 2017-09-11T23:05:29.246Z,1505171129.246 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2017-09-11T23:05:29.287Z,1505171129.287 [Depth_Keller] Loaded 2017-09-11T23:05:29.288Z,1505171129.288 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2017-09-11T23:05:29.294Z,1505171129.294 [DropWeight] Loaded 2017-09-11T23:05:29.294Z,1505171129.294 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2017-09-11T23:05:29.546Z,1505171129.546 [NAL9602] Loaded 2017-09-11T23:05:29.547Z,1505171129.546 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2017-09-11T23:05:29.570Z,1505171129.570 [Onboard] Loaded 2017-09-11T23:05:29.571Z,1505171129.571 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2017-09-11T23:05:29.592Z,1505171129.592 [Radio_Surface] Loaded 2017-09-11T23:05:29.592Z,1505171129.592 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2017-09-11T23:05:29.602Z,1505171129.602 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40ACB4E0 2017-09-11T23:05:29.603Z,1505171129.603 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1444 2017-09-11T23:05:29.897Z,1505171129.897 [DAT] Loaded 2017-09-11T23:05:29.897Z,1505171129.897 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2017-09-11T23:05:29.981Z,1505171129.981 [PNI_TCM] Loaded 2017-09-11T23:05:29.981Z,1505171129.981 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread. 2017-09-11T23:05:34.259Z,1505171134.259 [BPC1] Loaded 2017-09-11T23:05:34.259Z,1505171134.259 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2017-09-11T23:05:34.260Z,1505171134.260 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2017-09-11T23:05:34.260Z,1505171134.260 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2017-09-11T23:05:34.534Z,1505171134.534 [BuoyancyServo] Loaded 2017-09-11T23:05:34.534Z,1505171134.534 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2017-09-11T23:05:34.558Z,1505171134.558 [ElevatorServo] Loaded 2017-09-11T23:05:34.559Z,1505171134.559 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2017-09-11T23:05:34.573Z,1505171134.573 [MassServo] Loaded 2017-09-11T23:05:34.574Z,1505171134.574 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2017-09-11T23:05:34.597Z,1505171134.597 [RudderServo] Loaded 2017-09-11T23:05:34.597Z,1505171134.597 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2017-09-11T23:05:34.620Z,1505171134.620 [ThrusterServo] Loaded 2017-09-11T23:05:34.621Z,1505171134.621 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2017-09-11T23:05:34.621Z,1505171134.621 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2017-09-11T23:05:34.622Z,1505171134.622 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2017-09-11T23:05:34.778Z,1505171134.778 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2017-09-11T23:05:34.778Z,1505171134.778 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2017-09-11T23:05:34.811Z,1505171134.811 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2017-09-11T23:05:34.825Z,1505171134.825 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2017-09-11T23:05:34.826Z,1505171134.826 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2017-09-11T23:05:34.837Z,1505171134.837 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2017-09-11T23:05:34.838Z,1505171134.838 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B9F4E0 2017-09-11T23:05:34.838Z,1505171134.838 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1445 2017-09-11T23:05:34.853Z,1505171134.853 [Supervisor](INFO): Main Thread ID is 1352 2017-09-11T23:05:34.854Z,1505171134.854 [Supervisor](DEBUG): Running supervisor. 2017-09-11T23:05:34.854Z,1505171134.854 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1446 2017-09-11T23:05:34.858Z,1505171134.858 [controlThread ThreadHandler](INFO): Handler Thread ID is 1447 2017-09-11T23:05:34.859Z,1505171134.859 [controlThread](DEBUG): Initializing ControlThread 2017-09-11T23:05:34.860Z,1505171134.860 [SBIT](INFO): Initialize SBIT Component. 2017-09-11T23:05:34.860Z,1505171134.860 [SBIT](IMPORTANT): git: 2017-08-02-81-g2dedf71 2017-09-11T23:05:34.860Z,1505171134.860 [SBIT](INFO): git hash: 2dedf719d304b5c3f7e3acd061a0c8109ea4feed 2017-09-11T23:05:34.871Z,1505171134.871 [SBIT](INFO): Kernel Reporting Different Release From Configuration. Kernel Expected: 2.6.27.8 Kernel Reported: 2.6.27.8-00011-g2bc81df-dirty 2017-09-11T23:05:34.871Z,1505171134.871 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 Kernel Reported: #646 PREEMPT Thu Feb 11 17:01:12 PST 2016 2017-09-11T23:05:34.872Z,1505171134.872 [SBIT](INFO): Beginning SBIT in 23.000000 seconds. 2017-09-11T23:05:34.873Z,1505171134.873 [IBIT](INFO): Initialize IBIT Component. 2017-09-11T23:05:34.874Z,1505171134.874 [CBIT](DEBUG): Initialize CBIT Component. 2017-09-11T23:05:34.874Z,1505171134.874 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2017-09-11T23:05:34.875Z,1505171134.875 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2017-09-11T23:05:34.876Z,1505171134.876 [logger ThreadHandler](INFO): Handler Thread ID is 1448 2017-09-11T23:05:34.907Z,1505171134.907 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1449 2017-09-11T23:05:34.908Z,1505171134.908 [CTD_NeilBrown](INFO): Powering down 2017-09-11T23:05:34.971Z,1505171134.971 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2017-09-11T23:05:34.973Z,1505171134.973 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2017-09-11T23:05:34.974Z,1505171134.974 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2017-09-11T23:05:34.975Z,1505171134.975 [LoopControl](DEBUG): Initialize LoopControlComponent. 2017-09-11T23:05:34.975Z,1505171134.975 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2017-09-11T23:05:34.975Z,1505171134.975 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2017-09-11T23:05:34.976Z,1505171134.976 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2017-09-11T23:05:34.976Z,1505171134.976 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2017-09-11T23:05:34.977Z,1505171134.977 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2017-09-11T23:05:34.978Z,1505171134.978 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2017-09-11T23:05:34.978Z,1505171134.978 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2017-09-11T23:05:34.979Z,1505171134.979 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2017-09-11T23:05:34.980Z,1505171134.980 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2017-09-11T23:05:34.980Z,1505171134.980 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2017-09-11T23:05:34.981Z,1505171134.981 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2017-09-11T23:05:34.981Z,1505171134.981 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2017-09-11T23:05:34.982Z,1505171134.982 [NavChart](DEBUG): Initialize NavChart Navigation. 2017-09-11T23:05:34.982Z,1505171134.982 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2017-09-11T23:05:34.000Z,1505171135.000 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1450 2017-09-11T23:05:35.001Z,1505171135.001 [WetLabsBB2FL](INFO): Powering down 2017-09-11T23:05:35.046Z,1505171135.046 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2017-09-11T23:05:35.051Z,1505171135.051 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1451 2017-09-11T23:05:35.068Z,1505171135.068 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1452 2017-09-11T23:05:35.072Z,1505171135.072 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2017-09-11T23:05:35.072Z,1505171135.072 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2017-09-11T23:05:35.073Z,1505171135.073 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2017-09-11T23:05:35.073Z,1505171135.073 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2017-09-11T23:05:35.073Z,1505171135.073 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2017-09-11T23:05:35.073Z,1505171135.073 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2017-09-11T23:05:35.074Z,1505171135.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2017-09-11T23:05:35.074Z,1505171135.074 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2017-09-11T23:05:35.074Z,1505171135.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2017-09-11T23:05:35.074Z,1505171135.074 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2017-09-11T23:05:35.074Z,1505171135.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2017-09-11T23:05:35.075Z,1505171135.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2017-09-11T23:05:35.075Z,1505171135.075 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2017-09-11T23:05:35.075Z,1505171135.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2017-09-11T23:05:35.076Z,1505171135.076 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2017-09-11T23:05:35.076Z,1505171135.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2017-09-11T23:05:35.117Z,1505171135.117 [Radio_Surface](INFO): Powering up 2017-09-11T23:05:35.145Z,1505171135.145 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2017-09-11T23:05:35.220Z,1505171135.220 [MissionManager](DEBUG): 2017-09-11T23:05:35.220Z,1505171135.220 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2017-09-11T23:05:35.332Z,1505171135.332 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2017-09-11T23:05:35.333Z,1505171135.333 [Default:A.Wait](DEBUG): Construct Wait. 2017-09-11T23:05:35.360Z,1505171135.360 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2017-09-11T23:05:35.405Z,1505171135.405 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2017-09-11T23:05:35.408Z,1505171135.408 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2017-09-11T23:05:35.440Z,1505171135.440 [Default:E.Execute](DEBUG): Construct Execute. 2017-09-11T23:05:35.496Z,1505171135.496 [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 2017-09-11T23:05:35.502Z,1505171135.502 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2017-09-11T23:05:35.765Z,1505171135.765 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2017-09-11T23:05:35.914Z,1505171135.914 [NAL9602](INFO): Powering up NAL9602 2017-09-11T23:05:36.053Z,1505171136.053 [DAT](INFO): Powering up 2017-09-11T23:05:36.053Z,1505171136.053 [DAT](DEBUG): Initializing DAT. 2017-09-11T23:05:36.518Z,1505171136.518 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:36.558Z,1505171136.558 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:36.778Z,1505171136.778 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2017-09-11T23:05:36.795Z,1505171136.795 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2017-09-11T23:05:36.842Z,1505171136.842 [ElevatorServo](DEBUG): Initializing EZServoServo. 2017-09-11T23:05:36.846Z,1505171136.846 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2017-09-11T23:05:36.890Z,1505171136.890 [MassServo](DEBUG): Initializing EZServoServo. 2017-09-11T23:05:36.902Z,1505171136.902 [MassServo](DEBUG): Initializing MassServo. 2017-09-11T23:05:36.914Z,1505171136.914 [RudderServo](DEBUG): Initializing EZServoServo. 2017-09-11T23:05:36.922Z,1505171136.922 [RudderServo](DEBUG): Initializing RudderServo. 2017-09-11T23:05:36.929Z,1505171136.929 [ThrusterServo](DEBUG): Initializing EZServoServo. 2017-09-11T23:05:36.943Z,1505171136.943 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2017-09-11T23:05:37.500Z,1505171137.500 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:37.501Z,1505171137.501 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:49.316Z,1505171149.316 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:49.330Z,1505171149.330 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:49.594Z,1505171149.594 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:49.595Z,1505171149.595 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:49.927Z,1505171149.927 [Aanderaa_O2](INFO): Powering down 2017-09-11T23:05:50.201Z,1505171150.201 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:50.203Z,1505171150.203 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:50.294Z,1505171150.294 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003807 2017-09-11T23:05:50.357Z,1505171150.357 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:50.358Z,1505171150.358 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:50.745Z,1505171150.745 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:50.746Z,1505171150.746 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:51.527Z,1505171151.527 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:51.528Z,1505171151.528 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2017-09-11T23:05:58.708Z,1505171158.708 [SBIT](IMPORTANT): Beginning Startup BIT 2017-09-11T23:05:58.713Z,1505171158.713 [CBIT](IMPORTANT): Beginning ground fault scan 2017-09-11T23:05:59.765Z,1505171159.765 [NAL9602](ERROR): NAL9602 initialization error. 2017-09-11T23:05:59.765Z,1505171159.765 [NAL9602] Communications Fault, FailCount= 1 2017-09-11T23:05:59.765Z,1505171159.765 [NAL9602](ERROR): Communications Fault 2017-09-11T23:05:59.985Z,1505171159.985 [CBIT](ERROR): Communications Fault in component: NAL9602 2017-09-11T23:06:00.165Z,1505171160.165 [NAL9602](INFO): Powering down 2017-09-11T23:06:01.186Z,1505171161.186 [CBIT](INFO): Clearing failed state for component NAL9602 2017-09-11T23:06:01.186Z,1505171161.186 [NAL9602] No Fault, FailCount= 1 2017-09-11T23:06:05.366Z,1505171165.366 [NAL9602](INFO): Powering up NAL9602 2017-09-11T23:06:07.791Z,1505171167.791 [BPC1](ERROR): Failed to receive battery data 2017-09-11T23:06:07.791Z,1505171167.791 [BPC1] Communications Fault, FailCount= 1 2017-09-11T23:06:07.791Z,1505171167.791 [BPC1](ERROR): Communications Fault 2017-09-11T23:06:07.898Z,1505171167.898 [CBIT](ERROR): Communications Fault in component: BPC1 2017-09-11T23:06:09.115Z,1505171169.115 [CBIT](INFO): Clearing failed state for component BPC1 2017-09-11T23:06:09.115Z,1505171169.115 [BPC1] No Fault, FailCount= 1 2017-09-11T23:06:09.124Z,1505171169.124 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.005069 CHAN A1 (24V): 0.125849 CHAN A2 (12V): -0.002171 CHAN A3 (5V): 0.000332 CHAN B0 (3.3V): -0.000525 CHAN B1 (3.15aV): 4.767929 CHAN B2 (3.15bV): 0.002650 CHAN B3 (GND): 4.792929 OPEN: -0.000262 Full Scale Calc: 4.765 mA, -1.589 mA 2017-09-11T23:06:11.882Z,1505171171.882 [SBIT](FAULT): Mass: EXPECTED:0.004450 ACTUAL:0.000992 2017-09-11T23:06:16.563Z,1505171176.563 [NAL9602](INFO): NAL9602 initialized 2017-09-11T23:06:46.375Z,1505171206.375 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: , available: 2017-09-11T23:06:46.375Z,1505171206.375 [DAT] Communications Fault, FailCount= 1 2017-09-11T23:06:46.375Z,1505171206.375 [DAT](ERROR): Communications Fault 2017-09-11T23:06:46.574Z,1505171206.574 [CBIT](ERROR): Communications Fault in component: DAT 2017-09-11T23:06:46.775Z,1505171206.775 [DAT](INFO): Powering down 2017-09-11T23:06:47.852Z,1505171207.852 [CBIT](INFO): Clearing failed state for component DAT 2017-09-11T23:06:47.853Z,1505171207.853 [DAT] No Fault, FailCount= 1 2017-09-11T23:06:49.981Z,1505171209.981 [DAT](INFO): Powering up 2017-09-11T23:06:49.981Z,1505171209.981 [DAT](DEBUG): Initializing DAT. 2017-09-11T23:06:56.477Z,1505171216.477 [SBIT](CRITICAL): SBIT FAILED 2017-09-11T23:06:56.479Z,1505171216.479 [CommandLine](FAULT): Scheduling is paused 2017-09-11T23:06:56.479Z,1505171216.479 [CBIT](INFO): Critical error at 20170911T230656 2017-09-11T23:06:56.488Z,1505171216.488 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2017-09-11T23:06:56.900Z,1505171216.900 [MissionManager](IMPORTANT): Started mission Startup 2017-09-11T23:06:56.900Z,1505171216.900 [Startup] Running Loop=1 2017-09-11T23:06:56.909Z,1505171216.909 [Startup](DEBUG): Aggregate::initialize Startup 2017-09-11T23:06:56.909Z,1505171216.909 [Startup:A.GoToSurface] Running Loop=1 2017-09-11T23:06:56.909Z,1505171216.909 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2017-09-11T23:06:56.909Z,1505171216.909 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2017-09-11T23:06:56.910Z,1505171216.910 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2017-09-11T23:06:56.910Z,1505171216.910 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2017-09-11T23:06:56.911Z,1505171216.911 [Startup:A.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds. 2017-09-11T23:06:56.911Z,1505171216.911 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2017-09-11T23:06:56.934Z,1505171216.934 [Startup:StartupSatComms] Running Loop=1 2017-09-11T23:06:56.935Z,1505171216.935 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2017-09-11T23:06:56.935Z,1505171216.935 [Startup:StartupSatComms:A] Running Loop=1 2017-09-11T23:06:57.248Z,1505171217.248 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2017-09-11T23:07:10.005Z,1505171230.005 [BPC1](ERROR): Failed to parse bank A battery data 2017-09-11T23:07:10.006Z,1505171230.006 [BPC1] Data Fault, FailCount= 1 2017-09-11T23:07:10.006Z,1505171230.006 [BPC1](ERROR): Data Fault 2017-09-11T23:07:10.098Z,1505171230.098 [CBIT](ERROR): Data Fault in component: BPC1 2017-09-11T23:07:11.294Z,1505171231.294 [CBIT](INFO): Clearing failed state for component BPC1 2017-09-11T23:07:11.294Z,1505171231.294 [BPC1] No Fault, FailCount= 1 2017-09-11T23:07:39.640Z,1505171259.640 [DAT](DEBUG): 2017-09-11T23:07:39.782Z,1505171259.782 [DAT](DEBUG): Teledyne Benthos ATM-900 Series 2017-09-11T23:07:40.142Z,1505171260.142 [DAT](DEBUG): MF Frequency Band 2017-09-11T23:07:40.548Z,1505171260.548 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1 2017-09-11T23:07:40.921Z,1505171260.921 [DAT](DEBUG): Jan 3 2000 01:49:06 2017-09-11T23:07:41.328Z,1505171261.328 [DAT](DEBUG): Warning battery low 2017-09-11T23:07:42.545Z,1505171262.545 [BPC1](ERROR): Failed to receive battery data 2017-09-11T23:07:42.545Z,1505171262.545 [BPC1] Communications Fault, FailCount= 1 2017-09-11T23:07:42.546Z,1505171262.546 [BPC1](ERROR): Communications Fault 2017-09-11T23:07:42.573Z,1505171262.573 [CBIT](ERROR): Communications Fault in component: BPC1 2017-09-11T23:07:43.883Z,1505171263.883 [CBIT](INFO): Clearing failed state for component BPC1 2017-09-11T23:07:43.883Z,1505171263.883 [BPC1] No Fault, FailCount= 1 2017-09-11T23:07:56.999Z,1505171276.999 [Startup:StartupSatComms:A](INFO): Timed out from 2017-09-11T23:06:56.9Z 2017-09-11T23:07:56.999Z,1505171276.999 [Startup:StartupSatComms:A] Stopped 2017-09-11T23:07:56.999Z,1505171276.999 [Startup:StartupSatComms:B] Running Loop=1 2017-09-11T23:07:57.386Z,1505171277.386 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2017-09-11T23:08:01.443Z,1505171281.443 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: Warning battery low , available: CONNECT 02400 bits/sec 1 of 4 @Àü 2017-09-11T23:08:01.444Z,1505171281.444 [DAT] Communications Fault, FailCount= 2 2017-09-11T23:08:01.444Z,1505171281.444 [DAT](ERROR): Communications Fault 2017-09-11T23:08:01.478Z,1505171281.478 [CBIT](ERROR): Communications Fault in component: DAT 2017-09-11T23:08:01.560Z,1505171281.560 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170911T225852/Courier0004.lzma 2017-09-11T23:08:01.605Z,1505171281.605 [DAT](INFO): Powering down 2017-09-11T23:08:02.339Z,1505171282.339 [DataOverHttps](INFO): Moved sent file to Logs/20170911T225852/Courier0004.lzma.bak 2017-09-11T23:08:02.339Z,1505171282.339 [DataOverHttps](INFO): SBD MOMSN=5085979 2017-09-11T23:08:02.454Z,1505171282.454 [CBIT](INFO): Clearing failed state for component DAT 2017-09-11T23:08:02.454Z,1505171282.454 [DAT] No Fault, FailCount= 2 2017-09-11T23:08:06.475Z,1505171286.475 [DAT](INFO): Powering up 2017-09-11T23:08:06.475Z,1505171286.475 [DAT](DEBUG): Initializing DAT. 2017-09-11T23:08:11.687Z,1505171291.687 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20170911T230521/Courier0000.lzma 2017-09-11T23:08:12.454Z,1505171292.454 [DataOverHttps](INFO): Moved sent file to Logs/20170911T230521/Courier0000.lzma.bak 2017-09-11T23:08:12.455Z,1505171292.455 [DataOverHttps](INFO): SBD MOMSN=5085981 2017-09-11T23:08:21.771Z,1505171301.771 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170911T225852/Express0005.lzma 2017-09-11T23:08:22.547Z,1505171302.547 [DataOverHttps](INFO): Moved sent file to Logs/20170911T225852/Express0005.lzma.bak 2017-09-11T23:08:22.547Z,1505171302.547 [DataOverHttps](INFO): SBD MOMSN=5085985 2017-09-11T23:08:31.757Z,1505171311.757 [BPC1](ERROR): Failed to receive battery data 2017-09-11T23:08:31.757Z,1505171311.757 [BPC1] Communications Fault, FailCount= 1 2017-09-11T23:08:31.757Z,1505171311.757 [BPC1](ERROR): Communications Fault 2017-09-11T23:08:31.830Z,1505171311.830 [CBIT](ERROR): Communications Fault in component: BPC1 2017-09-11T23:08:31.854Z,1505171311.854 [DataOverHttps](INFO): Sending 681 bytes from file Logs/20170911T230521/Express0001.lzma 2017-09-11T23:08:32.646Z,1505171312.646 [DataOverHttps](INFO): Moved sent file to Logs/20170911T230521/Express0001.lzma.bak 2017-09-11T23:08:32.647Z,1505171312.647 [DataOverHttps](INFO): SBD MOMSN=5085987 2017-09-11T23:08:32.786Z,1505171312.786 [CBIT](INFO): Clearing failed state for component BPC1 2017-09-11T23:08:32.786Z,1505171312.786 [BPC1] No Fault, FailCount= 1 2017-09-11T23:08:33.415Z,1505171313.415 [Startup:StartupSatComms:B] Stopped 2017-09-11T23:08:33.416Z,1505171313.416 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2017-09-11T23:08:33.416Z,1505171313.416 [Startup:StartupSatComms] Stopped 2017-09-11T23:08:33.416Z,1505171313.416 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2017-09-11T23:08:33.417Z,1505171313.417 [Startup](INFO): Completed Startup 2017-09-11T23:08:33.417Z,1505171313.417 [MissionManager](INFO): Startup is completed. 2017-09-11T23:08:33.418Z,1505171313.418 [MissionManager](INFO): Uninitializing Mission Startup 2017-09-11T23:08:33.418Z,1505171313.418 [Startup] Stopped 2017-09-11T23:08:33.418Z,1505171313.418 [Startup](DEBUG): Aggregate::uninitialize Startup 2017-09-11T23:08:33.418Z,1505171313.418 [Startup:A.GoToSurface] Stopped 2017-09-11T23:08:33.418Z,1505171313.418 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2017-09-11T23:08:33.588Z,1505171313.588 [MissionManager](IMPORTANT): Started mission Default 2017-09-11T23:08:33.588Z,1505171313.588 [Default] Running Loop=1 2017-09-11T23:08:33.589Z,1505171313.589 [Default](DEBUG): Aggregate::initialize Default 2017-09-11T23:08:33.589Z,1505171313.589 [Default:B.GoToSurface] Running Loop=1 2017-09-11T23:08:33.589Z,1505171313.589 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2017-09-11T23:08:33.593Z,1505171313.593 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2017-09-11T23:08:33.594Z,1505171313.594 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2017-09-11T23:08:33.594Z,1505171313.594 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2017-09-11T23:08:33.594Z,1505171313.594 [Default:B.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds. 2017-09-11T23:08:33.595Z,1505171313.595 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2017-09-11T23:08:33.595Z,1505171313.595 [Default:A.Wait] Running Loop=1 2017-09-11T23:08:33.595Z,1505171313.595 [Default:A.Wait](DEBUG): Initialize Wait Component. 2017-09-11T23:08:36.852Z,1505171316.852 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2017-09-11T23:08:36.852Z,1505171316.852 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2017-09-11T23:08:36.852Z,1505171316.852 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2017-09-11T23:08:36.855Z,1505171316.855 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2017-09-11T23:08:36.855Z,1505171316.855 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1 2017-09-11T23:08:36.855Z,1505171316.855 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault 2017-09-11T23:08:36.870Z,1505171316.870 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2017-09-11T23:08:36.870Z,1505171316.870 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator 2017-09-11T23:08:37.064Z,1505171317.064 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2017-09-11T23:08:37.064Z,1505171317.064 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2017-09-11T23:08:37.065Z,1505171317.065 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator 2017-09-11T23:08:37.065Z,1505171317.065 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1 2017-09-11T23:08:37.388Z,1505171317.388 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2017-09-11T23:08:37.388Z,1505171317.388 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2017-09-11T23:08:37.389Z,1505171317.389 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2017-09-11T23:08:37.389Z,1505171317.389 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2017-09-11T23:08:37.390Z,1505171317.390 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2017-09-11T23:08:37.390Z,1505171317.390 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2017-09-11T23:08:37.796Z,1505171317.796 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 0.9 s old, using for 20.0 s. 2017-09-11T23:08:38.171Z,1505171318.171 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.3 s old, using for 20.0 s. 2017-09-11T23:08:38.575Z,1505171318.575 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 1.7 s old, using for 20.0 s. 2017-09-11T23:08:38.968Z,1505171318.968 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.1 s old, using for 20.0 s. 2017-09-11T23:08:39.367Z,1505171319.367 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.5 s old, using for 20.0 s. 2017-09-11T23:08:39.775Z,1505171319.775 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 2.9 s old, using for 20.0 s. 2017-09-11T23:08:40.169Z,1505171320.169 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.3 s old, using for 20.0 s. 2017-09-11T23:08:40.576Z,1505171320.576 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 3.7 s old, using for 20.0 s. 2017-09-11T23:08:40.976Z,1505171320.976 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.1 s old, using for 20.0 s. 2017-09-11T23:08:41.380Z,1505171321.380 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.5 s old, using for 20.0 s. 2017-09-11T23:08:41.784Z,1505171321.784 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 4.9 s old, using for 20.0 s. 2017-09-11T23:08:42.190Z,1505171322.190 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.3 s old, using for 20.0 s. 2017-09-11T23:08:42.597Z,1505171322.597 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 5.7 s old, using for 20.0 s. 2017-09-11T23:08:42.987Z,1505171322.987 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.1 s old, using for 20.0 s. 2017-09-11T23:08:43.390Z,1505171323.390 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.5 s old, using for 20.0 s. 2017-09-11T23:08:43.787Z,1505171323.787 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 6.9 s old, using for 20.0 s. 2017-09-11T23:08:44.172Z,1505171324.172 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.3 s old, using for 20.0 s. 2017-09-11T23:08:44.571Z,1505171324.571 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 7.7 s old, using for 20.0 s. 2017-09-11T23:08:44.976Z,1505171324.976 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.1 s old, using for 20.0 s. 2017-09-11T23:08:45.378Z,1505171325.378 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.5 s old, using for 20.0 s. 2017-09-11T23:08:45.778Z,1505171325.778 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 8.9 s old, using for 20.0 s. 2017-09-11T23:08:46.181Z,1505171326.181 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.3 s old, using for 20.0 s. 2017-09-11T23:08:46.581Z,1505171326.581 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 9.7 s old, using for 20.0 s. 2017-09-11T23:08:46.990Z,1505171326.990 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.1 s old, using for 20.0 s. 2017-09-11T23:08:46.995Z,1505171326.995 [Default:A.Wait](INFO): Done Waiting. 2017-09-11T23:08:46.995Z,1505171326.995 [Default:A.Wait] Stopped 2017-09-11T23:08:46.995Z,1505171326.995 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2017-09-11T23:08:47.397Z,1505171327.397 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.5 s old, using for 20.0 s. 2017-09-11T23:08:47.402Z,1505171327.402 [Default:CheckIn] Running Loop=1 2017-09-11T23:08:47.402Z,1505171327.402 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2017-09-11T23:08:47.402Z,1505171327.402 [Default:CheckIn:Read_GPS] Running Loop=1 2017-09-11T23:08:47.789Z,1505171327.789 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 10.9 s old, using for 20.0 s. 2017-09-11T23:08:47.794Z,1505171327.794 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2017-09-11T23:08:48.239Z,1505171328.239 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.4 s old, using for 20.0 s. 2017-09-11T23:08:48.565Z,1505171328.565 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 11.7 s old, using for 20.0 s. 2017-09-11T23:08:48.974Z,1505171328.974 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.1 s old, using for 20.0 s. 2017-09-11T23:08:49.425Z,1505171329.425 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.6 s old, using for 20.0 s. 2017-09-11T23:08:49.778Z,1505171329.778 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 12.9 s old, using for 20.0 s. 2017-09-11T23:08:50.177Z,1505171330.177 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.3 s old, using for 20.0 s. 2017-09-11T23:08:50.614Z,1505171330.614 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 13.8 s old, using for 20.0 s. 2017-09-11T23:08:50.977Z,1505171330.977 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.1 s old, using for 20.0 s. 2017-09-11T23:08:51.385Z,1505171331.385 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.5 s old, using for 20.0 s. 2017-09-11T23:08:51.770Z,1505171331.770 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 14.9 s old, using for 20.0 s. 2017-09-11T23:08:52.229Z,1505171332.229 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.4 s old, using for 20.0 s. 2017-09-11T23:08:52.588Z,1505171332.588 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 15.7 s old, using for 20.0 s. 2017-09-11T23:08:52.991Z,1505171332.991 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.1 s old, using for 20.0 s. 2017-09-11T23:08:53.390Z,1505171333.390 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.5 s old, using for 20.0 s. 2017-09-11T23:08:53.787Z,1505171333.787 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 16.9 s old, using for 20.0 s. 2017-09-11T23:08:54.197Z,1505171334.197 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.3 s old, using for 20.0 s. 2017-09-11T23:08:54.566Z,1505171334.566 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 17.7 s old, using for 20.0 s. 2017-09-11T23:08:54.973Z,1505171334.973 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.1 s old, using for 20.0 s. 2017-09-11T23:08:55.360Z,1505171335.360 [DAT](DEBUG): 2017-09-11T23:08:55.412Z,1505171335.412 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.6 s old, using for 20.0 s. 2017-09-11T23:08:55.741Z,1505171335.741 [DAT](DEBUG): Teledyne Benthos ATM-900 Series 2017-09-11T23:08:55.790Z,1505171335.790 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 18.9 s old, using for 20.0 s. 2017-09-11T23:08:56.135Z,1505171336.135 [DAT](DEBUG): MF Frequency Band 2017-09-11T23:08:56.165Z,1505171336.165 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.3 s old, using for 20.0 s. 2017-09-11T23:08:56.546Z,1505171336.546 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1 2017-09-11T23:08:56.577Z,1505171336.577 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 19.7 s old, using for 20.0 s. 2017-09-11T23:08:56.944Z,1505171336.944 [DAT](DEBUG): Jan 3 2000 01:50:23 2017-09-11T23:08:57.352Z,1505171337.352 [DAT](DEBUG): Warning battery low 2017-09-11T23:09:16.552Z,1505171356.552 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: Warning battery low , available: CONNECT 02400 bits/sec 1 of 4 @Àü 2017-09-11T23:09:16.552Z,1505171356.552 [DAT] Communications Fault, FailCount= 3 2017-09-11T23:09:16.552Z,1505171356.552 [DAT](ERROR): Communications Fault 2017-09-11T23:09:16.687Z,1505171356.687 [CBIT](ERROR): Communications Fault in component: DAT 2017-09-11T23:09:16.964Z,1505171356.964 [DAT](INFO): Powering down 2017-09-11T23:09:17.854Z,1505171357.854 [CBIT](INFO): Clearing failed state for component DAT 2017-09-11T23:09:17.854Z,1505171357.854 [DAT] No Fault, FailCount= 3 2017-09-11T23:09:20.154Z,1505171360.154 [DAT](INFO): Powering up 2017-09-11T23:09:20.154Z,1505171360.154 [DAT](DEBUG): Initializing DAT. 2017-09-11T23:10:09.247Z,1505171409.247 [DAT](DEBUG): 2017-09-11T23:10:09.621Z,1505171409.621 [DAT](DEBUG): Teledyne Benthos ATM-900 Series 2017-09-11T23:10:10.017Z,1505171410.017 [DAT](DEBUG): MF Frequency Band 2017-09-11T23:10:10.415Z,1505171410.415 [DAT](DEBUG): Directional Acoustic Transponder version 8.3.1 2017-09-11T23:10:10.825Z,1505171410.825 [DAT](DEBUG): Jan 3 2000 01:51:37 2017-09-11T23:10:11.224Z,1505171411.224 [DAT](DEBUG): Warning battery low 2017-09-11T23:10:30.410Z,1505171430.410 [DAT](FAULT): failed to initialize; deviceResponse_ loaded: Warning battery low , available: CONNECT 02400 bits/sec 1 of 4 @Àü 2017-09-11T23:10:30.410Z,1505171430.410 [DAT] Communications Fault, FailCount= 4 2017-09-11T23:10:30.410Z,1505171430.410 [DAT](ERROR): Communications Fault 2017-09-11T23:10:30.521Z,1505171430.521 [CBIT](ERROR): Communications Fault in component: DAT 2017-09-11T23:10:30.818Z,1505171430.818 [DAT](INFO): Powering down 2017-09-11T23:10:31.690Z,1505171431.690 [CBIT](INFO): Clearing failed state for component DAT 2017-09-11T23:10:31.690Z,1505171431.690 [DAT] No Fault, FailCount= 4 2017-09-11T23:10:34.040Z,1505171434.040 [DAT](INFO): Powering up 2017-09-11T23:10:34.041Z,1505171434.041 [DAT](DEBUG): Initializing DAT. 2017-09-11T23:11:19.827Z,1505171479.827 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry thi