2014-05-13T16:22:52.380Z,1399998172.380 [Supervisor](DEBUG): Initializing supervisor. 2014-05-13T16:22:52.383Z,1399998172.383 [SyncHandler](DEBUG): Created PCaller Thread at 4034C4E0 2014-05-13T16:22:52.383Z,1399998172.383 [SyncHandler](INFO): Protected caller Thread ID is 772 2014-05-13T16:22:52.384Z,1399998172.384 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2014-05-13T16:22:52.385Z,1399998172.385 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4037C4E0 2014-05-13T16:22:52.385Z,1399998172.385 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 773 2014-05-13T16:22:52.388Z,1399998172.388 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2014-05-13T16:22:52.399Z,1399998172.399 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2014-05-13T16:22:52.400Z,1399998172.400 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 403AC4E0 2014-05-13T16:22:52.401Z,1399998172.401 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 774 2014-05-13T16:22:52.401Z,1399998172.401 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2014-05-13T16:22:52.402Z,1399998172.402 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403DC4E0 2014-05-13T16:22:52.403Z,1399998172.403 [logger ThreadHandler](INFO): Protected caller Thread ID is 775 2014-05-13T16:22:52.405Z,1399998172.405 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2014-05-13T16:22:52.405Z,1399998172.405 [Supervisor](INFO): Looking for Config files in directory: Config/ 2014-05-13T16:22:52.410Z,1399998172.410 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2014-05-13T16:22:52.769Z,1399998172.769 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2014-05-13T16:22:52.771Z,1399998172.771 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2014-05-13T16:22:53.056Z,1399998173.056 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2014-05-13T16:22:53.057Z,1399998173.057 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2014-05-13T16:22:53.144Z,1399998173.144 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2014-05-13T16:22:53.145Z,1399998173.145 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2014-05-13T16:22:53.331Z,1399998173.331 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2014-05-13T16:22:53.333Z,1399998173.333 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2014-05-13T16:22:53.499Z,1399998173.499 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2014-05-13T16:22:53.501Z,1399998173.501 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2014-05-13T16:22:53.810Z,1399998173.810 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2014-05-13T16:22:53.811Z,1399998173.811 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2014-05-13T16:22:53.995Z,1399998173.995 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2014-05-13T16:22:53.996Z,1399998173.996 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2014-05-13T16:22:54.349Z,1399998174.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2014-05-13T16:22:54.350Z,1399998174.350 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2014-05-13T16:22:54.461Z,1399998174.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2014-05-13T16:22:54.463Z,1399998174.463 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2014-05-13T16:22:54.968Z,1399998174.968 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2014-05-13T16:22:54.970Z,1399998174.970 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2014-05-13T16:22:55.082Z,1399998175.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2014-05-13T16:22:55.084Z,1399998175.084 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2014-05-13T16:22:55.171Z,1399998175.171 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2014-05-13T16:22:55.282Z,1399998175.282 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2014-05-13T16:22:55.283Z,1399998175.283 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2014-05-13T16:22:55.391Z,1399998175.391 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2014-05-13T16:22:55.569Z,1399998175.569 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2014-05-13T16:22:55.730Z,1399998175.730 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2014-05-13T16:22:55.732Z,1399998175.732 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2014-05-13T16:22:55.737Z,1399998175.737 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2014-05-13T16:22:55.848Z,1399998175.848 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2014-05-13T16:22:55.983Z,1399998175.983 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2014-05-13T16:22:56.082Z,1399998176.082 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2014-05-13T16:22:56.177Z,1399998176.177 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2014-05-13T16:22:56.327Z,1399998176.327 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2014-05-13T16:22:56.448Z,1399998176.448 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2014-05-13T16:22:56.537Z,1399998176.537 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2014-05-13T16:22:56.647Z,1399998176.647 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2014-05-13T16:22:56.751Z,1399998176.751 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2014-05-13T16:22:56.851Z,1399998176.851 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2014-05-13T16:22:56.941Z,1399998176.941 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Estimation.cfg 2014-05-13T16:22:57.041Z,1399998177.041 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2014-05-13T16:22:57.045Z,1399998177.045 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2014-05-13T16:22:57.743Z,1399998177.743 [AHRS_sp3003D] Loaded 2014-05-13T16:22:57.744Z,1399998177.744 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2014-05-13T16:22:58.040Z,1399998178.040 [Batt_Ocean_Server] Loaded 2014-05-13T16:22:58.040Z,1399998178.040 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread. 2014-05-13T16:22:58.054Z,1399998178.054 [Depth_Keller] Loaded 2014-05-13T16:22:58.054Z,1399998178.054 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2014-05-13T16:22:58.059Z,1399998178.059 [DropWeight] Loaded 2014-05-13T16:22:58.059Z,1399998178.059 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2014-05-13T16:22:58.200Z,1399998178.200 [DVL_micro] Loaded 2014-05-13T16:22:58.201Z,1399998178.201 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2014-05-13T16:22:58.301Z,1399998178.301 [NAL9602] Loaded 2014-05-13T16:22:58.301Z,1399998178.301 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2014-05-13T16:22:58.353Z,1399998178.353 [Onboard] Loaded 2014-05-13T16:22:58.353Z,1399998178.353 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2014-05-13T16:22:58.360Z,1399998178.360 [Radio_Freewave] Loaded 2014-05-13T16:22:58.360Z,1399998178.360 [ComponentRegistry](DEBUG): Component "Radio_Freewave" handled in its own thread. 2014-05-13T16:22:58.362Z,1399998178.362 [Radio_Freewave ThreadHandler](DEBUG): Created PCaller Thread at 406074E0 2014-05-13T16:22:58.362Z,1399998178.362 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 857 2014-05-13T16:22:58.369Z,1399998178.369 [SCPI] Loaded 2014-05-13T16:22:58.369Z,1399998178.369 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread. 2014-05-13T16:22:58.370Z,1399998178.370 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2014-05-13T16:22:58.370Z,1399998178.370 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2014-05-13T16:22:58.569Z,1399998178.569 [InternalSim] Loaded 2014-05-13T16:22:58.569Z,1399998178.569 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2014-05-13T16:22:58.569Z,1399998178.569 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2014-05-13T16:22:58.572Z,1399998178.572 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2014-05-13T16:22:58.864Z,1399998178.864 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2014-05-13T16:22:58.864Z,1399998178.864 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2014-05-13T16:22:58.873Z,1399998178.873 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2014-05-13T16:22:58.878Z,1399998178.878 [AsyncPiEstimator] Loaded 2014-05-13T16:22:58.878Z,1399998178.878 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2014-05-13T16:22:58.879Z,1399998178.879 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406E44E0 2014-05-13T16:22:58.880Z,1399998178.880 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 858 2014-05-13T16:22:58.880Z,1399998178.880 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2014-05-13T16:22:58.882Z,1399998178.882 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2014-05-13T16:22:58.979Z,1399998178.979 [DeadReckonUsingMultipleVelocitySources] Loaded 2014-05-13T16:22:58.979Z,1399998178.979 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2014-05-13T16:22:59.025Z,1399998179.025 [DeadReckonWithRespectToWater] Loaded 2014-05-13T16:22:59.025Z,1399998179.025 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToWater" handled in the control thread. 2014-05-13T16:22:59.072Z,1399998179.072 [DeadReckonWithRespectToSeafloor] Loaded 2014-05-13T16:22:59.072Z,1399998179.072 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonWithRespectToSeafloor" handled in the control thread. 2014-05-13T16:22:59.120Z,1399998179.120 [DeadReckonUsingDVLWaterTrack] Loaded 2014-05-13T16:22:59.120Z,1399998179.120 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingDVLWaterTrack" handled in the control thread. 2014-05-13T16:22:59.136Z,1399998179.136 [NavChart] Loaded 2014-05-13T16:22:59.137Z,1399998179.137 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2014-05-13T16:22:59.141Z,1399998179.141 [UniversalFixResidualReporter] Loaded 2014-05-13T16:22:59.141Z,1399998179.141 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2014-05-13T16:22:59.142Z,1399998179.142 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2014-05-13T16:22:59.142Z,1399998179.142 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2014-05-13T16:22:59.214Z,1399998179.214 [VerticalControl](DEBUG): Construct VerticalControl. 2014-05-13T16:22:59.325Z,1399998179.325 [VerticalControl] Loaded 2014-05-13T16:22:59.325Z,1399998179.325 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2014-05-13T16:22:59.326Z,1399998179.326 [HorizontalControl](DEBUG): Construct HorizontalControl. 2014-05-13T16:22:59.395Z,1399998179.395 [HorizontalControl] Loaded 2014-05-13T16:22:59.395Z,1399998179.395 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2014-05-13T16:22:59.396Z,1399998179.396 [SpeedControl](DEBUG): Construct SpeedControl. 2014-05-13T16:22:59.398Z,1399998179.398 [SpeedControl] Loaded 2014-05-13T16:22:59.398Z,1399998179.398 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2014-05-13T16:22:59.399Z,1399998179.399 [LoopControl](DEBUG): Construct LoopControl. 2014-05-13T16:22:59.399Z,1399998179.399 [LoopControl] Loaded 2014-05-13T16:22:59.399Z,1399998179.399 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2014-05-13T16:22:59.400Z,1399998179.400 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2014-05-13T16:22:59.402Z,1399998179.402 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2014-05-13T16:22:59.432Z,1399998179.432 [DepthRateCalculator] Loaded 2014-05-13T16:22:59.432Z,1399998179.432 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2014-05-13T16:22:59.437Z,1399998179.437 [PitchRateCalculator] Loaded 2014-05-13T16:22:59.438Z,1399998179.438 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2014-05-13T16:22:59.445Z,1399998179.445 [SpeedCalculator] Loaded 2014-05-13T16:22:59.445Z,1399998179.445 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2014-05-13T16:22:59.462Z,1399998179.462 [TempGradientCalculator] Loaded 2014-05-13T16:22:59.462Z,1399998179.462 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2014-05-13T16:22:59.467Z,1399998179.467 [YawRateCalculator] Loaded 2014-05-13T16:22:59.467Z,1399998179.467 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2014-05-13T16:22:59.468Z,1399998179.468 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2014-05-13T16:22:59.470Z,1399998179.470 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2014-05-13T16:22:59.600Z,1399998179.600 [CTD_NeilBrown] Loaded 2014-05-13T16:22:59.600Z,1399998179.600 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2014-05-13T16:22:59.601Z,1399998179.601 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407864E0 2014-05-13T16:22:59.602Z,1399998179.602 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 859 2014-05-13T16:22:59.615Z,1399998179.615 [ISUS] Loaded 2014-05-13T16:22:59.615Z,1399998179.615 [ComponentRegistry](DEBUG): SyncComponent "ISUS" handled in the control thread. 2014-05-13T16:22:59.630Z,1399998179.630 [PAR_Licor] Loaded 2014-05-13T16:22:59.630Z,1399998179.630 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2014-05-13T16:22:59.666Z,1399998179.666 [WetLabsBB2FL] Loaded 2014-05-13T16:22:59.667Z,1399998179.667 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2014-05-13T16:22:59.668Z,1399998179.668 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407B64E0 2014-05-13T16:22:59.668Z,1399998179.668 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 860 2014-05-13T16:22:59.669Z,1399998179.669 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2014-05-13T16:22:59.669Z,1399998179.669 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2014-05-13T16:22:59.790Z,1399998179.790 [SBIT](DEBUG): Construct Startup Built In Test. 2014-05-13T16:22:59.801Z,1399998179.801 [SBIT] Loaded 2014-05-13T16:22:59.802Z,1399998179.802 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2014-05-13T16:22:59.802Z,1399998179.802 [IBIT](DEBUG): Construct Initiated Built In Test. 2014-05-13T16:22:59.815Z,1399998179.815 [IBIT] Loaded 2014-05-13T16:22:59.816Z,1399998179.816 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2014-05-13T16:22:59.818Z,1399998179.818 [CBIT](DEBUG): Construct CBIT Built In Test. 2014-05-13T16:22:59.887Z,1399998179.887 [CBIT] Loaded 2014-05-13T16:22:59.887Z,1399998179.887 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2014-05-13T16:22:59.888Z,1399998179.888 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2014-05-13T16:22:59.890Z,1399998179.890 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2014-05-13T16:22:59.960Z,1399998179.960 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2014-05-13T16:22:59.962Z,1399998179.962 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2014-05-13T16:23:00.086Z,1399998180.086 [BuoyancyServo] Loaded 2014-05-13T16:23:00.086Z,1399998180.086 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2014-05-13T16:23:00.099Z,1399998180.099 [ElevatorServo] Loaded 2014-05-13T16:23:00.099Z,1399998180.099 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2014-05-13T16:23:00.111Z,1399998180.111 [MassServo] Loaded 2014-05-13T16:23:00.111Z,1399998180.111 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2014-05-13T16:23:00.123Z,1399998180.123 [RudderServo] Loaded 2014-05-13T16:23:00.123Z,1399998180.123 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2014-05-13T16:23:00.135Z,1399998180.135 [ThrusterServo] Loaded 2014-05-13T16:23:00.135Z,1399998180.135 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2014-05-13T16:23:00.136Z,1399998180.136 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2014-05-13T16:23:00.136Z,1399998180.136 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2014-05-13T16:23:00.175Z,1399998180.175 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2014-05-13T16:23:00.177Z,1399998180.177 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2014-05-13T16:23:00.178Z,1399998180.178 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2014-05-13T16:23:00.185Z,1399998180.185 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2014-05-13T16:23:00.186Z,1399998180.186 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 408854E0 2014-05-13T16:23:00.186Z,1399998180.186 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 861 2014-05-13T16:23:00.191Z,1399998180.191 [Supervisor](INFO): Main Thread ID is 762 2014-05-13T16:23:00.191Z,1399998180.191 [Supervisor](DEBUG): Running supervisor. 2014-05-13T16:23:00.192Z,1399998180.192 [CommandLine ThreadHandler](INFO): Handler Thread ID is 862 2014-05-13T16:23:00.195Z,1399998180.195 [controlThread ThreadHandler](INFO): Handler Thread ID is 863 2014-05-13T16:23:00.195Z,1399998180.195 [controlThread](DEBUG): Initializing ControlThread 2014-05-13T16:23:00.198Z,1399998180.198 [logger ThreadHandler](INFO): Handler Thread ID is 864 2014-05-13T16:23:00.216Z,1399998180.216 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 865 2014-05-13T16:23:00.232Z,1399998180.232 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 866 2014-05-13T16:23:00.233Z,1399998180.233 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2014-05-13T16:23:00.252Z,1399998180.252 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 867 2014-05-13T16:23:00.253Z,1399998180.253 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2014-05-13T16:23:00.256Z,1399998180.256 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2014-05-13T16:23:00.258Z,1399998180.258 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 869 2014-05-13T16:23:00.260Z,1399998180.260 [WetLabsBB2FL](INFO): Powering down 2014-05-13T16:23:00.300Z,1399998180.300 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 870 2014-05-13T16:23:00.310Z,1399998180.310 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2014-05-13T16:23:00.313Z,1399998180.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2014-05-13T16:23:00.313Z,1399998180.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2014-05-13T16:23:00.313Z,1399998180.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2014-05-13T16:23:00.313Z,1399998180.313 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2014-05-13T16:23:00.314Z,1399998180.314 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2014-05-13T16:23:00.314Z,1399998180.314 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2014-05-13T16:23:00.314Z,1399998180.314 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2014-05-13T16:23:00.314Z,1399998180.314 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2014-05-13T16:23:02.081Z,1399998182.081 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized 2014-05-13T16:23:02.114Z,1399998182.114 [InternalSim](DEBUG): InternalSim initializing... 2014-05-13T16:23:02.416Z,1399998182.416 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2014-05-13T16:23:02.416Z,1399998182.416 [DeadReckonWithRespectToWater](DEBUG): Initializing DeadReckonWithRespectToWater component. 2014-05-13T16:23:02.416Z,1399998182.416 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2014-05-13T16:23:02.417Z,1399998182.417 [DeadReckonUsingDVLWaterTrack](DEBUG): Initializing DeadReckonUsingDVLWaterTrack component. 2014-05-13T16:23:02.417Z,1399998182.417 [NavChart](DEBUG): Initialize NavChart Navigation. 2014-05-13T16:23:02.417Z,1399998182.417 [UniversalFixResidualReporter](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2014-05-13T16:23:02.418Z,1399998182.418 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2014-05-13T16:23:02.435Z,1399998182.435 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2014-05-13T16:23:02.436Z,1399998182.436 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2014-05-13T16:23:02.436Z,1399998182.436 [LoopControl](DEBUG): Initialize LoopControlComponent. 2014-05-13T16:23:02.437Z,1399998182.437 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2014-05-13T16:23:02.437Z,1399998182.437 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2014-05-13T16:23:02.438Z,1399998182.438 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2014-05-13T16:23:02.438Z,1399998182.438 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2014-05-13T16:23:02.438Z,1399998182.438 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2014-05-13T16:23:02.440Z,1399998182.440 [SBIT](INFO): Initialize SBIT Component. 2014-05-13T16:23:02.440Z,1399998182.440 [SBIT](IMPORTANT): Tethys CM Info: $Rev:11288 2014-05-13T16:23:02.441Z,1399998182.441 [SBIT](IMPORTANT): Kernel Release:2.6.27.8 2014-05-13T16:23:02.441Z,1399998182.441 [SBIT](IMPORTANT): Kernel Version:#639 PREEMPT Wed Mar 12 12:53:33 PDT 2014 2014-05-13T16:23:02.442Z,1399998182.442 [IBIT](INFO): Initialize IBIT Component. 2014-05-13T16:23:02.443Z,1399998182.443 [CBIT](DEBUG): Initialize CBIT Component. 2014-05-13T16:23:02.451Z,1399998182.451 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2014-05-13T16:23:02.477Z,1399998182.477 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2014-05-13T16:23:02.501Z,1399998182.501 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2014-05-13T16:23:02.518Z,1399998182.518 [MissionManager](DEBUG): 2014-05-13T16:23:02.518Z,1399998182.518 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2014-05-13T16:23:02.618Z,1399998182.618 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2014-05-13T16:23:02.672Z,1399998182.672 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2014-05-13T16:23:02.675Z,1399998182.675 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2014-05-13T16:23:02.708Z,1399998182.708 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2014-05-13T16:23:02.711Z,1399998182.711 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2014-05-13T16:23:02.738Z,1399998182.738 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2014-05-13T16:23:02.797Z,1399998182.797 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Construct. 2014-05-13T16:23:02.800Z,1399998182.800 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Construct GoToSurface. 2014-05-13T16:23:02.824Z,1399998182.824 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2014-05-13T16:23:02.845Z,1399998182.845 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,SCPI,ISUS,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonWithRespectToWater,DeadReckonWithRespectToSeafloor,DeadReckonUsingDVLWaterTrack,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2014-05-13T16:23:02.898Z,1399998182.898 [Radio_Freewave](INFO): Powering up 2014-05-13T16:23:02.968Z,1399998182.968 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2014-05-13T16:23:03.153Z,1399998183.153 [DVL_micro](INFO): Initializing 2014-05-13T16:23:03.557Z,1399998183.557 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:03.565Z,1399998183.565 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2014-05-13T16:23:03.579Z,1399998183.579 [ElevatorServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:03.585Z,1399998183.585 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2014-05-13T16:23:03.599Z,1399998183.599 [MassServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:03.605Z,1399998183.605 [MassServo](DEBUG): Initializing MassServo. 2014-05-13T16:23:03.631Z,1399998183.631 [RudderServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:03.637Z,1399998183.637 [RudderServo](DEBUG): Initializing RudderServo. 2014-05-13T16:23:03.651Z,1399998183.651 [ThrusterServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:03.657Z,1399998183.657 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2014-05-13T16:23:03.706Z,1399998183.706 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0 2014-05-13T16:23:03.993Z,1399998183.993 [NAL9602](INFO): Powering up NAL9602 2014-05-13T16:23:04.446Z,1399998184.446 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout 2014-05-13T16:23:04.447Z,1399998184.447 [BuoyancyServo](FAULT): Buoyancy failed to initialize 2014-05-13T16:23:04.447Z,1399998184.447 [BuoyancyServo] Communications Fault, FailCount= 1 2014-05-13T16:23:04.447Z,1399998184.447 [BuoyancyServo](ERROR): Communications Fault 2014-05-13T16:23:04.681Z,1399998184.681 [CBIT](ERROR): Communications Fault in component: BuoyancyServo 2014-05-13T16:23:05.120Z,1399998185.120 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2014-05-13T16:23:05.122Z,1399998185.122 [BuoyancyServo](INFO): Powering down 2014-05-13T16:23:07.674Z,1399998187.674 [CBIT](INFO): Clearing failed state for component BuoyancyServo 2014-05-13T16:23:07.674Z,1399998187.674 [BuoyancyServo] No Fault, FailCount= 1 2014-05-13T16:23:08.120Z,1399998188.120 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2014-05-13T16:23:08.121Z,1399998188.121 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2014-05-13T16:23:14.546Z,1399998194.546 [NAL9602](INFO): NAL9602 initialized 2014-05-13T16:23:18.140Z,1399998198.140 [SBIT](IMPORTANT): Beginning Startup BIT 2014-05-13T16:23:18.142Z,1399998198.142 [CBIT](IMPORTANT): Beginning GF scan 2014-05-13T16:23:28.628Z,1399998208.628 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 45 of 46 2014-05-13T16:23:28.628Z,1399998208.628 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 5.7 6.1 6.0 5.6 -147.6 -24.5 128.4 57.1 0 0 0 0 0 0 0 0 -368.4 -108.9 3.6 1 -377.7 -65.6 -24.0 1 0 0 0 0 0 0 0 0 -5.65 -5.97 353.2 5.6 14.9 00 1489 73 2014-05-13T16:23:37.366Z,1399998217.366 [NAL9602](INFO): SBD MO Status=2, MOMSN=28396, MT Status=2, MTMSN=0 2014-05-13T16:23:37.366Z,1399998217.366 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:23:45.155Z,1399998225.155 [CBIT](IMPORTANT): No ground fault detected 2014-05-13T16:23:48.177Z,1399998228.177 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=28396, MT Status=1, MTMSN=1845 2014-05-13T16:23:48.178Z,1399998228.178 [NAL9602](INFO): Data available in MT queue 2014-05-13T16:23:48.820Z,1399998228.820 [NAL9602](INFO): Received command:! ps -ear | grep -rni lrauv 2014-05-13T16:23:48.908Z,1399998228.908 [CommandLine](IMPORTANT): got command ! ps -ear | grep -rni lrauv 2014-05-13T16:23:49.572Z,1399998229.572 [CommandLine](IMPORTANT): 2: 890 pts/0 R+ 0:00 ps -ear TMPFS_SIZE=512k INETD_ARGS= CONSOLE=/dev/console HOSTNAME=lrauv-daphne SHELL=/bin/sh TERM=screen SYSCFG_DHCPC_CMD=udhcpc -H lrauv-daphne -b -i READONLY_FS= DHCP_ARG= TMPFS=tmpfs NTP_SERVER=134.89.12.49 INIT_VERSION=sysvinit-2.85 INTERFACE0=eth0 SYSCFG_IFACE0=y TERMCAP=SC|screen|VT 100/ANSI X3.64 virtual terminal:\??:DO=\E[%dB:LE=\E[%dD:RI=\E[%dC:UP=\E[%dA:bs:bt=\E[Z:\??:cd=\E[J:ce=\E[K:cl=\E[H\E[J:cm=\E[%i%d;%dH:ct=\E[3g:\??:do=^J:nd=\E[C:pt:rc=\E8:rs=\Ec:sc=\E7:st=\EH:up=\EM:\??:le=^H:bl=^G:cr=^M:it#8:ho=\E[H:nw=\EE:ta=^I:is=\E)0:\??:li#24:co#80:am:xn:xv:LP:sr=\EM:al=\E[L:AL=\E[%dL:\??:cs=\E[%i%d;%dr:dl=\E[M:DL=\E[%dM:dc=\E[P:DC=\E[%dP:\??:im=\E[4h:ei=\E[4l:mi:IC=\E[%d@:ks=\E[?1h\E=:\??:ke=\E[?1l\E>:vi=\E[?25l:ve=\E[34h\E[?25h:vs=\E[34l:\??:ti=\E[?1049h:te=\E[?1049l:k0=\E[10~:k1=\EOP:k2=\EOQ:\??:k3=\EOR:k4=\EOS:k5=\E[15~:k6=\E[17~:k7=\E[18~:\??:k8=\E[19~:k9=\E[20~:k;=\E[21~:F1=\E[23~:F2=\E[24~:\??:kh=\E[1~:@1=\E[1~:kH=\E[4~:@7=\E[4~:kN=\E[6~:kP=\E[5~:\??:kI=\E[2~:kD=\E[3~:ku=\EOA:kd=\EOB:kr=\EOC:kl=\EOD: PATH=/usr/local/sbin:/sbin:/bin:/usr/sbin:/usr/bin STY=761.app _=/bin/ps RUNLEVEL=S PWD=/mnt/mmc/LRAUV BOA_ARGS= NMBD_ARGS= MODLIST= PREVLEVEL=N ADJTIMEX_FREQ=-3091535 RAMDIRS=/tmp /var SHLVL=4 SMBD_ARGS= IPADDR0=dhcp DEPLOYMENT_STYLE=JFFS2 ADJTIMEX_TICK=10016 WINDOW=0 DROPBEAR_ARGS= 2014-05-13T16:23:50.485Z,1399998230.485 [NAL9602](IMPORTANT): GPS fix at: 1399998227.00 2014-05-13T16:23:58.076Z,1399998238.076 [NAL9602](INFO): Powering down 2014-05-13T16:24:07.226Z,1399998247.226 [DVL_micro](ERROR): NQ1 string checksum mismatch. Reported:88 Calculated:90 2014-05-13T16:24:07.227Z,1399998247.227 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 6 6.5 6.2 -62.5 29.6 96.1 -21.2 0 0 0 0 0 0 0 0 -211.7 67.8 11.3 1 -216.9 -47.9 -14.2 1 0 0 0 0 0 0 0 0 -4.38 -5.50 30.2 6.2 14.9 0.005 35.0 1489 88 2014-05-13T16:24:12.458Z,1399998252.458 [SBIT](IMPORTANT): SBIT PASSED 2014-05-13T16:24:12.839Z,1399998252.839 [MissionManager](IMPORTANT): Started mission Startup 2014-05-13T16:24:12.839Z,1399998252.839 [Startup] Running Loop=1 2014-05-13T16:24:12.839Z,1399998252.839 [Startup](INFO): Aggregate::initialize Startup 2014-05-13T16:24:12.839Z,1399998252.839 [Startup:A.GoToSurface] Running Loop=1 2014-05-13T16:24:12.839Z,1399998252.839 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:24:12.866Z,1399998252.866 [Startup:StartupSatComms] Running Loop=1 2014-05-13T16:24:12.866Z,1399998252.866 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2014-05-13T16:24:12.866Z,1399998252.866 [Startup:StartupSatComms:A] Running Loop=1 2014-05-13T16:24:13.304Z,1399998253.304 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2014-05-13T16:24:13.748Z,1399998253.748 [NAL9602](INFO): Powering up 2014-05-13T16:24:24.659Z,1399998264.659 [NAL9602](INFO): NAL9602 initialized 2014-05-13T16:24:45.158Z,1399998285.158 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=28397, MT Status=1, MTMSN=1846 2014-05-13T16:24:45.158Z,1399998285.158 [NAL9602](INFO): Data available in MT queue 2014-05-13T16:24:45.828Z,1399998285.828 [NAL9602](INFO): Received command:! ps -eaf | grep -rni lrauv 2014-05-13T16:24:45.888Z,1399998285.888 [CommandLine](IMPORTANT): got command ! ps -eaf | grep -rni lrauv 2014-05-13T16:24:46.158Z,1399998286.158 [CommandLine](IMPORTANT): 21:root 733 1 0 16:22 ? 00:00:00 udhcpc -H lrauv-daphne -b -i eth0 25:root 761 1 0 16:22 ? 00:00:00 /usr/bin/SCREEN -dmS app ./bin/LRAUV 26:root 762 761 62 16:22 pts/0 00:01:12 ./bin/LRAUV 28:root 765 1 0 16:22 ? 00:00:00 /bin/bash /mnt/mmc/LRAUV/fake_cron 39:root 894 762 0 16:24 pts/0 00:00:00 sh -c ps -eaf | grep -rni lrauv 41:root 896 894 0 16:24 pts/0 00:00:00 grep -rni lrauv 2014-05-13T16:24:47.212Z,1399998287.212 [NAL9602](IMPORTANT): GPS fix at: 1399998284.00 2014-05-13T16:24:47.262Z,1399998287.262 [Startup:StartupSatComms:A] Stopped 2014-05-13T16:24:47.262Z,1399998287.262 [Startup:StartupSatComms:B] Running Loop=1 2014-05-13T16:24:47.763Z,1399998287.763 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2014-05-13T16:25:05.805Z,1399998305.805 [DVL_micro](ERROR): DVL Failure: Failed to read in all data items. Got 38 of 46 2014-05-13T16:25:05.805Z,1399998305.805 [DVL_micro](ERROR): Failed to parse DVL response:$#NQ.RES 0X0000 1 1 1 1 6.4 6.8 7.0 6.3 -76.4 61.8 72.2 -16.0.2 1 -203.9 91.8 -15.3 1 0 0 0 0 0 0 0 0 -3.70 -5.70 3.4 6.3 14.8 0.005 35.0 1489 117 2014-05-13T16:25:09.715Z,1399998309.715 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=28398, MT Status=1, MTMSN=1847 2014-05-13T16:25:09.765Z,1399998309.765 [NAL9602](INFO): Sent 74 bytes from file Logs/20140513T161103/Courier0012.lzma 2014-05-13T16:25:09.765Z,1399998309.765 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:25:09.767Z,1399998309.767 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T161103/Courier0012.lzma.parts/0000.sbd 2014-05-13T16:25:09.767Z,1399998309.767 [NAL9602](INFO): Completed sending Logs/20140513T161103/Courier0012.lzma 2014-05-13T16:25:10.630Z,1399998310.630 [NAL9602](INFO): Received command:! grep "Thread ID" /mnt/mmc/LRAUV/Logs/latest/syslog | tee /mnt/mmc/LRAUV/Logs/latest/threads 2014-05-13T16:25:10.727Z,1399998310.727 [CommandLine](IMPORTANT): got command ! grep "Thread ID" /mnt/mmc/LRAUV/Logs/latest/syslog | tee /mnt/mmc/LRAUV/Logs/latest/threads 2014-05-13T16:25:10.856Z,1399998310.856 [CommandLine](IMPORTANT): 2014-05-13T16:22:52.383Z,1399998172.383 [SyncHandler](INFO): Protected caller Thread ID is 772 2014-05-13T16:22:52.385Z,1399998172.385 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 773 2014-05-13T16:22:52.401Z,1399998172.401 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 774 2014-05-13T16:22:52.403Z,1399998172.403 [logger ThreadHandler](INFO): Protected caller Thread ID is 775 2014-05-13T16:22:58.362Z,1399998178.362 [Radio_Freewave ThreadHandler](INFO): Protected caller Thread ID is 857 2014-05-13T16:22:58.880Z,1399998178.880 [AsyncPiEstimator ThreadHandler](INFO): Protected caller Thread ID is 858 2014-05-13T16:22:59.602Z,1399998179.602 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 859 2014-05-13T16:22:59.668Z,1399998179.668 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 860 2014-05-13T16:23:00.186Z,1399998180.186 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 861 2014-05-13T16:23:00.191Z,1399998180.191 [Supervisor](INFO): Main Thread ID is 762 2014-05-13T16:23:00.192Z,1399998180.192 [CommandLine ThreadHandler](INFO): Handler Thread ID is 862 2014-05-13T16:23:00.195Z,1399998180.195 [controlThread ThreadHandler](INFO): Handler Thread ID is 863 2014-05-13T16:23:00.198Z,1399998180.198 [logger ThreadHandler](INFO): Handler Thread ID is 864 2014-05-13T16:23:00.216Z,1399998180.216 [Radio_Freewave ThreadHandler](INFO): Handler Thread ID is 865 2014-05-13T16:23:00.232Z,1399998180.232 [AsyncPiEstimator ThreadHandler](INFO): Handler Thread ID is 866 2014-05-13T16:23:00.252Z,1399998180.252 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 867 2014-05-13T16:23:00.258Z,1399998180.258 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 869 2014-05-13T16:23:00.300Z,1399998180.300 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 870 2014-05-13T16:25:25.839Z,1399998325.839 [NAL9602](INFO): SBD MO Status=1, MOMSN=28399, MT Status=0, MTMSN=0 2014-05-13T16:25:25.890Z,1399998325.890 [NAL9602](INFO): Sent 296 bytes from file Logs/20140513T162252/Courier0000.lzma 2014-05-13T16:25:25.890Z,1399998325.890 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:25:25.892Z,1399998325.892 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0000.lzma.parts/0000.sbd 2014-05-13T16:25:25.892Z,1399998325.892 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0000.lzma 2014-05-13T16:25:33.347Z,1399998333.347 [NAL9602](INFO): SBD MO Status=1, MOMSN=28400, MT Status=0, MTMSN=0 2014-05-13T16:25:33.414Z,1399998333.414 [NAL9602](INFO): Sent 120 bytes from file Logs/20140513T161103/Express0009.lzma 2014-05-13T16:25:33.414Z,1399998333.414 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:25:33.415Z,1399998333.415 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T161103/Express0009.lzma.parts/0000.sbd 2014-05-13T16:25:33.416Z,1399998333.416 [NAL9602](INFO): Completed sending Logs/20140513T161103/Express0009.lzma 2014-05-13T16:25:44.090Z,1399998344.090 [NAL9602](INFO): SBD MO Status=1, MOMSN=28401, MT Status=0, MTMSN=0 2014-05-13T16:25:44.138Z,1399998344.138 [NAL9602](INFO): Sent 188 bytes from file Logs/20140513T161103/Express0013.lzma 2014-05-13T16:25:44.138Z,1399998344.138 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:25:44.141Z,1399998344.141 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T161103/Express0013.lzma.parts/0000.sbd 2014-05-13T16:25:44.141Z,1399998344.141 [NAL9602](INFO): Completed sending Logs/20140513T161103/Express0013.lzma 2014-05-13T16:25:47.297Z,1399998347.297 [Startup:StartupSatComms:B](INFO): Timed out from 2014-05-13T16:24:47.3Z 2014-05-13T16:25:47.297Z,1399998347.297 [Startup:StartupSatComms:B] Stopped 2014-05-13T16:25:47.297Z,1399998347.297 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2014-05-13T16:25:47.297Z,1399998347.297 [Startup:StartupSatComms] Stopped 2014-05-13T16:25:47.298Z,1399998347.298 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2014-05-13T16:25:47.298Z,1399998347.298 [Startup](INFO): Completed Startup 2014-05-13T16:25:47.299Z,1399998347.299 [Startup] Stopped 2014-05-13T16:25:47.299Z,1399998347.299 [Startup](INFO): Aggregate::uninitialize Startup 2014-05-13T16:25:47.299Z,1399998347.299 [Startup:A.GoToSurface] Stopped 2014-05-13T16:25:47.299Z,1399998347.299 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:25:47.875Z,1399998347.875 [MissionManager](IMPORTANT): Started mission Default 2014-05-13T16:25:47.875Z,1399998347.875 [Default] Running Loop=1 2014-05-13T16:25:47.875Z,1399998347.875 [Default](INFO): Aggregate::initialize Default 2014-05-13T16:25:47.875Z,1399998347.875 [Default:Iridium] Running Loop=1 2014-05-13T16:25:47.875Z,1399998347.875 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2014-05-13T16:25:47.875Z,1399998347.875 [Default:Iridium:A.SetSpeed] Running Loop=1 2014-05-13T16:25:47.876Z,1399998347.876 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:25:47.876Z,1399998347.876 [Default:Iridium:B.GoToSurface] Running Loop=1 2014-05-13T16:25:47.876Z,1399998347.876 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:25:47.876Z,1399998347.876 [Default:CallIridium] Running Loop=1 2014-05-13T16:25:47.877Z,1399998347.877 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2014-05-13T16:25:47.877Z,1399998347.877 [Default:CallIridium:A] Running Loop=1 2014-05-13T16:25:47.879Z,1399998347.879 [Default:CallIridium:A] Stopped 2014-05-13T16:25:47.879Z,1399998347.879 [Default:CallIridium:B] Running Loop=1 2014-05-13T16:25:47.879Z,1399998347.879 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2014-05-13T16:25:47.904Z,1399998347.904 [Default:Iridium:B.GoToSurface] Stopped 2014-05-13T16:25:47.905Z,1399998347.905 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:25:47.905Z,1399998347.905 [Default:Iridium:Read_Iridium] Running Loop=1 2014-05-13T16:25:47.905Z,1399998347.905 [Default:Iridium:A.SetSpeed] Running Loop=1 2014-05-13T16:25:47.918Z,1399998347.918 [Default:GPS] Running Loop=1 2014-05-13T16:25:47.918Z,1399998347.918 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2014-05-13T16:25:47.918Z,1399998347.918 [Default:GPS:A.SetSpeed] Running Loop=1 2014-05-13T16:25:47.918Z,1399998347.918 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:25:47.919Z,1399998347.919 [Default:GPS:B.GoToSurface] Running Loop=1 2014-05-13T16:25:47.919Z,1399998347.919 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:25:47.936Z,1399998347.936 [Default:GPS:B.GoToSurface] Stopped 2014-05-13T16:25:47.937Z,1399998347.937 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:25:47.937Z,1399998347.937 [Default:GPS:Read_GPS] Running Loop=1 2014-05-13T16:25:47.937Z,1399998347.937 [Default:GPS:A.SetSpeed] Running Loop=1 2014-05-13T16:25:48.372Z,1399998348.372 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2014-05-13T16:25:48.379Z,1399998348.379 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2014-05-13T16:25:54.839Z,1399998354.839 [NAL9602](INFO): SBD MO Status=1, MOMSN=28402, MT Status=0, MTMSN=0 2014-05-13T16:25:54.895Z,1399998354.895 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:25:54.895Z,1399998354.895 [NAL9602](INFO): Packets left to send: 5 2014-05-13T16:25:55.021Z,1399998355.021 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0005.sbd 2014-05-13T16:26:06.530Z,1399998366.530 [NAL9602](INFO): SBD MO Status=1, MOMSN=28403, MT Status=0, MTMSN=0 2014-05-13T16:26:06.585Z,1399998366.585 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T162252/Courier0004.lzma 2014-05-13T16:26:06.585Z,1399998366.585 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:26:06.587Z,1399998366.587 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0004.lzma.parts/0000.sbd 2014-05-13T16:26:06.587Z,1399998366.587 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0004.lzma 2014-05-13T16:26:17.659Z,1399998377.659 [NAL9602](INFO): SBD MO Status=1, MOMSN=28404, MT Status=0, MTMSN=0 2014-05-13T16:26:17.706Z,1399998377.706 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:26:17.706Z,1399998377.706 [NAL9602](INFO): Packets left to send: 4 2014-05-13T16:26:17.708Z,1399998377.708 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0004.sbd 2014-05-13T16:26:29.734Z,1399998389.734 [NAL9602](INFO): SBD MO Status=1, MOMSN=28405, MT Status=0, MTMSN=0 2014-05-13T16:26:29.781Z,1399998389.781 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:26:29.781Z,1399998389.781 [NAL9602](INFO): Packets left to send: 3 2014-05-13T16:26:29.782Z,1399998389.782 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0003.sbd 2014-05-13T16:26:44.824Z,1399998404.824 [NAL9602](INFO): SBD MO Status=1, MOMSN=28406, MT Status=0, MTMSN=0 2014-05-13T16:26:44.876Z,1399998404.876 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:26:44.877Z,1399998404.877 [NAL9602](INFO): Packets left to send: 2 2014-05-13T16:26:44.878Z,1399998404.878 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0002.sbd 2014-05-13T16:26:56.291Z,1399998416.291 [NAL9602](INFO): SBD MO Status=1, MOMSN=28407, MT Status=0, MTMSN=0 2014-05-13T16:26:56.344Z,1399998416.344 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:26:56.344Z,1399998416.344 [NAL9602](INFO): Packets left to send: 1 2014-05-13T16:26:56.345Z,1399998416.345 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0001.sbd 2014-05-13T16:27:08.270Z,1399998428.270 [NAL9602](INFO): SBD MO Status=1, MOMSN=28408, MT Status=0, MTMSN=0 2014-05-13T16:27:08.329Z,1399998428.329 [NAL9602](INFO): Sent 150 bytes from file Logs/20140513T162252/Express0001.lzma 2014-05-13T16:27:08.329Z,1399998428.329 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:27:08.330Z,1399998428.330 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0001.lzma.parts/0000.sbd 2014-05-13T16:27:08.330Z,1399998428.330 [NAL9602](INFO): Completed sending Logs/20140513T162252/Express0001.lzma 2014-05-13T16:27:18.131Z,1399998438.131 [NAL9602](INFO): SBD MO Status=1, MOMSN=28409, MT Status=0, MTMSN=0 2014-05-13T16:27:18.184Z,1399998438.184 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0005.lzma 2014-05-13T16:27:18.184Z,1399998438.184 [NAL9602](INFO): Packets left to send: 1 2014-05-13T16:27:18.186Z,1399998438.186 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0005.lzma.parts/0001.sbd 2014-05-13T16:27:26.499Z,1399998446.499 [NAL9602](INFO): SBD MO Status=1, MOMSN=28410, MT Status=0, MTMSN=0 2014-05-13T16:27:26.549Z,1399998446.549 [NAL9602](INFO): Sent 262 bytes from file Logs/20140513T162252/Express0005.lzma 2014-05-13T16:27:26.549Z,1399998446.549 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:27:26.550Z,1399998446.550 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0005.lzma.parts/0000.sbd 2014-05-13T16:27:26.551Z,1399998446.551 [NAL9602](INFO): Completed sending Logs/20140513T162252/Express0005.lzma 2014-05-13T16:27:37.129Z,1399998457.129 [NAL9602](INFO): SBD MO Status=0, MOMSN=28411, MT Status=0, MTMSN=0 2014-05-13T16:27:38.774Z,1399998458.774 [NAL9602](IMPORTANT): GPS fix at: 1399998456.00 2014-05-13T16:27:38.824Z,1399998458.824 [Default:GPS:Read_GPS] Stopped 2014-05-13T16:27:38.824Z,1399998458.824 [Default:GPS:D] Running Loop=1 2014-05-13T16:27:39.247Z,1399998459.247 [Default:GPS:D] Stopped 2014-05-13T16:27:39.247Z,1399998459.247 [Default:GPS](INFO): Completed Default:GPS 2014-05-13T16:27:39.247Z,1399998459.247 [Default:GPS] Stopped 2014-05-13T16:27:39.247Z,1399998459.247 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2014-05-13T16:27:39.248Z,1399998459.248 [Default:GPS:A.SetSpeed] Stopped 2014-05-13T16:27:39.248Z,1399998459.248 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2014-05-13T16:27:48.161Z,1399998468.161 [NAL9602](INFO): SBD MO Status=1, MOMSN=28412, MT Status=0, MTMSN=0 2014-05-13T16:27:48.215Z,1399998468.215 [NAL9602](INFO): Sent 47 bytes from file Logs/20140513T162252/Courier0008.lzma 2014-05-13T16:27:48.215Z,1399998468.215 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:27:48.216Z,1399998468.216 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0008.lzma.parts/0000.sbd 2014-05-13T16:27:48.217Z,1399998468.217 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0008.lzma 2014-05-13T16:27:59.876Z,1399998479.876 [NAL9602](INFO): SBD MO Status=1, MOMSN=28413, MT Status=0, MTMSN=0 2014-05-13T16:27:59.921Z,1399998479.921 [NAL9602](INFO): Sent 79 bytes from file Logs/20140513T162252/Express0009.lzma 2014-05-13T16:27:59.921Z,1399998479.921 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:27:59.923Z,1399998479.923 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0009.lzma.parts/0000.sbd 2014-05-13T16:27:59.923Z,1399998479.923 [NAL9602](INFO): Completed sending Logs/20140513T162252/Express0009.lzma 2014-05-13T16:28:07.804Z,1399998487.804 [NAL9602](INFO): SBD MO Status=0, MOMSN=28414, MT Status=0, MTMSN=0 2014-05-13T16:28:07.896Z,1399998487.896 [Default:Iridium:Read_Iridium] Stopped 2014-05-13T16:28:07.897Z,1399998487.897 [Default:Iridium](INFO): Completed Default:Iridium 2014-05-13T16:28:07.897Z,1399998487.897 [Default:Iridium] Stopped 2014-05-13T16:28:07.897Z,1399998487.897 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2014-05-13T16:28:07.897Z,1399998487.897 [Default:Iridium:A.SetSpeed] Stopped 2014-05-13T16:28:07.897Z,1399998487.897 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2014-05-13T16:28:07.897Z,1399998487.897 [Default:WaitAtTheSurface] Running Loop=1 2014-05-13T16:28:07.898Z,1399998487.898 [Default:WaitAtTheSurface](INFO): Aggregate::initialize Default:WaitAtTheSurface 2014-05-13T16:28:07.898Z,1399998487.898 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1 2014-05-13T16:28:07.898Z,1399998487.898 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed](DEBUG): Initialize. 2014-05-13T16:28:07.898Z,1399998487.898 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1 2014-05-13T16:28:07.898Z,1399998487.898 [Default:WaitAtTheSurface:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:28:08.342Z,1399998488.342 [Default:WaitAtTheSurface:B.GoToSurface] Running Loop=1 2014-05-13T16:28:08.347Z,1399998488.347 [Default:WaitAtTheSurface:RunAtLowSpeed.SetSpeed] Running Loop=1 2014-05-13T16:28:08.352Z,1399998488.352 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B 2014-05-13T16:28:08.352Z,1399998488.352 [Default:CallIridium:B] Stopped 2014-05-13T16:28:08.353Z,1399998488.353 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2014-05-13T16:28:08.353Z,1399998488.353 [Default:CallIridium](INFO): Completed Default:CallIridium 2014-05-13T16:28:08.353Z,1399998488.353 [Default:CallIridium] Stopped 2014-05-13T16:28:08.353Z,1399998488.353 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2014-05-13T16:28:18.415Z,1399998498.415 [NAL9602](INFO): Powering down 2014-05-13T16:33:08.488Z,1399998788.488 [Default:CallIridium] Running Loop=1 2014-05-13T16:33:08.489Z,1399998788.489 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2014-05-13T16:33:08.489Z,1399998788.489 [Default:CallIridium:A] Running Loop=1 2014-05-13T16:33:08.489Z,1399998788.489 [Default:CallIridium:A] Stopped 2014-05-13T16:33:08.489Z,1399998788.489 [Default:CallIridium:B] Running Loop=1 2014-05-13T16:33:08.489Z,1399998788.489 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2014-05-13T16:33:13.539Z,1399998793.539 [Default:Iridium] Running Loop=1 2014-05-13T16:33:13.540Z,1399998793.540 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2014-05-13T16:33:13.540Z,1399998793.540 [Default:Iridium:A.SetSpeed] Running Loop=1 2014-05-13T16:33:13.540Z,1399998793.540 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:33:13.540Z,1399998793.540 [Default:Iridium:B.GoToSurface] Running Loop=1 2014-05-13T16:33:13.540Z,1399998793.540 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:33:13.541Z,1399998793.541 [Default:Iridium:B.GoToSurface] Stopped 2014-05-13T16:33:13.541Z,1399998793.541 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:33:13.541Z,1399998793.541 [Default:Iridium:Read_Iridium] Running Loop=1 2014-05-13T16:33:13.541Z,1399998793.541 [Default:GPS] Running Loop=1 2014-05-13T16:33:13.541Z,1399998793.541 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2014-05-13T16:33:13.541Z,1399998793.541 [Default:GPS:A.SetSpeed] Running Loop=1 2014-05-13T16:33:13.542Z,1399998793.542 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:33:13.542Z,1399998793.542 [Default:GPS:B.GoToSurface] Running Loop=1 2014-05-13T16:33:13.542Z,1399998793.542 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:33:13.543Z,1399998793.543 [Default:GPS:B.GoToSurface] Stopped 2014-05-13T16:33:13.543Z,1399998793.543 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:33:13.543Z,1399998793.543 [Default:GPS:Read_GPS] Running Loop=1 2014-05-13T16:33:14.559Z,1399998794.559 [NAL9602](INFO): Powering up 2014-05-13T16:33:25.217Z,1399998805.217 [NAL9602](ERROR): NAL9602 initialize error - Can't enter command mode: +CIEV:1,1 2014-05-13T16:33:25.217Z,1399998805.217 [NAL9602] Communications Fault, FailCount= 1 2014-05-13T16:33:25.217Z,1399998805.217 [NAL9602](ERROR): Communications Fault 2014-05-13T16:33:25.296Z,1399998805.296 [CBIT](ERROR): Communications Fault in component: NAL9602 2014-05-13T16:33:25.720Z,1399998805.720 [NAL9602](INFO): Powering down 2014-05-13T16:33:26.677Z,1399998806.677 [CBIT](INFO): Clearing failed state for component NAL9602 2014-05-13T16:33:26.677Z,1399998806.677 [NAL9602] No Fault, FailCount= 1 2014-05-13T16:33:30.972Z,1399998810.972 [NAL9602](INFO): Powering up NAL9602 2014-05-13T16:33:41.518Z,1399998821.518 [NAL9602](INFO): NAL9602 initialized 2014-05-13T16:34:02.937Z,1399998842.937 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:34:02.938Z,1399998842.938 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:34:04.248Z,1399998844.248 [NAL9602](IMPORTANT): GPS fix at: 1399998841.00 2014-05-13T16:34:04.303Z,1399998844.303 [Default:GPS:Read_GPS] Stopped 2014-05-13T16:34:04.303Z,1399998844.303 [Default:GPS:D] Running Loop=1 2014-05-13T16:34:04.723Z,1399998844.723 [Default:GPS:D] Stopped 2014-05-13T16:34:04.724Z,1399998844.724 [Default:GPS](INFO): Completed Default:GPS 2014-05-13T16:34:04.724Z,1399998844.724 [Default:GPS] Stopped 2014-05-13T16:34:04.724Z,1399998844.724 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2014-05-13T16:34:04.724Z,1399998844.724 [Default:GPS:A.SetSpeed] Stopped 2014-05-13T16:34:04.724Z,1399998844.724 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2014-05-13T16:34:29.589Z,1399998869.589 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:34:29.589Z,1399998869.589 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:34:54.559Z,1399998894.559 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:34:54.559Z,1399998894.559 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:35:29.110Z,1399998929.110 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:35:29.110Z,1399998929.110 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:36:14.979Z,1399998974.979 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:36:14.979Z,1399998974.979 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:37:11.464Z,1399999031.464 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:37:11.464Z,1399999031.464 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:37:41.846Z,1399999061.846 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:37:41.847Z,1399999061.847 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:38:06.557Z,1399999086.557 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:38:06.557Z,1399999086.557 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:38:26.977Z,1399999106.977 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:38:26.977Z,1399999106.977 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:39:04.036Z,1399999144.036 [DVL_micro](ERROR): No DVL communication! Re-initializing 2014-05-13T16:39:04.036Z,1399999144.036 [DVL_micro] Communications Fault, FailCount= 1 2014-05-13T16:39:04.036Z,1399999144.036 [DVL_micro](ERROR): Communications Fault 2014-05-13T16:39:04.097Z,1399999144.097 [CBIT](ERROR): Communications Fault in component: DVL_micro 2014-05-13T16:39:04.474Z,1399999144.474 [DVL_micro](INFO): uninitialize:Powering down 2014-05-13T16:39:04.893Z,1399999144.893 [DVL_micro](FAULT): LCB fault: Software Overcurrent. 2014-05-13T16:39:04.893Z,1399999144.893 [DVL_micro] Hardware Fault, FailCount= 1 2014-05-13T16:39:04.893Z,1399999144.893 [DVL_micro](ERROR): Hardware Fault 2014-05-13T16:39:05.365Z,1399999145.365 [DVL_micro](INFO): Initializing 2014-05-13T16:39:05.422Z,1399999145.422 [CBIT](INFO): Clearing failed state for component DVL_micro 2014-05-13T16:39:05.422Z,1399999145.422 [DVL_micro] No Fault, FailCount= 1 2014-05-13T16:39:05.780Z,1399999145.780 [NAL9602](INFO): SBD MO Status=2, MOMSN=28415, MT Status=2, MTMSN=0 2014-05-13T16:39:05.780Z,1399999145.780 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:39:28.052Z,1399999168.052 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=28415, MT Status=1, MTMSN=1848 2014-05-13T16:39:28.104Z,1399999168.104 [NAL9602](INFO): Sent 76 bytes from file Logs/20140513T162252/Courier0012.lzma 2014-05-13T16:39:28.104Z,1399999168.104 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:39:28.105Z,1399999168.105 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0012.lzma.parts/0000.sbd 2014-05-13T16:39:28.106Z,1399999168.106 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0012.lzma 2014-05-13T16:39:28.781Z,1399999168.781 [NAL9602](INFO): Received command:! top -b -d 5 -H -p 762 > /mnt/mmc/LRAUV/Logs/latest/toplog & 2014-05-13T16:39:28.869Z,1399999168.869 [CommandLine](IMPORTANT): got command ! top -b -d 5 -H -p 762 > /mnt/mmc/LRAUV/Logs/latest/toplog & 2014-05-13T16:39:46.692Z,1399999186.692 [NAL9602](INFO): SBD MO Status=1, MOMSN=28416, MT Status=0, MTMSN=0 2014-05-13T16:39:46.744Z,1399999186.744 [NAL9602](INFO): Sent 113 bytes from file Logs/20140513T162252/Express0013.lzma 2014-05-13T16:39:46.745Z,1399999186.745 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:39:46.746Z,1399999186.746 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0013.lzma.parts/0000.sbd 2014-05-13T16:39:46.747Z,1399999186.747 [NAL9602](INFO): Completed sending Logs/20140513T162252/Express0013.lzma 2014-05-13T16:40:04.288Z,1399999204.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=28417, MT Status=2, MTMSN=0 2014-05-13T16:40:04.288Z,1399999204.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:40:14.411Z,1399999214.411 [NAL9602](INFO): SBD MO Status=0, MOMSN=28417, MT Status=0, MTMSN=0 2014-05-13T16:40:26.053Z,1399999226.053 [NAL9602](INFO): SBD MO Status=1, MOMSN=28418, MT Status=0, MTMSN=0 2014-05-13T16:40:26.110Z,1399999226.110 [NAL9602](INFO): Sent 76 bytes from file Logs/20140513T162252/Courier0016.lzma 2014-05-13T16:40:26.110Z,1399999226.110 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:40:26.111Z,1399999226.111 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0016.lzma.parts/0000.sbd 2014-05-13T16:40:26.112Z,1399999226.112 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0016.lzma 2014-05-13T16:40:39.345Z,1399999239.345 [NAL9602](INFO): SBD MO Status=1, MOMSN=28419, MT Status=0, MTMSN=0 2014-05-13T16:40:39.399Z,1399999239.399 [NAL9602](INFO): Sent 332 bytes from file Logs/20140513T162252/Express0017.lzma 2014-05-13T16:40:39.399Z,1399999239.399 [NAL9602](INFO): Packets left to send: 1 2014-05-13T16:40:39.401Z,1399999239.401 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0017.lzma.parts/0001.sbd 2014-05-13T16:40:51.608Z,1399999251.608 [NAL9602](INFO): SBD MO Status=1, MOMSN=28420, MT Status=0, MTMSN=0 2014-05-13T16:40:51.657Z,1399999251.657 [NAL9602](INFO): Sent 110 bytes from file Logs/20140513T162252/Express0017.lzma 2014-05-13T16:40:51.657Z,1399999251.657 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:40:51.659Z,1399999251.659 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Express0017.lzma.parts/0000.sbd 2014-05-13T16:40:51.659Z,1399999251.659 [NAL9602](INFO): Completed sending Logs/20140513T162252/Express0017.lzma 2014-05-13T16:41:36.891Z,1399999296.891 [NAL9602](INFO): SBD MO Status=2, MOMSN=28421, MT Status=2, MTMSN=0 2014-05-13T16:41:36.891Z,1399999296.891 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2014-05-13T16:41:53.921Z,1399999313.921 [NAL9602](INFO): SBD MO Status=0, MOMSN=28421, MT Status=0, MTMSN=0 2014-05-13T16:41:54.010Z,1399999314.010 [Default:Iridium:Read_Iridium] Stopped 2014-05-13T16:41:54.010Z,1399999314.010 [Default:Iridium](INFO): Completed Default:Iridium 2014-05-13T16:41:54.010Z,1399999314.010 [Default:Iridium] Stopped 2014-05-13T16:41:54.010Z,1399999314.010 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2014-05-13T16:41:54.011Z,1399999314.011 [Default:Iridium:A.SetSpeed] Stopped 2014-05-13T16:41:54.011Z,1399999314.011 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2014-05-13T16:41:54.469Z,1399999314.469 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B 2014-05-13T16:41:54.469Z,1399999314.469 [Default:CallIridium:B] Stopped 2014-05-13T16:41:54.469Z,1399999314.469 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2014-05-13T16:41:54.469Z,1399999314.469 [Default:CallIridium](INFO): Completed Default:CallIridium 2014-05-13T16:41:54.469Z,1399999314.469 [Default:CallIridium] Stopped 2014-05-13T16:41:54.470Z,1399999314.470 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2014-05-13T16:41:59.556Z,1399999319.556 [Depth_Keller](ERROR): Pressure reading out of range: 1830.865234 decibar 2014-05-13T16:42:04.090Z,1399999324.090 [InternalSim](ERROR): Simulator run error: error=UNSTABLE SIMULATION -- ABORTED, rate=[1715614201381891328.000000,230402005388573728.000000,-35220311798281793536.000000,- 2014-05-13T16:42:04.090Z,1399999324.090 [InternalSim] Software Fault, FailCount= 1 2014-05-13T16:42:04.090Z,1399999324.090 [InternalSim](ERROR): Software Fault 2014-05-13T16:42:04.559Z,1399999324.559 [NAL9602](INFO): Powering down 2014-05-13T16:42:04.622Z,1399999324.622 [CBIT](ERROR): Software Fault in component: InternalSim 2014-05-13T16:42:09.524Z,1399999329.524 [CBIT](INFO): Clearing failed state for component InternalSim 2014-05-13T16:42:09.524Z,1399999329.524 [InternalSim] No Fault, FailCount= 1 2014-05-13T16:42:14.027Z,1399999334.027 [InternalSim](DEBUG): InternalSim initializing... 2014-05-13T16:42:14.483Z,1399999334.483 [Depth_Keller](ERROR): Pressure reading out of range: 1373.112915 decibar 2014-05-13T16:42:19.096Z,1399999339.096 [InternalSim](ERROR): Simulator run error: error=UNSTABLE SIMULATION -- ABORTED, rate=[14333980594.800201,-53780896.114890,-283098921024.311829,-3656946827.689455,-306163 2014-05-13T16:42:19.096Z,1399999339.096 [InternalSim] Software Fault, FailCount= 2 2014-05-13T16:42:19.096Z,1399999339.096 [InternalSim](ERROR): Software Fault 2014-05-13T16:42:19.616Z,1399999339.616 [CBIT](ERROR): Software Fault in component: InternalSim 2014-05-13T16:42:24.526Z,1399999344.526 [CBIT](INFO): Clearing failed state for component InternalSim 2014-05-13T16:42:24.526Z,1399999344.526 [InternalSim] No Fault, FailCount= 2 2014-05-13T16:42:29.027Z,1399999349.027 [InternalSim](DEBUG): InternalSim initializing... 2014-05-13T16:42:29.558Z,1399999349.558 [Depth_Keller](ERROR): Pressure reading out of range: 1830.953369 decibar 2014-05-13T16:42:39.089Z,1399999359.089 [InternalSim](ERROR): Simulator run error: error=UNSTABLE SIMULATION -- ABORTED, rate=[14916197580031260672.000000,-478201909944718144.000000,-307166035801855950848.00000 2014-05-13T16:42:39.089Z,1399999359.089 [InternalSim] Software Fault, FailCount= 3 2014-05-13T16:42:39.089Z,1399999359.089 [InternalSim](ERROR): Software Fault 2014-05-13T16:42:39.610Z,1399999359.610 [CBIT](ERROR): Software Fault in component: InternalSim 2014-05-13T16:42:44.519Z,1399999364.519 [CBIT](INFO): Clearing failed state for component InternalSim 2014-05-13T16:42:44.519Z,1399999364.519 [InternalSim] No Fault, FailCount= 3 2014-05-13T16:42:49.026Z,1399999369.026 [InternalSim](DEBUG): InternalSim initializing... 2014-05-13T16:42:49.513Z,1399999369.513 [Depth_Keller](ERROR): Pressure reading out of range: 1830.894043 decibar 2014-05-13T16:42:54.093Z,1399999374.093 [InternalSim](ERROR): Simulator run error: error=UNSTABLE SIMULATION -- ABORTED, rate=[19684206025698992.000000,1783466757296504.250000,-403129794842691648.000000,-447324 2014-05-13T16:42:54.093Z,1399999374.093 [InternalSim] Software Fault, FailCount= 4 2014-05-13T16:42:54.094Z,1399999374.094 [InternalSim](ERROR): Software Fault 2014-05-13T16:42:54.629Z,1399999374.629 [CBIT](ERROR): Software Fault in component: InternalSim 2014-05-13T16:42:59.476Z,1399999379.476 [CBIT](INFO): Clearing failed state for component InternalSim 2014-05-13T16:42:59.476Z,1399999379.476 [InternalSim] No Fault, FailCount= 4 2014-05-13T16:43:04.025Z,1399999384.025 [InternalSim](DEBUG): InternalSim initializing... 2014-05-13T16:43:04.508Z,1399999384.508 [Depth_Keller](ERROR): Pressure reading out of range: 1830.820679 decibar 2014-05-13T16:43:14.559Z,1399999394.559 [Depth_Keller](ERROR): Pressure reading out of range: 1831.001465 decibar 2014-05-13T16:43:34.531Z,1399999414.531 [Depth_Keller](ERROR): Pressure reading out of range: 1830.993530 decibar 2014-05-13T16:43:44.530Z,1399999424.530 [Depth_Keller](ERROR): Pressure reading out of range: 1369.639282 decibar 2014-05-13T16:43:54.533Z,1399999434.533 [Depth_Keller](ERROR): Pressure reading out of range: 1830.916748 decibar 2014-05-13T16:44:14.521Z,1399999454.521 [Depth_Keller](ERROR): Pressure reading out of range: 1355.256592 decibar 2014-05-13T16:44:24.521Z,1399999464.521 [Depth_Keller](ERROR): Pressure reading out of range: -850.357788 decibar 2014-05-13T16:44:34.548Z,1399999474.548 [Depth_Keller](ERROR): Pressure reading out of range: 1830.873901 decibar 2014-05-13T16:45:09.542Z,1399999509.542 [Depth_Keller](ERROR): Pressure reading out of range: -850.162292 decibar 2014-05-13T16:45:09.909Z,1399999509.909 [Radio_Freewave](INFO): Powering down 2014-05-13T16:45:14.813Z,1399999514.813 [Radio_Freewave](INFO): Powering up 2014-05-13T16:45:16.024Z,1399999516.024 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0 2014-05-13T16:45:59.572Z,1399999559.572 [Depth_Keller](ERROR): Pressure reading out of range: -850.162292 decibar 2014-05-13T16:45:59.779Z,1399999559.779 [Radio_Freewave](INFO): Powering down 2014-05-13T16:46:09.958Z,1399999569.958 [Radio_Freewave](INFO): Powering up 2014-05-13T16:46:11.165Z,1399999571.165 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0 2014-05-13T16:46:24.496Z,1399999584.496 [Depth_Keller](ERROR): Pressure reading out of range: -907.375183 decibar 2014-05-13T16:46:24.691Z,1399999584.691 [Radio_Freewave](INFO): Powering down 2014-05-13T16:46:29.997Z,1399999589.997 [Radio_Freewave](INFO): Powering up 2014-05-13T16:46:31.208Z,1399999591.208 [Radio_Freewave](IMPORTANT): Starting PPPD with command:/sbin/pppd nocrtscts /dev/ttyS1 noauth 115200 10.1.1.2:10.1.1.1 persist maxfail 0 2014-05-13T16:46:54.583Z,1399999614.583 [Default:CallIridium] Running Loop=1 2014-05-13T16:46:54.583Z,1399999614.583 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2014-05-13T16:46:54.583Z,1399999614.583 [Default:CallIridium:A] Running Loop=1 2014-05-13T16:46:54.584Z,1399999614.584 [Default:CallIridium:A] Stopped 2014-05-13T16:46:54.584Z,1399999614.584 [Default:CallIridium:B] Running Loop=1 2014-05-13T16:46:54.584Z,1399999614.584 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2014-05-13T16:46:59.539Z,1399999619.539 [Default:Iridium] Running Loop=1 2014-05-13T16:46:59.539Z,1399999619.539 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2014-05-13T16:46:59.539Z,1399999619.539 [Default:Iridium:A.SetSpeed] Running Loop=1 2014-05-13T16:46:59.539Z,1399999619.539 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:46:59.540Z,1399999619.540 [Default:Iridium:B.GoToSurface] Running Loop=1 2014-05-13T16:46:59.540Z,1399999619.540 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:46:59.540Z,1399999619.540 [Default:Iridium:B.GoToSurface] Stopped 2014-05-13T16:46:59.541Z,1399999619.541 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:46:59.541Z,1399999619.541 [Default:Iridium:Read_Iridium] Running Loop=1 2014-05-13T16:46:59.541Z,1399999619.541 [Default:GPS] Running Loop=1 2014-05-13T16:46:59.541Z,1399999619.541 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2014-05-13T16:46:59.541Z,1399999619.541 [Default:GPS:A.SetSpeed] Running Loop=1 2014-05-13T16:46:59.541Z,1399999619.541 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2014-05-13T16:46:59.541Z,1399999619.541 [Default:GPS:B.GoToSurface] Running Loop=1 2014-05-13T16:46:59.542Z,1399999619.542 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2014-05-13T16:46:59.542Z,1399999619.542 [Default:GPS:B.GoToSurface] Stopped 2014-05-13T16:46:59.542Z,1399999619.542 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2014-05-13T16:46:59.542Z,1399999619.542 [Default:GPS:Read_GPS] Running Loop=1 2014-05-13T16:47:00.555Z,1399999620.555 [NAL9602](INFO): Powering up 2014-05-13T16:47:11.298Z,1399999631.298 [NAL9602](INFO): NAL9602 initialized 2014-05-13T16:47:29.033Z,1399999649.033 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=28422, MT Status=1, MTMSN=1849 2014-05-13T16:47:29.086Z,1399999649.086 [NAL9602](INFO): Sent 45 bytes from file Logs/20140513T162252/Courier0020.lzma 2014-05-13T16:47:29.086Z,1399999649.086 [NAL9602](INFO): Packets left to send: 0 2014-05-13T16:47:29.087Z,1399999649.087 [NAL9602](INFO): Stored copy of sent data in Logs/20140513T162252/Courier0020.lzma.parts/0000.sbd 2014-05-13T16:47:29.088Z,1399999649.088 [NAL9602](INFO): Completed sending Logs/20140513T162252/Courier0020.lzma 2014-05-13T16:47:29.626Z,1399999649.626 [NAL9602](INFO): Received command:restart logs