2013-10-31T21:34:25.347Z,1383255265.347 [Supervisor](DEBUG): Initializing supervisor. 2013-10-31T21:34:25.349Z,1383255265.349 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2013-10-31T21:34:25.350Z,1383255265.350 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2013-10-31T21:34:25.351Z,1383255265.351 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2013-10-31T21:34:25.354Z,1383255265.354 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2013-10-31T21:34:25.366Z,1383255265.366 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2013-10-31T21:34:25.367Z,1383255265.367 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2013-10-31T21:34:25.368Z,1383255265.368 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2013-10-31T21:34:25.369Z,1383255265.369 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0 2013-10-31T21:34:25.370Z,1383255265.370 [Supervisor](INFO): Looking for Config files in directory: Config/ 2013-10-31T21:34:25.371Z,1383255265.371 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2013-10-31T21:34:25.665Z,1383255265.665 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2013-10-31T21:34:25.665Z,1383255265.665 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2013-10-31T21:34:25.857Z,1383255265.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2013-10-31T21:34:25.858Z,1383255265.858 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2013-10-31T21:34:25.944Z,1383255265.944 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2013-10-31T21:34:25.945Z,1383255265.945 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2013-10-31T21:34:26.062Z,1383255266.062 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2013-10-31T21:34:26.062Z,1383255266.062 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2013-10-31T21:34:26.206Z,1383255266.206 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2013-10-31T21:34:26.207Z,1383255266.207 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2013-10-31T21:34:26.460Z,1383255266.460 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2013-10-31T21:34:26.460Z,1383255266.460 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2013-10-31T21:34:26.629Z,1383255266.629 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2013-10-31T21:34:26.630Z,1383255266.630 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2013-10-31T21:34:26.910Z,1383255266.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2013-10-31T21:34:26.911Z,1383255266.911 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2013-10-31T21:34:27.014Z,1383255267.014 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2013-10-31T21:34:27.014Z,1383255267.014 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2013-10-31T21:34:27.445Z,1383255267.445 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2013-10-31T21:34:27.446Z,1383255267.446 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2013-10-31T21:34:27.559Z,1383255267.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2013-10-31T21:34:27.560Z,1383255267.560 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2013-10-31T21:34:27.647Z,1383255267.647 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2013-10-31T21:34:27.648Z,1383255267.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2013-10-31T21:34:27.749Z,1383255267.749 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2013-10-31T21:34:27.878Z,1383255267.878 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2013-10-31T21:34:27.978Z,1383255267.978 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2013-10-31T21:34:28.086Z,1383255268.086 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2013-10-31T21:34:28.183Z,1383255268.183 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2013-10-31T21:34:28.301Z,1383255268.301 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2013-10-31T21:34:28.399Z,1383255268.399 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2013-10-31T21:34:28.486Z,1383255268.486 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/LOGIN/ 2013-10-31T21:34:28.487Z,1383255268.487 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2013-10-31T21:34:28.488Z,1383255268.488 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2013-10-31T21:34:28.659Z,1383255268.659 [InternalSim] Loaded 2013-10-31T21:34:28.659Z,1383255268.659 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2013-10-31T21:34:28.660Z,1383255268.660 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2013-10-31T21:34:28.660Z,1383255268.660 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2013-10-31T21:34:28.751Z,1383255268.751 [SBIT](DEBUG): Construct Startup Built In Test. 2013-10-31T21:34:28.781Z,1383255268.781 [SBIT] Loaded 2013-10-31T21:34:28.781Z,1383255268.781 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2013-10-31T21:34:28.782Z,1383255268.782 [IBIT](DEBUG): Construct Initiated Built In Test. 2013-10-31T21:34:28.812Z,1383255268.812 [IBIT] Loaded 2013-10-31T21:34:28.813Z,1383255268.813 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2013-10-31T21:34:28.815Z,1383255268.815 [CBIT](DEBUG): Construct CBIT Built In Test. 2013-10-31T21:34:28.935Z,1383255268.935 [CBIT] Loaded 2013-10-31T21:34:28.935Z,1383255268.935 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2013-10-31T21:34:28.936Z,1383255268.936 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2013-10-31T21:34:28.936Z,1383255268.936 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2013-10-31T21:34:29.108Z,1383255269.108 [BuoyancyServo] Loaded 2013-10-31T21:34:29.109Z,1383255269.109 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2013-10-31T21:34:29.121Z,1383255269.121 [ElevatorServo] Loaded 2013-10-31T21:34:29.121Z,1383255269.121 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2013-10-31T21:34:29.133Z,1383255269.133 [MassServo] Loaded 2013-10-31T21:34:29.133Z,1383255269.133 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2013-10-31T21:34:29.145Z,1383255269.145 [RudderServo] Loaded 2013-10-31T21:34:29.145Z,1383255269.145 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2013-10-31T21:34:29.157Z,1383255269.157 [ThrusterServo] Loaded 2013-10-31T21:34:29.157Z,1383255269.157 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2013-10-31T21:34:29.157Z,1383255269.157 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2013-10-31T21:34:29.158Z,1383255269.158 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2013-10-31T21:34:29.194Z,1383255269.194 [DepthRateCalculator] Loaded 2013-10-31T21:34:29.194Z,1383255269.194 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2013-10-31T21:34:32.042Z,1383255272.042 [HFRadarModelCalc] Loaded 2013-10-31T21:34:32.042Z,1383255272.042 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2013-10-31T21:34:32.059Z,1383255272.059 [NavChart] Loaded 2013-10-31T21:34:32.059Z,1383255272.059 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2013-10-31T21:34:32.065Z,1383255272.065 [PitchRateCalculator] Loaded 2013-10-31T21:34:32.065Z,1383255272.065 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2013-10-31T21:34:32.077Z,1383255272.077 [SpeedCalculator] Loaded 2013-10-31T21:34:32.077Z,1383255272.077 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2013-10-31T21:34:32.094Z,1383255272.094 [TempGradientCalculator] Loaded 2013-10-31T21:34:32.094Z,1383255272.094 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2013-10-31T21:34:32.100Z,1383255272.100 [YawRateCalculator] Loaded 2013-10-31T21:34:32.100Z,1383255272.100 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2013-10-31T21:34:32.149Z,1383255272.149 [Navigation] Loaded 2013-10-31T21:34:32.149Z,1383255272.149 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2013-10-31T21:34:32.149Z,1383255272.149 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2013-10-31T21:34:32.150Z,1383255272.150 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2013-10-31T21:34:32.398Z,1383255272.398 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2013-10-31T21:34:32.399Z,1383255272.399 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2013-10-31T21:34:32.422Z,1383255272.422 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2013-10-31T21:34:32.423Z,1383255272.423 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2013-10-31T21:34:32.473Z,1383255272.473 [VerticalControl](DEBUG): Construct VerticalControl. 2013-10-31T21:34:32.570Z,1383255272.570 [VerticalControl] Loaded 2013-10-31T21:34:32.571Z,1383255272.571 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2013-10-31T21:34:32.571Z,1383255272.571 [HorizontalControl](DEBUG): Construct HorizontalControl. 2013-10-31T21:34:32.631Z,1383255272.631 [HorizontalControl] Loaded 2013-10-31T21:34:32.631Z,1383255272.631 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2013-10-31T21:34:32.632Z,1383255272.632 [SpeedControl](DEBUG): Construct SpeedControl. 2013-10-31T21:34:32.634Z,1383255272.634 [SpeedControl] Loaded 2013-10-31T21:34:32.634Z,1383255272.634 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2013-10-31T21:34:32.634Z,1383255272.634 [LoopControl](DEBUG): Construct LoopControl. 2013-10-31T21:34:32.635Z,1383255272.635 [LoopControl] Loaded 2013-10-31T21:34:32.635Z,1383255272.635 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2013-10-31T21:34:32.636Z,1383255272.636 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2013-10-31T21:34:32.636Z,1383255272.636 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2013-10-31T21:34:32.642Z,1383255272.642 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2013-10-31T21:34:32.647Z,1383255272.647 [AsyncPiEstimator] Loaded 2013-10-31T21:34:32.648Z,1383255272.648 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2013-10-31T21:34:32.649Z,1383255272.649 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406474E0 2013-10-31T21:34:32.650Z,1383255272.650 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2013-10-31T21:34:32.650Z,1383255272.650 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2013-10-31T21:34:32.858Z,1383255272.858 [AHRS_sp3003D] Loaded 2013-10-31T21:34:32.858Z,1383255272.858 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2013-10-31T21:34:32.873Z,1383255272.873 [Depth_Keller] Loaded 2013-10-31T21:34:32.873Z,1383255272.873 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2013-10-31T21:34:33.067Z,1383255273.067 [DVL_micro] Loaded 2013-10-31T21:34:33.067Z,1383255273.067 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2013-10-31T21:34:33.068Z,1383255273.068 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406D64E0 2013-10-31T21:34:33.161Z,1383255273.161 [NAL9602] Loaded 2013-10-31T21:34:33.161Z,1383255273.161 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2013-10-31T21:34:33.204Z,1383255273.204 [Onboard] Loaded 2013-10-31T21:34:33.204Z,1383255273.204 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2013-10-31T21:34:33.211Z,1383255273.211 [Radio_Freewave] Loaded 2013-10-31T21:34:33.211Z,1383255273.211 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2013-10-31T21:34:33.364Z,1383255273.364 [DAT] Loaded 2013-10-31T21:34:33.364Z,1383255273.364 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2013-10-31T21:34:33.364Z,1383255273.364 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2013-10-31T21:34:33.365Z,1383255273.365 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2013-10-31T21:34:33.469Z,1383255273.469 [CTD_NeilBrown] Loaded 2013-10-31T21:34:33.469Z,1383255273.469 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2013-10-31T21:34:33.470Z,1383255273.470 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 407334E0 2013-10-31T21:34:33.504Z,1383255273.504 [WetLabsBB2FL] Loaded 2013-10-31T21:34:33.505Z,1383255273.505 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2013-10-31T21:34:33.506Z,1383255273.506 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407634E0 2013-10-31T21:34:33.507Z,1383255273.507 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2013-10-31T21:34:33.509Z,1383255273.509 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2013-10-31T21:34:33.510Z,1383255273.510 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2013-10-31T21:34:33.517Z,1383255273.517 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2013-10-31T21:34:33.518Z,1383255273.518 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407934E0 2013-10-31T21:34:33.523Z,1383255273.523 [Supervisor](DEBUG): Running supervisor. 2013-10-31T21:34:33.524Z,1383255273.524 [CommandLine](INFO): Thread ID is 7413 2013-10-31T21:34:33.526Z,1383255273.526 [controlThread](INFO): Thread ID is 7412 2013-10-31T21:34:33.526Z,1383255273.526 [controlThread](DEBUG): Initializing ControlThread 2013-10-31T21:34:33.527Z,1383255273.527 [CycleStarter](INFO): Thread ID is 7411 2013-10-31T21:34:33.527Z,1383255273.527 [InternalSim](DEBUG): InternalSim initializing... 2013-10-31T21:34:33.562Z,1383255273.562 [logger](INFO): Thread ID is 7414 2013-10-31T21:34:33.588Z,1383255273.588 [SBIT](INFO): Initialize SBIT Component. 2013-10-31T21:34:33.589Z,1383255273.589 [SBIT](IMPORTANT): Tethys CM Info: $Rev:10711 2013-10-31T21:34:33.589Z,1383255273.589 [SBIT](IMPORTANT): Kernel Release:2.6.27.8 2013-10-31T21:34:33.589Z,1383255273.589 [SBIT](IMPORTANT): Kernel Version:#634 PREEMPT Wed Feb 13 10:21:48 PST 2013 2013-10-31T21:34:33.590Z,1383255273.590 [IBIT](INFO): Initialize IBIT Component. 2013-10-31T21:34:33.591Z,1383255273.591 [CBIT](DEBUG): Initialize CBIT Component. 2013-10-31T21:34:33.591Z,1383255273.591 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2013-10-31T21:34:33.602Z,1383255273.602 [AsyncPiEstimator](INFO): Thread ID is 7475 2013-10-31T21:34:33.602Z,1383255273.602 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2013-10-31T21:34:33.615Z,1383255273.615 [DVL_micro](INFO): Thread ID is 7476 2013-10-31T21:34:33.622Z,1383255273.622 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2013-10-31T21:34:33.623Z,1383255273.623 [NavChart](DEBUG): Initialize NavChart Derivation. 2013-10-31T21:34:33.623Z,1383255273.623 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2013-10-31T21:34:33.624Z,1383255273.624 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2013-10-31T21:34:33.624Z,1383255273.624 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2013-10-31T21:34:33.625Z,1383255273.625 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2013-10-31T21:34:33.625Z,1383255273.625 [Navigation](DEBUG): Initializing Navigation. 2013-10-31T21:34:33.625Z,1383255273.625 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2013-10-31T21:34:33.627Z,1383255273.627 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2013-10-31T21:34:33.628Z,1383255273.628 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2013-10-31T21:34:33.629Z,1383255273.629 [LoopControl](DEBUG): Initialize LoopControlComponent. 2013-10-31T21:34:33.635Z,1383255273.635 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2013-10-31T21:34:33.641Z,1383255273.641 [DVL_micro](INFO): Initializing 2013-10-31T21:34:33.645Z,1383255273.645 [DVL_micro](INFO): start:Powering up 2013-10-31T21:34:33.646Z,1383255273.646 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-10-31T21:34:33.647Z,1383255273.647 [DVL_micro](INFO): Cycling power to configure device. 2013-10-31T21:34:33.658Z,1383255273.658 [CTD_NeilBrown](INFO): Thread ID is 7477 2013-10-31T21:34:33.658Z,1383255273.658 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2013-10-31T21:34:33.662Z,1383255273.662 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2013-10-31T21:34:33.667Z,1383255273.667 [WetLabsBB2FL](INFO): Thread ID is 7478 2013-10-31T21:34:33.667Z,1383255273.667 [WetLabsBB2FL](INFO): Powering down 2013-10-31T21:34:33.672Z,1383255273.672 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2013-10-31T21:34:33.707Z,1383255273.707 [NavChartDb](INFO): Thread ID is 7479 2013-10-31T21:34:33.710Z,1383255273.710 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2013-10-31T21:34:33.711Z,1383255273.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2013-10-31T21:34:33.711Z,1383255273.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2013-10-31T21:34:33.711Z,1383255273.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2013-10-31T21:34:33.711Z,1383255273.711 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2013-10-31T21:34:33.712Z,1383255273.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2013-10-31T21:34:33.712Z,1383255273.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2013-10-31T21:34:33.712Z,1383255273.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2013-10-31T21:34:33.712Z,1383255273.712 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2013-10-31T21:34:33.753Z,1383255273.753 [MissionManager](DEBUG): 2013-10-31T21:34:33.754Z,1383255273.754 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2013-10-31T21:34:33.836Z,1383255273.836 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2013-10-31T21:34:33.838Z,1383255273.838 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2013-10-31T21:34:33.853Z,1383255273.853 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2013-10-31T21:34:33.861Z,1383255273.861 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2013-10-31T21:34:33.864Z,1383255273.864 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2013-10-31T21:34:33.920Z,1383255273.920 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2013-10-31T21:34:33.944Z,1383255273.944 [Default:D.SetSpeed](DEBUG): Construct. 2013-10-31T21:34:33.947Z,1383255273.947 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2013-10-31T21:34:33.964Z,1383255273.964 [Default:F.Wait](DEBUG): Construct Wait. 2013-10-31T21:34:33.988Z,1383255273.988 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2013-10-31T21:34:33.992Z,1383255273.992 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Depth_Keller,NAL9602,Onboard,Radio_Freewave,DAT,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter, 2013-10-31T21:34:34.046Z,1383255274.046 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2013-10-31T21:34:34.061Z,1383255274.061 [Depth_Keller](ERROR): Pressure reading out of range: 915.671448 decibar 2013-10-31T21:34:34.134Z,1383255274.134 [Radio_Freewave](INFO): Powering up 2013-10-31T21:34:34.161Z,1383255274.161 [DAT](INFO): Powering up 2013-10-31T21:34:34.161Z,1383255274.161 [DAT](DEBUG): Initializing DAT. 2013-10-31T21:34:34.383Z,1383255274.383 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2013-10-31T21:34:34.391Z,1383255274.391 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2013-10-31T21:34:34.417Z,1383255274.417 [ElevatorServo](DEBUG): Initializing EZServoServo. 2013-10-31T21:34:34.423Z,1383255274.423 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2013-10-31T21:34:34.429Z,1383255274.429 [MassServo](DEBUG): Initializing EZServoServo. 2013-10-31T21:34:34.435Z,1383255274.435 [MassServo](DEBUG): Initializing MassServo. 2013-10-31T21:34:34.440Z,1383255274.440 [RudderServo](DEBUG): Initializing EZServoServo. 2013-10-31T21:34:34.447Z,1383255274.447 [RudderServo](DEBUG): Initializing RudderServo. 2013-10-31T21:34:34.452Z,1383255274.452 [ThrusterServo](DEBUG): Initializing EZServoServo. 2013-10-31T21:34:34.459Z,1383255274.459 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2013-10-31T21:34:35.761Z,1383255275.761 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2013-10-31T21:34:35.761Z,1383255275.761 [DVL_micro](INFO): Querying output modes 2013-10-31T21:34:35.761Z,1383255275.761 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2013-10-31T21:34:35.776Z,1383255275.776 [DVL_micro](DEBUG): cmdResponse: 01 2013-10-31T21:34:35.777Z,1383255275.777 [DVL_micro](INFO): NQ1 output enabled 2013-10-31T21:34:35.777Z,1383255275.777 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2013-10-31T21:34:35.789Z,1383255275.789 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2013-10-31T21:34:35.794Z,1383255275.794 [DVL_micro](INFO): pause:Powering down 2013-10-31T21:34:38.378Z,1383255278.378 [NAL9602](INFO): Powering up NAL9602 2013-10-31T21:34:49.029Z,1383255289.029 [NAL9602](INFO): NAL9602 initialized 2013-10-31T21:34:49.147Z,1383255289.147 [SBIT](IMPORTANT): Beginning Startup BIT 2013-10-31T21:34:49.150Z,1383255289.150 [CBIT](IMPORTANT): Beginning GF scan 2013-10-31T21:34:54.561Z,1383255294.561 [DAT](INFO): Powering down 2013-10-31T21:35:12.888Z,1383255312.888 [NAL9602](IMPORTANT): GPS fix at: 1383255334.00 2013-10-31T21:35:15.983Z,1383255315.983 [CBIT](IMPORTANT): No ground fault detected 2013-10-31T21:35:20.022Z,1383255320.022 [NAL9602](INFO): Powering down 2013-10-31T21:35:42.891Z,1383255342.891 [SBIT](IMPORTANT): SBIT PASSED 2013-10-31T21:35:43.293Z,1383255343.293 [MissionManager](IMPORTANT): Started mission Startup 2013-10-31T21:35:43.293Z,1383255343.293 [Startup] Running Loop=1 2013-10-31T21:35:43.293Z,1383255343.293 [Startup](INFO): Aggregate::initialize Startup 2013-10-31T21:35:43.293Z,1383255343.293 [Startup:A.GoToSurface] Running Loop=1 2013-10-31T21:35:43.293Z,1383255343.293 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:35:43.300Z,1383255343.300 [Startup:StartupSatComms] Running Loop=1 2013-10-31T21:35:43.300Z,1383255343.300 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2013-10-31T21:35:43.300Z,1383255343.300 [Startup:StartupSatComms:A] Running Loop=1 2013-10-31T21:35:43.687Z,1383255343.687 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2013-10-31T21:35:44.051Z,1383255344.051 [NAL9602](INFO): Powering up 2013-10-31T21:35:54.711Z,1383255354.711 [NAL9602](INFO): NAL9602 initialized 2013-10-31T21:36:10.988Z,1383255370.988 [NAL9602](IMPORTANT): GPS fix at: 1383255392.00 2013-10-31T21:36:11.002Z,1383255371.002 [Startup:StartupSatComms:A] Stopped 2013-10-31T21:36:11.002Z,1383255371.002 [Startup:StartupSatComms:B] Running Loop=1 2013-10-31T21:36:11.418Z,1383255371.418 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2013-10-31T21:36:28.293Z,1383255388.293 [NAL9602](INFO): SBD MO Status=1, MOMSN=20460, MT Status=0, MTMSN=0 2013-10-31T21:36:28.343Z,1383255388.343 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T210651/Courier0016.lzma 2013-10-31T21:36:28.343Z,1383255388.343 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:36:28.345Z,1383255388.345 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Courier0016.lzma.parts/0000.sbd 2013-10-31T21:36:40.770Z,1383255400.770 [NAL9602](INFO): SBD MO Status=1, MOMSN=20461, MT Status=0, MTMSN=0 2013-10-31T21:36:40.819Z,1383255400.819 [NAL9602](INFO): Sent 206 bytes from file Logs/20131031T213425/Courier0000.lzma 2013-10-31T21:36:40.819Z,1383255400.819 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:36:40.820Z,1383255400.820 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Courier0000.lzma.parts/0000.sbd 2013-10-31T21:36:51.061Z,1383255411.061 [NAL9602](INFO): SBD MO Status=1, MOMSN=20462, MT Status=0, MTMSN=0 2013-10-31T21:36:51.111Z,1383255411.111 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0017.lzma 2013-10-31T21:36:51.111Z,1383255411.111 [NAL9602](INFO): Packets left to send: 3 2013-10-31T21:36:51.112Z,1383255411.112 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0017.lzma.parts/0003.sbd 2013-10-31T21:37:04.381Z,1383255424.381 [NAL9602](INFO): SBD MO Status=1, MOMSN=20463, MT Status=0, MTMSN=0 2013-10-31T21:37:04.431Z,1383255424.431 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0017.lzma 2013-10-31T21:37:04.431Z,1383255424.431 [NAL9602](INFO): Packets left to send: 2 2013-10-31T21:37:04.433Z,1383255424.433 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0017.lzma.parts/0002.sbd 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms:B](INFO): Timed out from 2013-10-31T21:36:11.0Z 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms:B] Stopped 2013-10-31T21:37:11.393Z,1383255431.393 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2013-10-31T21:37:11.394Z,1383255431.394 [Startup:StartupSatComms] Stopped 2013-10-31T21:37:11.394Z,1383255431.394 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2013-10-31T21:37:11.395Z,1383255431.395 [Startup](INFO): Completed Startup 2013-10-31T21:37:11.395Z,1383255431.395 [Startup] Stopped 2013-10-31T21:37:11.395Z,1383255431.395 [Startup](INFO): Aggregate::uninitialize Startup 2013-10-31T21:37:11.395Z,1383255431.395 [Startup:A.GoToSurface] Stopped 2013-10-31T21:37:11.395Z,1383255431.395 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:37:11.793Z,1383255431.793 [MissionManager](IMPORTANT): Started mission Default 2013-10-31T21:37:11.793Z,1383255431.793 [Default] Running Loop=1 2013-10-31T21:37:11.794Z,1383255431.794 [Default](INFO): Aggregate::initialize Default 2013-10-31T21:37:11.794Z,1383255431.794 [Default:D.SetSpeed] Running Loop=1 2013-10-31T21:37:11.794Z,1383255431.794 [Default:D.SetSpeed](DEBUG): Initialize. 2013-10-31T21:37:11.794Z,1383255431.794 [Default:E.GoToSurface] Running Loop=1 2013-10-31T21:37:11.794Z,1383255431.794 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:37:11.794Z,1383255431.794 [Default:Iridium] Running Loop=1 2013-10-31T21:37:11.795Z,1383255431.795 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2013-10-31T21:37:11.795Z,1383255431.795 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-10-31T21:37:11.795Z,1383255431.795 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:37:11.795Z,1383255431.795 [Default:Iridium:B.GoToSurface] Running Loop=1 2013-10-31T21:37:11.795Z,1383255431.795 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:37:11.795Z,1383255431.795 [Default:E.GoToSurface] Running Loop=1 2013-10-31T21:37:11.801Z,1383255431.801 [Default:D.SetSpeed] Running Loop=1 2013-10-31T21:37:11.806Z,1383255431.806 [Default:CallIridium] Running Loop=1 2013-10-31T21:37:11.806Z,1383255431.806 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2013-10-31T21:37:11.806Z,1383255431.806 [Default:CallIridium:A] Running Loop=1 2013-10-31T21:37:11.808Z,1383255431.808 [Default:CallIridium:A] Stopped 2013-10-31T21:37:11.808Z,1383255431.808 [Default:CallIridium:B] Running Loop=1 2013-10-31T21:37:11.808Z,1383255431.808 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2013-10-31T21:37:11.814Z,1383255431.814 [Default:Iridium:B.GoToSurface] Stopped 2013-10-31T21:37:11.814Z,1383255431.814 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:37:11.814Z,1383255431.814 [Default:Iridium:Read_Iridium] Running Loop=1 2013-10-31T21:37:11.814Z,1383255431.814 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-10-31T21:37:11.819Z,1383255431.819 [Default:GPS] Running Loop=1 2013-10-31T21:37:11.819Z,1383255431.819 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2013-10-31T21:37:11.820Z,1383255431.820 [Default:GPS:A.SetSpeed] Running Loop=1 2013-10-31T21:37:11.820Z,1383255431.820 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:37:11.820Z,1383255431.820 [Default:GPS:B.GoToSurface] Running Loop=1 2013-10-31T21:37:11.820Z,1383255431.820 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:37:11.825Z,1383255431.825 [Default:GPS:B.GoToSurface] Stopped 2013-10-31T21:37:11.825Z,1383255431.825 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:37:11.826Z,1383255431.826 [Default:GPS:Read_GPS] Running Loop=1 2013-10-31T21:37:11.826Z,1383255431.826 [Default:GPS:A.SetSpeed] Running Loop=1 2013-10-31T21:37:12.193Z,1383255432.193 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2013-10-31T21:37:12.196Z,1383255432.196 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2013-10-31T21:37:16.624Z,1383255436.624 [NAL9602](INFO): SBD MO Status=1, MOMSN=20464, MT Status=0, MTMSN=0 2013-10-31T21:37:16.677Z,1383255436.677 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T210651/Express0017.lzma 2013-10-31T21:37:16.677Z,1383255436.677 [NAL9602](INFO): Packets left to send: 1 2013-10-31T21:37:16.681Z,1383255436.681 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0017.lzma.parts/0001.sbd 2013-10-31T21:37:38.057Z,1383255458.057 [NAL9602](INFO): SBD MO Status=1, MOMSN=20465, MT Status=0, MTMSN=0 2013-10-31T21:37:38.111Z,1383255458.111 [NAL9602](INFO): Sent 89 bytes from file Logs/20131031T210651/Express0017.lzma 2013-10-31T21:37:38.112Z,1383255458.112 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:37:38.113Z,1383255458.113 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T210651/Express0017.lzma.parts/0000.sbd 2013-10-31T21:37:51.526Z,1383255471.526 [NAL9602](INFO): SBD MO Status=1, MOMSN=20466, MT Status=0, MTMSN=0 2013-10-31T21:37:51.584Z,1383255471.584 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:37:51.585Z,1383255471.585 [NAL9602](INFO): Packets left to send: 5 2013-10-31T21:37:51.586Z,1383255471.586 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0005.sbd 2013-10-31T21:38:02.099Z,1383255482.099 [NAL9602](INFO): SBD MO Status=1, MOMSN=20467, MT Status=0, MTMSN=0 2013-10-31T21:38:02.149Z,1383255482.149 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:38:02.149Z,1383255482.149 [NAL9602](INFO): Packets left to send: 4 2013-10-31T21:38:02.150Z,1383255482.150 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0004.sbd 2013-10-31T21:38:15.087Z,1383255495.087 [NAL9602](INFO): SBD MO Status=1, MOMSN=20468, MT Status=0, MTMSN=0 2013-10-31T21:38:15.137Z,1383255495.137 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:38:15.137Z,1383255495.137 [NAL9602](INFO): Packets left to send: 3 2013-10-31T21:38:15.138Z,1383255495.138 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0003.sbd 2013-10-31T21:38:25.287Z,1383255505.287 [NAL9602](INFO): SBD MO Status=1, MOMSN=20469, MT Status=0, MTMSN=0 2013-10-31T21:38:25.337Z,1383255505.337 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:38:25.337Z,1383255505.337 [NAL9602](INFO): Packets left to send: 2 2013-10-31T21:38:25.338Z,1383255505.338 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0002.sbd 2013-10-31T21:38:53.586Z,1383255533.586 [NAL9602](INFO): SBD MO Status=2, MOMSN=20470, MT Status=2, MTMSN=0 2013-10-31T21:38:53.587Z,1383255533.587 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:38:53.587Z,1383255533.587 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:38:54.794Z,1383255534.794 [NAL9602](IMPORTANT): GPS fix at: 1383255557.00 2013-10-31T21:38:54.810Z,1383255534.810 [Default:GPS:Read_GPS] Stopped 2013-10-31T21:38:54.810Z,1383255534.810 [Default:GPS:D] Running Loop=1 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS:D] Stopped 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS](INFO): Completed Default:GPS 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS] Stopped 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS:A.SetSpeed] Stopped 2013-10-31T21:38:55.233Z,1383255535.233 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2013-10-31T21:40:39.755Z,1383255639.755 [NAL9602](INFO): SBD MO Status=1, MOMSN=20470, MT Status=0, MTMSN=0 2013-10-31T21:40:39.809Z,1383255639.809 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:40:39.809Z,1383255639.809 [NAL9602](INFO): Packets left to send: 1 2013-10-31T21:40:39.810Z,1383255639.810 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0001.sbd 2013-10-31T21:40:50.348Z,1383255650.348 [NAL9602](INFO): SBD MO Status=1, MOMSN=20471, MT Status=0, MTMSN=0 2013-10-31T21:40:50.401Z,1383255650.401 [NAL9602](INFO): Sent 64 bytes from file Logs/20131031T213425/Express0001.lzma 2013-10-31T21:40:50.402Z,1383255650.402 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:40:50.403Z,1383255650.403 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0001.lzma.parts/0000.sbd 2013-10-31T21:40:58.872Z,1383255658.872 [NAL9602](INFO): SBD MO Status=0, MOMSN=20472, MT Status=0, MTMSN=0 2013-10-31T21:41:02.503Z,1383255662.503 [Default:Iridium:Read_Iridium] Stopped 2013-10-31T21:41:02.504Z,1383255662.504 [Default:Iridium](INFO): Completed Default:Iridium 2013-10-31T21:41:02.504Z,1383255662.504 [Default:Iridium] Stopped 2013-10-31T21:41:02.504Z,1383255662.504 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2013-10-31T21:41:02.504Z,1383255662.504 [Default:Iridium:A.SetSpeed] Stopped 2013-10-31T21:41:02.504Z,1383255662.504 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2013-10-31T21:41:02.504Z,1383255662.504 [Default:F.Wait] Running Loop=1 2013-10-31T21:41:02.504Z,1383255662.504 [Default:F.Wait](DEBUG): Initialize Wait Component. 2013-10-31T21:41:02.992Z,1383255662.992 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B 2013-10-31T21:41:02.992Z,1383255662.992 [Default:CallIridium:B] Stopped 2013-10-31T21:41:02.992Z,1383255662.992 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2013-10-31T21:41:02.993Z,1383255662.993 [Default:CallIridium](INFO): Completed Default:CallIridium 2013-10-31T21:41:02.993Z,1383255662.993 [Default:CallIridium] Stopped 2013-10-31T21:41:02.994Z,1383255662.994 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2013-10-31T21:41:12.933Z,1383255672.933 [NAL9602](INFO): Powering down 2013-10-31T21:46:02.941Z,1383255962.941 [Default:CallIridium] Running Loop=1 2013-10-31T21:46:02.941Z,1383255962.941 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2013-10-31T21:46:02.941Z,1383255962.941 [Default:CallIridium:A] Running Loop=1 2013-10-31T21:46:02.941Z,1383255962.941 [Default:CallIridium:A] Stopped 2013-10-31T21:46:02.941Z,1383255962.941 [Default:CallIridium:B] Running Loop=1 2013-10-31T21:46:02.942Z,1383255962.942 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium] Running Loop=1 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium:B.GoToSurface] Running Loop=1 2013-10-31T21:46:07.936Z,1383255967.936 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:46:07.937Z,1383255967.937 [Default:Iridium:B.GoToSurface] Stopped 2013-10-31T21:46:07.937Z,1383255967.937 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:46:07.937Z,1383255967.937 [Default:Iridium:Read_Iridium] Running Loop=1 2013-10-31T21:46:07.940Z,1383255967.940 [Default:GPS] Running Loop=1 2013-10-31T21:46:07.940Z,1383255967.940 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2013-10-31T21:46:07.940Z,1383255967.940 [Default:GPS:A.SetSpeed] Running Loop=1 2013-10-31T21:46:07.940Z,1383255967.940 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:46:07.941Z,1383255967.941 [Default:GPS:B.GoToSurface] Running Loop=1 2013-10-31T21:46:07.941Z,1383255967.941 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:46:07.942Z,1383255967.942 [Default:GPS:B.GoToSurface] Stopped 2013-10-31T21:46:07.942Z,1383255967.942 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:46:07.942Z,1383255967.942 [Default:GPS:Read_GPS] Running Loop=1 2013-10-31T21:46:08.761Z,1383255968.761 [NAL9602](INFO): Powering up 2013-10-31T21:46:19.616Z,1383255979.616 [NAL9602](INFO): NAL9602 initialized 2013-10-31T21:46:44.210Z,1383256004.210 [NAL9602](INFO): SBD MO Status=1, MOMSN=20473, MT Status=0, MTMSN=0 2013-10-31T21:46:44.258Z,1383256004.258 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T213425/Courier0004.lzma 2013-10-31T21:46:44.258Z,1383256004.258 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:46:44.260Z,1383256004.260 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Courier0004.lzma.parts/0000.sbd 2013-10-31T21:46:54.560Z,1383256014.560 [NAL9602](INFO): SBD MO Status=1, MOMSN=20474, MT Status=0, MTMSN=0 2013-10-31T21:46:54.618Z,1383256014.618 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:46:54.618Z,1383256014.618 [NAL9602](INFO): Packets left to send: 8 2013-10-31T21:46:54.620Z,1383256014.620 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0008.sbd 2013-10-31T21:47:06.373Z,1383256026.373 [NAL9602](INFO): SBD MO Status=1, MOMSN=20475, MT Status=0, MTMSN=0 2013-10-31T21:47:06.420Z,1383256026.420 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:47:06.421Z,1383256026.421 [NAL9602](INFO): Packets left to send: 7 2013-10-31T21:47:06.422Z,1383256026.422 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0007.sbd 2013-10-31T21:47:18.978Z,1383256038.978 [NAL9602](INFO): SBD MO Status=1, MOMSN=20476, MT Status=0, MTMSN=0 2013-10-31T21:47:19.028Z,1383256039.028 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:47:19.028Z,1383256039.028 [NAL9602](INFO): Packets left to send: 6 2013-10-31T21:47:19.029Z,1383256039.029 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0006.sbd 2013-10-31T21:47:34.378Z,1383256054.378 [NAL9602](INFO): SBD MO Status=1, MOMSN=20477, MT Status=0, MTMSN=0 2013-10-31T21:47:34.428Z,1383256054.428 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:47:34.429Z,1383256054.429 [NAL9602](INFO): Packets left to send: 5 2013-10-31T21:47:34.430Z,1383256054.430 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0005.sbd 2013-10-31T21:48:01.111Z,1383256081.111 [NAL9602](INFO): SBD MO Status=2, MOMSN=20478, MT Status=2, MTMSN=0 2013-10-31T21:48:01.112Z,1383256081.112 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:48:01.112Z,1383256081.112 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:48:02.295Z,1383256082.295 [NAL9602](IMPORTANT): GPS fix at: 1383256103.00 2013-10-31T21:48:02.312Z,1383256082.312 [Default:GPS:Read_GPS] Stopped 2013-10-31T21:48:02.312Z,1383256082.312 [Default:GPS:D] Running Loop=1 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS:D] Stopped 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS](INFO): Completed Default:GPS 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS] Stopped 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS:A.SetSpeed] Stopped 2013-10-31T21:48:02.717Z,1383256082.717 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2013-10-31T21:49:48.494Z,1383256188.494 [NAL9602](INFO): SBD MO Status=2, MOMSN=20478, MT Status=0, MTMSN=0 2013-10-31T21:49:48.494Z,1383256188.494 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:49:48.494Z,1383256188.494 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:50:29.578Z,1383256229.578 [NAL9602](INFO): SBD MO Status=2, MOMSN=20478, MT Status=2, MTMSN=0 2013-10-31T21:50:29.578Z,1383256229.578 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:50:29.578Z,1383256229.578 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:50:48.964Z,1383256248.964 [NAL9602](INFO): SBD MO Status=1, MOMSN=20478, MT Status=0, MTMSN=0 2013-10-31T21:50:49.014Z,1383256249.014 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:50:49.014Z,1383256249.014 [NAL9602](INFO): Packets left to send: 4 2013-10-31T21:50:49.015Z,1383256249.015 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0004.sbd 2013-10-31T21:51:04.027Z,1383256264.027 [NAL9602](INFO): SBD MO Status=1, MOMSN=20479, MT Status=0, MTMSN=0 2013-10-31T21:51:04.077Z,1383256264.077 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:51:04.077Z,1383256264.077 [NAL9602](INFO): Packets left to send: 3 2013-10-31T21:51:04.078Z,1383256264.078 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0003.sbd 2013-10-31T21:51:14.565Z,1383256274.565 [NAL9602](INFO): SBD MO Status=1, MOMSN=20480, MT Status=0, MTMSN=0 2013-10-31T21:51:14.613Z,1383256274.613 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:51:14.614Z,1383256274.614 [NAL9602](INFO): Packets left to send: 2 2013-10-31T21:51:14.615Z,1383256274.615 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0002.sbd 2013-10-31T21:51:35.574Z,1383256295.574 [NAL9602](INFO): SBD MO Status=2, MOMSN=20481, MT Status=2, MTMSN=0 2013-10-31T21:51:35.575Z,1383256295.575 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:51:35.575Z,1383256295.575 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:51:50.557Z,1383256310.557 [NAL9602](INFO): SBD MO Status=1, MOMSN=20481, MT Status=0, MTMSN=0 2013-10-31T21:51:50.613Z,1383256310.613 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:51:50.613Z,1383256310.613 [NAL9602](INFO): Packets left to send: 1 2013-10-31T21:51:50.615Z,1383256310.615 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0001.sbd 2013-10-31T21:52:03.174Z,1383256323.174 [NAL9602](INFO): SBD MO Status=1, MOMSN=20482, MT Status=0, MTMSN=0 2013-10-31T21:52:03.221Z,1383256323.221 [NAL9602](INFO): Sent 259 bytes from file Logs/20131031T213425/Express0005.lzma 2013-10-31T21:52:03.221Z,1383256323.221 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:52:03.222Z,1383256323.222 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0005.lzma.parts/0000.sbd 2013-10-31T21:52:13.770Z,1383256333.770 [NAL9602](INFO): SBD MO Status=0, MOMSN=20483, MT Status=0, MTMSN=0 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium:Read_Iridium] Stopped 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium](INFO): Completed Default:Iridium 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium] Stopped 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium:A.SetSpeed] Stopped 2013-10-31T21:52:17.380Z,1383256337.380 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium:B] Stopped 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium](INFO): Completed Default:CallIridium 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium] Stopped 2013-10-31T21:52:17.800Z,1383256337.800 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2013-10-31T21:52:27.811Z,1383256347.811 [NAL9602](INFO): Powering down 2013-10-31T21:57:17.824Z,1383256637.824 [Default:CallIridium] Running Loop=1 2013-10-31T21:57:17.824Z,1383256637.824 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2013-10-31T21:57:17.824Z,1383256637.824 [Default:CallIridium:A] Running Loop=1 2013-10-31T21:57:17.825Z,1383256637.825 [Default:CallIridium:A] Stopped 2013-10-31T21:57:17.825Z,1383256637.825 [Default:CallIridium:B] Running Loop=1 2013-10-31T21:57:17.825Z,1383256637.825 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium] Running Loop=1 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium:A.SetSpeed] Running Loop=1 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium:B.GoToSurface] Running Loop=1 2013-10-31T21:57:22.806Z,1383256642.806 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:57:22.807Z,1383256642.807 [Default:Iridium:B.GoToSurface] Stopped 2013-10-31T21:57:22.807Z,1383256642.807 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:57:22.807Z,1383256642.807 [Default:Iridium:Read_Iridium] Running Loop=1 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS] Running Loop=1 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS:A.SetSpeed] Running Loop=1 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS:B.GoToSurface] Running Loop=1 2013-10-31T21:57:22.808Z,1383256642.808 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2013-10-31T21:57:22.809Z,1383256642.809 [Default:GPS:B.GoToSurface] Stopped 2013-10-31T21:57:22.809Z,1383256642.809 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2013-10-31T21:57:22.809Z,1383256642.809 [Default:GPS:Read_GPS] Running Loop=1 2013-10-31T21:57:23.560Z,1383256643.560 [NAL9602](INFO): Powering up 2013-10-31T21:57:34.098Z,1383256654.098 [NAL9602](INFO): NAL9602 initialized 2013-10-31T21:57:50.978Z,1383256670.978 [NAL9602](INFO): SBD MO Status=1, MOMSN=20484, MT Status=0, MTMSN=0 2013-10-31T21:57:51.028Z,1383256671.028 [NAL9602](INFO): Sent 60 bytes from file Logs/20131031T213425/Courier0008.lzma 2013-10-31T21:57:51.028Z,1383256671.028 [NAL9602](INFO): Packets left to send: 0 2013-10-31T21:57:51.030Z,1383256671.030 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Courier0008.lzma.parts/0000.sbd 2013-10-31T21:58:03.674Z,1383256683.674 [NAL9602](INFO): SBD MO Status=1, MOMSN=20485, MT Status=0, MTMSN=0 2013-10-31T21:58:03.724Z,1383256683.724 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:58:03.724Z,1383256683.724 [NAL9602](INFO): Packets left to send: 9 2013-10-31T21:58:03.725Z,1383256683.725 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0009.sbd 2013-10-31T21:58:18.761Z,1383256698.761 [NAL9602](INFO): SBD MO Status=1, MOMSN=20486, MT Status=0, MTMSN=0 2013-10-31T21:58:18.811Z,1383256698.811 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:58:18.811Z,1383256698.811 [NAL9602](INFO): Packets left to send: 8 2013-10-31T21:58:18.812Z,1383256698.812 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0008.sbd 2013-10-31T21:58:44.160Z,1383256724.160 [NAL9602](INFO): SBD MO Status=1, MOMSN=20487, MT Status=0, MTMSN=0 2013-10-31T21:58:44.214Z,1383256724.214 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:58:44.215Z,1383256724.215 [NAL9602](INFO): Packets left to send: 7 2013-10-31T21:58:44.216Z,1383256724.216 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0007.sbd 2013-10-31T21:59:01.592Z,1383256741.592 [NAL9602](INFO): SBD MO Status=1, MOMSN=20488, MT Status=0, MTMSN=0 2013-10-31T21:59:01.641Z,1383256741.641 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:59:01.642Z,1383256741.642 [NAL9602](INFO): Packets left to send: 6 2013-10-31T21:59:01.643Z,1383256741.643 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0006.sbd 2013-10-31T21:59:16.170Z,1383256756.170 [NAL9602](INFO): SBD MO Status=1, MOMSN=20489, MT Status=0, MTMSN=0 2013-10-31T21:59:16.220Z,1383256756.220 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:59:16.220Z,1383256756.220 [NAL9602](INFO): Packets left to send: 5 2013-10-31T21:59:16.222Z,1383256756.222 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0005.sbd 2013-10-31T21:59:30.364Z,1383256770.364 [NAL9602](INFO): SBD MO Status=1, MOMSN=20490, MT Status=0, MTMSN=0 2013-10-31T21:59:30.414Z,1383256770.414 [NAL9602](INFO): Sent 332 bytes from file Logs/20131031T213425/Express0009.lzma 2013-10-31T21:59:30.414Z,1383256770.414 [NAL9602](INFO): Packets left to send: 4 2013-10-31T21:59:30.415Z,1383256770.415 [NAL9602](INFO): Stored copy of sent data in Logs/20131031T213425/Express0009.lzma.parts/0004.sbd 2013-10-31T21:59:54.076Z,1383256794.076 [NAL9602](INFO): SBD MO Status=2, MOMSN=20491, MT Status=0, MTMSN=0 2013-10-31T21:59:54.076Z,1383256794.076 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2013-10-31T21:59:54.076Z,1383256794.076 [NAL9602](INFO): XMIT Failed. Starting over. 2013-10-31T21:59:55.267Z,1383256795.267 [NAL9602](IMPORTANT): GPS fix at: 1383256816.00 2013-10-31T21:59:55.310Z,1383256795.310 [Default:GPS:Read_GPS] Stopped 2013-10-31T21:59:55.310Z,1383256795.310 [Default:GPS:D] Running Loop=1 2013-10-31T21:59:55.690Z,1383256795.690 [Default:GPS:D] Stopped 2013-10-31T21:59:55.691Z,1383256795.691 [Default:GPS](INFO): Completed Default:GPS 2013-10-31T21:59:55.691Z,1383256795.691 [Default:GPS] Stopped 2013-10-31T21:59:55.691Z,1383256795.691 [Default:GPS](INFO): Aggregate::un