2012-11-12T15:41:21.707Z,1352734881.707 [Supervisor](DEBUG): Initializing supervisor. 2012-11-12T15:41:21.710Z,1352734881.710 [SyncHandler](DEBUG): Created PCaller Thread at 4033B4E0 2012-11-12T15:41:21.710Z,1352734881.710 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2012-11-12T15:41:21.711Z,1352734881.711 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4036B4E0 2012-11-12T15:41:21.729Z,1352734881.729 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2012-11-12T15:41:21.740Z,1352734881.740 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2012-11-12T15:41:21.741Z,1352734881.741 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4039B4E0 2012-11-12T15:41:21.742Z,1352734881.742 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2012-11-12T15:41:21.743Z,1352734881.743 [logger ThreadHandler](DEBUG): Created PCaller Thread at 403CB4E0 2012-11-12T15:41:21.744Z,1352734881.744 [Supervisor](INFO): Looking for Config files in directory: Config/ 2012-11-12T15:41:21.747Z,1352734881.747 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2012-11-12T15:41:22.113Z,1352734882.113 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2012-11-12T15:41:22.115Z,1352734882.115 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2012-11-12T15:41:22.312Z,1352734882.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2012-11-12T15:41:22.313Z,1352734882.313 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2012-11-12T15:41:22.399Z,1352734882.399 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2012-11-12T15:41:22.401Z,1352734882.401 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2012-11-12T15:41:22.600Z,1352734882.600 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2012-11-12T15:41:22.601Z,1352734882.601 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2012-11-12T15:41:22.736Z,1352734882.736 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2012-11-12T15:41:22.738Z,1352734882.738 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2012-11-12T15:41:22.975Z,1352734882.975 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2012-11-12T15:41:22.975Z,1352734882.975 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2012-11-12T15:41:23.150Z,1352734883.150 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2012-11-12T15:41:23.152Z,1352734883.152 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2012-11-12T15:41:23.411Z,1352734883.411 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2012-11-12T15:41:23.414Z,1352734883.414 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2012-11-12T15:41:23.513Z,1352734883.513 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2012-11-12T15:41:23.514Z,1352734883.514 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2012-11-12T15:41:23.925Z,1352734883.925 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2012-11-12T15:41:23.925Z,1352734883.925 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2012-11-12T15:41:24.041Z,1352734884.041 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2012-11-12T15:41:24.042Z,1352734884.042 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2012-11-12T15:41:24.128Z,1352734884.128 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2012-11-12T15:41:24.132Z,1352734884.132 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2012-11-12T15:41:24.234Z,1352734884.234 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2012-11-12T15:41:24.365Z,1352734884.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2012-11-12T15:41:24.463Z,1352734884.463 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2012-11-12T15:41:25.099Z,1352734885.099 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2012-11-12T15:41:25.201Z,1352734885.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2012-11-12T15:41:25.321Z,1352734885.321 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2012-11-12T15:41:25.415Z,1352734885.415 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2012-11-12T15:41:25.503Z,1352734885.503 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2012-11-12T15:41:25.537Z,1352734885.537 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2012-11-12T15:41:25.826Z,1352734885.826 [ExternalSim] Loaded 2012-11-12T15:41:25.826Z,1352734885.826 [ComponentRegistry](DEBUG): SyncComponent "ExternalSim" handled in the control thread. 2012-11-12T15:41:25.880Z,1352734885.880 [InternalSim] Loaded 2012-11-12T15:41:25.881Z,1352734885.881 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2012-11-12T15:41:25.882Z,1352734885.882 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2012-11-12T15:41:25.882Z,1352734885.882 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2012-11-12T15:41:25.962Z,1352734885.962 [SBIT](DEBUG): Construct Startup Built In Test. 2012-11-12T15:41:25.990Z,1352734885.990 [SBIT] Loaded 2012-11-12T15:41:25.991Z,1352734885.991 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2012-11-12T15:41:25.992Z,1352734885.991 [IBIT](DEBUG): Construct Initiated Built In Test. 2012-11-12T15:41:26.027Z,1352734886.027 [IBIT] Loaded 2012-11-12T15:41:26.027Z,1352734886.027 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2012-11-12T15:41:26.031Z,1352734886.030 [CBIT](DEBUG): Construct CBIT Built In Test. 2012-11-12T15:41:26.149Z,1352734886.149 [CBIT] Loaded 2012-11-12T15:41:26.150Z,1352734886.150 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2012-11-12T15:41:26.150Z,1352734886.150 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2012-11-12T15:41:26.151Z,1352734886.151 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2012-11-12T15:41:26.315Z,1352734886.315 [BuoyancyServo] Loaded 2012-11-12T15:41:26.316Z,1352734886.316 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2012-11-12T15:41:26.324Z,1352734886.324 [ElevatorServo] Loaded 2012-11-12T15:41:26.324Z,1352734886.324 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2012-11-12T15:41:26.333Z,1352734886.333 [MassServo] Loaded 2012-11-12T15:41:26.333Z,1352734886.333 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2012-11-12T15:41:26.342Z,1352734886.342 [RudderServo] Loaded 2012-11-12T15:41:26.342Z,1352734886.342 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2012-11-12T15:41:26.350Z,1352734886.351 [ThrusterServo] Loaded 2012-11-12T15:41:26.351Z,1352734886.351 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2012-11-12T15:41:26.351Z,1352734886.351 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2012-11-12T15:41:26.352Z,1352734886.352 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2012-11-12T15:41:26.387Z,1352734886.386 [DepthRateCalculator] Loaded 2012-11-12T15:41:26.387Z,1352734886.387 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2012-11-12T15:41:31.421Z,1352734891.421 [HFRadarModelCalc] Loaded 2012-11-12T15:41:31.421Z,1352734891.421 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread. 2012-11-12T15:41:31.438Z,1352734891.438 [NavChart] Loaded 2012-11-12T15:41:31.438Z,1352734891.438 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2012-11-12T15:41:31.444Z,1352734891.444 [PitchRateCalculator] Loaded 2012-11-12T15:41:31.444Z,1352734891.444 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2012-11-12T15:41:31.451Z,1352734891.451 [SpeedCalculator] Loaded 2012-11-12T15:41:31.451Z,1352734891.451 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2012-11-12T15:41:31.466Z,1352734891.466 [TempGradientCalculator] Loaded 2012-11-12T15:41:31.466Z,1352734891.466 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2012-11-12T15:41:31.472Z,1352734891.472 [YawRateCalculator] Loaded 2012-11-12T15:41:31.472Z,1352734891.472 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2012-11-12T15:41:31.513Z,1352734891.513 [Navigation] Loaded 2012-11-12T15:41:31.513Z,1352734891.513 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread. 2012-11-12T15:41:31.514Z,1352734891.514 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2012-11-12T15:41:31.515Z,1352734891.514 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2012-11-12T15:41:31.783Z,1352734891.783 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2012-11-12T15:41:31.783Z,1352734891.783 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2012-11-12T15:41:31.821Z,1352734891.821 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2012-11-12T15:41:31.822Z,1352734891.822 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2012-11-12T15:41:31.881Z,1352734891.881 [VerticalControl](DEBUG): Construct VerticalControl. 2012-11-12T15:41:31.977Z,1352734891.977 [VerticalControl] Loaded 2012-11-12T15:41:31.977Z,1352734891.977 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2012-11-12T15:41:31.978Z,1352734891.978 [HorizontalControl](DEBUG): Construct HorizontalControl. 2012-11-12T15:41:32.035Z,1352734892.035 [HorizontalControl] Loaded 2012-11-12T15:41:32.036Z,1352734892.036 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2012-11-12T15:41:32.037Z,1352734892.037 [SpeedControl](DEBUG): Construct SpeedControl. 2012-11-12T15:41:32.038Z,1352734892.038 [SpeedControl] Loaded 2012-11-12T15:41:32.039Z,1352734892.039 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2012-11-12T15:41:32.040Z,1352734892.039 [LoopControl](DEBUG): Construct LoopControl. 2012-11-12T15:41:32.040Z,1352734892.040 [LoopControl] Loaded 2012-11-12T15:41:32.040Z,1352734892.040 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2012-11-12T15:41:32.041Z,1352734892.041 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2012-11-12T15:41:32.041Z,1352734892.041 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2012-11-12T15:41:32.049Z,1352734892.049 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator. 2012-11-12T15:41:32.054Z,1352734892.054 [AsyncPiEstimator] Loaded 2012-11-12T15:41:32.055Z,1352734892.055 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread. 2012-11-12T15:41:32.056Z,1352734892.056 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 406A14E0 2012-11-12T15:41:32.056Z,1352734892.056 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2012-11-12T15:41:32.057Z,1352734892.057 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2012-11-12T15:41:32.231Z,1352734892.231 [AHRS_sp3003D] Loaded 2012-11-12T15:41:32.232Z,1352734892.232 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2012-11-12T15:41:32.496Z,1352734892.496 [Batt_Ocean_Server] Loaded 2012-11-12T15:41:32.496Z,1352734892.496 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread. 2012-11-12T15:41:32.510Z,1352734892.510 [Depth_Keller] Loaded 2012-11-12T15:41:32.510Z,1352734892.510 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2012-11-12T15:41:32.512Z,1352734892.512 [DropWeight] Loaded 2012-11-12T15:41:32.512Z,1352734892.512 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2012-11-12T15:41:32.672Z,1352734892.671 [DVL_micro] Loaded 2012-11-12T15:41:32.672Z,1352734892.672 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread. 2012-11-12T15:41:32.673Z,1352734892.673 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 407234E0 2012-11-12T15:41:32.757Z,1352734892.757 [NAL9602] Loaded 2012-11-12T15:41:32.757Z,1352734892.757 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2012-11-12T15:41:32.808Z,1352734892.808 [Onboard] Loaded 2012-11-12T15:41:32.808Z,1352734892.808 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2012-11-12T15:41:32.815Z,1352734892.815 [Radio_Freewave] Loaded 2012-11-12T15:41:32.815Z,1352734892.815 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread. 2012-11-12T15:41:32.816Z,1352734892.816 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2012-11-12T15:41:32.817Z,1352734892.817 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2012-11-12T15:41:32.919Z,1352734892.919 [CTD_NeilBrown] Loaded 2012-11-12T15:41:32.919Z,1352734892.920 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2012-11-12T15:41:32.921Z,1352734892.921 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4077C4E0 2012-11-12T15:41:32.937Z,1352734892.937 [PAR_Licor] Loaded 2012-11-12T15:41:32.937Z,1352734892.937 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2012-11-12T15:41:32.992Z,1352734892.992 [Turbulence_NPS] Loaded 2012-11-12T15:41:32.992Z,1352734892.992 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread. 2012-11-12T15:41:32.993Z,1352734892.993 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 407AC4E0 2012-11-12T15:41:33.025Z,1352734893.025 [WetLabsBB2FL] Loaded 2012-11-12T15:41:33.025Z,1352734893.025 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2012-11-12T15:41:33.026Z,1352734893.026 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 407DC4E0 2012-11-12T15:41:33.027Z,1352734893.027 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2012-11-12T15:41:33.029Z,1352734893.029 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2012-11-12T15:41:33.032Z,1352734893.032 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2012-11-12T15:41:33.041Z,1352734893.042 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2012-11-12T15:41:33.045Z,1352734893.045 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 4080C4E0 2012-11-12T15:41:33.049Z,1352734893.049 [Supervisor](DEBUG): Running supervisor. 2012-11-12T15:41:33.051Z,1352734893.051 [CommandLine](INFO): Thread ID is 9524 2012-11-12T15:41:33.053Z,1352734893.053 [controlThread](INFO): Thread ID is 9523 2012-11-12T15:41:33.053Z,1352734893.053 [controlThread](DEBUG): Initializing ControlThread 2012-11-12T15:41:33.054Z,1352734893.054 [CycleStarter](INFO): Thread ID is 9522 2012-11-12T15:41:33.055Z,1352734893.055 [ExternalSim](INFO): ExternalSim initializing... 2012-11-12T15:41:33.103Z,1352734893.103 [logger](INFO): Thread ID is 9525 2012-11-12T15:41:33.144Z,1352734893.144 [AsyncPiEstimator](INFO): Thread ID is 9586 2012-11-12T15:41:33.144Z,1352734893.144 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator. 2012-11-12T15:41:33.167Z,1352734893.167 [DVL_micro](INFO): Thread ID is 9587 2012-11-12T15:41:33.279Z,1352734893.279 [CTD_NeilBrown](INFO): Thread ID is 9588 2012-11-12T15:41:33.279Z,1352734893.279 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown. 2012-11-12T15:41:33.283Z,1352734893.283 [CTD_NeilBrown](INFO): Opening uart, block timeout 10ths=4 2012-11-12T15:41:33.387Z,1352734893.387 [Turbulence_NPS](INFO): Thread ID is 9589 2012-11-12T15:41:33.387Z,1352734893.388 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS. 2012-11-12T15:41:33.388Z,1352734893.388 [Turbulence_NPS](INFO): Opening uart, block timeout 10ths=1 2012-11-12T15:41:33.399Z,1352734893.399 [WetLabsBB2FL](INFO): Thread ID is 9590 2012-11-12T15:41:33.400Z,1352734893.400 [WetLabsBB2FL](INFO): Powering down 2012-11-12T15:41:33.481Z,1352734893.481 [Turbulence_NPS](INFO): Pause powering down 2012-11-12T15:41:33.531Z,1352734893.531 [NavChartDb](INFO): Thread ID is 9591 2012-11-12T15:41:33.542Z,1352734893.542 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources 2012-11-12T15:41:33.543Z,1352734893.543 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2012-11-12T15:41:33.543Z,1352734893.543 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2012-11-12T15:41:33.544Z,1352734893.543 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2012-11-12T15:41:33.544Z,1352734893.544 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2012-11-12T15:41:33.595Z,1352734893.595 [DVL_micro](INFO): Initializing 2012-11-12T15:41:33.596Z,1352734893.596 [DVL_micro](INFO): start:Powering up 2012-11-12T15:41:33.596Z,1352734893.596 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2012-11-12T15:41:33.597Z,1352734893.597 [DVL_micro](INFO): Cycling power to configure device. 2012-11-12T15:41:33.723Z,1352734893.723 [ExternalSim](DEBUG): beaconLat = 36.81340 2012-11-12T15:41:33.723Z,1352734893.723 [ExternalSim](DEBUG): beaconLon = -121.82240 2012-11-12T15:41:33.723Z,1352734893.723 [ExternalSim](DEBUG): beaconDepth = 25.00 2012-11-12T15:41:33.978Z,1352734893.978 [ExternalSim](DEBUG): Simulator initialized 2012-11-12T15:41:33.984Z,1352734893.984 [InternalSim](DEBUG): InternalSim initializing... 2012-11-12T15:41:34.082Z,1352734894.082 [SBIT](INFO): Initialize SBIT Component. 2012-11-12T15:41:34.083Z,1352734894.083 [SBIT](IMPORTANT): Tethys CM Info: $Rev: 10047 2012-11-12T15:41:34.095Z,1352734894.095 [IBIT](INFO): Initialize IBIT Component. 2012-11-12T15:41:34.095Z,1352734894.095 [CBIT](DEBUG): Initialize CBIT Component. 2012-11-12T15:41:34.096Z,1352734894.096 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2012-11-12T15:41:34.136Z,1352734894.136 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2012-11-12T15:41:34.136Z,1352734894.136 [NavChart](DEBUG): Initialize NavChart Derivation. 2012-11-12T15:41:34.137Z,1352734894.137 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2012-11-12T15:41:34.137Z,1352734894.137 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2012-11-12T15:41:34.137Z,1352734894.137 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2012-11-12T15:41:34.139Z,1352734894.139 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2012-11-12T15:41:34.139Z,1352734894.139 [Navigation](DEBUG): Initializing Navigation. 2012-11-12T15:41:34.140Z,1352734894.139 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2012-11-12T15:41:34.141Z,1352734894.141 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2012-11-12T15:41:34.142Z,1352734894.142 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2012-11-12T15:41:34.142Z,1352734894.142 [LoopControl](DEBUG): Initialize LoopControlComponent. 2012-11-12T15:41:35.696Z,1352734895.696 [DVL_micro](INFO): Opening uart, block timeout 10ths=20 2012-11-12T15:41:35.696Z,1352734895.696 [DVL_micro](INFO): Querying output modes 2012-11-12T15:41:35.696Z,1352734895.696 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606 2012-11-12T15:41:35.711Z,1352734895.711 [DVL_micro](DEBUG): cmdResponse: 01 03 16 2012-11-12T15:41:35.711Z,1352734895.711 [DVL_micro](INFO): NQ1 output enabled 2012-11-12T15:41:35.711Z,1352734895.711 [DVL_micro](INFO): RSSI output enabled 2012-11-12T15:41:35.711Z,1352734895.711 [DVL_micro](INFO): ADCP output enabled 2012-11-12T15:41:35.711Z,1352734895.711 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525 2012-11-12T15:41:35.723Z,1352734895.723 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 2012-11-12T15:41:35.728Z,1352734895.728 [DVL_micro](INFO): pause:Powering down 2012-11-12T15:41:35.955Z,1352734895.955 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized 2012-11-12T15:41:35.991Z,1352734895.991 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2012-11-12T15:41:36.035Z,1352734896.035 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2012-11-12T15:41:36.061Z,1352734896.061 [MissionManager](DEBUG): 2012-11-12T15:41:36.062Z,1352734896.062 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2012-11-12T15:41:36.168Z,1352734896.168 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool 2012-11-12T15:41:36.170Z,1352734896.170 [Default:GPS:A.SetSpeed](DEBUG): Construct. 2012-11-12T15:41:36.184Z,1352734896.184 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-11-12T15:41:36.192Z,1352734896.192 [Default:Iridium:A.SetSpeed](DEBUG): Construct. 2012-11-12T15:41:36.227Z,1352734896.227 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface. 2012-11-12T15:41:36.234Z,1352734896.234 [Default:Iridium:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2012-11-12T15:41:36.263Z,1352734896.263 [Default:D.SetSpeed](DEBUG): Construct. 2012-11-12T15:41:36.266Z,1352734896.266 [Default:E.GoToSurface](DEBUG): Construct GoToSurface. 2012-11-12T15:41:36.271Z,1352734896.271 [Default:F.Wait](DEBUG): Construct Wait. 2012-11-12T15:41:36.287Z,1352734896.286 [MissionManager](DEBUG): 400 400 Burn 300 Dropped drop weight due to communications timeout 5.0 1.0 5 2012-11-12T15:41:36.292Z,1352734896.292 [controlThread](DEBUG): Component order: CycleStarter,ExternalSim,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, 2012-11-12T15:41:36.387Z,1352734896.386 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D. 2012-11-12T15:41:36.603Z,1352734896.603 [Radio_Freewave](INFO): Powering up 2012-11-12T15:41:36.934Z,1352734896.934 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2012-11-12T15:41:36.947Z,1352734896.947 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2012-11-12T15:41:36.963Z,1352734896.963 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2012-11-12T15:41:36.979Z,1352734896.978 [MassServo](DEBUG): Initializing EZServoServo. 2012-11-12T15:41:36.987Z,1352734896.987 [MassServo](DEBUG): Initializing MassServo. 2012-11-12T15:41:36.992Z,1352734896.992 [RudderServo](DEBUG): Initializing RudderServo. 2012-11-12T15:41:36.998Z,1352734896.998 [ThrusterServo](DEBUG): Initializing EZServoServo. 2012-11-12T15:41:37.027Z,1352734897.027 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2012-11-12T15:41:42.769Z,1352734902.769 [NAL9602](IMPORTANT): GPS fix at: 1352734902.74 2012-11-12T15:41:48.852Z,1352734908.852 [NAL9602](INFO): Powering down 2012-11-12T15:41:49.752Z,1352734909.753 [SBIT](IMPORTANT): Beginning Startup BIT 2012-11-12T15:41:49.755Z,1352734909.755 [CBIT](IMPORTANT): Beginning GF scan 2012-11-12T15:42:16.143Z,1352734936.143 [CBIT](IMPORTANT): No ground fault detected 2012-11-12T15:42:43.425Z,1352734963.425 [SBIT](IMPORTANT): SBIT PASSED 2012-11-12T15:42:43.852Z,1352734963.852 [MissionManager](IMPORTANT): Started mission Startup 2012-11-12T15:42:43.852Z,1352734963.852 [Startup] Running Loop=1 2012-11-12T15:42:43.852Z,1352734963.852 [Startup](INFO): Aggregate::initialize Startup 2012-11-12T15:42:43.852Z,1352734963.852 [Startup:A.GoToSurface] Running Loop=1 2012-11-12T15:42:43.853Z,1352734963.852 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-11-12T15:42:43.859Z,1352734963.859 [Startup:StartupSatComms] Running Loop=1 2012-11-12T15:42:43.859Z,1352734963.859 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms 2012-11-12T15:42:43.860Z,1352734963.860 [Startup:StartupSatComms:A] Running Loop=1 2012-11-12T15:42:44.226Z,1352734964.226 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-11-12T15:42:44.660Z,1352734964.660 [NAL9602](INFO): Powering up 2012-11-12T15:42:50.211Z,1352734970.211 [NAL9602](IMPORTANT): GPS fix at: 1352734970.21 2012-11-12T15:42:50.226Z,1352734970.226 [Startup:StartupSatComms:A] Stopped 2012-11-12T15:42:50.226Z,1352734970.226 [Startup:StartupSatComms:B] Running Loop=1 2012-11-12T15:42:50.620Z,1352734970.620 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-11-12T15:42:53.012Z,1352734973.012 [NAL9602](INFO): Sent 168 bytes from file Logs/20121110T052714/shore0019.lzma 2012-11-12T15:42:53.013Z,1352734973.013 [NAL9602](INFO): Packets left to send: 0 2012-11-12T15:42:53.018Z,1352734973.018 [NAL9602](INFO): Stored copy of sent data in Logs/20121110T052714/shore0019.lzma.parts/0000.sbd 2012-11-12T15:42:54.372Z,1352734974.372 [NAL9602](INFO): Sent 332 bytes from file Logs/20121112T154121/shore0000.lzma 2012-11-12T15:42:54.372Z,1352734974.372 [NAL9602](INFO): Packets left to send: 2 2012-11-12T15:42:54.374Z,1352734974.374 [NAL9602](INFO): Stored copy of sent data in Logs/20121112T154121/shore0000.lzma.parts/0002.sbd 2012-11-12T15:42:55.492Z,1352734975.492 [NAL9602](INFO): Sent 332 bytes from file Logs/20121112T154121/shore0000.lzma 2012-11-12T15:42:55.492Z,1352734975.492 [NAL9602](INFO): Packets left to send: 1 2012-11-12T15:42:55.493Z,1352734975.493 [NAL9602](INFO): Stored copy of sent data in Logs/20121112T154121/shore0000.lzma.parts/0001.sbd 2012-11-12T15:42:56.695Z,1352734976.695 [NAL9602](INFO): Sent 31 bytes from file Logs/20121112T154121/shore0000.lzma 2012-11-12T15:42:56.695Z,1352734976.695 [NAL9602](INFO): Packets left to send: 0 2012-11-12T15:42:56.696Z,1352734976.696 [NAL9602](INFO): Stored copy of sent data in Logs/20121112T154121/shore0000.lzma.parts/0000.sbd 2012-11-12T15:42:57.517Z,1352734977.517 [Startup:StartupSatComms:B] Stopped 2012-11-12T15:42:57.517Z,1352734977.517 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2012-11-12T15:42:57.517Z,1352734977.517 [Startup:StartupSatComms] Stopped 2012-11-12T15:42:57.518Z,1352734977.518 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms 2012-11-12T15:42:57.519Z,1352734977.519 [Startup](INFO): Completed Startup 2012-11-12T15:42:57.519Z,1352734977.519 [Startup] Stopped 2012-11-12T15:42:57.519Z,1352734977.519 [Startup](INFO): Aggregate::uninitialize Startup 2012-11-12T15:42:57.519Z,1352734977.519 [Startup:A.GoToSurface] Stopped 2012-11-12T15:42:57.519Z,1352734977.519 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-11-12T15:42:57.897Z,1352734977.897 [MissionManager](IMPORTANT): Started mission Default 2012-11-12T15:42:57.897Z,1352734977.897 [Default] Running Loop=1 2012-11-12T15:42:57.897Z,1352734977.897 [Default](INFO): Aggregate::initialize Default 2012-11-12T15:42:57.897Z,1352734977.897 [Default:D.SetSpeed] Running Loop=1 2012-11-12T15:42:57.897Z,1352734977.897 [Default:D.SetSpeed](DEBUG): Initialize. 2012-11-12T15:42:57.897Z,1352734977.898 [Default:E.GoToSurface] Running Loop=1 2012-11-12T15:42:57.898Z,1352734977.898 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-11-12T15:42:57.898Z,1352734977.898 [Default:Iridium] Running Loop=1 2012-11-12T15:42:57.898Z,1352734977.898 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium 2012-11-12T15:42:57.898Z,1352734977.898 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-11-12T15:42:57.898Z,1352734977.898 [Default:Iridium:A.SetSpeed](DEBUG): Initialize. 2012-11-12T15:42:57.898Z,1352734977.898 [Default:Iridium:B.GoToSurface] Running Loop=1 2012-11-12T15:42:57.899Z,1352734977.898 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-11-12T15:42:57.899Z,1352734977.899 [Default:E.GoToSurface] Running Loop=1 2012-11-12T15:42:57.928Z,1352734977.928 [Default:D.SetSpeed] Running Loop=1 2012-11-12T15:42:57.953Z,1352734977.953 [Default:Iridium:B.GoToSurface] Stopped 2012-11-12T15:42:57.953Z,1352734977.954 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-11-12T15:42:57.954Z,1352734977.954 [Default:Iridium:Read_Iridium] Running Loop=1 2012-11-12T15:42:57.954Z,1352734977.954 [Default:Iridium:A.SetSpeed] Running Loop=1 2012-11-12T15:42:57.959Z,1352734977.959 [Default:GPS] Running Loop=1 2012-11-12T15:42:57.959Z,1352734977.959 [Default:GPS](INFO): Aggregate::initialize Default:GPS 2012-11-12T15:42:57.959Z,1352734977.959 [Default:GPS:A.SetSpeed] Running Loop=1 2012-11-12T15:42:57.959Z,1352734977.959 [Default:GPS:A.SetSpeed](DEBUG): Initialize. 2012-11-12T15:42:57.960Z,1352734977.960 [Default:GPS:B.GoToSurface] Running Loop=1 2012-11-12T15:42:57.960Z,1352734977.960 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2012-11-12T15:42:57.965Z,1352734977.965 [Default:GPS:B.GoToSurface] Stopped 2012-11-12T15:42:57.965Z,1352734977.965 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2012-11-12T15:42:57.965Z,1352734977.965 [Default:GPS:Read_GPS] Running Loop=1 2012-11-12T15:42:57.965Z,1352734977.965 [Default:GPS:A.SetSpeed] Running Loop=1 2012-11-12T15:42:58.315Z,1352734978.315 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2012-11-12T15:42:58.317Z,1352734978.317 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2012-11-12T15:43:02.695Z,1352734982.695 [NAL9602](IMPORTANT): GPS fix at: 1352734982.69 2012-11-12T15:43:02.723Z,1352734982.723 [Default:GPS:Read_GPS] Stopped 2012-11-12T15:43:02.723Z,1352734982.723 [Default:GPS:D] Running Loop=1 2012-11-12T15:43:03.119Z,1352734983.119 [Default:GPS:D] Stopped 2012-11-12T15:43:03.119Z,1352734983.119 [Default:GPS](INFO): Completed Default:GPS 2012-11-12T15:43:03.119Z,1352734983.119 [Default:GPS] Stopped 2012-11-12T15:43:03.120Z,1352734983.120 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS 2012-11-12T15:43:03.120Z,1352734983.120 [Default:GPS:A.SetSpeed] Stopped 2012-11-12T15:43:03.120Z,1352734983.120 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize. 2012-11-12T15:43:04.740Z,1352734984.740 [NAL9602](INFO): Sent 156 bytes from file Logs/20121112T154121/shore0001.lzma 2012-11-12T15:43:04.740Z,1352734984.740 [NAL9602](INFO): Packets left to send: 0 2012-11-12T15:43:04.742Z,1352734984.742 [NAL9602](INFO): Stored copy of sent data in Logs/20121112T154121/shore0001.lzma.parts/0000.sbd 2012-11-12T15:43:05.589Z,1352734985.589 [Default:Iridium:Read_Iridium] Stopped 2012-11-12T15:43:05.590Z,1352734985.590 [Default:Iridium](INFO): Completed Default:Iridium 2012-11-12T15:43:05.590Z,1352734985.590 [Default:Iridium] Stopped 2012-11-12T15:43:05.590Z,1352734985.590 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium 2012-11-12T15:43:05.590Z,1352734985.590 [Default:Iridium:A.SetSpeed] Stopped 2012-11-12T15:43:05.590Z,1352734985.590 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize. 2012-11-12T15:43:05.590Z,1352734985.590 [Default:F.Wait] Running Loop=1 2012-11-12T15:43:05.590Z,1352734985.591 [Default:F.Wait](DEBUG): Initialize Wait Component. 2012-11-12T15:43:16.140Z,1352734996.140 [NAL9602](INFO): Powering down 2012-11-12T15:43:17.295Z,1352734997.295 [CommandLine](IMPORTANT): got command show variable battery 2012-11-12T15:43:17.354Z,1352734997.354 [CommandLine](INFO): platform_battery_charge (ampere_hour) 2012-11-12T15:43:17.354Z,1352734997.355 [CommandLine](INFO): platform_battery_charge_usage (ampere_hour) 2012-11-12T15:43:17.355Z,1352734997.355 [CommandLine](INFO): platform_battery_energy_usage (unknown) 2012-11-12T15:43:17.355Z,1352734997.355 [CommandLine](INFO): platform_battery_voltage (volt) 2012-11-12T15:43:17.356Z,1352734997.356 [CommandLine](INFO): platform_battery_fully_charged (bool) 2012-11-12T15:43:17.356Z,1352734997.356 [CommandLine](INFO): platform_battery_discharging (bool) 2012-11-12T15:43:17.361Z,1352734997.361 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_ad (none) 2012-11-12T15:43:17.362Z,1352734997.362 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_vref (volt) 2012-11-12T15:43:17.362Z,1352734997.362 [CommandLine](INFO): Config/vehicle.secondaryBatteryCurrent_res (bit) 2012-11-12T15:43:17.363Z,1352734997.363 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_ad (none) 2012-11-12T15:43:17.363Z,1352734997.363 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_vref (volt) 2012-11-12T15:43:17.363Z,1352734997.363 [CommandLine](INFO): Config/vehicle.emergencyBatteryCurrent_res (bit) 2012-11-12T15:43:17.368Z,1352734997.368 [CommandLine](INFO): IBIT.batteryCapacityThreshold (ampere_hour) 2012-11-12T15:43:17.369Z,1352734997.369 [CommandLine](INFO): IBIT.batteryVoltageThreshold (volt) 2012-11-12T15:43:17.390Z,1352734997.390 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_charge (ampere_hour) 2012-11-12T15:43:17.390Z,1352734997.390 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_voltage (volt) 2012-11-12T15:43:17.391Z,1352734997.391 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_discharging (bool) 2012-11-12T15:43:17.391Z,1352734997.391 [CommandLine](INFO): Batt_Ocean_Server.platform_battery_fully_charged (bool) 2012-11-12T15:43:17.394Z,1352734997.394 [CommandLine](INFO): Onboard.platform_battery_charge_usage (ampere_hour) 2012-11-12T15:43:31.987Z,1352735011.987 [CommandLine](IMPORTANT): got command get platform_battery_charge 2012-11-12T15:43:31.992Z,1352735011.992 [CommandLine](IMPORTANT): platform_battery_charge 125.200000 ampere_hour