2012-10-26T16:34:51.253Z,1351269291.253 [Supervisor](DEBUG): Initializing supervisor. 2012-10-26T16:34:51.256Z,1351269291.256 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2012-10-26T16:34:51.257Z,1351269291.257 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2012-10-26T16:34:51.257Z,1351269291.257 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2012-10-26T16:34:51.261Z,1351269291.261 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2012-10-26T16:34:51.272Z,1351269291.272 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2012-10-26T16:34:51.273Z,1351269291.273 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2012-10-26T16:34:51.274Z,1351269291.274 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread. 2012-10-26T16:34:51.274Z,1351269291.274 [Supervisor](INFO): Looking for Config files in directory: Config/ 2012-10-26T16:34:51.277Z,1351269291.277 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2012-10-26T16:34:51.560Z,1351269291.560 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2012-10-26T16:34:51.562Z,1351269291.562 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2012-10-26T16:34:51.743Z,1351269291.743 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2012-10-26T16:34:51.744Z,1351269291.744 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2012-10-26T16:34:51.830Z,1351269291.830 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2012-10-26T16:34:51.832Z,1351269291.832 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2012-10-26T16:34:52.039Z,1351269292.039 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2012-10-26T16:34:52.039Z,1351269292.039 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2012-10-26T16:34:52.177Z,1351269292.177 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2012-10-26T16:34:52.179Z,1351269292.179 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2012-10-26T16:34:52.412Z,1351269292.412 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2012-10-26T16:34:52.413Z,1351269292.413 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2012-10-26T16:34:52.585Z,1351269292.585 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2012-10-26T16:34:52.587Z,1351269292.587 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2012-10-26T16:34:52.840Z,1351269292.840 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2012-10-26T16:34:52.842Z,1351269292.842 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2012-10-26T16:34:52.942Z,1351269292.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2012-10-26T16:34:52.943Z,1351269292.943 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2012-10-26T16:34:53.345Z,1351269293.345 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2012-10-26T16:34:53.346Z,1351269293.346 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2012-10-26T16:34:53.461Z,1351269293.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2012-10-26T16:34:53.461Z,1351269293.461 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2012-10-26T16:34:53.548Z,1351269293.548 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2012-10-26T16:34:53.552Z,1351269293.552 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2012-10-26T16:34:53.654Z,1351269293.654 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2012-10-26T16:34:53.787Z,1351269293.787 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2012-10-26T16:34:53.874Z,1351269293.874 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2012-10-26T16:34:53.977Z,1351269293.977 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2012-10-26T16:34:54.079Z,1351269294.079 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2012-10-26T16:34:54.198Z,1351269294.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2012-10-26T16:34:54.316Z,1351269294.316 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2012-10-26T16:34:54.404Z,1351269294.404 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2012-10-26T16:34:54.435Z,1351269294.434 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2012-10-26T16:34:54.604Z,1351269294.604 [InternalSim] Loaded 2012-10-26T16:34:54.604Z,1351269294.604 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2012-10-26T16:34:54.605Z,1351269294.605 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2012-10-26T16:34:54.605Z,1351269294.605 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2012-10-26T16:34:54.683Z,1351269294.683 [SBIT](DEBUG): Construct Startup Built In Test. 2012-10-26T16:34:54.697Z,1351269294.697 [SBIT] Loaded 2012-10-26T16:34:54.697Z,1351269294.697 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2012-10-26T16:34:54.698Z,1351269294.698 [IBIT](DEBUG): Construct Initiated Built In Test. 2012-10-26T16:34:54.726Z,1351269294.726 [IBIT] Loaded 2012-10-26T16:34:54.726Z,1351269294.727 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2012-10-26T16:34:54.730Z,1351269294.730 [CBIT](DEBUG): Construct CBIT Built In Test. 2012-10-26T16:34:54.846Z,1351269294.846 [CBIT] Loaded 2012-10-26T16:34:54.847Z,1351269294.847 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2012-10-26T16:34:54.847Z,1351269294.847 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2012-10-26T16:34:54.848Z,1351269294.848 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2012-10-26T16:34:55.021Z,1351269295.021 [BuoyancyServo] Loaded 2012-10-26T16:34:55.021Z,1351269295.021 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2012-10-26T16:34:55.030Z,1351269295.030 [ElevatorServo] Loaded 2012-10-26T16:34:55.031Z,1351269295.030 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2012-10-26T16:34:55.042Z,1351269295.042 [MassServo] Loaded 2012-10-26T16:34:55.043Z,1351269295.043 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2012-10-26T16:34:55.054Z,1351269295.054 [RudderServo] Loaded 2012-10-26T16:34:55.055Z,1351269295.055 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2012-10-26T16:34:55.066Z,1351269295.066 [ThrusterServo] Loaded 2012-10-26T16:34:55.066Z,1351269295.066 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2012-10-26T16:34:55.067Z,1351269295.067 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2012-10-26T16:34:55.067Z,1351269295.067 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2012-10-26T16:34:55.100Z,1351269295.100 [DepthRateCalculator] Loaded 2012-10-26T16:34:55.101Z,1351269295.101 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2012-10-26T16:34:59.113Z,1351269299.113 [HFRadarModelCalc] Loaded 2012-10-26T16:34:59.113Z,1351269299.114 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2012-10-26T16:34:59.129Z,1351269299.129 [NavChart] Loaded 2012-10-26T16:34:59.130Z,1351269299.130 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2012-10-26T16:34:59.135Z,1351269299.135 [PitchRateCalculator] Loaded 2012-10-26T16:34:59.136Z,1351269299.136 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2012-10-26T16:34:59.142Z,1351269299.142 [SpeedCalculator] Loaded 2012-10-26T16:34:59.142Z,1351269299.142 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2012-10-26T16:34:59.156Z,1351269299.156 [TempGradientCalculator] Loaded 2012-10-26T16:34:59.157Z,1351269299.157 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2012-10-26T16:34:59.162Z,1351269299.162 [YawRateCalculator] Loaded 2012-10-26T16:34:59.162Z,1351269299.162 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2012-10-26T16:34:59.182Z,1351269299.182 [Navigation] Loaded 2012-10-26T16:34:59.182Z,1351269299.182 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2012-10-26T16:34:59.183Z,1351269299.183 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2012-10-26T16:34:59.183Z,1351269299.183 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2012-10-26T16:34:59.436Z,1351269299.436 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2012-10-26T16:34:59.437Z,1351269299.437 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2012-10-26T16:34:59.474Z,1351269299.474 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2012-10-26T16:34:59.475Z,1351269299.475 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2012-10-26T16:34:59.533Z,1351269299.533 [VerticalControl](DEBUG): Construct VerticalControl. 2012-10-26T16:34:59.577Z,1351269299.578 [VerticalControl] Loaded 2012-10-26T16:34:59.578Z,1351269299.578 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2012-10-26T16:34:59.579Z,1351269299.579 [HorizontalControl](DEBUG): Construct HorizontalControl. 2012-10-26T16:34:59.600Z,1351269299.599 [HorizontalControl] Loaded 2012-10-26T16:34:59.600Z,1351269299.600 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2012-10-26T16:34:59.601Z,1351269299.601 [SpeedControl](DEBUG): Construct SpeedControl. 2012-10-26T16:34:59.603Z,1351269299.602 [SpeedControl] Loaded 2012-10-26T16:34:59.603Z,1351269299.603 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2012-10-26T16:34:59.604Z,1351269299.604 [LoopControl](DEBUG): Construct LoopControl. 2012-10-26T16:34:59.604Z,1351269299.604 [LoopControl] Loaded 2012-10-26T16:34:59.604Z,1351269299.605 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2012-10-26T16:34:59.605Z,1351269299.605 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2012-10-26T16:34:59.606Z,1351269299.606 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2012-10-26T16:34:59.613Z,1351269299.613 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2012-10-26T16:34:59.618Z,1351269299.618 [AsyncPiEstimator] Loaded 2012-10-26T16:34:59.619Z,1351269299.619 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2012-10-26T16:34:59.620Z,1351269299.620 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406724E0 2012-10-26T16:34:59.620Z,1351269299.620 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2012-10-26T16:34:59.621Z,1351269299.621 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2012-10-26T16:34:59.785Z,1351269299.785 [AHRS_sp3003D] Loaded 2012-10-26T16:34:59.785Z,1351269299.785 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2012-10-26T16:35:00.040Z,1351269300.040 [Batt_Ocean_Server] Loaded 2012-10-26T16:35:00.041Z,1351269300.041 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread. 2012-10-26T16:35:00.053Z,1351269300.053 [Depth_Keller] Loaded 2012-10-26T16:35:00.054Z,1351269300.053 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2012-10-26T16:35:00.059Z,1351269300.059 [DropWeight] Loaded 2012-10-26T16:35:00.059Z,1351269300.059 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2012-10-26T16:35:00.178Z,1351269300.178 [DVL_micro] Loaded 2012-10-26T16:35:00.178Z,1351269300.178 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2012-10-26T16:35:00.179Z,1351269300.180 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 406F34E0 2012-10-26T16:35:00.263Z,1351269300.263 [NAL9602] Loaded 2012-10-26T16:35:00.263Z,1351269300.263 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2012-10-26T16:35:00.313Z,1351269300.313 [Onboard] Loaded 2012-10-26T16:35:00.313Z,1351269300.313 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2012-10-26T16:35:00.320Z,1351269300.320 [Radio_Freewave] Loaded 2012-10-26T16:35:00.320Z,1351269300.320 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2012-10-26T16:35:00.321Z,1351269300.321 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2012-10-26T16:35:00.322Z,1351269300.322 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2012-10-26T16:35:00.419Z,1351269300.419 [CTD_NeilBrown] Loaded 2012-10-26T16:35:00.419Z,1351269300.420 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2012-10-26T16:35:00.421Z,1351269300.421 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4074B4E0 2012-10-26T16:35:00.431Z,1351269300.431 [PAR_Licor] Loaded 2012-10-26T16:35:00.431Z,1351269300.431 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2012-10-26T16:35:00.447Z,1351269300.447 [Turbulence_NPS] Loaded 2012-10-26T16:35:00.447Z,1351269300.447 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread. 2012-10-26T16:35:00.449Z,1351269300.448 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 4077B4E0 2012-10-26T16:35:00.478Z,1351269300.478 [WetLabsBB2FL] Loaded 2012-10-26T16:35:00.479Z,1351269300.478 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2012-10-26T16:35:00.480Z,1351269300.480 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407AB4E0 2012-10-26T16:35:00.480Z,1351269300.480 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2012-10-26T16:35:00.483Z,1351269300.483 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2012-10-26T16:35:00.484Z,1351269300.484 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2012-10-26T16:35:00.493Z,1351269300.493 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2012-10-26T16:35:00.494Z,1351269300.494 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 407DB4E0 2012-10-26T16:35:00.499Z,1351269300.499 [Supervisor](DEBUG): Running supervisor. 2012-10-26T16:35:00.500Z,1351269300.500 [CommandLine](INFO): Thread ID is 746 2012-10-26T16:35:00.502Z,1351269300.502 [controlThread](INFO): Thread ID is 745 2012-10-26T16:35:00.502Z,1351269300.502 [controlThread](DEBUG): Initializing ControlThread 2012-10-26T16:35:00.503Z,1351269300.503 [CycleStarter](INFO): Thread ID is 744 2012-10-26T16:35:00.503Z,1351269300.503 [InternalSim](DEBUG): InternalSim initializing... 2012-10-26T16:35:00.600Z,1351269300.600 [AsyncPiEstimator](INFO): Thread ID is 807 2012-10-26T16:35:00.600Z,1351269300.600 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2012-10-26T16:35:00.662Z,1351269300.662 [DVL_micro](INFO): Thread ID is 808 2012-10-26T16:35:00.738Z,1351269300.738 [CTD_NeilBrown](INFO): Thread ID is 809 2012-10-26T16:35:00.738Z,1351269300.738 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2012-10-26T16:35:00.741Z,1351269300.741 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2012-10-26T16:35:00.762Z,1351269300.762 [DVL_micro](INFO): Initializing 2012-10-26T16:35:00.762Z,1351269300.762 [DVL_micro](INFO): start:Powering up 2012-10-26T16:35:00.771Z,1351269300.771 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2012-10-26T16:35:00.772Z,1351269300.772 [DVL_micro](INFO): Cycling power to configure device. 2012-10-26T16:35:00.784Z,1351269300.784 [Turbulence_NPS](INFO): Thread ID is 810 2012-10-26T16:35:00.784Z,1351269300.784 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS. 2012-10-26T16:35:00.785Z,1351269300.785 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1 2012-10-26T16:35:00.797Z,1351269300.797 [SBIT](INFO): Initialize SBIT Component. 2012-10-26T16:35:00.798Z,1351269300.798 [SBIT](IMPORTANT): Tethys CM Info: $Rev: 10014 2012-10-26T16:35:00.803Z,1351269300.803 [IBIT](INFO): Initialize IBIT Component. 2012-10-26T16:35:00.808Z,1351269300.808 [WetLabsBB2FL](INFO): Thread ID is 811 2012-10-26T16:35:00.808Z,1351269300.808 [WetLabsBB2FL](INFO): Powering down 2012-10-26T16:35:00.827Z,1351269300.827 [CBIT](DEBUG): Initialize CBIT Component. 2012-10-26T16:35:00.827Z,1351269300.827 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2012-10-26T16:35:00.835Z,1351269300.835 [NavChartDb](INFO): Thread ID is 812 2012-10-26T16:35:00.837Z,1351269300.837 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2012-10-26T16:35:00.840Z,1351269300.840 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA50M.000 2012-10-26T16:35:00.842Z,1351269300.842 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US2WC11M.000 2012-10-26T16:35:00.844Z,1351269300.844 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US1WC07M.000 2012-10-26T16:35:00.845Z,1351269300.845 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US3CA52M.000 2012-10-26T16:35:00.851Z,1351269300.851 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2012-10-26T16:35:00.852Z,1351269300.852 [NavChart](DEBUG): Initialize NavChart Derivation. 2012-10-26T16:35:00.852Z,1351269300.852 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2012-10-26T16:35:00.852Z,1351269300.852 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2012-10-26T16:35:00.853Z,1351269300.853 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2012-10-26T16:35:00.854Z,1351269300.854 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2012-10-26T16:35:00.854Z,1351269300.854 [Navigation](DEBUG): Initializing Navigation. 2012-10-26T16:35:00.855Z,1351269300.855 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2012-10-26T16:35:00.856Z,1351269300.856 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2012-10-26T16:35:00.857Z,1351269300.857 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2012-10-26T16:35:00.857Z,1351269300.857 [LoopControl](DEBUG): Initialize LoopControlComponent. 2012-10-26T16:35:00.859Z,1351269300.859 [NavChartDb](INFO): Setup scan of Resources/US5CA50M.000 2012-10-26T16:35:00.911Z,1351269300.911 [Turbulence_NPS](INFO): Pause powering down 2012-10-26T16:35:02.587Z,1351269302.587 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized 2012-10-26T16:35:02.601Z,1351269302.601 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2012-10-26T16:35:02.623Z,1351269302.623 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2012-10-26T16:35:02.638Z,1351269302.638 [MissionManager](DEBUG): 2012-10-26T16:35:02.639Z,1351269302.639 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2012-10-26T16:35:02.674Z,1351269302.674 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2012-10-26T16:35:02.676Z,1351269302.676 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2012-10-26T16:35:02.679Z,1351269302.679 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-10-26T16:35:02.687Z,1351269302.687 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2012-10-26T16:35:02.690Z,1351269302.690 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-10-26T16:35:02.697Z,1351269302.697 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2012-10-26T16:35:02.705Z,1351269302.705 [Default:D.SetSpeed](DEBUG): Construct. 2012-10-26T16:35:02.709Z,1351269302.708 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2012-10-26T16:35:02.713Z,1351269302.713 [Default:F.Wait](DEBUG): Construct Wait. 2012-10-26T16:35:02.717Z,1351269302.717 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2012-10-26T16:35:02.721Z,1351269302.721 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger, 2012-10-26T16:35:02.741Z,1351269302.741 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2012-10-26T16:35:02.849Z,1351269302.849 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2012-10-26T16:35:02.849Z,1351269302.849 [DVL_micro](INFO): Querying output modes 2012-10-26T16:35:02.850Z,1351269302.849 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-10-26T16:35:02.859Z,1351269302.859 [DVL_micro](DEBUG): cmdResponse: 01 03 16 2012-10-26T16:35:02.859Z,1351269302.859 [DVL_micro](INFO): NQ1 output enabled 2012-10-26T16:35:02.859Z,1351269302.859 [DVL_micro](INFO): RSSI output enabled 2012-10-26T16:35:02.859Z,1351269302.859 [DVL_micro](INFO): ADCP output enabled 2012-10-26T16:35:02.859Z,1351269302.859 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-10-26T16:35:02.867Z,1351269302.867 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2012-10-26T16:35:02.871Z,1351269302.871 [DVL_micro](INFO): pause:Powering down 2012-10-26T16:35:02.877Z,1351269302.877 [Radio_Freewave](INFO): Powering up 2012-10-26T16:35:02.999Z,1351269302.999 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2012-10-26T16:35:03.003Z,1351269303.003 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2012-10-26T16:35:03.009Z,1351269303.009 [ElevatorServo](DEBUG): Initializing EZServoServo. 2012-10-26T16:35:03.010Z,1351269303.010 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-10-26T16:35:03.016Z,1351269303.016 [MassServo](DEBUG): Initializing EZServoServo. 2012-10-26T16:35:03.019Z,1351269303.019 [MassServo](DEBUG): Initializing MassServo. 2012-10-26T16:35:03.024Z,1351269303.024 [RudderServo](DEBUG): Initializing EZServoServo. 2012-10-26T16:35:03.025Z,1351269303.025 [RudderServo](DEBUG): Initializing RudderServo. 2012-10-26T16:35:03.031Z,1351269303.031 [ThrusterServo](DEBUG): Initializing EZServoServo. 2012-10-26T16:35:03.035Z,1351269303.035 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2012-10-26T16:35:05.441Z,1351269305.441 [NAL9602](INFO): Powering up NAL9602 2012-10-26T16:35:16.769Z,1351269316.769 [SBIT](IMPORTANT): Beginning Startup BIT 2012-10-26T16:35:16.772Z,1351269316.772 [CBIT](IMPORTANT): Beginning GF scan 2012-10-26T16:35:17.031Z,1351269317.031 [NAL9602](INFO): NAL9602 initialized 2012-10-26T16:35:25.542Z,1351269325.542 [NavChartDb](INFO): Done scanning features of Resources/US5CA50M.000 2012-10-26T16:35:30.361Z,1351269330.361 [SBIT](FAULT): Mass: EXPECTED:0.004000 ACTUAL:0.002743 2012-10-26T16:35:45.919Z,1351269345.919 [CBIT](IMPORTANT): No ground fault detected 2012-10-26T16:36:05.865Z,1351269365.865 [NavChartDb](INFO): # of records loaded: 5000 2012-10-26T16:36:05.944Z,1351269365.944 [NAL9602](IMPORTANT): GPS fix at: 1351269364.00 2012-10-26T16:36:14.120Z,1351269374.120 [SBIT](CRITICAL): SBIT FAILED 2012-10-26T16:36:14.941Z,1351269374.941 [MissionManager](IMPORTANT): Started mission Startup 2012-10-26T16:36:14.941Z,1351269374.941 [Startup] Running Loop=1 2012-10-26T16:36:14.941Z,1351269374.941 [Startup](INFO): Aggregate::initialize Startup 2012-10-26T16:36:14.941Z,1351269374.941 [Startup:A.GoToSurface] Running Loop=1 2012-10-26T16:36:14.941Z,1351269374.941 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T16:36:14.947Z,1351269374.947 [Startup:StartupSatComms] Running Loop=1 2012-10-26T16:36:14.947Z,1351269374.947 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2012-10-26T16:36:14.947Z,1351269374.947 [Startup:StartupSatComms:A] Running Loop=1 2012-10-26T16:36:15.280Z,1351269375.280 [NAL9602](INFO): Powering down 2012-10-26T16:36:15.320Z,1351269375.320 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-10-26T16:36:15.635Z,1351269375.635 [NAL9602](INFO): Powering up 2012-10-26T16:36:27.707Z,1351269387.707 [NavChartDb](INFO): # of records loaded: 10000 2012-10-26T16:36:29.558Z,1351269389.558 [NAL9602](ERROR): NAL9602 initialize uart error: serial timeout 2012-10-26T16:36:29.558Z,1351269389.559 [NAL9602] Communications Fault, FailCount= 1 2012-10-26T16:36:29.559Z,1351269389.559 [NAL9602](ERROR): Communications Fault 2012-10-26T16:36:30.386Z,1351269390.386 [CBIT](ERROR): Communications Fault in component: NAL9602 2012-10-26T16:36:30.720Z,1351269390.720 [NAL9602](INFO): Powering down 2012-10-26T16:36:31.626Z,1351269391.626 [CBIT](INFO): Clearing failed state for component NAL9602 2012-10-26T16:36:31.626Z,1351269391.626 [NAL9602] No Fault, FailCount= 1 2012-10-26T16:36:35.753Z,1351269395.753 [NAL9602](INFO): Powering up NAL9602 2012-10-26T16:36:45.911Z,1351269405.911 [CommandLine](IMPORTANT): got command failComponent 2012-10-26T16:36:45.911Z,1351269405.911 [CommandLine](IMPORTANT): Failed components: 2012-10-26T16:36:45.911Z,1351269405.911 [CommandLine](IMPORTANT): No failed Components. 2012-10-26T16:36:47.049Z,1351269407.049 [NavChartDb](INFO): # of records loaded: 15000 2012-10-26T16:36:47.211Z,1351269407.211 [NAL9602](INFO): NAL9602 initialized 2012-10-26T16:36:53.823Z,1351269413.823 [CommandLine](IMPORTANT): got command ibit 2012-10-26T16:36:54.026Z,1351269414.026 [IBIT](IMPORTANT): Beginning Initiated BIT 2012-10-26T16:36:54.026Z,1351269414.026 [IBIT](IMPORTANT): Beginning control surface checks. 2012-10-26T16:36:54.028Z,1351269414.028 [CBIT](IMPORTANT): Beginning GF scan 2012-10-26T16:37:11.911Z,1351269431.911 [NavChartDb](INFO): # of records loaded: 20000 2012-10-26T16:37:22.812Z,1351269442.812 [CBIT](IMPORTANT): No ground fault detected 2012-10-26T16:37:34.099Z,1351269454.099 [NAL9602](IMPORTANT): GPS fix at: 1351269453.00 2012-10-26T16:37:34.344Z,1351269454.344 [NavChartDb](INFO): # of records loaded: 25000 2012-10-26T16:37:39.347Z,1351269459.347 [NAL9602](IMPORTANT): GPS fix at: 1351269458.00 2012-10-26T16:37:44.819Z,1351269464.819 [NAL9602](IMPORTANT): GPS fix at: 1351269464.00 2012-10-26T16:37:49.058Z,1351269469.059 [NAL9602](IMPORTANT): GPS fix at: 1351269468.00 2012-10-26T16:37:53.511Z,1351269473.511 [NAL9602](IMPORTANT): GPS fix at: 1351269472.00 2012-10-26T16:37:57.526Z,1351269477.526 [NAL9602](IMPORTANT): GPS fix at: 1351269476.00 2012-10-26T16:37:59.434Z,1351269479.434 [NavChartDb](INFO): # of records loaded: 30000 2012-10-26T16:38:02.234Z,1351269482.234 [NAL9602](IMPORTANT): GPS fix at: 1351269480.00 2012-10-26T16:38:07.031Z,1351269487.030 [NAL9602](IMPORTANT): GPS fix at: 1351269485.00 2012-10-26T16:38:10.335Z,1351269490.335 [NAL9602](IMPORTANT): GPS fix at: 1351269489.00 2012-10-26T16:38:15.322Z,1351269495.322 [NAL9602](IMPORTANT): GPS fix at: 1351269494.00 2012-10-26T16:38:20.267Z,1351269500.267 [NAL9602](IMPORTANT): GPS fix at: 1351269498.00 2012-10-26T16:38:24.214Z,1351269504.214 [NAL9602](IMPORTANT): GPS fix at: 1351269503.00 2012-10-26T16:38:27.014Z,1351269507.014 [NavChartDb](INFO): # of records loaded: 35000 2012-10-26T16:38:29.470Z,1351269509.470 [NAL9602](IMPORTANT): GPS fix at: 1351269508.00 2012-10-26T16:38:33.171Z,1351269513.171 [NAL9602](IMPORTANT): GPS fix at: 1351269512.00 2012-10-26T16:38:36.618Z,1351269516.618 [NAL9602](IMPORTANT): GPS fix at: 1351269515.00 2012-10-26T16:38:40.887Z,1351269520.887 [NAL9602](IMPORTANT): GPS fix at: 1351269519.00 2012-10-26T16:38:44.883Z,1351269524.883 [NAL9602](IMPORTANT): GPS fix at: 1351269523.00 2012-10-26T16:38:44.961Z,1351269524.961 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired. 2012-10-26T16:38:45.749Z,1351269525.749 [IBIT](IMPORTANT): batteryCapacityThreshold: 5.000000 Ah 2012-10-26T16:38:45.749Z,1351269525.749 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.500000 V 2012-10-26T16:38:45.750Z,1351269525.750 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 239.890015 Voltage: 16.359188 2012-10-26T16:38:46.057Z,1351269526.057 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2012-10-26T16:38:46.057Z,1351269526.057 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2012-10-26T16:38:46.058Z,1351269526.058 [IBIT](IMPORTANT): Pressure:16.575218 PSI 2012-10-26T16:38:46.058Z,1351269526.058 [IBIT](IMPORTANT): Humidity:23.825445 % 2012-10-26T16:38:46.529Z,1351269526.529 [IBIT](IMPORTANT): surfaceThreshold: 0.500000 m 2012-10-26T16:38:46.530Z,1351269526.530 [IBIT](IMPORTANT): buoyancyDefault: 945.000000 cc 2012-10-26T16:38:46.530Z,1351269526.530 [IBIT](IMPORTANT): stopDepth: 125.000000 m 2012-10-26T16:38:46.530Z,1351269526.530 [IBIT](IMPORTANT): abortDepth: 150.000000 m 2012-10-26T16:38:46.530Z,1351269526.530 [IBIT](IMPORTANT): IBIT FAILED 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:A](INFO): Timed out from 2012-10-26T16:36:14.9Z 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:A:A_Timeout] Running Loop=1 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:A:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A:A_Timeout 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:A:A_Timeout](INFO): Completed Startup:StartupSatComms:A:A_Timeout 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:A] Stopped 2012-10-26T16:38:47.825Z,1351269527.825 [Startup:StartupSatComms:B] Running Loop=1 2012-10-26T16:38:48.153Z,1351269528.153 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-10-26T16:38:48.511Z,1351269528.510 [NAL9602](IMPORTANT): GPS fix at: 1351269528.00 2012-10-26T16:38:48.605Z,1351269528.605 [NavChartDb](INFO): # of records loaded: 40000 2012-10-26T16:39:09.604Z,1351269549.604 [NavChartDb](INFO): # of records loaded: 45000 2012-10-26T16:39:34.743Z,1351269574.743 [NavChartDb](INFO): # of records loaded: 50000 2012-10-26T16:39:48.001Z,1351269588.001 [Startup:StartupSatComms:B](INFO): Timed out from 2012-10-26T16:38:47.8Z 2012-10-26T16:39:48.001Z,1351269588.001 [Startup:StartupSatComms:B:A_Timeout] Running Loop=1 2012-10-26T16:39:48.001Z,1351269588.001 [Startup:StartupSatComms:B:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:B:A_Timeout 2012-10-26T16:39:48.001Z,1351269588.001 [Startup:StartupSatComms:B:A_Timeout](INFO): Completed Startup:StartupSatComms:B:A_Timeout 2012-10-26T16:39:48.002Z,1351269588.001 [Startup:StartupSatComms:B] Stopped 2012-10-26T16:39:48.002Z,1351269588.002 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2012-10-26T16:39:48.002Z,1351269588.002 [Startup:StartupSatComms] Stopped 2012-10-26T16:39:48.002Z,1351269588.002 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2012-10-26T16:39:48.003Z,1351269588.003 [Startup](INFO): Completed Startup 2012-10-26T16:39:48.003Z,1351269588.003 [Startup] Stopped 2012-10-26T16:39:48.003Z,1351269588.003 [Startup](INFO): Aggregate::uninitialize Startup 2012-10-26T16:39:48.003Z,1351269588.003 [Startup:A.GoToSurface] Stopped 2012-10-26T16:39:48.003Z,1351269588.003 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T16:39:49.520Z,1351269589.520 [MissionManager](IMPORTANT): Started mission Default 2012-10-26T16:39:49.520Z,1351269589.520 [Default] Running Loop=1 2012-10-26T16:39:49.520Z,1351269589.520 [Default](INFO): Aggregate::initialize Default 2012-10-26T16:39:49.520Z,1351269589.520 [Default:D.SetSpeed] Running Loop=1 2012-10-26T16:39:49.520Z,1351269589.520 [Default:D.SetSpeed](DEBUG): Initialize. 2012-10-26T16:39:49.521Z,1351269589.521 [Default:E.GoToSurface] Running Loop=1 2012-10-26T16:39:49.521Z,1351269589.521 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium] Running Loop=1 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-10-26T16:39:49.521Z,1351269589.521 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T16:39:49.522Z,1351269589.522 [Default:E.GoToSurface] Running Loop=1 2012-10-26T16:39:49.527Z,1351269589.527 [Default:D.SetSpeed] Running Loop=1 2012-10-26T16:39:49.532Z,1351269589.532 [Default:CallIridium] Running Loop=1 2012-10-26T16:39:49.532Z,1351269589.532 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2012-10-26T16:39:49.532Z,1351269589.532 [Default:CallIridium:A] Running Loop=1 2012-10-26T16:39:49.534Z,1351269589.534 [Default:CallIridium:A] Stopped 2012-10-26T16:39:49.538Z,1351269589.538 [Default:CallIridium:B] Running Loop=1 2012-10-26T16:39:49.538Z,1351269589.538 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2012-10-26T16:39:49.544Z,1351269589.543 [Default:Iridium:B.GoToSurface] Stopped 2012-10-26T16:39:49.544Z,1351269589.544 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T16:39:49.544Z,1351269589.544 [Default:Iridium:Read_Iridium] Running Loop=1 2012-10-26T16:39:49.544Z,1351269589.544 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS] Running Loop=1 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS:A.SetSpeed] Running Loop=1 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS:B.GoToSurface] Running Loop=1 2012-10-26T16:39:49.549Z,1351269589.549 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T16:39:49.554Z,1351269589.554 [Default:GPS:B.GoToSurface] Stopped 2012-10-26T16:39:49.554Z,1351269589.554 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T16:39:49.554Z,1351269589.555 [Default:GPS:Read_GPS] Running Loop=1 2012-10-26T16:39:49.554Z,1351269589.555 [Default:GPS:A.SetSpeed] Running Loop=1 2012-10-26T16:39:50.894Z,1351269590.894 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-10-26T16:39:50.897Z,1351269590.897 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-10-26T16:39:56.806Z,1351269596.806 [NavChartDb](INFO): # of records loaded: 55000 2012-10-26T16:39:57.561Z,1351269597.561 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:39:57.561Z,1351269597.561 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:39:59.579Z,1351269599.579 [NAL9602](IMPORTANT): GPS fix at: 1351269598.00 2012-10-26T16:39:59.922Z,1351269599.921 [Default:GPS:Read_GPS] Stopped 2012-10-26T16:39:59.922Z,1351269599.922 [Default:GPS:D] Running Loop=1 2012-10-26T16:40:01.208Z,1351269601.208 [Default:GPS:D] Stopped 2012-10-26T16:40:01.208Z,1351269601.208 [Default:GPS](INFO): Completed Default:GPS 2012-10-26T16:40:01.209Z,1351269601.209 [Default:GPS] Stopped 2012-10-26T16:40:01.209Z,1351269601.209 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2012-10-26T16:40:01.209Z,1351269601.209 [Default:GPS:A.SetSpeed] Stopped 2012-10-26T16:40:01.209Z,1351269601.209 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2012-10-26T16:40:01.452Z,1351269601.452 [NavChartDb](INFO): Calculating coverage of Resources/US5CA50M.000 2012-10-26T16:40:09.962Z,1351269609.962 [NavChartDb](INFO): Done scanning edges of Resources/US5CA50M.000 2012-10-26T16:40:26.549Z,1351269626.549 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:40:26.549Z,1351269626.549 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:40:27.848Z,1351269627.848 [NavChartDb](INFO): # of records loaded: 60000 2012-10-26T16:40:48.049Z,1351269648.049 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:40:48.050Z,1351269648.050 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:40:54.341Z,1351269654.341 [NavChartDb](INFO): Done scanning nodes of Resources/US5CA50M.000 2012-10-26T16:40:54.379Z,1351269654.379 [NavChartDb](INFO): # of records loaded: 62026 2012-10-26T16:40:54.389Z,1351269654.389 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US5CA50M.000 2012-10-26T16:40:54.391Z,1351269654.391 [NavChartDb](INFO): Setup scan of Resources/US3CA52M.000 2012-10-26T16:41:06.228Z,1351269666.228 [NavChartDb](INFO): Done scanning features of Resources/US3CA52M.000 2012-10-26T16:41:13.597Z,1351269673.597 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:41:13.597Z,1351269673.597 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:41:29.897Z,1351269689.897 [NavChartDb](INFO): # of records loaded: 5000 2012-10-26T16:41:38.915Z,1351269698.915 [CommandLine](IMPORTANT): got command show variable threshold 2012-10-26T16:41:38.933Z,1351269698.933 [CommandLine](INFO): CBIT.humidityThreshold (percent) 2012-10-26T16:41:38.933Z,1351269698.933 [CommandLine](INFO): CBIT.pressureThreshold (pound_per_square_inch) 2012-10-26T16:41:38.934Z,1351269698.934 [CommandLine](INFO): CBIT.tempThreshold (fahrenheit) 2012-10-26T16:41:38.939Z,1351269698.939 [CommandLine](INFO): CBIT.battTempThreshold (celsius) 2012-10-26T16:41:38.939Z,1351269698.939 [CommandLine](INFO): CBIT.gfChan0_Threshold (milliampere) 2012-10-26T16:41:38.940Z,1351269698.940 [CommandLine](INFO): CBIT.gfChan1_Threshold (milliampere) 2012-10-26T16:41:38.940Z,1351269698.940 [CommandLine](INFO): CBIT.gfChan2_Threshold (milliampere) 2012-10-26T16:41:38.941Z,1351269698.941 [CommandLine](INFO): CBIT.gfChan4_Threshold (milliampere) 2012-10-26T16:41:38.941Z,1351269698.941 [CommandLine](INFO): CBIT.gfChan5_Threshold (milliampere) 2012-10-26T16:41:38.942Z,1351269698.941 [CommandLine](INFO): IBIT.batteryCapacityThreshold (ampere_hour) 2012-10-26T16:41:38.942Z,1351269698.942 [CommandLine](INFO): IBIT.batteryVoltageThreshold (volt) 2012-10-26T16:41:38.975Z,1351269698.975 [CommandLine](INFO): VerticalControl.surfaceThreshold (meter) 2012-10-26T16:41:39.333Z,1351269699.333 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:41:39.333Z,1351269699.333 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:41:50.771Z,1351269710.771 [NavChartDb](INFO): # of records loaded: 10000 2012-10-26T16:41:58.396Z,1351269718.396 [NavChartDb](INFO): # of records loaded: 15000 2012-10-26T16:42:08.561Z,1351269728.561 [NavChartDb](INFO): # of records loaded: 20000 2012-10-26T16:42:10.653Z,1351269730.653 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:42:10.653Z,1351269730.653 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:42:18.929Z,1351269738.929 [NavChartDb](INFO): # of records loaded: 25000 2012-10-26T16:42:20.986Z,1351269740.986 [CommandLine](IMPORTANT): got command get IBIT.batteryCapacityThreshold 2012-10-26T16:42:20.987Z,1351269740.987 [CommandLine](IMPORTANT): IBIT.batteryCapacityThreshold 5.000000 ampere_hour 2012-10-26T16:42:27.228Z,1351269747.228 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:42:27.228Z,1351269747.228 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:42:32.588Z,1351269752.588 [NavChartDb](INFO): # of records loaded: 30000 2012-10-26T16:42:35.492Z,1351269755.492 [NavChartDb](INFO): # of records loaded: 35000 2012-10-26T16:42:51.497Z,1351269771.497 [NavChartDb](INFO): # of records loaded: 40000 2012-10-26T16:42:54.089Z,1351269774.089 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:42:54.089Z,1351269774.089 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:43:05.746Z,1351269785.746 [NavChartDb](INFO): # of records loaded: 45000 2012-10-26T16:43:14.825Z,1351269794.825 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:43:14.825Z,1351269794.825 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:43:29.140Z,1351269809.140 [NavChartDb](INFO): # of records loaded: 50000 2012-10-26T16:43:38.463Z,1351269818.463 [CommandLine](IMPORTANT): got command get IBIT.batteryVoltageThreshold 2012-10-26T16:43:38.463Z,1351269818.463 [CommandLine](IMPORTANT): IBIT.batteryVoltageThreshold 13.500000 volt 2012-10-26T16:43:38.822Z,1351269818.822 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:43:38.822Z,1351269818.822 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:43:44.560Z,1351269824.560 [NavChartDb](INFO): # of records loaded: 55000 2012-10-26T16:43:57.759Z,1351269837.759 [NavChartDb](INFO): # of records loaded: 60000 2012-10-26T16:44:05.533Z,1351269845.533 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:44:05.533Z,1351269845.533 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:44:06.292Z,1351269846.292 [NavChartDb](INFO): # of records loaded: 65000 2012-10-26T16:44:12.727Z,1351269852.727 [NavChartDb](INFO): # of records loaded: 70000 2012-10-26T16:44:21.829Z,1351269861.829 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:44:21.829Z,1351269861.829 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:44:28.928Z,1351269868.928 [NavChartDb](INFO): # of records loaded: 75000 2012-10-26T16:44:47.800Z,1351269887.800 [NavChartDb](INFO): # of records loaded: 80000 2012-10-26T16:44:49.429Z,1351269889.429 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:44:49.429Z,1351269889.429 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:45:03.239Z,1351269903.239 [NavChartDb](INFO): # of records loaded: 85000 2012-10-26T16:45:18.366Z,1351269918.366 [NavChartDb](INFO): # of records loaded: 90000 2012-10-26T16:45:36.169Z,1351269936.169 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:45:36.169Z,1351269936.169 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:45:39.624Z,1351269939.624 [NavChartDb](INFO): # of records loaded: 95000 2012-10-26T16:45:58.390Z,1351269958.390 [NavChartDb](INFO): # of records loaded: 100000 2012-10-26T16:46:01.469Z,1351269961.469 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:46:01.469Z,1351269961.469 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:46:16.068Z,1351269976.068 [NavChartDb](INFO): # of records loaded: 105000 2012-10-26T16:46:22.889Z,1351269982.889 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:46:22.889Z,1351269982.889 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:46:38.751Z,1351269998.751 [NavChartDb](INFO): # of records loaded: 110000 2012-10-26T16:46:58.266Z,1351270018.266 [NavChartDb](INFO): Calculating coverage of Resources/US3CA52M.000 2012-10-26T16:47:02.840Z,1351270022.839 [NavChartDb](INFO): Done scanning edges of Resources/US3CA52M.000 2012-10-26T16:47:11.314Z,1351270031.314 [NavChartDb](INFO): # of records loaded: 115000 2012-10-26T16:47:30.220Z,1351270050.220 [NavChartDb](INFO): Done scanning nodes of Resources/US3CA52M.000 2012-10-26T16:47:30.287Z,1351270050.287 [NavChartDb](INFO): # of records loaded: 117290 2012-10-26T16:47:30.292Z,1351270050.292 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US3CA52M.000 2012-10-26T16:47:30.293Z,1351270050.293 [NavChartDb](INFO): Setup scan of Resources/US2WC11M.000 2012-10-26T16:47:39.766Z,1351270059.766 [NavChartDb](INFO): Done scanning features of Resources/US2WC11M.000 2012-10-26T16:47:56.579Z,1351270076.579 [NavChartDb](INFO): # of records loaded: 5000 2012-10-26T16:48:04.133Z,1351270084.133 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:48:04.133Z,1351270084.133 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:48:19.853Z,1351270099.853 [NavChartDb](INFO): # of records loaded: 10000 2012-10-26T16:48:41.308Z,1351270121.308 [NavChartDb](INFO): # of records loaded: 15000 2012-10-26T16:48:46.897Z,1351270126.897 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:48:46.897Z,1351270126.897 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:48:54.473Z,1351270134.473 [NavChartDb](INFO): # of records loaded: 20000 2012-10-26T16:49:03.797Z,1351270143.797 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:49:03.797Z,1351270143.797 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:49:12.763Z,1351270152.763 [NavChartDb](INFO): # of records loaded: 25000 2012-10-26T16:49:21.162Z,1351270161.161 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:49:21.162Z,1351270161.162 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:49:30.729Z,1351270170.729 [NavChartDb](INFO): # of records loaded: 30000 2012-10-26T16:49:48.913Z,1351270188.913 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:49:48.913Z,1351270188.913 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:49:53.088Z,1351270193.088 [NavChartDb](INFO): # of records loaded: 35000 2012-10-26T16:50:04.961Z,1351270204.961 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:50:04.961Z,1351270204.961 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:50:11.478Z,1351270211.478 [NavChartDb](INFO): # of records loaded: 40000 2012-10-26T16:50:12.843Z,1351270212.843 [NavChartDb](INFO): Calculating coverage of Resources/US2WC11M.000 2012-10-26T16:50:15.007Z,1351270215.007 [NavChartDb](INFO): Done scanning edges of Resources/US2WC11M.000 2012-10-26T16:50:21.741Z,1351270221.741 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:50:21.741Z,1351270221.741 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:50:33.820Z,1351270233.820 [NavChartDb](INFO): Done scanning nodes of Resources/US2WC11M.000 2012-10-26T16:50:34.603Z,1351270234.603 [NavChartDb](INFO): # of records loaded: 44880 2012-10-26T16:50:34.608Z,1351270234.608 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US2WC11M.000 2012-10-26T16:50:34.610Z,1351270234.610 [NavChartDb](INFO): Setup scan of Resources/US1WC07M.000 2012-10-26T16:50:47.509Z,1351270247.509 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:50:47.509Z,1351270247.509 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:50:53.784Z,1351270253.784 [NavChartDb](INFO): Done scanning features of Resources/US1WC07M.000 2012-10-26T16:51:05.473Z,1351270265.473 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:51:05.473Z,1351270265.473 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:51:18.316Z,1351270278.316 [NavChartDb](INFO): # of records loaded: 5000 2012-10-26T16:51:22.394Z,1351270282.394 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:51:22.394Z,1351270282.394 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:51:43.095Z,1351270303.095 [NavChartDb](INFO): # of records loaded: 10000 2012-10-26T16:51:53.169Z,1351270313.169 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:51:53.169Z,1351270313.169 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:52:00.068Z,1351270320.068 [NavChartDb](INFO): # of records loaded: 15000 2012-10-26T16:52:08.781Z,1351270328.781 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:52:08.781Z,1351270328.781 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:52:16.705Z,1351270336.705 [NavChartDb](INFO): # of records loaded: 20000 2012-10-26T16:52:20.843Z,1351270340.843 [NavChartDb](INFO): Calculating coverage of Resources/US1WC07M.000 2012-10-26T16:52:22.452Z,1351270342.452 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:52:22.452Z,1351270342.452 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:52:27.828Z,1351270347.828 [NavChartDb](INFO): Done scanning edges of Resources/US1WC07M.000 2012-10-26T16:52:40.325Z,1351270360.325 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:52:40.325Z,1351270360.325 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:52:57.633Z,1351270377.633 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:52:57.633Z,1351270377.633 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:52:59.957Z,1351270379.957 [NavChartDb](INFO): Done scanning nodes of Resources/US1WC07M.000 2012-10-26T16:53:00.304Z,1351270380.304 [NavChartDb](INFO): # of records loaded: 24424 2012-10-26T16:53:00.315Z,1351270380.315 [NavChartDb](IMPORTANT): Loaded Electronic Nav Chart data from US1WC07M.000 2012-10-26T16:53:03.734Z,1351270383.734 [NavChartDb](INFO): Creating index for soundings 2012-10-26T16:53:09.182Z,1351270389.182 [NavChartDb](INFO): Creating index for 0p0 2012-10-26T16:53:13.162Z,1351270393.162 [NavChartDb](INFO): Creating index for 1p8 2012-10-26T16:53:13.316Z,1351270393.316 [NavChartDb](INFO): Creating index for 3p6 2012-10-26T16:53:15.590Z,1351270395.591 [NavChartDb](INFO): Creating index for 5p4 2012-10-26T16:53:15.777Z,1351270395.777 [NAL9602](INFO): SBD MO Status=2, MOMSN=3434, MT Status=2, MTMSN=0 2012-10-26T16:53:15.777Z,1351270395.777 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:53:16.359Z,1351270396.359 [NavChartDb](INFO): Creating index for 9p1 2012-10-26T16:53:16.384Z,1351270396.384 [NavChartDb](INFO): Creating index for 10p9 2012-10-26T16:53:19.193Z,1351270399.193 [NavChartDb](INFO): Creating index for 18p2 2012-10-26T16:53:20.441Z,1351270400.441 [NavChartDb](INFO): Creating index for 36p5 2012-10-26T16:53:22.371Z,1351270402.371 [NavChartDb](INFO): Creating index for 54p8 2012-10-26T16:53:23.157Z,1351270403.157 [NavChartDb](INFO): Creating index for 73p1 2012-10-26T16:53:26.348Z,1351270406.348 [NavChartDb](INFO): Creating index for 91p4 2012-10-26T16:53:31.893Z,1351270411.893 [NavChartDb](INFO): Creating index for 182p8 2012-10-26T16:53:37.181Z,1351270417.181 [NavChartDb](INFO): Creating index for 365p7 2012-10-26T16:53:41.524Z,1351270421.524 [NavChartDb](INFO): Creating index for 548p6 2012-10-26T16:53:44.700Z,1351270424.700 [NavChartDb](INFO): Creating index for 731p5 2012-10-26T16:53:53.745Z,1351270433.745 [NavChartDb](INFO): Creating index for 914p4 2012-10-26T16:53:55.577Z,1351270435.577 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=3434, MT Status=1, MTMSN=287 2012-10-26T16:53:55.615Z,1351270435.615 [NAL9602](INFO): Sent 332 bytes from file Logs/20121026T163451/shore0000.lzma 2012-10-26T16:53:55.615Z,1351270435.615 [NAL9602](INFO): Packets left to send: 4 2012-10-26T16:53:55.617Z,1351270435.617 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0000.lzma.parts/0004.sbd 2012-10-26T16:53:56.067Z,1351270436.067 [NAL9602](INFO): Received command:stop 2012-10-26T16:53:56.129Z,1351270436.129 [CommandLine](IMPORTANT): got command stop 2012-10-26T16:53:56.775Z,1351270436.775 [NavChartDb](INFO): Creating index for 1097p2 2012-10-26T16:53:59.946Z,1351270439.946 [NavChartDb](INFO): Creating index for 1280p1 2012-10-26T16:54:00.532Z,1351270440.532 [NavChartDb](INFO): Creating index for 1463p0 2012-10-26T16:54:02.313Z,1351270442.313 [NavChartDb](INFO): Creating index for 1645p9 2012-10-26T16:54:03.759Z,1351270443.759 [NavChartDb](INFO): Creating index for 1828p8 2012-10-26T16:54:05.688Z,1351270445.688 [NavChartDb](INFO): Creating index for 2011p6 2012-10-26T16:54:07.646Z,1351270447.646 [NavChartDb](INFO): Creating index for 2194p5 2012-10-26T16:54:07.705Z,1351270447.705 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:54:07.705Z,1351270447.705 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:54:09.192Z,1351270449.192 [NavChartDb](INFO): Creating index for 2377p4 2012-10-26T16:54:11.028Z,1351270451.028 [NavChartDb](INFO): Creating index for 2560p3 2012-10-26T16:54:11.616Z,1351270451.616 [NavChartDb](INFO): Creating index for 2743p2 2012-10-26T16:54:13.700Z,1351270453.700 [NavChartDb](INFO): Creating index for 2926p0 2012-10-26T16:54:14.010Z,1351270454.010 [NavChartDb](INFO): Creating index for 3108p9 2012-10-26T16:54:14.326Z,1351270454.326 [NavChartDb](INFO): Creating index for 3291p8 2012-10-26T16:54:14.520Z,1351270454.520 [NavChartDb](INFO): Creating index for 3474p7 2012-10-26T16:54:16.663Z,1351270456.663 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:54:16.664Z,1351270456.664 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:54:21.403Z,1351270461.403 [NavChartDb](INFO): Creating index for 3657p6 2012-10-26T16:54:34.204Z,1351270474.204 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:54:34.204Z,1351270474.204 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:54:42.783Z,1351270482.783 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:54:42.784Z,1351270482.784 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:54:51.030Z,1351270491.030 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:54:51.030Z,1351270491.030 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:55:07.226Z,1351270507.226 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:55:07.226Z,1351270507.226 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:55:15.724Z,1351270515.724 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:55:15.724Z,1351270515.724 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:55:24.672Z,1351270524.672 [NAL9602](INFO): SBD MO Status=2, MOMSN=3435, MT Status=2, MTMSN=0 2012-10-26T16:55:24.672Z,1351270524.672 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:55:37.650Z,1351270537.650 [NAL9602](INFO): SBD MO Status=1, MOMSN=3435, MT Status=0, MTMSN=0 2012-10-26T16:55:37.691Z,1351270537.691 [NAL9602](INFO): Sent 332 bytes from file Logs/20121026T163451/shore0000.lzma 2012-10-26T16:55:37.691Z,1351270537.691 [NAL9602](INFO): Packets left to send: 3 2012-10-26T16:55:37.695Z,1351270537.695 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0000.lzma.parts/0003.sbd 2012-10-26T16:55:49.836Z,1351270549.836 [NAL9602](INFO): SBD MO Status=1, MOMSN=3436, MT Status=0, MTMSN=0 2012-10-26T16:55:49.871Z,1351270549.871 [NAL9602](INFO): Sent 332 bytes from file Logs/20121026T163451/shore0000.lzma 2012-10-26T16:55:49.871Z,1351270549.871 [NAL9602](INFO): Packets left to send: 2 2012-10-26T16:55:49.872Z,1351270549.872 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0000.lzma.parts/0002.sbd 2012-10-26T16:55:58.389Z,1351270558.389 [NAL9602](INFO): SBD MO Status=2, MOMSN=3437, MT Status=2, MTMSN=0 2012-10-26T16:55:58.389Z,1351270558.389 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2012-10-26T16:56:10.937Z,1351270570.937 [NAL9602](INFO): SBD MO Status=1, MOMSN=3437, MT Status=0, MTMSN=0 2012-10-26T16:56:10.975Z,1351270570.975 [NAL9602](INFO): Sent 332 bytes from file Logs/20121026T163451/shore0000.lzma 2012-10-26T16:56:10.975Z,1351270570.975 [NAL9602](INFO): Packets left to send: 1 2012-10-26T16:56:10.976Z,1351270570.976 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0000.lzma.parts/0001.sbd 2012-10-26T16:56:17.564Z,1351270577.564 [NAL9602](INFO): SBD MO Status=1, MOMSN=3438, MT Status=0, MTMSN=0 2012-10-26T16:56:17.599Z,1351270577.599 [NAL9602](INFO): Sent 138 bytes from file Logs/20121026T163451/shore0000.lzma 2012-10-26T16:56:17.599Z,1351270577.599 [NAL9602](INFO): Packets left to send: 0 2012-10-26T16:56:17.600Z,1351270577.600 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0000.lzma.parts/0000.sbd 2012-10-26T16:56:24.365Z,1351270584.365 [NAL9602](INFO): SBD MO Status=0, MOMSN=3439, MT Status=0, MTMSN=0 2012-10-26T16:56:43.754Z,1351270603.754 [NAL9602](INFO): SBD MO Status=1, MOMSN=3440, MT Status=0, MTMSN=0 2012-10-26T16:56:43.791Z,1351270603.791 [NAL9602](INFO): Sent 332 bytes from file Logs/20121026T163451/shore0001.lzma 2012-10-26T16:56:43.791Z,1351270603.791 [NAL9602](INFO): Packets left to send: 1 2012-10-26T16:56:43.793Z,1351270603.793 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0001.lzma.parts/0001.sbd 2012-10-26T16:56:56.744Z,1351270616.744 [NAL9602](INFO): SBD MO Status=1, MOMSN=3441, MT Status=0, MTMSN=0 2012-10-26T16:56:56.779Z,1351270616.779 [NAL9602](INFO): Sent 201 bytes from file Logs/20121026T163451/shore0001.lzma 2012-10-26T16:56:56.779Z,1351270616.779 [NAL9602](INFO): Packets left to send: 0 2012-10-26T16:56:56.780Z,1351270616.780 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0001.lzma.parts/0000.sbd 2012-10-26T16:57:09.214Z,1351270629.214 [NAL9602](INFO): SBD MO Status=0, MOMSN=3442, MT Status=0, MTMSN=0 2012-10-26T16:57:09.271Z,1351270629.271 [Default:Iridium:Read_Iridium] Stopped 2012-10-26T16:57:09.271Z,1351270629.272 [Default:Iridium](INFO): Completed Default:Iridium 2012-10-26T16:57:09.272Z,1351270629.272 [Default:Iridium] Stopped 2012-10-26T16:57:09.272Z,1351270629.272 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2012-10-26T16:57:09.272Z,1351270629.272 [Default:Iridium:A.SetSpeed] Stopped 2012-10-26T16:57:09.272Z,1351270629.272 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2012-10-26T16:57:09.272Z,1351270629.272 [Default:F.Wait] Running Loop=1 2012-10-26T16:57:09.272Z,1351270629.272 [Default:F.Wait](DEBUG): Initialize Wait Component. 2012-10-26T16:57:09.563Z,1351270629.563 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B 2012-10-26T16:57:09.563Z,1351270629.563 [Default:CallIridium:B] Stopped 2012-10-26T16:57:09.563Z,1351270629.563 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2012-10-26T16:57:09.563Z,1351270629.563 [Default:CallIridium](INFO): Completed Default:CallIridium 2012-10-26T16:57:09.564Z,1351270629.564 [Default:CallIridium] Stopped 2012-10-26T16:57:09.564Z,1351270629.564 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2012-10-26T16:57:19.704Z,1351270639.704 [NAL9602](INFO): Powering down 2012-10-26T17:02:09.712Z,1351270929.712 [Default:CallIridium] Running Loop=1 2012-10-26T17:02:09.712Z,1351270929.712 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium 2012-10-26T17:02:09.712Z,1351270929.712 [Default:CallIridium:A] Running Loop=1 2012-10-26T17:02:09.712Z,1351270929.713 [Default:CallIridium:A] Stopped 2012-10-26T17:02:09.713Z,1351270929.713 [Default:CallIridium:B] Running Loop=1 2012-10-26T17:02:09.713Z,1351270929.713 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium] Running Loop=1 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-10-26T17:02:14.707Z,1351270934.707 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T17:02:14.708Z,1351270934.708 [Default:Iridium:B.GoToSurface] Stopped 2012-10-26T17:02:14.708Z,1351270934.708 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T17:02:14.708Z,1351270934.708 [Default:Iridium:Read_Iridium] Running Loop=1 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS] Running Loop=1 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS:A.SetSpeed] Running Loop=1 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS:B.GoToSurface] Running Loop=1 2012-10-26T17:02:14.709Z,1351270934.709 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-10-26T17:02:14.710Z,1351270934.710 [Default:GPS:B.GoToSurface] Stopped 2012-10-26T17:02:14.710Z,1351270934.710 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T17:02:14.710Z,1351270934.710 [Default:GPS:Read_GPS] Running Loop=1 2012-10-26T17:02:15.372Z,1351270935.372 [NAL9602](INFO): Powering up 2012-10-26T17:02:26.183Z,1351270946.183 [NAL9602](INFO): NAL9602 initialized 2012-10-26T17:02:44.296Z,1351270964.296 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=3443, MT Status=1, MTMSN=288 2012-10-26T17:02:44.331Z,1351270964.331 [NAL9602](INFO): Sent 104 bytes from file Logs/20121026T163451/shore0002.lzma 2012-10-26T17:02:44.331Z,1351270964.331 [NAL9602](INFO): Packets left to send: 0 2012-10-26T17:02:44.332Z,1351270964.332 [NAL9602](INFO): Stored copy of sent data in Logs/20121026T163451/shore0002.lzma.parts/0000.sbd 2012-10-26T17:02:44.807Z,1351270964.807 [NAL9602](INFO): Received command:restart app 2012-10-26T17:02:44.908Z,1351270964.908 [CommandLine](IMPORTANT): got command restart application 2012-10-26T17:02:46.042Z,1351270966.042 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2012-10-26T17:02:46.042Z,1351270966.042 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2012-10-26T17:02:46.062Z,1351270966.062 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2012-10-26T17:02:46.119Z,1351270966.119 [WetLabsBB2FL](INFO): Powering down 2012-10-26T17:02:46.122Z,1351270966.122 [ComponentRegistry](INFO): Shutting down Turbulence_NPS ThreadHandler 2012-10-26T17:02:46.523Z,1351270966.523 [Turbulence_NPS](INFO): Uninitialize Powering down 2012-10-26T17:02:46.526Z,1351270966.526 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2012-10-26T17:02:46.927Z,1351270966.927 [CTD_NeilBrown](INFO): Powering down 2012-10-26T17:02:46.946Z,1351270966.946 [ComponentRegistry](INFO): Shutting down DVL_micro ThreadHandler 2012-10-26T17:02:46.955Z,1351270966.955 [DVL_micro](INFO): uninitialize:Powering down 2012-10-26T17:02:46.967Z,1351270966.967 [ComponentRegistry](INFO): Shutting down AsyncPiEstimator ThreadHandler 2012-10-26T17:02:46.995Z,1351270966.995 [AsyncPiEstimator](DEBUG): Uninitialize AsyncPiEstimator. 2012-10-26T17:02:47.008Z,1351270967.008 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2012-10-26T17:02:47.010Z,1351270967.010 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2012-10-26T17:02:47.144Z,1351270967.144 [controlThread](DEBUG): Uninitializing ControlThread 2012-10-26T17:02:47.145Z,1351270967.145 [AHRS_sp3003D](INFO): Powering down 2012-10-26T17:02:47.231Z,1351270967.231 [NAL9602](INFO): Powering down 2012-10-26T17:02:47.233Z,1351270967.233 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2012-10-26T17:02:47.234Z,1351270967.234 [NavChart](DEBUG): Uninitialize NavChart Derivation. 2012-10-26T17:02:47.235Z,1351270967.235 [Default] Stopped 2012-10-26T17:02:47.235Z,1351270967.235 [Default](INFO): Aggregate::uninitialize Default 2012-10-26T17:02:47.235Z,1351270967.235 [Default:GPS] Stopped 2012-10-26T17:02:47.235Z,1351270967.235 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2012-10-26T17:02:47.235Z,1351270967.235 [Default:GPS:A.SetSpeed] Stopped 2012-10-26T17:02:47.235Z,1351270967.235 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2012-10-26T17:02:47.235Z,1351270967.236 [Default:GPS:Read_GPS] Stopped 2012-10-26T17:02:47.235Z,1351270967.236 [Default:Iridium] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2012-10-26T17:02:47.236Z,1351270967.236 [Default:Iridium:A.SetSpeed] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2012-10-26T17:02:47.236Z,1351270967.236 [Default:Iridium:Read_Iridium] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:CallIridium] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium 2012-10-26T17:02:47.236Z,1351270967.236 [Default:CallIridium:B] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B 2012-10-26T17:02:47.236Z,1351270967.236 [Default:D.SetSpeed] Stopped 2012-10-26T17:02:47.236Z,1351270967.236 [Default:D.SetSpeed](DEBUG): Uninitialize. 2012-10-26T17:02:47.236Z,1351270967.236 [Default:E.GoToSurface] Stopped 2012-10-26T17:02:47.236Z,1351270967.237 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-10-26T17:02:47.237Z,1351270967.237 [Default:F.Wait] Stopped 2012-10-26T17:02:47.237Z,1351270967.237 [Default:F.Wait](DEBUG): Uninitialize Wait Component. 2012-10-26T17:02:47.241Z,1351270967.241 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2012-10-26T17:02:47.241Z,1351270967.241 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2012-10-26T17:02:47.242Z,1351270967.242 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2012-10-26T17:02:47.242Z,1351270967.242 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2012-10-26T17:02:47.242Z,1351270967.242 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2012-10-26T17:02:47.243Z,1351270967.243 [BuoyancyServo](INFO): Powering down 2012-10-26T17:02:47.247Z,1351270967.247 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2012-10-26T17:02:47.247Z,1351270967.247 [ElevatorServo](INFO): Powering down 2012-10-26T17:02:47.248Z,1351270967.247 [MassServo](DEBUG): Uninitialize Mass Servo. 2012-10-26T17:02:47.248Z,1351270967.248 [MassServo](INFO): Powering down 2012-10-26T17:02:47.248Z,1351270967.248 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2012-10-26T17:02:47.248Z,1351270967.248 [RudderServo](INFO): Powering down 2012-10-26T17:02:47.249Z,1351270967.249 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2012-10-26T17:02:47.249Z,1351270967.249 [ThrusterServo](INFO): Powering down 2012-10-26T17:02:47.250Z,1351270967.250 [SBIT](DEBUG): Uninitialize SBIT Component. 2012-10-26T17:02:47.251Z,1351270967.251 [IBIT](DEBUG): Uninitialize IBIT Component. 2012-10-26T17:02:47.251Z,1351270967.251 [CBIT](DEBUG): Uninitialize CBIT Component.