2012-08-23T16:04:46.547Z,1345737886.547 [Supervisor](DEBUG): Initializing supervisor.
2012-08-23T16:04:46.550Z,1345737886.550 [SyncHandler](DEBUG): Created PCaller Thread at 1077130464
2012-08-23T16:04:46.551Z,1345737886.551 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2012-08-23T16:04:46.554Z,1345737886.554 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 1077327072
2012-08-23T16:04:46.557Z,1345737886.557 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2012-08-23T16:04:46.569Z,1345737886.569 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2012-08-23T16:04:46.570Z,1345737886.570 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 1077523680
2012-08-23T16:04:46.571Z,1345737886.571 [ComponentRegistry](DEBUG): SyncComponent "logger" handled in the control thread.
2012-08-23T16:04:46.572Z,1345737886.572 [Supervisor](INFO): Looking for Config files in directory: Config/
2012-08-23T16:04:46.575Z,1345737886.575 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2012-08-23T16:04:46.903Z,1345737886.903 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2012-08-23T16:04:46.905Z,1345737886.905 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2012-08-23T16:04:47.115Z,1345737887.115 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2012-08-23T16:04:47.116Z,1345737887.116 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2012-08-23T16:04:47.210Z,1345737887.210 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2012-08-23T16:04:47.212Z,1345737887.212 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2012-08-23T16:04:47.447Z,1345737887.447 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2012-08-23T16:04:47.448Z,1345737887.448 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2012-08-23T16:04:47.603Z,1345737887.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2012-08-23T16:04:47.605Z,1345737887.605 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2012-08-23T16:04:47.862Z,1345737887.862 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2012-08-23T16:04:47.863Z,1345737887.862 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2012-08-23T16:04:48.055Z,1345737888.055 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2012-08-23T16:04:48.057Z,1345737888.057 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2012-08-23T16:04:48.356Z,1345737888.355 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2012-08-23T16:04:48.358Z,1345737888.358 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2012-08-23T16:04:48.471Z,1345737888.471 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2012-08-23T16:04:48.472Z,1345737888.471 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2012-08-23T16:04:48.930Z,1345737888.930 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2012-08-23T16:04:48.930Z,1345737888.931 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2012-08-23T16:04:49.059Z,1345737889.059 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2012-08-23T16:04:49.060Z,1345737889.060 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2012-08-23T16:04:49.155Z,1345737889.155 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2012-08-23T16:04:49.159Z,1345737889.159 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2012-08-23T16:04:49.271Z,1345737889.271 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2012-08-23T16:04:49.415Z,1345737889.415 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2012-08-23T16:04:49.515Z,1345737889.515 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2012-08-23T16:04:49.683Z,1345737889.683 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2012-08-23T16:04:49.794Z,1345737889.794 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2012-08-23T16:04:49.928Z,1345737889.928 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2012-08-23T16:04:50.030Z,1345737890.030 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2012-08-23T16:04:50.175Z,1345737890.174 [Supervisor](FAULT): Ignoring configuration overrides from Data/config.db
2012-08-23T16:04:50.215Z,1345737890.215 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2012-08-23T16:04:50.419Z,1345737890.419 [InternalSim] Loaded
2012-08-23T16:04:50.420Z,1345737890.420 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread.
2012-08-23T16:04:50.421Z,1345737890.421 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2012-08-23T16:04:50.421Z,1345737890.421 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2012-08-23T16:04:50.509Z,1345737890.509 [SBIT](DEBUG): Construct Startup Built In Test.
2012-08-23T16:04:50.527Z,1345737890.527 [SBIT] Loaded
2012-08-23T16:04:50.528Z,1345737890.528 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2012-08-23T16:04:50.529Z,1345737890.529 [IBIT](DEBUG): Construct Initiated Built In Test.
2012-08-23T16:04:50.563Z,1345737890.563 [IBIT] Loaded
2012-08-23T16:04:50.564Z,1345737890.564 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2012-08-23T16:04:50.567Z,1345737890.567 [CBIT](DEBUG): Construct CBIT Built In Test.
2012-08-23T16:04:50.707Z,1345737890.707 [CBIT] Loaded
2012-08-23T16:04:50.707Z,1345737890.707 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2012-08-23T16:04:50.708Z,1345737890.708 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2012-08-23T16:04:50.709Z,1345737890.708 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2012-08-23T16:04:50.886Z,1345737890.886 [BuoyancyServo] Loaded
2012-08-23T16:04:50.886Z,1345737890.886 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2012-08-23T16:04:50.896Z,1345737890.896 [ElevatorServo] Loaded
2012-08-23T16:04:50.896Z,1345737890.896 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2012-08-23T16:04:50.909Z,1345737890.909 [MassServo] Loaded
2012-08-23T16:04:50.910Z,1345737890.910 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2012-08-23T16:04:50.927Z,1345737890.927 [RudderServo] Loaded
2012-08-23T16:04:50.927Z,1345737890.927 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2012-08-23T16:04:50.940Z,1345737890.940 [ThrusterServo] Loaded
2012-08-23T16:04:50.940Z,1345737890.940 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2012-08-23T16:04:50.941Z,1345737890.941 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2012-08-23T16:04:50.941Z,1345737890.941 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2012-08-23T16:04:50.975Z,1345737890.975 [DepthRateCalculator] Loaded
2012-08-23T16:04:50.975Z,1345737890.975 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2012-08-23T16:04:53.826Z,1345737893.826 [HFRadarModelCalc] Loaded
2012-08-23T16:04:53.826Z,1345737893.826 [ComponentRegistry](DEBUG): SyncComponent "HFRadarModelCalc" handled in the control thread.
2012-08-23T16:04:53.844Z,1345737893.844 [NavChart] Loaded
2012-08-23T16:04:53.844Z,1345737893.844 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2012-08-23T16:04:53.850Z,1345737893.850 [PitchRateCalculator] Loaded
2012-08-23T16:04:53.851Z,1345737893.851 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2012-08-23T16:04:53.862Z,1345737893.862 [SpeedCalculator] Loaded
2012-08-23T16:04:53.862Z,1345737893.862 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2012-08-23T16:04:53.878Z,1345737893.878 [TempGradientCalculator] Loaded
2012-08-23T16:04:53.879Z,1345737893.879 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2012-08-23T16:04:53.885Z,1345737893.885 [YawRateCalculator] Loaded
2012-08-23T16:04:53.886Z,1345737893.886 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2012-08-23T16:04:53.911Z,1345737893.911 [Navigation] Loaded
2012-08-23T16:04:53.912Z,1345737893.912 [ComponentRegistry](DEBUG): SyncComponent "Navigation" handled in the control thread.
2012-08-23T16:04:53.912Z,1345737893.912 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2012-08-23T16:04:53.913Z,1345737893.913 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2012-08-23T16:04:54.232Z,1345737894.232 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2012-08-23T16:04:54.233Z,1345737894.233 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2012-08-23T16:04:54.276Z,1345737894.276 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2012-08-23T16:04:54.277Z,1345737894.277 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2012-08-23T16:04:54.344Z,1345737894.344 [VerticalControl](DEBUG): Construct VerticalControl.
2012-08-23T16:04:54.397Z,1345737894.397 [VerticalControl] Loaded
2012-08-23T16:04:54.398Z,1345737894.398 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2012-08-23T16:04:54.399Z,1345737894.399 [HorizontalControl](DEBUG): Construct HorizontalControl.
2012-08-23T16:04:54.425Z,1345737894.425 [HorizontalControl] Loaded
2012-08-23T16:04:54.425Z,1345737894.425 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2012-08-23T16:04:54.427Z,1345737894.427 [SpeedControl](DEBUG): Construct SpeedControl.
2012-08-23T16:04:54.428Z,1345737894.428 [SpeedControl] Loaded
2012-08-23T16:04:54.429Z,1345737894.429 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2012-08-23T16:04:54.430Z,1345737894.430 [LoopControl](DEBUG): Construct LoopControl.
2012-08-23T16:04:54.431Z,1345737894.431 [LoopControl] Loaded
2012-08-23T16:04:54.431Z,1345737894.431 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2012-08-23T16:04:54.431Z,1345737894.431 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2012-08-23T16:04:54.432Z,1345737894.432 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2012-08-23T16:04:54.440Z,1345737894.440 [AsyncPiEstimator](DEBUG): Construct AsyncPiEstimator.
2012-08-23T16:04:54.445Z,1345737894.445 [AsyncPiEstimator] Loaded
2012-08-23T16:04:54.446Z,1345737894.446 [ComponentRegistry](DEBUG): Component "AsyncPiEstimator" handled in its own thread.
2012-08-23T16:04:54.450Z,1345737894.450 [AsyncPiEstimator ThreadHandler](DEBUG): Created PCaller Thread at 1080075488
2012-08-23T16:04:54.451Z,1345737894.451 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2012-08-23T16:04:54.452Z,1345737894.452 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2012-08-23T16:04:54.647Z,1345737894.647 [AHRS_sp3003D] Loaded
2012-08-23T16:04:54.648Z,1345737894.648 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread.
2012-08-23T16:04:54.959Z,1345737894.959 [Batt_Ocean_Server] Loaded
2012-08-23T16:04:54.960Z,1345737894.960 [ComponentRegistry](DEBUG): SyncComponent "Batt_Ocean_Server" handled in the control thread.
2012-08-23T16:04:54.977Z,1345737894.977 [Depth_Keller] Loaded
2012-08-23T16:04:54.978Z,1345737894.978 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2012-08-23T16:04:54.984Z,1345737894.984 [DropWeight] Loaded
2012-08-23T16:04:54.984Z,1345737894.984 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2012-08-23T16:04:55.125Z,1345737895.125 [DVL_micro] Loaded
2012-08-23T16:04:55.126Z,1345737895.126 [ComponentRegistry](DEBUG): Component "DVL_micro" handled in its own thread.
2012-08-23T16:04:55.130Z,1345737895.130 [DVL_micro ThreadHandler](DEBUG): Created PCaller Thread at 1080739040
2012-08-23T16:04:55.229Z,1345737895.229 [NAL9602] Loaded
2012-08-23T16:04:55.229Z,1345737895.229 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2012-08-23T16:04:55.288Z,1345737895.288 [Onboard] Loaded
2012-08-23T16:04:55.289Z,1345737895.289 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2012-08-23T16:04:55.296Z,1345737895.296 [Radio_Freewave] Loaded
2012-08-23T16:04:55.296Z,1345737895.296 [ComponentRegistry](DEBUG): SyncComponent "Radio_Freewave" handled in the control thread.
2012-08-23T16:04:55.297Z,1345737895.297 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2012-08-23T16:04:55.298Z,1345737895.298 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2012-08-23T16:04:55.403Z,1345737895.403 [CTD_NeilBrown] Loaded
2012-08-23T16:04:55.403Z,1345737895.403 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2012-08-23T16:04:55.406Z,1345737895.406 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 1081099488
2012-08-23T16:04:55.426Z,1345737895.426 [Turbulence_NPS] Loaded
2012-08-23T16:04:55.426Z,1345737895.426 [ComponentRegistry](DEBUG): Component "Turbulence_NPS" handled in its own thread.
2012-08-23T16:04:55.430Z,1345737895.430 [Turbulence_NPS ThreadHandler](DEBUG): Created PCaller Thread at 1081296096
2012-08-23T16:04:55.467Z,1345737895.467 [WetLabsBB2FL] Loaded
2012-08-23T16:04:55.467Z,1345737895.467 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2012-08-23T16:04:55.470Z,1345737895.470 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 1081492704
2012-08-23T16:04:55.471Z,1345737895.471 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2012-08-23T16:04:55.473Z,1345737895.473 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2012-08-23T16:04:55.474Z,1345737895.474 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2012-08-23T16:04:55.481Z,1345737895.481 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2012-08-23T16:04:55.482Z,1345737895.482 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 1081689312
2012-08-23T16:04:55.487Z,1345737895.487 [Supervisor](DEBUG): Running supervisor.
2012-08-23T16:04:55.491Z,1345737895.491 [controlThread](DEBUG): Initializing ControlThread
2012-08-23T16:04:55.492Z,1345737895.492 [InternalSim](DEBUG):  InternalSim initializing...
2012-08-23T16:04:55.612Z,1345737895.612 [AsyncPiEstimator](DEBUG): Initialize AsyncPiEstimator.
2012-08-23T16:04:55.773Z,1345737895.773 [CTD_NeilBrown](DEBUG): Initializing CTD_NeilBrown.
2012-08-23T16:04:55.818Z,1345737895.818 [DVL_micro](INFO): Initializing
2012-08-23T16:04:55.820Z,1345737895.820 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2828

2012-08-23T16:04:55.821Z,1345737895.821 [Turbulence_NPS](DEBUG): Initializing Turbulence_NPS.
2012-08-23T16:04:55.830Z,1345737895.830 [WetLabsBB2FL](INFO): Powering down
2012-08-23T16:04:55.851Z,1345737895.851 [SBIT](INFO): Initialize SBIT Component.
2012-08-23T16:04:55.851Z,1345737895.851 [SBIT](IMPORTANT): Tethys CM Info:
$Rev: 9804
2012-08-23T16:04:55.852Z,1345737895.852 [IBIT](INFO): Initialize IBIT Component.
2012-08-23T16:04:55.853Z,1345737895.853 [CBIT](DEBUG): Initialize CBIT Component.
2012-08-23T16:04:55.853Z,1345737895.853 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2012-08-23T16:04:55.853Z,1345737895.853 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2012-08-23T16:04:55.883Z,1345737895.883 [DVL_micro](DEBUG): cmdResponse: 
2012-08-23T16:04:55.883Z,1345737895.883 [DVL_micro](INFO): Querying output modes
2012-08-23T16:04:55.883Z,1345737895.883 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD0606

2012-08-23T16:04:55.885Z,1345737895.885 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2012-08-23T16:04:55.886Z,1345737895.886 [NavChart](DEBUG): Initialize NavChart Derivation.
2012-08-23T16:04:55.887Z,1345737895.887 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2012-08-23T16:04:55.887Z,1345737895.887 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2012-08-23T16:04:55.888Z,1345737895.888 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2012-08-23T16:04:55.889Z,1345737895.889 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2012-08-23T16:04:55.890Z,1345737895.890 [Navigation](DEBUG): Initializing Navigation.
2012-08-23T16:04:55.891Z,1345737895.891 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2012-08-23T16:04:55.892Z,1345737895.892 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2012-08-23T16:04:55.893Z,1345737895.893 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2012-08-23T16:04:55.894Z,1345737895.894 [LoopControl](DEBUG): Initialize LoopControlComponent.
2012-08-23T16:04:56.065Z,1345737896.065 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources
2012-08-23T16:04:56.072Z,1345737896.072 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2012-08-23T16:04:56.077Z,1345737896.077 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2012-08-23T16:04:56.081Z,1345737896.081 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2012-08-23T16:04:56.086Z,1345737896.086 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2012-08-23T16:04:56.087Z,1345737896.087 [NavChartDb](INFO): Creating index for Soundings
2012-08-23T16:04:56.091Z,1345737896.091 [NavChartDb](INFO): Creating index for Contour 0p0
2012-08-23T16:04:56.093Z,1345737896.093 [NavChartDb](INFO): Creating index for Contour 1p8
2012-08-23T16:04:56.096Z,1345737896.096 [NavChartDb](INFO): Creating index for Contour 3p6
2012-08-23T16:04:56.097Z,1345737896.098 [NavChartDb](INFO): Creating index for Contour 5p4
2012-08-23T16:04:56.100Z,1345737896.100 [NavChartDb](INFO): Creating index for Contour 9p1
2012-08-23T16:04:56.102Z,1345737896.102 [NavChartDb](INFO): Creating index for Contour 10p9
2012-08-23T16:04:56.109Z,1345737896.109 [NavChartDb](INFO): Creating index for Contour 18p2
2012-08-23T16:04:56.111Z,1345737896.111 [NavChartDb](INFO): Creating index for Contour 36p5
2012-08-23T16:04:56.112Z,1345737896.112 [NavChartDb](INFO): Creating index for Contour 54p8
2012-08-23T16:04:56.115Z,1345737896.115 [NavChartDb](INFO): Creating index for Contour 73p1
2012-08-23T16:04:56.116Z,1345737896.116 [NavChartDb](INFO): Creating index for Contour 91p4
2012-08-23T16:04:56.119Z,1345737896.118 [NavChartDb](INFO): Creating index for Contour 182p8
2012-08-23T16:04:56.120Z,1345737896.120 [NavChartDb](INFO): Creating index for Contour 365p7
2012-08-23T16:04:56.123Z,1345737896.123 [NavChartDb](INFO): Creating index for Contour 548p6
2012-08-23T16:04:56.125Z,1345737896.125 [NavChartDb](INFO): Creating index for Contour 731p5
2012-08-23T16:04:56.127Z,1345737896.127 [NavChartDb](INFO): Creating index for Contour 914p4
2012-08-23T16:04:56.129Z,1345737896.129 [NavChartDb](INFO): Creating index for Contour 1097p2
2012-08-23T16:04:56.131Z,1345737896.131 [NavChartDb](INFO): Creating index for Contour 1280p1
2012-08-23T16:04:56.133Z,1345737896.133 [NavChartDb](INFO): Creating index for Contour 1463p0
2012-08-23T16:04:56.135Z,1345737896.135 [NavChartDb](INFO): Creating index for Contour 1645p9
2012-08-23T16:04:56.137Z,1345737896.137 [NavChartDb](INFO): Creating index for Contour 1828p8
2012-08-23T16:04:56.140Z,1345737896.140 [NavChartDb](INFO): Creating index for Contour 2011p6
2012-08-23T16:04:56.142Z,1345737896.142 [NavChartDb](INFO): Creating index for Contour 2194p5
2012-08-23T16:04:56.144Z,1345737896.144 [NavChartDb](INFO): Creating index for Contour 2377p4
2012-08-23T16:04:56.146Z,1345737896.146 [NavChartDb](INFO): Creating index for Contour 2560p3
2012-08-23T16:04:56.148Z,1345737896.148 [NavChartDb](INFO): Creating index for Contour 2743p2
2012-08-23T16:04:56.155Z,1345737896.155 [NavChartDb](INFO): Creating index for Contour 2926p0
2012-08-23T16:04:56.157Z,1345737896.157 [NavChartDb](INFO): Creating index for Contour 3108p9
2012-08-23T16:04:56.159Z,1345737896.159 [NavChartDb](INFO): Creating index for Contour 3291p8
2012-08-23T16:04:56.161Z,1345737896.161 [NavChartDb](INFO): Creating index for Contour 3474p7
2012-08-23T16:04:56.163Z,1345737896.163 [NavChartDb](INFO): Creating index for Contour 3657p6
2012-08-23T16:04:57.399Z,1345737897.399 [Batt_Ocean_Server](INFO): Ocean Server Batteries initialized
2012-08-23T16:04:57.408Z,1345737897.408 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2012-08-23T16:04:57.423Z,1345737897.423 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-08-23T16:04:57.438Z,1345737897.438 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface RunIn="Progression"/>

    <Aggregate Id="StartupSatComms" >

        <ReadDatum>
            <Timeout Duration="P1M" /><Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" /><Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2012-08-23T16:04:57.438Z,1345737897.438 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2012-08-23T16:04:57.474Z,1345737897.474 [MissionManager](INFO): DefineArg Default.NeedGPS = 1 bool
2012-08-23T16:04:57.476Z,1345737897.476 [Default:GPS:A.SetSpeed](DEBUG): Construct.
2012-08-23T16:04:57.480Z,1345737897.480 [Default:GPS:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-08-23T16:04:57.489Z,1345737897.489 [Default:Iridium:A.SetSpeed](DEBUG): Construct.
2012-08-23T16:04:57.497Z,1345737897.497 [Default:Iridium:B.GoToSurface](DEBUG): Construct GoToSurface.
2012-08-23T16:04:57.504Z,1345737897.504 [Default:Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2012-08-23T16:04:57.513Z,1345737897.513 [Default:D.SetSpeed](DEBUG): Construct.
2012-08-23T16:04:57.517Z,1345737897.517 [Default:E.GoToSurface](DEBUG): Construct GoToSurface.
2012-08-23T16:04:57.522Z,1345737897.523 [Default:F.Wait](DEBUG): Construct Wait.
2012-08-23T16:04:57.527Z,1345737897.527 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
xmlns:Control="Tethys/Control"
xmlns:Guidance="Tethys/Guidance" 
xmlns:Units="Tethys/Units"
xmlns:Universal="Tethys/Universal"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
Tethys/Control http://aosn.mbari.org/tethys/Xml/Control.xsd
Tethys/Guidance http://aosn.mbari.org/tethys/Xml/Guidance.xsd
Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd
Tethys/Universal http://aosn.mbari.org/tethys/Xml/Universal.xsd"
Id="Default">

    <DefineArg Name="NeedGPS"><True/></DefineArg>

    <Aggregate Id="GPS" >

        <When><Arg Name="NeedGPS"/>
        </When>

<!-- Run at high speed -->

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Get GPS fix -->

        <ReadDatum Id="Read_GPS"><Universal:latitude_fix/>
        </ReadDatum>

        <Assign><Arg Name="NeedGPS"/><False/></Assign>

    </Aggregate>

    <Aggregate Id="Iridium" >

<!-- Run at high speed -->

        <Guidance:SetSpeed RunIn="Parallel">
            <Setting><Guidance:SetSpeed.period/><Units:millisecond/><Value>400</Value></Setting>
        </Guidance:SetSpeed>

<!-- Get to the surface -->

        <Guidance:GoToSurface RunIn="Sequence"/>

<!-- Do data comms -->

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute RunIn="Sequence">
                    <Setting>
                    <Guidance:Execute.command/><String>Burn 300</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped drop weight due to communications timeout</Syslog>
            </Timeout><Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

    <Aggregate Id="CallIridium" >

        <When>
            <Elapsed><Universal:platform_communications/></Elapsed>
            <Gt><Units:minute/><Value>5.0</Value></Gt>
            <And><Universal:platform_conversation/><Eq><True/></Eq></And>
            <Or>
            <Elapsed><Universal:platform_communications/></Elapsed><Gt><Units:hour/><Value>1.0</Value></Gt></Or>
        </When>

        <Assign><Arg Name="NeedGPS"/><True/></Assign>

        <Call RefId="Iridium"/>

    </Aggregate>

<!-- Wait forever at the surface-->

<!-- Run at low speed -->

    <Guidance:SetSpeed RunIn="Parallel">
        <Setting><Guidance:SetSpeed.period/><Units:second/><Value>5</Value></Setting>
    </Guidance:SetSpeed>

    <Guidance:GoToSurface RunIn="Parallel"/>

    <Guidance:Wait RunIn="Sequence"></Guidance:Wait>

</Mission>


2012-08-23T16:04:57.531Z,1345737897.531 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,Batt_Ocean_Server,Depth_Keller,DropWeight,NAL9602,Onboard,Radio_Freewave,Depth_Keller,DepthRateCalculator,HFRadarModelCalc,NavChart,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,Navigation,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,logger,
2012-08-23T16:04:57.556Z,1345737897.556 [AHRS_sp3003D](DEBUG): Initializing AHRS_sp3003D.
2012-08-23T16:04:57.744Z,1345737897.744 [Radio_Freewave](INFO): Powering up
2012-08-23T16:04:57.837Z,1345737897.837 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:04:57.838Z,1345737897.838 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2012-08-23T16:04:57.845Z,1345737897.845 [ElevatorServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:04:57.847Z,1345737897.847 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2012-08-23T16:04:57.853Z,1345737897.853 [MassServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:04:57.854Z,1345737897.854 [MassServo](DEBUG): Initializing MassServo.
2012-08-23T16:04:57.860Z,1345737897.861 [RudderServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:04:57.863Z,1345737897.863 [RudderServo](DEBUG): Initializing RudderServo.
2012-08-23T16:04:57.869Z,1345737897.869 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:04:57.870Z,1345737897.870 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-08-23T16:04:57.886Z,1345737897.886 [DVL_micro](DEBUG): cmdResponse: 
2012-08-23T16:04:57.887Z,1345737897.887 [DVL_micro](INFO): Output Modes: No Response
2012-08-23T16:04:57.887Z,1345737897.887 [DVL_micro](DEBUG): commandDVL: #&!LQNQ.COMD2525

2012-08-23T16:04:57.891Z,1345737897.891 [DVL_micro](DEBUG): cmdResponse: AUTO_VEL_ON 
2012-08-23T16:05:00.569Z,1345737900.569 [NAL9602](INFO): Powering up NAL9602
2012-08-23T16:05:11.351Z,1345737911.351 [NAL9602](INFO): NAL9602 initialized
2012-08-23T16:05:11.416Z,1345737911.416 [SBIT](IMPORTANT): Beginning Startup BIT
2012-08-23T16:05:11.419Z,1345737911.419 [CBIT](IMPORTANT): Beginning GF scan
2012-08-23T16:05:24.657Z,1345737924.657 [SBIT](FAULT): Elevator: EXPECTED:15.000000 ACTUAL:14.936239
2012-08-23T16:05:24.658Z,1345737924.658 [SBIT](FAULT): Rudder: EXPECTED:15.000000 ACTUAL:14.894450
2012-08-23T16:05:38.133Z,1345737938.133 [CBIT](FAULT): Chan 0 High side GF detected
mA:
CHAN 5 (24V): 0.391695
CHAN 4 (Batt): 0.326078
CHAN 2 (12V): 0.207948
CHAN 1 (5V): 0.050696
CHAN 0 (3.3V): 0.018557
OPEN: 0.011574
Full Scale Calc: 0.392
2012-08-23T16:05:40.426Z,1345737940.426 [NAL9602](IMPORTANT): GPS fix at: 1345737932.00
2012-08-23T16:05:40.891Z,1345737940.891 [NavChartDb](INFO): Charting Soundings
2012-08-23T16:05:42.491Z,1345737942.490 [NavChartDb](INFO): Charting 0p0
2012-08-23T16:05:47.672Z,1345737947.672 [NAL9602](INFO): Powering down
2012-08-23T16:05:59.183Z,1345737959.183 [NavChartDb](INFO): Charting 1p8
2012-08-23T16:06:01.080Z,1345737961.080 [NavChartDb](INFO): Charting 3p6
2012-08-23T16:06:02.929Z,1345737962.929 [NavChartDb](INFO): Charting 5p4
2012-08-23T16:06:05.433Z,1345737965.433 [SBIT](CRITICAL): SBIT FAILED
2012-08-23T16:06:05.765Z,1345737965.765 [MissionManager](IMPORTANT): Started mission Startup
2012-08-23T16:06:05.765Z,1345737965.765 [Startup] Running Loop=1
2012-08-23T16:06:05.765Z,1345737965.765 [Startup](INFO): Aggregate::initialize Startup
2012-08-23T16:06:05.765Z,1345737965.765 [Startup:A.GoToSurface] Running Loop=1
2012-08-23T16:06:05.765Z,1345737965.765 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:06:05.780Z,1345737965.780 [Startup:StartupSatComms] Running Loop=1
2012-08-23T16:06:05.780Z,1345737965.780 [Startup:StartupSatComms](INFO): Aggregate::initialize Startup:StartupSatComms
2012-08-23T16:06:05.780Z,1345737965.780 [Startup:StartupSatComms:A] Running Loop=1
2012-08-23T16:06:06.217Z,1345737966.217 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-08-23T16:06:06.539Z,1345737966.539 [NAL9602](INFO): Powering up
2012-08-23T16:06:07.327Z,1345737967.327 [NavChartDb](INFO): Charting 9p1
2012-08-23T16:06:08.951Z,1345737968.951 [NavChartDb](INFO): Charting 10p9
2012-08-23T16:06:10.554Z,1345737970.554 [NavChartDb](INFO): Charting 18p2
2012-08-23T16:06:15.048Z,1345737975.048 [NavChartDb](INFO): Charting 36p5
2012-08-23T16:06:17.087Z,1345737977.087 [NAL9602](INFO): NAL9602 initialized
2012-08-23T16:06:18.617Z,1345737978.617 [NavChartDb](INFO): Charting 54p8
2012-08-23T16:06:22.189Z,1345737982.189 [NavChartDb](INFO): Charting 73p1
2012-08-23T16:06:24.817Z,1345737984.817 [NavChartDb](INFO): Charting 91p4
2012-08-23T16:06:26.979Z,1345737986.979 [NavChartDb](INFO): Charting 182p8
2012-08-23T16:06:28.578Z,1345737988.579 [NavChartDb](INFO): Charting 365p7
2012-08-23T16:06:30.178Z,1345737990.178 [NavChartDb](INFO): Charting 548p6
2012-08-23T16:06:32.779Z,1345737992.779 [NavChartDb](INFO): Charting 731p5
2012-08-23T16:06:34.634Z,1345737994.634 [NavChartDb](INFO): Charting 914p4
2012-08-23T16:06:42.158Z,1345738002.158 [NAL9602](IMPORTANT): GPS fix at: 1345737994.00
2012-08-23T16:06:42.185Z,1345738002.185 [Startup:StartupSatComms:A] Stopped
2012-08-23T16:06:42.186Z,1345738002.186 [Startup:StartupSatComms:B] Running Loop=1
2012-08-23T16:06:42.566Z,1345738002.566 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-08-23T16:06:56.241Z,1345738016.241 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=488, MT Status=1, MTMSN=67
2012-08-23T16:06:56.275Z,1345738016.275 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:06:56.275Z,1345738016.275 [NAL9602](INFO): Packets left to send: 7
2012-08-23T16:06:56.278Z,1345738016.278 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0007.sbd
2012-08-23T16:06:56.782Z,1345738016.782 [NAL9602](INFO): Received command:set track.CenterLat 36.811949 degree;set track.CenterLon -121.905548 degree;
2012-08-23T16:06:57.083Z,1345738017.083 [CommandLine](IMPORTANT): got command set 
2012-08-23T16:06:57.083Z,1345738017.083 [CommandLine](FAULT): Incomplete syntax. Try: help set
2012-08-23T16:06:57.415Z,1345738017.415 [CommandLine](IMPORTANT): got command set 
2012-08-23T16:06:57.415Z,1345738017.415 [CommandLine](FAULT): Incomplete syntax. Try: help set
2012-08-23T16:07:15.877Z,1345738035.877 [NAL9602](INFO): SBD MO Status=1, MOMSN=489, MT Status=0, MTMSN=0
2012-08-23T16:07:15.911Z,1345738035.911 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:07:15.911Z,1345738035.911 [NAL9602](INFO): Packets left to send: 6
2012-08-23T16:07:15.912Z,1345738035.912 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0006.sbd
2012-08-23T16:07:23.094Z,1345738043.095 [NavChartDb](INFO): Charting 1097p2
2012-08-23T16:07:26.322Z,1345738046.322 [NavChartDb](INFO): Charting 1280p1
2012-08-23T16:07:29.171Z,1345738049.171 [NAL9602](INFO): SBD MO Status=1, MOMSN=490, MT Status=0, MTMSN=0
2012-08-23T16:07:29.207Z,1345738049.207 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:07:29.207Z,1345738049.207 [NAL9602](INFO): Packets left to send: 5
2012-08-23T16:07:29.208Z,1345738049.208 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0005.sbd
2012-08-23T16:07:29.211Z,1345738049.211 [NavChartDb](INFO): Charting 1463p0
2012-08-23T16:07:31.658Z,1345738051.658 [NavChartDb](INFO): Charting 1645p9
2012-08-23T16:07:33.895Z,1345738053.895 [NavChartDb](INFO): Charting 1828p8
2012-08-23T16:07:42.193Z,1345738062.193 [Startup:StartupSatComms:B](INFO): Timed out from 2012-08-23T16:06:42.2Z
2012-08-23T16:07:42.193Z,1345738062.193 [Startup:StartupSatComms:A_Timeout] Running Loop=1
2012-08-23T16:07:42.194Z,1345738062.194 [Startup:StartupSatComms:A_Timeout](INFO): Aggregate::initialize Startup:StartupSatComms:A_Timeout
2012-08-23T16:07:42.194Z,1345738062.194 [Startup:StartupSatComms:A_Timeout](INFO): Completed Startup:StartupSatComms:A_Timeout
2012-08-23T16:07:42.198Z,1345738062.198 [Startup:StartupSatComms:B] Stopped
2012-08-23T16:07:42.198Z,1345738062.198 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2012-08-23T16:07:42.199Z,1345738062.198 [Startup:StartupSatComms] Stopped
2012-08-23T16:07:42.199Z,1345738062.199 [Startup:StartupSatComms](INFO): Aggregate::uninitialize Startup:StartupSatComms
2012-08-23T16:07:42.200Z,1345738062.200 [Startup](INFO): Completed Startup
2012-08-23T16:07:42.200Z,1345738062.200 [Startup] Stopped
2012-08-23T16:07:42.200Z,1345738062.200 [Startup](INFO): Aggregate::uninitialize Startup
2012-08-23T16:07:42.200Z,1345738062.200 [Startup:A.GoToSurface] Stopped
2012-08-23T16:07:42.200Z,1345738062.200 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:07:42.617Z,1345738062.617 [MissionManager](IMPORTANT): Started mission Default
2012-08-23T16:07:42.617Z,1345738062.617 [Default] Running Loop=1
2012-08-23T16:07:42.617Z,1345738062.617 [Default](INFO): Aggregate::initialize Default
2012-08-23T16:07:42.618Z,1345738062.618 [Default:D.SetSpeed] Running Loop=1
2012-08-23T16:07:42.618Z,1345738062.618 [Default:D.SetSpeed](DEBUG): Initialize.
2012-08-23T16:07:42.618Z,1345738062.618 [Default:E.GoToSurface] Running Loop=1
2012-08-23T16:07:42.618Z,1345738062.618 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:07:42.622Z,1345738062.622 [Default:Iridium] Running Loop=1
2012-08-23T16:07:42.623Z,1345738062.622 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T16:07:42.623Z,1345738062.623 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T16:07:42.623Z,1345738062.623 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:07:42.623Z,1345738062.623 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T16:07:42.623Z,1345738062.623 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:07:42.623Z,1345738062.624 [Default:E.GoToSurface] Running Loop=1
2012-08-23T16:07:42.633Z,1345738062.633 [Default:D.SetSpeed] Running Loop=1
2012-08-23T16:07:42.647Z,1345738062.647 [Default:CallIridium] Running Loop=1
2012-08-23T16:07:42.647Z,1345738062.647 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T16:07:42.647Z,1345738062.647 [Default:CallIridium:A] Running Loop=1
2012-08-23T16:07:42.649Z,1345738062.649 [Default:CallIridium:A] Stopped
2012-08-23T16:07:42.649Z,1345738062.649 [Default:CallIridium:B] Running Loop=1
2012-08-23T16:07:42.649Z,1345738062.649 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T16:07:42.663Z,1345738062.663 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T16:07:42.663Z,1345738062.663 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:07:42.664Z,1345738062.664 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T16:07:42.664Z,1345738062.664 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS] Running Loop=1
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T16:07:42.673Z,1345738062.673 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:07:42.688Z,1345738062.688 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T16:07:42.688Z,1345738062.688 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:07:42.688Z,1345738062.688 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T16:07:42.688Z,1345738062.688 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T16:07:43.003Z,1345738063.003 [Default:Iridium:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-08-23T16:07:43.006Z,1345738063.006 [Default:GPS:Read_GPS](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-08-23T16:07:47.519Z,1345738067.519 [NavChartDb](INFO): Charting 2011p6
2012-08-23T16:07:49.355Z,1345738069.355 [NavChartDb](INFO): Charting 2194p5
2012-08-23T16:07:51.119Z,1345738071.118 [NavChartDb](INFO): Charting 2377p4
2012-08-23T16:07:53.123Z,1345738073.122 [NavChartDb](INFO): Charting 2560p3
2012-08-23T16:07:55.006Z,1345738075.006 [NavChartDb](INFO): Charting 2743p2
2012-08-23T16:07:59.356Z,1345738079.356 [NAL9602](INFO): SBD MO Status=2, MOMSN=491, MT Status=2, MTMSN=0
2012-08-23T16:07:59.357Z,1345738079.357 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T16:08:00.586Z,1345738080.586 [NAL9602](IMPORTANT): GPS fix at: 1345738072.00
2012-08-23T16:08:00.602Z,1345738080.602 [Default:GPS:Read_GPS] Stopped
2012-08-23T16:08:00.602Z,1345738080.602 [Default:GPS:D] Running Loop=1
2012-08-23T16:08:00.998Z,1345738080.998 [Default:GPS:D] Stopped
2012-08-23T16:08:01.002Z,1345738081.002 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T16:08:01.002Z,1345738081.002 [Default:GPS] Stopped
2012-08-23T16:08:01.002Z,1345738081.003 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T16:08:01.003Z,1345738081.003 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T16:08:01.003Z,1345738081.003 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:08:46.228Z,1345738126.228 [NAL9602](INFO): SBD MO Status=2, MOMSN=491, MT Status=0, MTMSN=0
2012-08-23T16:08:46.228Z,1345738126.228 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T16:08:53.893Z,1345738133.893 [NavChartDb](INFO): Charting 2926p0
2012-08-23T16:08:55.635Z,1345738135.635 [NavChartDb](INFO): Charting 3108p9
2012-08-23T16:08:58.146Z,1345738138.146 [NavChartDb](INFO): Charting 3291p8
2012-08-23T16:09:00.382Z,1345738140.382 [NavChartDb](INFO): Charting 3474p7
2012-08-23T16:09:00.602Z,1345738140.602 [NAL9602](INFO): SBD MO Status=1, MOMSN=491, MT Status=0, MTMSN=0
2012-08-23T16:09:00.635Z,1345738140.635 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:09:00.635Z,1345738140.635 [NAL9602](INFO): Packets left to send: 4
2012-08-23T16:09:00.636Z,1345738140.636 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0004.sbd
2012-08-23T16:09:01.982Z,1345738141.982 [NavChartDb](INFO): Charting 3657p6
2012-08-23T16:09:10.423Z,1345738150.423 [NAL9602](INFO): SBD MO Status=2, MOMSN=492, MT Status=2, MTMSN=0
2012-08-23T16:09:10.423Z,1345738150.423 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T16:09:42.964Z,1345738182.964 [NAL9602](INFO): SBD MO Status=2, MOMSN=492, MT Status=2, MTMSN=0
2012-08-23T16:09:42.964Z,1345738182.964 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T16:10:02.312Z,1345738202.312 [NAL9602](INFO): SBD MO Status=1, MOMSN=492, MT Status=0, MTMSN=0
2012-08-23T16:10:02.347Z,1345738202.347 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:10:02.347Z,1345738202.347 [NAL9602](INFO): Packets left to send: 3
2012-08-23T16:10:02.348Z,1345738202.348 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0003.sbd
2012-08-23T16:10:27.288Z,1345738227.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=493, MT Status=0, MTMSN=0
2012-08-23T16:10:27.288Z,1345738227.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T16:10:40.428Z,1345738240.428 [NAL9602](INFO): SBD MO Status=1, MOMSN=493, MT Status=0, MTMSN=0
2012-08-23T16:10:40.463Z,1345738240.463 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:10:40.463Z,1345738240.463 [NAL9602](INFO): Packets left to send: 2
2012-08-23T16:10:40.464Z,1345738240.464 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0002.sbd
2012-08-23T16:10:52.569Z,1345738252.569 [NAL9602](INFO): SBD MO Status=1, MOMSN=494, MT Status=0, MTMSN=0
2012-08-23T16:10:52.607Z,1345738252.607 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:10:52.607Z,1345738252.607 [NAL9602](INFO): Packets left to send: 1
2012-08-23T16:10:52.608Z,1345738252.608 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0001.sbd
2012-08-23T16:11:06.338Z,1345738266.338 [NAL9602](INFO): SBD MO Status=1, MOMSN=495, MT Status=0, MTMSN=0
2012-08-23T16:11:06.371Z,1345738266.371 [NAL9602](INFO): Sent 311 bytes from file Logs/20120823T122007/shore0016.lzma
2012-08-23T16:11:06.371Z,1345738266.371 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:11:06.372Z,1345738266.372 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0016.lzma.parts/0000.sbd
2012-08-23T16:11:17.304Z,1345738277.304 [NAL9602](INFO): SBD MO Status=1, MOMSN=496, MT Status=0, MTMSN=0
2012-08-23T16:11:17.339Z,1345738277.339 [NAL9602](INFO): Sent 222 bytes from file Logs/20120823T122007/shore0017.lzma
2012-08-23T16:11:17.339Z,1345738277.339 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:11:17.341Z,1345738277.341 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T122007/shore0017.lzma.parts/0000.sbd
2012-08-23T16:11:26.577Z,1345738286.577 [NAL9602](INFO): SBD MO Status=1, MOMSN=497, MT Status=0, MTMSN=0
2012-08-23T16:11:26.611Z,1345738286.611 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0000.lzma
2012-08-23T16:11:26.611Z,1345738286.611 [NAL9602](INFO): Packets left to send: 3
2012-08-23T16:11:26.613Z,1345738286.613 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0000.lzma.parts/0003.sbd
2012-08-23T16:11:36.290Z,1345738296.290 [NAL9602](INFO): SBD MO Status=1, MOMSN=498, MT Status=0, MTMSN=0
2012-08-23T16:11:36.323Z,1345738296.323 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0000.lzma
2012-08-23T16:11:36.323Z,1345738296.323 [NAL9602](INFO): Packets left to send: 2
2012-08-23T16:11:36.324Z,1345738296.324 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0000.lzma.parts/0002.sbd
2012-08-23T16:11:49.174Z,1345738309.174 [NAL9602](INFO): SBD MO Status=1, MOMSN=499, MT Status=0, MTMSN=0
2012-08-23T16:11:49.207Z,1345738309.207 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0000.lzma
2012-08-23T16:11:49.207Z,1345738309.207 [NAL9602](INFO): Packets left to send: 1
2012-08-23T16:11:49.208Z,1345738309.208 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0000.lzma.parts/0001.sbd
2012-08-23T16:11:59.797Z,1345738319.797 [NAL9602](INFO): SBD MO Status=1, MOMSN=500, MT Status=0, MTMSN=0
2012-08-23T16:11:59.831Z,1345738319.831 [NAL9602](INFO): Sent 2 bytes from file Logs/20120823T160446/shore0000.lzma
2012-08-23T16:11:59.831Z,1345738319.831 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:11:59.832Z,1345738319.832 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0000.lzma.parts/0000.sbd
2012-08-23T16:12:08.537Z,1345738328.537 [NAL9602](INFO): SBD MO Status=0, MOMSN=501, MT Status=0, MTMSN=0
2012-08-23T16:12:29.291Z,1345738349.291 [NAL9602](INFO): SBD MO Status=1, MOMSN=502, MT Status=0, MTMSN=0
2012-08-23T16:12:29.327Z,1345738349.327 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0001.lzma
2012-08-23T16:12:29.327Z,1345738349.327 [NAL9602](INFO): Packets left to send: 1
2012-08-23T16:12:29.328Z,1345738349.328 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0001.lzma.parts/0001.sbd
2012-08-23T16:12:40.609Z,1345738360.609 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=503, MT Status=1, MTMSN=68
2012-08-23T16:12:40.643Z,1345738360.643 [NAL9602](INFO): Sent 68 bytes from file Logs/20120823T160446/shore0001.lzma
2012-08-23T16:12:40.643Z,1345738360.643 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:12:40.644Z,1345738360.644 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0001.lzma.parts/0000.sbd
2012-08-23T16:12:41.115Z,1345738361.115 [NAL9602](INFO): Received command:set track.CenterLat 36.813021 degree;set track.CenterLon -121.906146 degree;
2012-08-23T16:12:41.440Z,1345738361.440 [CommandLine](IMPORTANT): got command set 
2012-08-23T16:12:41.440Z,1345738361.440 [CommandLine](FAULT): Incomplete syntax. Try: help set
2012-08-23T16:12:41.779Z,1345738361.779 [CommandLine](IMPORTANT): got command set 
2012-08-23T16:12:41.779Z,1345738361.779 [CommandLine](FAULT): Incomplete syntax. Try: help set
2012-08-23T16:12:51.720Z,1345738371.720 [NAL9602](INFO): SBD MO Status=0, MOMSN=504, MT Status=0, MTMSN=0
2012-08-23T16:13:11.353Z,1345738391.353 [NAL9602](INFO): SBD MO Status=1, MOMSN=505, MT Status=0, MTMSN=0
2012-08-23T16:13:11.387Z,1345738391.387 [NAL9602](INFO): Sent 222 bytes from file Logs/20120823T160446/shore0002.lzma
2012-08-23T16:13:11.387Z,1345738391.387 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:13:11.388Z,1345738391.388 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0002.lzma.parts/0000.sbd
2012-08-23T16:13:22.108Z,1345738402.109 [NAL9602](INFO): SBD MO Status=0, MOMSN=506, MT Status=0, MTMSN=0
2012-08-23T16:13:22.167Z,1345738402.167 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T16:13:22.168Z,1345738402.168 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T16:13:22.168Z,1345738402.168 [Default:Iridium] Stopped
2012-08-23T16:13:22.168Z,1345738402.168 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T16:13:22.168Z,1345738402.168 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T16:13:22.168Z,1345738402.168 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:13:22.168Z,1345738402.168 [Default:F.Wait] Running Loop=1
2012-08-23T16:13:22.170Z,1345738402.170 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium:B] Stopped
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium] Stopped
2012-08-23T16:13:22.556Z,1345738402.556 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T16:13:32.640Z,1345738412.640 [NAL9602](INFO): Powering down
2012-08-23T16:18:22.675Z,1345738702.675 [Default:CallIridium] Running Loop=1
2012-08-23T16:18:22.676Z,1345738702.676 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T16:18:22.676Z,1345738702.676 [Default:CallIridium:A] Running Loop=1
2012-08-23T16:18:22.676Z,1345738702.676 [Default:CallIridium:A] Stopped
2012-08-23T16:18:22.676Z,1345738702.676 [Default:CallIridium:B] Running Loop=1
2012-08-23T16:18:22.677Z,1345738702.677 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium] Running Loop=1
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T16:18:27.724Z,1345738707.724 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:18:27.725Z,1345738707.725 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T16:18:27.725Z,1345738707.725 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:18:27.725Z,1345738707.725 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS] Running Loop=1
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T16:18:27.726Z,1345738707.726 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:18:27.727Z,1345738707.727 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T16:18:27.727Z,1345738707.727 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:18:27.727Z,1345738707.727 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T16:18:28.306Z,1345738708.306 [NAL9602](INFO): Powering up
2012-08-23T16:18:38.831Z,1345738718.831 [NAL9602](INFO): NAL9602 initialized
2012-08-23T16:19:04.221Z,1345738744.221 [NAL9602](INFO): SBD MO Status=1, MOMSN=507, MT Status=0, MTMSN=0
2012-08-23T16:19:04.255Z,1345738744.255 [NAL9602](INFO): Sent 110 bytes from file Logs/20120823T160446/shore0003.lzma
2012-08-23T16:19:04.255Z,1345738744.255 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:19:04.257Z,1345738744.257 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0003.lzma.parts/0000.sbd
2012-08-23T16:19:17.418Z,1345738757.418 [NAL9602](INFO): SBD MO Status=0, MOMSN=508, MT Status=0, MTMSN=0
2012-08-23T16:19:17.467Z,1345738757.467 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T16:19:17.467Z,1345738757.467 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T16:19:17.467Z,1345738757.467 [Default:Iridium] Stopped
2012-08-23T16:19:17.468Z,1345738757.468 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T16:19:17.468Z,1345738757.468 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T16:19:17.468Z,1345738757.468 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:19:17.872Z,1345738757.872 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T16:19:17.872Z,1345738757.872 [Default:CallIridium:B] Stopped
2012-08-23T16:19:17.873Z,1345738757.872 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T16:19:17.873Z,1345738757.873 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T16:19:17.873Z,1345738757.873 [Default:CallIridium] Stopped
2012-08-23T16:19:17.873Z,1345738757.873 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T16:19:18.678Z,1345738758.678 [NAL9602](IMPORTANT): GPS fix at: 1345738751.00
2012-08-23T16:19:18.824Z,1345738758.824 [Default:GPS:Read_GPS] Stopped
2012-08-23T16:19:18.825Z,1345738758.825 [Default:GPS:D] Running Loop=1
2012-08-23T16:19:19.059Z,1345738759.059 [Default:GPS:D] Stopped
2012-08-23T16:19:19.060Z,1345738759.060 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T16:19:19.060Z,1345738759.060 [Default:GPS] Stopped
2012-08-23T16:19:19.060Z,1345738759.060 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T16:19:19.060Z,1345738759.060 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T16:19:19.060Z,1345738759.060 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:19:39.561Z,1345738779.561 [NAL9602](INFO): Powering down
2012-08-23T16:24:19.581Z,1345739059.581 [Default:CallIridium] Running Loop=1
2012-08-23T16:24:19.581Z,1345739059.581 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T16:24:19.581Z,1345739059.581 [Default:CallIridium:A] Running Loop=1
2012-08-23T16:24:19.581Z,1345739059.582 [Default:CallIridium:A] Stopped
2012-08-23T16:24:19.582Z,1345739059.582 [Default:CallIridium:B] Running Loop=1
2012-08-23T16:24:19.582Z,1345739059.582 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T16:24:24.598Z,1345739064.598 [Default:Iridium] Running Loop=1
2012-08-23T16:24:24.598Z,1345739064.598 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T16:24:24.598Z,1345739064.598 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T16:24:24.598Z,1345739064.598 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:24:24.599Z,1345739064.599 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T16:24:24.599Z,1345739064.599 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:24:24.600Z,1345739064.599 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T16:24:24.600Z,1345739064.600 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:24:24.600Z,1345739064.600 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T16:24:24.600Z,1345739064.600 [Default:GPS] Running Loop=1
2012-08-23T16:24:24.600Z,1345739064.600 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T16:24:24.600Z,1345739064.600 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T16:24:24.600Z,1345739064.600 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:24:24.601Z,1345739064.601 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T16:24:24.601Z,1345739064.601 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:24:24.601Z,1345739064.602 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T16:24:24.602Z,1345739064.602 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:24:24.602Z,1345739064.602 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T16:24:25.215Z,1345739065.215 [NAL9602](INFO): Powering up
2012-08-23T16:24:35.831Z,1345739075.831 [NAL9602](INFO): NAL9602 initialized
2012-08-23T16:24:52.749Z,1345739092.749 [NAL9602](INFO): SBD MO Status=1, MOMSN=509, MT Status=0, MTMSN=0
2012-08-23T16:24:52.794Z,1345739092.794 [NAL9602](INFO): Sent 172 bytes from file Logs/20120823T160446/shore0004.lzma
2012-08-23T16:24:52.794Z,1345739092.794 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:24:52.796Z,1345739092.796 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0004.lzma.parts/0000.sbd
2012-08-23T16:25:00.750Z,1345739100.750 [NAL9602](INFO): SBD MO Status=0, MOMSN=510, MT Status=0, MTMSN=0
2012-08-23T16:25:00.799Z,1345739100.799 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T16:25:00.799Z,1345739100.799 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T16:25:00.800Z,1345739100.800 [Default:Iridium] Stopped
2012-08-23T16:25:00.800Z,1345739100.800 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T16:25:00.800Z,1345739100.800 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T16:25:00.800Z,1345739100.800 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium:B] Stopped
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium] Stopped
2012-08-23T16:25:01.163Z,1345739101.163 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T16:25:01.953Z,1345739101.953 [NAL9602](IMPORTANT): GPS fix at: 1345739095.00
2012-08-23T16:25:01.973Z,1345739101.973 [Default:GPS:Read_GPS] Stopped
2012-08-23T16:25:01.974Z,1345739101.974 [Default:GPS:D] Running Loop=1
2012-08-23T16:25:02.372Z,1345739102.372 [Default:GPS:D] Stopped
2012-08-23T16:25:02.372Z,1345739102.372 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T16:25:02.372Z,1345739102.372 [Default:GPS] Stopped
2012-08-23T16:25:02.372Z,1345739102.372 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T16:25:02.373Z,1345739102.372 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T16:25:02.373Z,1345739102.373 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:25:22.900Z,1345739122.899 [NAL9602](INFO): Powering down
2012-08-23T16:30:02.980Z,1345739402.980 [Default:CallIridium] Running Loop=1
2012-08-23T16:30:02.980Z,1345739402.980 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T16:30:02.980Z,1345739402.980 [Default:CallIridium:A] Running Loop=1
2012-08-23T16:30:02.980Z,1345739402.980 [Default:CallIridium:A] Stopped
2012-08-23T16:30:02.980Z,1345739402.980 [Default:CallIridium:B] Running Loop=1
2012-08-23T16:30:02.981Z,1345739402.981 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T16:30:08.103Z,1345739408.103 [Default:Iridium] Running Loop=1
2012-08-23T16:30:08.104Z,1345739408.104 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T16:30:08.104Z,1345739408.104 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T16:30:08.104Z,1345739408.104 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:30:08.104Z,1345739408.104 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T16:30:08.104Z,1345739408.104 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:30:08.105Z,1345739408.105 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T16:30:08.105Z,1345739408.105 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:30:08.105Z,1345739408.105 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T16:30:08.105Z,1345739408.105 [Default:GPS] Running Loop=1
2012-08-23T16:30:08.106Z,1345739408.106 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T16:30:08.106Z,1345739408.106 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T16:30:08.106Z,1345739408.106 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:30:08.106Z,1345739408.106 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T16:30:08.118Z,1345739408.118 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:30:08.119Z,1345739408.119 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T16:30:08.119Z,1345739408.119 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:30:08.120Z,1345739408.120 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T16:30:08.732Z,1345739408.732 [NAL9602](INFO): Powering up
2012-08-23T16:30:19.775Z,1345739419.775 [NAL9602](INFO): NAL9602 initialized
2012-08-23T16:30:35.054Z,1345739435.054 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=511, MT Status=1, MTMSN=69
2012-08-23T16:30:35.099Z,1345739435.099 [NAL9602](INFO): Sent 171 bytes from file Logs/20120823T160446/shore0005.lzma
2012-08-23T16:30:35.099Z,1345739435.099 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:30:35.100Z,1345739435.100 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0005.lzma.parts/0000.sbd
2012-08-23T16:30:35.671Z,1345739435.671 [NAL9602](INFO): Received command:configset VerticalControl.buoyancyNeutral 89 cc;configset VerticalControl.massDefault -1 cm;configset CBIT.pressureThreshold 0.75 pound_per_square_inch
2012-08-23T16:30:35.696Z,1345739435.696 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 89.000000 cubic_centimeter
2012-08-23T16:30:35.720Z,1345739435.720 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault -1.000000 centimeter
2012-08-23T16:30:35.757Z,1345739435.757 [CommandLine](IMPORTANT): got command configSet CBIT.pressureThreshold 0.750000 pound_per_square_inch
2012-08-23T16:30:46.445Z,1345739446.445 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=512, MT Status=1, MTMSN=70
2012-08-23T16:30:46.960Z,1345739446.960 [NAL9602](INFO): Received command:run Transport/transit_3km.xml
2012-08-23T16:30:47.059Z,1345739447.059 [CommandLine](IMPORTANT): got command run ./Missions/Transport/transit_3km.xml
2012-08-23T16:30:47.059Z,1345739447.059 [MissionManager](INFO): Loading Mission: ./Missions/Transport/transit_3km.xml
2012-08-23T16:30:47.072Z,1345739447.072 [MissionManager](INFO): Inserting Stack: Missions/Transport/transit.xml
2012-08-23T16:30:47.238Z,1345739447.238 [MissionManager](INFO): DefineArg transit_3km:transit.Depth = 10.000000 m
2012-08-23T16:30:47.241Z,1345739447.241 [MissionManager](INFO): DefineArg transit_3km:transit.MaxDepth = 20.000000 m
2012-08-23T16:30:47.257Z,1345739447.257 [MissionManager](INFO): DefineArg transit_3km:transit.Wpt1Lat = nan arcdeg
2012-08-23T16:30:47.260Z,1345739447.260 [MissionManager](INFO): DefineArg transit_3km:transit.Wpt1Lon = nan arcdeg
2012-08-23T16:30:47.277Z,1345739447.277 [MissionManager](INFO): DefineArg transit_3km:transit.Northings = 0.000000 m
2012-08-23T16:30:47.288Z,1345739447.288 [MissionManager](INFO): DefineArg transit_3km:transit.Eastings = 0.000000 m
2012-08-23T16:30:47.297Z,1345739447.297 [MissionManager](INFO): DefineArg transit_3km:transit.Speed = 1.000000 m/s
2012-08-23T16:30:47.300Z,1345739447.300 [MissionManager](INFO): DefineArg transit_3km:transit.MassHold = 1 bool
2012-08-23T16:30:47.315Z,1345739447.315 [MissionManager](INFO): DefineArg transit_3km:transit.BuoyancyHold = 1 bool
2012-08-23T16:30:47.319Z,1345739447.319 [MissionManager](INFO): DefineArg transit_3km:transit.BuoyancyNeutral = 0.000089 n/a
2012-08-23T16:30:47.335Z,1345739447.335 [MissionManager](INFO): DefineArg transit_3km:transit.MassDefault = -0.010000 n/a
2012-08-23T16:30:47.338Z,1345739447.338 [MissionManager](INFO): DefineArg transit_3km:transit.MinOffshore = 1.000000 km
2012-08-23T16:30:47.341Z,1345739447.341 [MissionManager](INFO): DefineArg transit_3km:transit.NeedCommsTime = 30.000000 min
2012-08-23T16:30:47.356Z,1345739447.356 [MissionManager](INFO): DefineArg transit_3km:transit.MinAltitude = 7.000000 m
2012-08-23T16:30:47.359Z,1345739447.359 [MissionManager](INFO): DefineArg transit_3km:transit.TimeoutDuration = 240.000000 min
2012-08-23T16:30:47.361Z,1345739447.361 [transit_3km:transit:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2012-08-23T16:30:47.381Z,1345739447.381 [transit_3km:transit:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2012-08-23T16:30:47.415Z,1345739447.415 [transit_3km:transit:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2012-08-23T16:30:47.434Z,1345739447.434 [transit_3km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Construct GoToSurface.
2012-08-23T16:30:47.440Z,1345739447.440 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Construct.
2012-08-23T16:30:47.475Z,1345739447.475 [transit_3km:transit:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy.
2012-08-23T16:30:47.479Z,1345739447.480 [transit_3km:transit:MassHold.Pitch](DEBUG): Construct.
2012-08-23T16:30:47.498Z,1345739447.498 [transit_3km:transit:WaypointOne:A.Pitch](DEBUG): Construct.
2012-08-23T16:30:47.520Z,1345739447.520 [transit_3km:transit:WaypointOne:B.SetSpeed](DEBUG): Construct.
2012-08-23T16:30:47.531Z,1345739447.531 [transit_3km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Construct Waypoint.
2012-08-23T16:30:47.553Z,1345739447.553 [MissionManager](INFO): RedefineArg transit_3km:transit.Wpt1Lat = 36.806966 arcdeg
2012-08-23T16:30:47.559Z,1345739447.559 [MissionManager](INFO): RedefineArg transit_3km:transit.Wpt1Lon = -121.824326 arcdeg
2012-08-23T16:30:47.587Z,1345739447.587 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="utf-8"?>
<Mission xmlns="Tethys"
	xmlns:Units="Tethys/Units"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="Tethys http://aosn.mbari.org/tethys/Xml/Tethys.xsd
	                    Tethys/Units http://aosn.mbari.org/tethys/Xml/Units.xsd"
    Id="transit_3km">

    <Description>
        Vehicle transits to the 3km waypoint and can be commanded to use/hold
        mass or buoyancy.
    </Description>

    <Insert Filename="Transport/transit.xml">
        <RedefineArg Name="Wpt1Lat"><Units:degree /><Value>36.806966</Value></RedefineArg>
        <RedefineArg Name="Wpt1Lon"><Units:degree /><Value>-121.824326</Value></RedefineArg>
    </Insert>

</Mission>


2012-08-23T16:30:47.587Z,1345739447.588 [CommandLine](IMPORTANT): Running ./Missions/Transport/transit_3km.xml
2012-08-23T16:30:48.079Z,1345739448.079 [Default] Stopped
2012-08-23T16:30:48.079Z,1345739448.079 [Default](INFO): Aggregate::uninitialize Default
2012-08-23T16:30:48.079Z,1345739448.079 [Default:GPS] Stopped
2012-08-23T16:30:48.079Z,1345739448.079 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T16:30:48.079Z,1345739448.079 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T16:30:48.079Z,1345739448.079 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:30:48.079Z,1345739448.079 [Default:GPS:Read_GPS] Stopped
2012-08-23T16:30:48.079Z,1345739448.079 [Default:Iridium] Stopped
2012-08-23T16:30:48.079Z,1345739448.079 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T16:30:48.079Z,1345739448.079 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:30:48.080Z,1345739448.080 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:CallIridium] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T16:30:48.080Z,1345739448.080 [Default:CallIridium:B] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T16:30:48.080Z,1345739448.080 [Default:D.SetSpeed] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:D.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:30:48.080Z,1345739448.080 [Default:E.GoToSurface] Stopped
2012-08-23T16:30:48.080Z,1345739448.080 [Default:E.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:30:48.080Z,1345739448.080 [Default:F.Wait] Stopped
2012-08-23T16:30:48.081Z,1345739448.081 [Default:F.Wait](DEBUG): Uninitialize Wait Component.
2012-08-23T16:30:48.081Z,1345739448.081 [MissionManager](IMPORTANT): Started mission transit_3km
2012-08-23T16:30:48.081Z,1345739448.081 [transit_3km] Running Loop=1
2012-08-23T16:30:48.081Z,1345739448.081 [transit_3km](INFO): Aggregate::initialize transit_3km
2012-08-23T16:30:48.081Z,1345739448.081 [transit_3km:transit] Running Loop=1
2012-08-23T16:30:48.082Z,1345739448.082 [transit_3km:transit](INFO): Aggregate::initialize transit_3km:transit
2012-08-23T16:30:48.082Z,1345739448.082 [transit_3km:transit:A.AltitudeEnvelope] Running Loop=1
2012-08-23T16:30:48.082Z,1345739448.082 [transit_3km:transit:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2012-08-23T16:30:48.082Z,1345739448.082 [transit_3km:transit:B.DepthEnvelope] Running Loop=1
2012-08-23T16:30:48.086Z,1345739448.086 [transit_3km:transit:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2012-08-23T16:30:48.087Z,1345739448.088 [transit_3km:transit:C.OffshoreEnvelope] Running Loop=1
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:BuoyancyHold.Buoyancy] Running Loop=1
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component.
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:MassHold.Pitch] Running Loop=1
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:MassHold.Pitch](DEBUG): Initialize.
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:SURFACECOMMS] Running Loop=1
2012-08-23T16:30:48.088Z,1345739448.088 [transit_3km:transit:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:transit:SURFACECOMMS
2012-08-23T16:30:48.089Z,1345739448.089 [transit_3km:transit:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-08-23T16:30:48.089Z,1345739448.089 [transit_3km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T16:30:48.089Z,1345739448.089 [transit_3km:transit:MassHold.Pitch] Running Loop=1
2012-08-23T16:30:48.110Z,1345739448.110 [transit_3km:transit:BuoyancyHold.Buoyancy] Running Loop=1
2012-08-23T16:30:48.130Z,1345739448.129 [transit_3km:transit:SURFACECOMMS:B] Running Loop=1
2012-08-23T16:30:48.130Z,1345739448.130 [transit_3km:transit:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:transit:SURFACECOMMS:B
2012-08-23T16:30:48.130Z,1345739448.130 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-08-23T16:30:48.130Z,1345739448.130 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-08-23T16:30:48.134Z,1345739448.134 [transit_3km:transit:SURFACECOMMS:B:B] Running Loop=1
2012-08-23T16:30:48.134Z,1345739448.135 [transit_3km:transit:C.OffshoreEnvelope] Running Loop=1
2012-08-23T16:30:48.144Z,1345739448.144 [transit_3km:transit:B.DepthEnvelope] Running Loop=1
2012-08-23T16:30:48.154Z,1345739448.154 [transit_3km:transit:A.AltitudeEnvelope] Running Loop=1
2012-08-23T16:30:48.482Z,1345739448.482 [NAL9602](IMPORTANT): GPS fix at: 1345739442.00
2012-08-23T16:30:48.514Z,1345739448.514 [transit_3km:transit:MassHold.Pitch] Preempted
2012-08-23T16:30:48.514Z,1345739448.514 [transit_3km:transit:BuoyancyHold.Buoyancy] Preempted
2012-08-23T16:30:48.515Z,1345739448.515 [transit_3km:transit:SURFACECOMMS:B:B](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-08-23T16:30:48.517Z,1345739448.517 [transit_3km:transit:SURFACECOMMS:B:B] Stopped
2012-08-23T16:30:48.517Z,1345739448.517 [transit_3km:transit:SURFACECOMMS:B:C] Running Loop=1
2012-08-23T16:30:48.517Z,1345739448.517 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-08-23T16:30:48.894Z,1345739448.894 [transit_3km:transit:SURFACECOMMS:B:C](DEBUG): Initialize ReadDataComponent to sense platform_communications
2012-08-23T16:30:55.120Z,1345739455.120 [NAL9602](INFO): SBD MO Status=0, MOMSN=513, MT Status=0, MTMSN=0
2012-08-23T16:31:15.547Z,1345739475.547 [NAL9602](INFO): SBD MO Status=1, MOMSN=514, MT Status=0, MTMSN=0
2012-08-23T16:31:15.583Z,1345739475.583 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0006.lzma
2012-08-23T16:31:15.583Z,1345739475.583 [NAL9602](INFO): Packets left to send: 1
2012-08-23T16:31:15.584Z,1345739475.584 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0006.lzma.parts/0001.sbd
2012-08-23T16:31:25.956Z,1345739485.955 [NAL9602](INFO): SBD MO Status=1, MOMSN=515, MT Status=0, MTMSN=0
2012-08-23T16:31:25.991Z,1345739485.991 [NAL9602](INFO): Sent 102 bytes from file Logs/20120823T160446/shore0006.lzma
2012-08-23T16:31:25.991Z,1345739485.991 [NAL9602](INFO): Packets left to send: 0
2012-08-23T16:31:25.992Z,1345739485.992 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0006.lzma.parts/0000.sbd
2012-08-23T16:31:37.160Z,1345739497.160 [NAL9602](INFO): SBD MO Status=0, MOMSN=516, MT Status=0, MTMSN=0
2012-08-23T16:31:37.209Z,1345739497.210 [transit_3km:transit:SURFACECOMMS:B:C] Stopped
2012-08-23T16:31:37.210Z,1345739497.210 [transit_3km:transit:SURFACECOMMS:B:D] Running Loop=1
2012-08-23T16:31:37.569Z,1345739497.569 [transit_3km:transit:SURFACECOMMS:B:D](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2012-08-23T16:31:39.586Z,1345739499.586 [NAL9602](IMPORTANT): GPS fix at: 1345739493.00
2012-08-23T16:31:39.695Z,1345739499.695 [transit_3km:transit:SURFACECOMMS:B:D] Stopped
2012-08-23T16:31:39.696Z,1345739499.696 [transit_3km:transit:SURFACECOMMS:B](INFO): Completed transit_3km:transit:SURFACECOMMS:B
2012-08-23T16:31:39.696Z,1345739499.696 [transit_3km:transit:SURFACECOMMS:B] Stopped
2012-08-23T16:31:39.696Z,1345739499.696 [transit_3km:transit:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:transit:SURFACECOMMS:B
2012-08-23T16:31:39.696Z,1345739499.696 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-08-23T16:31:39.696Z,1345739499.696 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T16:31:39.697Z,1345739499.697 [transit_3km:transit:SURFACECOMMS](INFO): Completed transit_3km:transit:SURFACECOMMS
2012-08-23T16:31:39.697Z,1345739499.697 [transit_3km:transit:SURFACECOMMS] Stopped
2012-08-23T16:31:39.697Z,1345739499.697 [transit_3km:transit:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:transit:SURFACECOMMS
2012-08-23T16:31:39.697Z,1345739499.697 [transit_3km:transit:SURFACECOMMS:A.GoToSurface] Stopped
2012-08-23T16:31:39.697Z,1345739499.697 [transit_3km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne] Running Loop=1
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne](INFO): Aggregate::initialize transit_3km:transit:WaypointOne
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne:A.Pitch] Running Loop=1
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne:A.Pitch](DEBUG): Initialize.
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne:B.SetSpeed] Running Loop=1
2012-08-23T16:31:39.698Z,1345739499.698 [transit_3km:transit:WaypointOne:B.SetSpeed](DEBUG): Initialize.
2012-08-23T16:31:39.699Z,1345739499.699 [transit_3km:transit:WaypointOne:WaypointW1.Waypoint] Running Loop=1
2012-08-23T16:31:39.699Z,1345739499.699 [transit_3km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Initialize WaypointComponent.
2012-08-23T16:31:40.008Z,1345739500.008 [transit_3km:transit:WaypointOne:B.SetSpeed] Running Loop=1
2012-08-23T16:31:40.017Z,1345739500.017 [transit_3km:transit:WaypointOne:A.Pitch] Running Loop=1
2012-08-23T16:31:40.030Z,1345739500.030 [transit_3km:transit:MassHold.Pitch] Running Loop=1
2012-08-23T16:31:40.031Z,1345739500.031 [transit_3km:transit:BuoyancyHold.Buoyancy] Running Loop=1
2012-08-23T16:31:41.330Z,1345739501.330 [ThrusterServo](FAULT): getVelocity uart error serial timeout
2012-08-23T16:31:41.331Z,1345739501.330 [ThrusterServo](FAULT): Thruster uart error: serial timeout
2012-08-23T16:31:41.331Z,1345739501.331 [ThrusterServo] Communications Fault, FailCount= 1
2012-08-23T16:31:41.331Z,1345739501.331 [ThrusterServo](ERROR): Communications Fault
2012-08-23T16:31:41.333Z,1345739501.333 [CBIT](ERROR): Communications Fault in component: ThrusterServo
2012-08-23T16:31:41.624Z,1345739501.624 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2012-08-23T16:31:41.624Z,1345739501.624 [ThrusterServo](INFO): Powering down
2012-08-23T16:31:41.627Z,1345739501.627 [CBIT](INFO): Clearing failed state for component ThrusterServo
2012-08-23T16:31:41.627Z,1345739501.627 [ThrusterServo] No Fault, FailCount= 1
2012-08-23T16:31:42.371Z,1345739502.371 [ThrusterServo](DEBUG): Initializing EZServoServo.
2012-08-23T16:31:42.491Z,1345739502.491 [ThrusterServo](DEBUG): Initialization error opening port: port not yet opened
2012-08-23T16:31:42.491Z,1345739502.491 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2012-08-23T16:31:46.622Z,1345739506.622 [NAL9602](INFO): Powering down
2012-08-23T16:32:07.491Z,1345739527.491 [Radio_Freewave](INFO): Powering down
2012-08-23T16:32:42.735Z,1345739562.735 [Radio_Freewave](INFO): Powering up
2012-08-23T16:34:27.097Z,1345739667.097 [Radio_Freewave](INFO): Powering down
2012-08-23T16:36:10.414Z,1345739770.414 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:12.814Z,1345739772.814 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:15.213Z,1345739775.213 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:17.613Z,1345739777.613 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:20.014Z,1345739780.013 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:22.433Z,1345739782.433 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:24.814Z,1345739784.814 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:27.213Z,1345739787.213 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:29.663Z,1345739789.663 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:32.013Z,1345739792.013 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:34.527Z,1345739794.527 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:37.229Z,1345739797.229 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:39.664Z,1345739799.664 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:42.012Z,1345739802.012 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:44.416Z,1345739804.416 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:46.812Z,1345739806.812 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:49.212Z,1345739809.212 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:51.651Z,1345739811.651 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:54.011Z,1345739814.011 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:56.412Z,1345739816.411 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:36:58.813Z,1345739818.813 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:01.215Z,1345739821.216 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:03.612Z,1345739823.612 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:06.013Z,1345739826.013 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:08.812Z,1345739828.812 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:11.216Z,1345739831.216 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:13.653Z,1345739833.653 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:15.724Z,1345739835.724 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:18.415Z,1345739838.415 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:20.964Z,1345739840.964 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:23.238Z,1345739843.238 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:25.719Z,1345739845.719 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T16:37:28.090Z,1345739848.090 [Batt_Ocean_Server](INFO): Bus busy reported for battery bank#8 STATUS: 65535
2012-08-23T17:01:39.799Z,1345741299.799 [transit_3km:transit:NeedComms] Running Loop=1
2012-08-23T17:01:39.799Z,1345741299.799 [transit_3km:transit:NeedComms](INFO): Aggregate::initialize transit_3km:transit:NeedComms
2012-08-23T17:01:39.799Z,1345741299.799 [transit_3km:transit:NeedComms:NEEDCOMMS] Running Loop=1
2012-08-23T17:01:39.800Z,1345741299.800 [transit_3km:transit:NeedComms:NEEDCOMMS](INFO): Aggregate::initialize transit_3km:transit:NeedComms:NEEDCOMMS
2012-08-23T17:01:40.174Z,1345741300.174 [transit_3km:transit:SURFACECOMMS] Running Loop=1
2012-08-23T17:01:40.174Z,1345741300.174 [transit_3km:transit:SURFACECOMMS](INFO): Aggregate::initialize transit_3km:transit:SURFACECOMMS
2012-08-23T17:01:40.174Z,1345741300.174 [transit_3km:transit:SURFACECOMMS:A.GoToSurface] Running Loop=1
2012-08-23T17:01:40.174Z,1345741300.174 [transit_3km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:04:59.250Z,1345741499.250 [Radio_Freewave](INFO): Powering up
2012-08-23T17:04:59.263Z,1345741499.263 [transit_3km:transit:SURFACECOMMS:B] Running Loop=1
2012-08-23T17:04:59.263Z,1345741499.263 [transit_3km:transit:SURFACECOMMS:B](INFO): Aggregate::initialize transit_3km:transit:SURFACECOMMS:B
2012-08-23T17:04:59.263Z,1345741499.263 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed] Running Loop=1
2012-08-23T17:04:59.263Z,1345741499.263 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:04:59.263Z,1345741499.263 [transit_3km:transit:SURFACECOMMS:B:B] Running Loop=1
2012-08-23T17:04:59.660Z,1345741499.660 [transit_3km:transit:MassHold.Pitch] Preempted
2012-08-23T17:04:59.660Z,1345741499.660 [transit_3km:transit:BuoyancyHold.Buoyancy] Preempted
2012-08-23T17:05:00.045Z,1345741500.045 [NAL9602](INFO): Powering up
2012-08-23T17:05:10.979Z,1345741510.978 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:05:35.614Z,1345741535.614 [NAL9602](IMPORTANT): GPS fix at: 1345741532.00
2012-08-23T17:05:35.629Z,1345741535.629 [Navigation](IMPORTANT): Error 6.9 %DT at bearing -169.2 deg., over the last 1891.9 m.
2012-08-23T17:05:35.630Z,1345741535.630 [transit_3km:transit:SURFACECOMMS:B:B] Stopped
2012-08-23T17:05:35.631Z,1345741535.631 [transit_3km:transit:SURFACECOMMS:B:C] Running Loop=1
2012-08-23T17:05:56.019Z,1345741556.019 [NAL9602](INFO): SBD MO Status=1, MOMSN=517, MT Status=0, MTMSN=0
2012-08-23T17:05:56.051Z,1345741556.051 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0007.lzma
2012-08-23T17:05:56.051Z,1345741556.051 [NAL9602](INFO): Packets left to send: 3
2012-08-23T17:05:56.052Z,1345741556.052 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0007.lzma.parts/0003.sbd
2012-08-23T17:06:04.517Z,1345741564.517 [NAL9602](INFO): SBD MO Status=2, MOMSN=518, MT Status=2, MTMSN=0
2012-08-23T17:06:04.517Z,1345741564.517 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T17:06:18.117Z,1345741578.117 [NAL9602](INFO): SBD MO Status=1, MOMSN=518, MT Status=0, MTMSN=0
2012-08-23T17:06:18.151Z,1345741578.151 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0007.lzma
2012-08-23T17:06:18.151Z,1345741578.151 [NAL9602](INFO): Packets left to send: 2
2012-08-23T17:06:18.152Z,1345741578.152 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0007.lzma.parts/0002.sbd
2012-08-23T17:06:28.253Z,1345741588.253 [NAL9602](INFO): SBD MO Status=1, MOMSN=519, MT Status=0, MTMSN=0
2012-08-23T17:06:28.287Z,1345741588.287 [NAL9602](INFO): Sent 332 bytes from file Logs/20120823T160446/shore0007.lzma
2012-08-23T17:06:28.287Z,1345741588.287 [NAL9602](INFO): Packets left to send: 1
2012-08-23T17:06:28.288Z,1345741588.288 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0007.lzma.parts/0001.sbd
2012-08-23T17:06:35.865Z,1345741595.865 [NAL9602](INFO): SBD MO Status=1, MOMSN=520, MT Status=0, MTMSN=0
2012-08-23T17:06:35.919Z,1345741595.919 [NAL9602](INFO): Sent 85 bytes from file Logs/20120823T160446/shore0007.lzma
2012-08-23T17:06:35.919Z,1345741595.919 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:06:35.920Z,1345741595.920 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0007.lzma.parts/0000.sbd
2012-08-23T17:06:43.594Z,1345741603.593 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=521, MT Status=1, MTMSN=71
2012-08-23T17:06:44.043Z,1345741604.043 [NAL9602](INFO): Received command:Stop
2012-08-23T17:06:44.106Z,1345741604.106 [CommandLine](IMPORTANT): got command stop
2012-08-23T17:06:44.112Z,1345741604.112 [transit_3km] Stopped
2012-08-23T17:06:44.112Z,1345741604.112 [transit_3km](INFO): Aggregate::uninitialize transit_3km
2012-08-23T17:06:44.112Z,1345741604.112 [transit_3km:transit] Stopped
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit](INFO): Aggregate::uninitialize transit_3km:transit
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:A.AltitudeEnvelope] Stopped
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:B.DepthEnvelope] Stopped
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:B.DepthEnvelope](DEBUG): Uninitialize.
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:C.OffshoreEnvelope] Stopped
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:SURFACECOMMS] Stopped
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:SURFACECOMMS](INFO): Aggregate::uninitialize transit_3km:transit:SURFACECOMMS
2012-08-23T17:06:44.113Z,1345741604.113 [transit_3km:transit:SURFACECOMMS:A.GoToSurface] Stopped
2012-08-23T17:06:44.113Z,1345741604.114 [transit_3km:transit:SURFACECOMMS:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:06:44.114Z,1345741604.114 [transit_3km:transit:SURFACECOMMS:B] Stopped
2012-08-23T17:06:44.114Z,1345741604.114 [transit_3km:transit:SURFACECOMMS:B](INFO): Aggregate::uninitialize transit_3km:transit:SURFACECOMMS:B
2012-08-23T17:06:44.114Z,1345741604.114 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed] Stopped
2012-08-23T17:06:44.114Z,1345741604.114 [transit_3km:transit:SURFACECOMMS:B:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:06:44.118Z,1345741604.118 [transit_3km:transit:SURFACECOMMS:B:C] Stopped
2012-08-23T17:06:44.118Z,1345741604.118 [transit_3km:transit:NeedComms] Stopped
2012-08-23T17:06:44.118Z,1345741604.118 [transit_3km:transit:NeedComms](INFO): Aggregate::uninitialize transit_3km:transit:NeedComms
2012-08-23T17:06:44.119Z,1345741604.118 [transit_3km:transit:NeedComms:NEEDCOMMS] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:NeedComms:NEEDCOMMS](INFO): Aggregate::uninitialize transit_3km:transit:NeedComms:NEEDCOMMS
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:BuoyancyHold.Buoyancy] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:MassHold.Pitch] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne](INFO): Aggregate::uninitialize transit_3km:transit:WaypointOne
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne:A.Pitch] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne:B.SetSpeed] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne:B.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne:WaypointW1.Waypoint] Stopped
2012-08-23T17:06:44.119Z,1345741604.119 [transit_3km:transit:WaypointOne:WaypointW1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2012-08-23T17:06:44.412Z,1345741604.412 [MissionManager](IMPORTANT): Started mission Default
2012-08-23T17:06:44.412Z,1345741604.412 [Default] Running Loop=1
2012-08-23T17:06:44.412Z,1345741604.412 [Default](INFO): Aggregate::initialize Default
2012-08-23T17:06:44.412Z,1345741604.412 [Default:D.SetSpeed] Running Loop=1
2012-08-23T17:06:44.412Z,1345741604.412 [Default:D.SetSpeed](DEBUG): Initialize.
2012-08-23T17:06:44.412Z,1345741604.412 [Default:E.GoToSurface] Running Loop=1
2012-08-23T17:06:44.413Z,1345741604.413 [Default:E.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium] Running Loop=1
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:06:44.413Z,1345741604.413 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:06:44.415Z,1345741604.415 [Default:CallIridium] Running Loop=1
2012-08-23T17:06:44.415Z,1345741604.415 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:06:44.415Z,1345741604.415 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:06:44.416Z,1345741604.416 [Default:CallIridium:A] Stopped
2012-08-23T17:06:44.416Z,1345741604.416 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:06:44.416Z,1345741604.416 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:06:44.417Z,1345741604.417 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:06:44.417Z,1345741604.417 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:06:44.417Z,1345741604.417 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:06:44.417Z,1345741604.417 [Default:GPS] Running Loop=1
2012-08-23T17:06:44.417Z,1345741604.417 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:06:44.417Z,1345741604.418 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:06:44.418Z,1345741604.418 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:06:44.418Z,1345741604.418 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:06:44.418Z,1345741604.418 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:06:44.427Z,1345741604.427 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:06:44.427Z,1345741604.427 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:06:44.427Z,1345741604.427 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:06:46.407Z,1345741606.407 [NAL9602](IMPORTANT): GPS fix at: 1345741603.00
2012-08-23T17:06:46.456Z,1345741606.456 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:06:46.456Z,1345741606.456 [Default:GPS:D] Running Loop=1
2012-08-23T17:06:46.847Z,1345741606.847 [Default:GPS:D] Stopped
2012-08-23T17:06:46.848Z,1345741606.848 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:06:46.848Z,1345741606.848 [Default:GPS] Stopped
2012-08-23T17:06:46.848Z,1345741606.848 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:06:46.848Z,1345741606.848 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:06:46.848Z,1345741606.848 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:07:01.430Z,1345741621.430 [NAL9602](INFO): SBD MO Status=0, MOMSN=522, MT Status=0, MTMSN=0
2012-08-23T17:07:13.675Z,1345741633.675 [NAL9602](INFO): SBD MO Status=1, MOMSN=523, MT Status=0, MTMSN=0
2012-08-23T17:07:13.707Z,1345741633.707 [NAL9602](INFO): Sent 267 bytes from file Logs/20120823T160446/shore0008.lzma
2012-08-23T17:07:13.707Z,1345741633.707 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:07:13.709Z,1345741633.708 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0008.lzma.parts/0000.sbd
2012-08-23T17:07:16.873Z,1345741636.873 [NAL9602](INFO): SBD MO Status=0, MOMSN=524, MT Status=0, MTMSN=0
2012-08-23T17:07:16.932Z,1345741636.932 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:07:16.932Z,1345741636.932 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:07:16.932Z,1345741636.932 [Default:Iridium] Stopped
2012-08-23T17:07:16.933Z,1345741636.933 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:07:16.933Z,1345741636.933 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:07:16.933Z,1345741636.933 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:07:16.933Z,1345741636.933 [Default:F.Wait] Running Loop=1
2012-08-23T17:07:16.933Z,1345741636.933 [Default:F.Wait](DEBUG): Initialize Wait Component.
2012-08-23T17:07:17.329Z,1345741637.329 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:07:17.329Z,1345741637.329 [Default:CallIridium:B] Stopped
2012-08-23T17:07:17.329Z,1345741637.329 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:07:17.329Z,1345741637.329 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:07:17.329Z,1345741637.329 [Default:CallIridium] Stopped
2012-08-23T17:07:17.330Z,1345741637.330 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:07:27.508Z,1345741647.508 [NAL9602](INFO): Powering down
2012-08-23T17:12:17.419Z,1345741937.419 [Default:CallIridium] Running Loop=1
2012-08-23T17:12:17.419Z,1345741937.419 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:12:17.419Z,1345741937.420 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:12:17.420Z,1345741937.420 [Default:CallIridium:A] Stopped
2012-08-23T17:12:17.420Z,1345741937.420 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:12:17.420Z,1345741937.420 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium] Running Loop=1
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:12:22.683Z,1345741942.683 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:12:22.684Z,1345741942.684 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:12:22.684Z,1345741942.684 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:12:22.684Z,1345741942.684 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:12:22.685Z,1345741942.685 [Default:GPS] Running Loop=1
2012-08-23T17:12:22.685Z,1345741942.685 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:12:22.685Z,1345741942.685 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:12:22.685Z,1345741942.685 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:12:22.685Z,1345741942.685 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:12:22.686Z,1345741942.685 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:12:22.686Z,1345741942.686 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:12:22.686Z,1345741942.686 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:12:22.687Z,1345741942.687 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:12:23.315Z,1345741943.316 [NAL9602](INFO): Powering up
2012-08-23T17:12:34.271Z,1345741954.270 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:12:56.401Z,1345741976.401 [NAL9602](INFO): SBD MO Status=1, MOMSN=525, MT Status=0, MTMSN=0
2012-08-23T17:12:56.435Z,1345741976.435 [NAL9602](INFO): Sent 110 bytes from file Logs/20120823T160446/shore0009.lzma
2012-08-23T17:12:56.436Z,1345741976.436 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:12:56.437Z,1345741976.437 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0009.lzma.parts/0000.sbd
2012-08-23T17:13:28.376Z,1345742008.376 [NAL9602](INFO): SBD MO Status=2, MOMSN=526, MT Status=2, MTMSN=0
2012-08-23T17:13:28.377Z,1345742008.377 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T17:13:29.575Z,1345742009.575 [NAL9602](IMPORTANT): GPS fix at: 1345742007.00
2012-08-23T17:13:29.592Z,1345742009.592 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:13:29.592Z,1345742009.592 [Default:GPS:D] Running Loop=1
2012-08-23T17:13:30.010Z,1345742010.010 [Default:GPS:D] Stopped
2012-08-23T17:13:30.010Z,1345742010.010 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:13:30.010Z,1345742010.010 [Default:GPS] Stopped
2012-08-23T17:13:30.010Z,1345742010.010 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:13:30.011Z,1345742010.011 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:13:30.011Z,1345742010.011 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:13:38.292Z,1345742018.292 [NAL9602](INFO): SBD MO Status=0, MOMSN=526, MT Status=0, MTMSN=0
2012-08-23T17:13:38.343Z,1345742018.343 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:13:38.344Z,1345742018.344 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:13:38.344Z,1345742018.344 [Default:Iridium] Stopped
2012-08-23T17:13:38.344Z,1345742018.344 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:13:38.344Z,1345742018.344 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:13:38.344Z,1345742018.344 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:13:38.703Z,1345742018.703 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:13:38.703Z,1345742018.703 [Default:CallIridium:B] Stopped
2012-08-23T17:13:38.703Z,1345742018.704 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:13:38.704Z,1345742018.704 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:13:38.704Z,1345742018.704 [Default:CallIridium] Stopped
2012-08-23T17:13:38.704Z,1345742018.704 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:13:48.844Z,1345742028.844 [NAL9602](INFO): Powering down
2012-08-23T17:18:38.846Z,1345742318.846 [Default:CallIridium] Running Loop=1
2012-08-23T17:18:38.847Z,1345742318.847 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:18:38.847Z,1345742318.847 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:18:38.847Z,1345742318.847 [Default:CallIridium:A] Stopped
2012-08-23T17:18:38.847Z,1345742318.847 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:18:38.848Z,1345742318.848 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:18:43.891Z,1345742323.891 [Default:Iridium] Running Loop=1
2012-08-23T17:18:43.892Z,1345742323.892 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:18:43.892Z,1345742323.892 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:18:43.892Z,1345742323.892 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:18:43.892Z,1345742323.892 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:18:43.892Z,1345742323.892 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:18:43.893Z,1345742323.893 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:18:43.893Z,1345742323.893 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:18:43.893Z,1345742323.893 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS] Running Loop=1
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:18:43.894Z,1345742323.894 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:18:43.895Z,1345742323.895 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:18:43.895Z,1345742323.895 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:18:43.896Z,1345742323.895 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:18:44.487Z,1345742324.487 [NAL9602](INFO): Powering up
2012-08-23T17:18:54.935Z,1345742334.935 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:19:16.785Z,1345742356.785 [NAL9602](INFO): SBD MO Status=1, MOMSN=527, MT Status=0, MTMSN=0
2012-08-23T17:19:16.819Z,1345742356.819 [NAL9602](INFO): Sent 173 bytes from file Logs/20120823T160446/shore0010.lzma
2012-08-23T17:19:16.819Z,1345742356.819 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:19:16.820Z,1345742356.820 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0010.lzma.parts/0000.sbd
2012-08-23T17:19:25.589Z,1345742365.589 [NAL9602](INFO): SBD MO Status=0, MOMSN=528, MT Status=0, MTMSN=0
2012-08-23T17:19:25.648Z,1345742365.648 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:19:25.648Z,1345742365.648 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:19:25.649Z,1345742365.648 [Default:Iridium] Stopped
2012-08-23T17:19:25.649Z,1345742365.649 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:19:25.649Z,1345742365.649 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:19:25.649Z,1345742365.649 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:19:26.004Z,1345742366.004 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:19:26.004Z,1345742366.004 [Default:CallIridium:B] Stopped
2012-08-23T17:19:26.004Z,1345742366.004 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:19:26.005Z,1345742366.005 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:19:26.005Z,1345742366.005 [Default:CallIridium] Stopped
2012-08-23T17:19:26.005Z,1345742366.005 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:19:26.793Z,1345742366.793 [NAL9602](IMPORTANT): GPS fix at: 1345742365.00
2012-08-23T17:19:26.809Z,1345742366.809 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:19:26.809Z,1345742366.809 [Default:GPS:D] Running Loop=1
2012-08-23T17:19:27.211Z,1345742367.211 [Default:GPS:D] Stopped
2012-08-23T17:19:27.211Z,1345742367.211 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:19:27.211Z,1345742367.211 [Default:GPS] Stopped
2012-08-23T17:19:27.212Z,1345742367.211 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:19:27.212Z,1345742367.212 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:19:27.212Z,1345742367.212 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:19:47.745Z,1345742387.745 [NAL9602](INFO): Powering down
2012-08-23T17:24:27.768Z,1345742667.768 [Default:CallIridium] Running Loop=1
2012-08-23T17:24:27.768Z,1345742667.768 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:24:27.768Z,1345742667.768 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:24:27.768Z,1345742667.768 [Default:CallIridium:A] Stopped
2012-08-23T17:24:27.768Z,1345742667.769 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:24:27.769Z,1345742667.769 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:24:32.795Z,1345742672.795 [Default:Iridium] Running Loop=1
2012-08-23T17:24:32.795Z,1345742672.795 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:24:32.795Z,1345742672.795 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:24:32.795Z,1345742672.795 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:24:32.795Z,1345742672.795 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:24:32.795Z,1345742672.796 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:24:32.796Z,1345742672.796 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:24:32.796Z,1345742672.796 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:24:32.797Z,1345742672.796 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:24:32.797Z,1345742672.797 [Default:GPS] Running Loop=1
2012-08-23T17:24:32.797Z,1345742672.797 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:24:32.797Z,1345742672.797 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:24:32.797Z,1345742672.797 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:24:32.797Z,1345742672.797 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:24:32.798Z,1345742672.797 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:24:32.799Z,1345742672.799 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:24:32.799Z,1345742672.799 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:24:32.799Z,1345742672.799 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:24:33.383Z,1345742673.383 [NAL9602](INFO): Powering up
2012-08-23T17:24:43.979Z,1345742683.978 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:25:01.701Z,1345742701.701 [NAL9602](INFO): SBD MO Status=1, MOMSN=529, MT Status=0, MTMSN=0
2012-08-23T17:25:01.735Z,1345742701.735 [NAL9602](INFO): Sent 176 bytes from file Logs/20120823T160446/shore0011.lzma
2012-08-23T17:25:01.735Z,1345742701.735 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:25:01.737Z,1345742701.737 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0011.lzma.parts/0000.sbd
2012-08-23T17:25:09.707Z,1345742709.707 [NAL9602](INFO): SBD MO Status=0, MOMSN=530, MT Status=0, MTMSN=0
2012-08-23T17:25:09.775Z,1345742709.776 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:25:09.776Z,1345742709.776 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:25:09.776Z,1345742709.776 [Default:Iridium] Stopped
2012-08-23T17:25:09.776Z,1345742709.776 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:25:09.776Z,1345742709.776 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:25:09.776Z,1345742709.776 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:25:10.157Z,1345742710.157 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:25:10.157Z,1345742710.157 [Default:CallIridium:B] Stopped
2012-08-23T17:25:10.157Z,1345742710.158 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:25:10.158Z,1345742710.158 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:25:10.158Z,1345742710.158 [Default:CallIridium] Stopped
2012-08-23T17:25:10.162Z,1345742710.162 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:25:10.895Z,1345742710.895 [NAL9602](IMPORTANT): GPS fix at: 1345742710.00
2012-08-23T17:25:10.911Z,1345742710.911 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:25:10.912Z,1345742710.912 [Default:GPS:D] Running Loop=1
2012-08-23T17:25:11.302Z,1345742711.302 [Default:GPS:D] Stopped
2012-08-23T17:25:11.303Z,1345742711.303 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:25:11.303Z,1345742711.303 [Default:GPS] Stopped
2012-08-23T17:25:11.303Z,1345742711.303 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:25:11.303Z,1345742711.303 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:25:11.304Z,1345742711.304 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:25:26.951Z,1345742726.951 [Radio_Freewave](INFO): Powering down
2012-08-23T17:25:31.836Z,1345742731.836 [NAL9602](INFO): Powering down
2012-08-23T17:25:36.870Z,1345742736.870 [Radio_Freewave](INFO): Powering up
2012-08-23T17:30:11.832Z,1345743011.832 [Default:CallIridium] Running Loop=1
2012-08-23T17:30:11.832Z,1345743011.832 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:30:11.832Z,1345743011.832 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:30:11.833Z,1345743011.833 [Default:CallIridium:A] Stopped
2012-08-23T17:30:11.833Z,1345743011.833 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:30:11.833Z,1345743011.833 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium] Running Loop=1
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:30:16.975Z,1345743016.975 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:30:16.976Z,1345743016.976 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:30:16.976Z,1345743016.976 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:30:16.976Z,1345743016.976 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS] Running Loop=1
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:30:16.977Z,1345743016.977 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:30:16.978Z,1345743016.978 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:30:16.978Z,1345743016.978 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:30:16.979Z,1345743016.978 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:30:17.520Z,1345743017.520 [NAL9602](INFO): Powering up
2012-08-23T17:30:28.127Z,1345743028.127 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:30:44.601Z,1345743044.602 [NAL9602](INFO): SBD MO Status=1, MOMSN=531, MT Status=0, MTMSN=0
2012-08-23T17:30:44.635Z,1345743044.635 [NAL9602](INFO): Sent 199 bytes from file Logs/20120823T160446/shore0012.lzma
2012-08-23T17:30:44.635Z,1345743044.635 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:30:44.637Z,1345743044.636 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0012.lzma.parts/0000.sbd
2012-08-23T17:30:53.401Z,1345743053.401 [NAL9602](INFO): SBD MO Status=0, MOMSN=532, MT Status=0, MTMSN=0
2012-08-23T17:30:53.451Z,1345743053.451 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:30:53.452Z,1345743053.452 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:30:53.452Z,1345743053.452 [Default:Iridium] Stopped
2012-08-23T17:30:53.452Z,1345743053.452 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:30:53.452Z,1345743053.452 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:30:53.452Z,1345743053.452 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:30:53.815Z,1345743053.815 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:30:53.815Z,1345743053.815 [Default:CallIridium:B] Stopped
2012-08-23T17:30:53.816Z,1345743053.816 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:30:53.816Z,1345743053.816 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:30:53.816Z,1345743053.816 [Default:CallIridium] Stopped
2012-08-23T17:30:53.816Z,1345743053.816 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:31:03.403Z,1345743063.403 [NAL9602](IMPORTANT): GPS fix at: 1345743063.00
2012-08-23T17:31:03.419Z,1345743063.419 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:31:03.419Z,1345743063.419 [Default:GPS:D] Running Loop=1
2012-08-23T17:31:03.816Z,1345743063.816 [Default:GPS:D] Stopped
2012-08-23T17:31:03.816Z,1345743063.816 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:31:03.816Z,1345743063.816 [Default:GPS] Stopped
2012-08-23T17:31:03.816Z,1345743063.816 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:31:03.816Z,1345743063.816 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:31:03.817Z,1345743063.816 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:31:24.400Z,1345743084.400 [NAL9602](INFO): Powering down
2012-08-23T17:35:54.456Z,1345743354.456 [Default:CallIridium] Running Loop=1
2012-08-23T17:35:54.456Z,1345743354.456 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:35:54.456Z,1345743354.456 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:35:54.456Z,1345743354.456 [Default:CallIridium:A] Stopped
2012-08-23T17:35:54.456Z,1345743354.457 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:35:54.457Z,1345743354.457 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:35:59.352Z,1345743359.352 [Default:Iridium] Running Loop=1
2012-08-23T17:35:59.353Z,1345743359.353 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:35:59.353Z,1345743359.353 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:35:59.353Z,1345743359.353 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:35:59.353Z,1345743359.353 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:35:59.353Z,1345743359.353 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:35:59.354Z,1345743359.354 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:35:59.354Z,1345743359.354 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:35:59.354Z,1345743359.354 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS] Running Loop=1
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:35:59.355Z,1345743359.355 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:35:59.356Z,1345743359.356 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:35:59.356Z,1345743359.356 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:35:59.356Z,1345743359.356 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:36:00.020Z,1345743360.020 [NAL9602](INFO): Powering up
2012-08-23T17:36:10.642Z,1345743370.642 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:36:33.663Z,1345743393.663 [NAL9602](INFO): SBD MO Status=1, MOMSN=533, MT Status=0, MTMSN=0
2012-08-23T17:36:33.695Z,1345743393.695 [NAL9602](INFO): Sent 189 bytes from file Logs/20120823T160446/shore0013.lzma
2012-08-23T17:36:33.695Z,1345743393.695 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:36:33.697Z,1345743393.697 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0013.lzma.parts/0000.sbd
2012-08-23T17:36:42.833Z,1345743402.833 [NAL9602](INFO): SBD MO Status=0, MOMSN=534, MT Status=0, MTMSN=0
2012-08-23T17:36:42.902Z,1345743402.902 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:36:42.902Z,1345743402.902 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:36:42.902Z,1345743402.902 [Default:Iridium] Stopped
2012-08-23T17:36:42.903Z,1345743402.903 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:36:42.903Z,1345743402.903 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:36:42.903Z,1345743402.903 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:36:43.247Z,1345743403.247 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:36:43.248Z,1345743403.247 [Default:CallIridium:B] Stopped
2012-08-23T17:36:43.248Z,1345743403.248 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:36:43.248Z,1345743403.248 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:36:43.248Z,1345743403.248 [Default:CallIridium] Stopped
2012-08-23T17:36:43.248Z,1345743403.248 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:37:55.638Z,1345743475.638 [NAL9602](IMPORTANT): GPS fix at: 1345743476.00
2012-08-23T17:37:55.655Z,1345743475.655 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:37:55.655Z,1345743475.655 [Default:GPS:D] Running Loop=1
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS:D] Stopped
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS] Stopped
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:37:56.049Z,1345743476.049 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:38:16.704Z,1345743496.704 [NAL9602](INFO): Powering down
2012-08-23T17:41:46.581Z,1345743706.582 [Default:CallIridium] Running Loop=1
2012-08-23T17:41:46.582Z,1345743706.582 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:41:46.582Z,1345743706.582 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:41:46.582Z,1345743706.582 [Default:CallIridium:A] Stopped
2012-08-23T17:41:46.583Z,1345743706.583 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:41:46.583Z,1345743706.583 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium] Running Loop=1
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:41:51.804Z,1345743711.804 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:41:51.805Z,1345743711.805 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:41:51.805Z,1345743711.805 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:41:51.805Z,1345743711.805 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:41:51.806Z,1345743711.806 [Default:GPS] Running Loop=1
2012-08-23T17:41:51.806Z,1345743711.806 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:41:51.806Z,1345743711.806 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:41:51.806Z,1345743711.806 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:41:51.806Z,1345743711.806 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:41:51.807Z,1345743711.806 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:41:51.807Z,1345743711.807 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:41:51.807Z,1345743711.807 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:41:51.808Z,1345743711.807 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:41:52.409Z,1345743712.409 [NAL9602](INFO): Powering up
2012-08-23T17:42:03.359Z,1345743723.359 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:42:43.929Z,1345743763.929 [NAL9602](INFO): SBD MO Status=2, MOMSN=535, MT Status=2, MTMSN=0
2012-08-23T17:42:43.930Z,1345743763.930 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2012-08-23T17:42:45.131Z,1345743765.131 [NAL9602](IMPORTANT): GPS fix at: 1345743765.00
2012-08-23T17:42:45.156Z,1345743765.156 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:42:45.156Z,1345743765.156 [Default:GPS:D] Running Loop=1
2012-08-23T17:42:45.547Z,1345743765.547 [Default:GPS:D] Stopped
2012-08-23T17:42:45.548Z,1345743765.548 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:42:45.548Z,1345743765.548 [Default:GPS] Stopped
2012-08-23T17:42:45.548Z,1345743765.548 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:42:45.548Z,1345743765.548 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:42:45.548Z,1345743765.548 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:43:05.032Z,1345743785.032 [NAL9602](INFO): SBD MO Status=1, MOMSN=535, MT Status=0, MTMSN=0
2012-08-23T17:43:05.067Z,1345743785.067 [NAL9602](INFO): Sent 207 bytes from file Logs/20120823T160446/shore0014.lzma
2012-08-23T17:43:05.067Z,1345743785.067 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:43:05.068Z,1345743785.069 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0014.lzma.parts/0000.sbd
2012-08-23T17:43:15.430Z,1345743795.430 [NAL9602](INFO): SBD MO Status=0, MOMSN=536, MT Status=0, MTMSN=0
2012-08-23T17:43:15.479Z,1345743795.479 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:43:15.479Z,1345743795.479 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:43:15.479Z,1345743795.480 [Default:Iridium] Stopped
2012-08-23T17:43:15.480Z,1345743795.480 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:43:15.480Z,1345743795.480 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:43:15.480Z,1345743795.480 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:43:15.843Z,1345743795.843 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:43:15.843Z,1345743795.843 [Default:CallIridium:B] Stopped
2012-08-23T17:43:15.843Z,1345743795.843 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:43:15.844Z,1345743795.843 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:43:15.844Z,1345743795.844 [Default:CallIridium] Stopped
2012-08-23T17:43:15.844Z,1345743795.844 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:43:25.987Z,1345743805.987 [NAL9602](INFO): Powering down
2012-08-23T17:48:16.118Z,1345744096.118 [Default:CallIridium] Running Loop=1
2012-08-23T17:48:16.122Z,1345744096.122 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:48:16.123Z,1345744096.122 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:48:16.123Z,1345744096.123 [Default:CallIridium:A] Stopped
2012-08-23T17:48:16.123Z,1345744096.123 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:48:16.123Z,1345744096.123 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:48:21.010Z,1345744101.010 [Default:Iridium] Running Loop=1
2012-08-23T17:48:21.010Z,1345744101.010 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:48:21.010Z,1345744101.010 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:48:21.010Z,1345744101.010 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:48:21.011Z,1345744101.011 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:48:21.011Z,1345744101.011 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:48:21.012Z,1345744101.012 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:48:21.012Z,1345744101.012 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:48:21.012Z,1345744101.012 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:48:21.012Z,1345744101.012 [Default:GPS] Running Loop=1
2012-08-23T17:48:21.012Z,1345744101.012 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:48:21.012Z,1345744101.012 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:48:21.013Z,1345744101.013 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:48:21.013Z,1345744101.013 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:48:21.013Z,1345744101.013 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:48:21.014Z,1345744101.014 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:48:21.014Z,1345744101.014 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:48:21.014Z,1345744101.014 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:48:21.630Z,1345744101.630 [NAL9602](INFO): Powering up
2012-08-23T17:48:32.591Z,1345744112.591 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:48:50.314Z,1345744130.314 [NAL9602](INFO): SBD MO Status=1, MOMSN=537, MT Status=0, MTMSN=0
2012-08-23T17:48:50.347Z,1345744130.347 [NAL9602](INFO): Sent 205 bytes from file Logs/20120823T160446/shore0015.lzma
2012-08-23T17:48:50.347Z,1345744130.347 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:48:50.349Z,1345744130.349 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0015.lzma.parts/0000.sbd
2012-08-23T17:49:00.315Z,1345744140.315 [NAL9602](INFO): SBD MO Status=0, MOMSN=538, MT Status=0, MTMSN=0
2012-08-23T17:49:00.367Z,1345744140.367 [Default:Iridium:Read_Iridium] Stopped
2012-08-23T17:49:00.368Z,1345744140.368 [Default:Iridium](INFO): Completed Default:Iridium
2012-08-23T17:49:00.368Z,1345744140.368 [Default:Iridium] Stopped
2012-08-23T17:49:00.368Z,1345744140.368 [Default:Iridium](INFO): Aggregate::uninitialize Default:Iridium
2012-08-23T17:49:00.368Z,1345744140.368 [Default:Iridium:A.SetSpeed] Stopped
2012-08-23T17:49:00.368Z,1345744140.368 [Default:Iridium:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:49:00.727Z,1345744140.727 [Default:CallIridium:B](INFO): Completed Default:CallIridium:B
2012-08-23T17:49:00.727Z,1345744140.727 [Default:CallIridium:B] Stopped
2012-08-23T17:49:00.727Z,1345744140.727 [Default:CallIridium:B](INFO): Aggregate::uninitialize Default:CallIridium:B
2012-08-23T17:49:00.727Z,1345744140.727 [Default:CallIridium](INFO): Completed Default:CallIridium
2012-08-23T17:49:00.727Z,1345744140.727 [Default:CallIridium] Stopped
2012-08-23T17:49:00.728Z,1345744140.727 [Default:CallIridium](INFO): Aggregate::uninitialize Default:CallIridium
2012-08-23T17:49:01.517Z,1345744141.517 [NAL9602](IMPORTANT): GPS fix at: 1345744143.00
2012-08-23T17:49:01.533Z,1345744141.533 [Default:GPS:Read_GPS] Stopped
2012-08-23T17:49:01.533Z,1345744141.533 [Default:GPS:D] Running Loop=1
2012-08-23T17:49:01.927Z,1345744141.927 [Default:GPS:D] Stopped
2012-08-23T17:49:01.928Z,1345744141.928 [Default:GPS](INFO): Completed Default:GPS
2012-08-23T17:49:01.928Z,1345744141.928 [Default:GPS] Stopped
2012-08-23T17:49:01.928Z,1345744141.928 [Default:GPS](INFO): Aggregate::uninitialize Default:GPS
2012-08-23T17:49:01.928Z,1345744141.928 [Default:GPS:A.SetSpeed] Stopped
2012-08-23T17:49:01.928Z,1345744141.928 [Default:GPS:A.SetSpeed](DEBUG): Uninitialize.
2012-08-23T17:49:17.445Z,1345744157.445 [NAL9602](INFO): Powering down
2012-08-23T17:54:02.555Z,1345744442.555 [Default:CallIridium] Running Loop=1
2012-08-23T17:54:02.555Z,1345744442.555 [Default:CallIridium](INFO): Aggregate::initialize Default:CallIridium
2012-08-23T17:54:02.555Z,1345744442.555 [Default:CallIridium:A] Running Loop=1
2012-08-23T17:54:02.555Z,1345744442.555 [Default:CallIridium:A] Stopped
2012-08-23T17:54:02.556Z,1345744442.556 [Default:CallIridium:B] Running Loop=1
2012-08-23T17:54:02.556Z,1345744442.556 [Default:CallIridium:B](INFO): Aggregate::initialize Default:CallIridium:B
2012-08-23T17:54:07.464Z,1345744447.464 [Default:Iridium] Running Loop=1
2012-08-23T17:54:07.464Z,1345744447.464 [Default:Iridium](INFO): Aggregate::initialize Default:Iridium
2012-08-23T17:54:07.465Z,1345744447.464 [Default:Iridium:A.SetSpeed] Running Loop=1
2012-08-23T17:54:07.465Z,1345744447.464 [Default:Iridium:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:54:07.465Z,1345744447.465 [Default:Iridium:B.GoToSurface] Running Loop=1
2012-08-23T17:54:07.465Z,1345744447.465 [Default:Iridium:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:54:07.466Z,1345744447.466 [Default:Iridium:B.GoToSurface] Stopped
2012-08-23T17:54:07.466Z,1345744447.466 [Default:Iridium:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:54:07.466Z,1345744447.466 [Default:Iridium:Read_Iridium] Running Loop=1
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS] Running Loop=1
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS](INFO): Aggregate::initialize Default:GPS
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS:A.SetSpeed] Running Loop=1
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS:A.SetSpeed](DEBUG): Initialize.
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS:B.GoToSurface] Running Loop=1
2012-08-23T17:54:07.467Z,1345744447.467 [Default:GPS:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2012-08-23T17:54:07.468Z,1345744447.468 [Default:GPS:B.GoToSurface] Stopped
2012-08-23T17:54:07.468Z,1345744447.468 [Default:GPS:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2012-08-23T17:54:07.468Z,1345744447.468 [Default:GPS:Read_GPS] Running Loop=1
2012-08-23T17:54:08.115Z,1345744448.115 [NAL9602](INFO): Powering up
2012-08-23T17:54:18.779Z,1345744458.779 [NAL9602](INFO): NAL9602 initialized
2012-08-23T17:54:47.189Z,1345744487.189 [NAL9602](INFO): SBD MO Status=1, MOMSN=539, MT Status=0, MTMSN=0
2012-08-23T17:54:47.223Z,1345744487.223 [NAL9602](INFO): Sent 186 bytes from file Logs/20120823T160446/shore0016.lzma
2012-08-23T17:54:47.223Z,1345744487.223 [NAL9602](INFO): Packets left to send: 0
2012-08-23T17:54:47.225Z,1345744487.225 [NAL9602](INFO): Stored copy of sent data in Logs/20120823T160446/shore0016.lzma.parts/0000.sbd
2012-08-23T17:54:58.789Z,1345744498.789 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=540, MT Status=1, MTMSN=72
2012-08-23T17:54:59.415Z,1345744499.415 [NAL9602](INFO): Received command:restart logs
2012-08-23T17:54:59.495Z,1345744499.494 [CommandLine](IMPORTANT): got command restart logs