2018-08-27T18:19:04.218Z,1535393944.218 [CommandLine](IMPORTANT): got command restart logs 2018-08-27T18:21:05.017Z,1535394065.017 [DataOverHttps](IMPORTANT): SBD MTMSN=20180827T182009 2018-08-27T18:21:09.450Z,1535394069.450 [DataOverHttps](INFO): Received command:sched asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 2 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.Speed 0 meter_per_second" 3n1kl 1 2 2018-08-27T18:21:09.491Z,1535394069.491 [CommandLine](IMPORTANT): got command schedule asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 2 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.Speed 0 meter_per_second" 3n1kl 1 2.000000 2018-08-27T18:21:09.492Z,1535394069.492 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=3n1kl 2018-08-27T18:21:09.493Z,1535394069.493 [CommandLine](IMPORTANT): Scheduled #9 (#1 of 2 with id='3n1kl'): "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 2 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.Speed 0 meter_per_second" ASAP 2018-08-27T18:21:10.248Z,1535394070.248 [DataOverHttps](IMPORTANT): SBD MTMSN=20180827T182014 2018-08-27T18:21:14.658Z,1535394074.658 [DataOverHttps](INFO): Received command:sched asap "set sample:SampleAtDepth.SpeedApproachingDepth 0 meter_per_second;set sample:SampleAtDepth.SpeedSamplingAtDepth 0 meter_per_second;set sample:SampleAtDepth.TargetDepth 2 meter;run " 3n1kl 2 2 2018-08-27T18:21:14.700Z,1535394074.700 [CommandLine](IMPORTANT): got command schedule asap "set sample:SampleAtDepth.SpeedApproachingDepth 0 meter_per_second;set sample:SampleAtDepth.SpeedSamplingAtDepth 0 meter_per_second;set sample:SampleAtDepth.TargetDepth 2 meter;run " 3n1kl 2 2.000000 2018-08-27T18:21:14.700Z,1535394074.700 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=3n1kl 2018-08-27T18:21:14.701Z,1535394074.701 [CommandLine](IMPORTANT): Scheduled #10 (#2 of 2 with id='3n1kl'): "set sample:SampleAtDepth.SpeedApproachingDepth 0 meter_per_second;set sample:SampleAtDepth.SpeedSamplingAtDepth 0 meter_per_second;set sample:SampleAtDepth.TargetDepth 2 meter;run " ASAP 2018-08-27T18:21:14.804Z,1535394074.804 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml 2018-08-27T18:21:14.804Z,1535394074.804 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml 2018-08-27T18:21:14.942Z,1535394074.942 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min 2018-08-27T18:21:14.945Z,1535394074.945 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m 2018-08-27T18:21:14.948Z,1535394074.948 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count 2018-08-27T18:21:14.951Z,1535394074.951 [MissionManager](INFO): DefineArg sample.SpeedApproachingTarget = 0.000000 m/s 2018-08-27T18:21:14.978Z,1535394074.978 [MissionManager](INFO): DefineArg sample.SpeedSampling = 0.000000 m/s 2018-08-27T18:21:14.981Z,1535394074.981 [MissionManager](INFO): DefineArg sample.RudderAngleSpiralOrDonut = 13.000000 arcdeg 2018-08-27T18:21:14.984Z,1535394074.984 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min 2018-08-27T18:21:14.986Z,1535394074.986 [sample:A.Pitch](DEBUG): Construct. 2018-08-27T18:21:14.992Z,1535394074.992 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml 2018-08-27T18:21:15.276Z,1535394075.276 [MissionManager](INFO): DefineArg sample:SampleAtDepth.Speed = 1.000000 m/s 2018-08-27T18:21:15.279Z,1535394075.279 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SpeedApproachingDepth = 1.000000 m/s 2018-08-27T18:21:15.306Z,1535394075.306 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SpeedSamplingAtDepth = 1.000000 m/s 2018-08-27T18:21:15.309Z,1535394075.309 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RudderAngleInSpiralOrDonut = 13.000000 arcdeg 2018-08-27T18:21:15.313Z,1535394075.313 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m 2018-08-27T18:21:15.316Z,1535394075.316 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s 2018-08-27T18:21:15.331Z,1535394075.331 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h 2018-08-27T18:21:15.334Z,1535394075.334 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool 2018-08-27T18:21:15.337Z,1535394075.337 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool 2018-08-27T18:21:15.353Z,1535394075.353 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool 2018-08-27T18:21:15.356Z,1535394075.356 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min 2018-08-27T18:21:15.360Z,1535394075.360 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min 2018-08-27T18:21:15.363Z,1535394075.363 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 538.999971 cc 2018-08-27T18:21:15.382Z,1535394075.382 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:A.SetSpeed](DEBUG): Construct. 2018-08-27T18:21:15.385Z,1535394075.385 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:B.Buoyancy](DEBUG): Construct Buoyancy. 2018-08-27T18:21:15.388Z,1535394075.388 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:C.Point](DEBUG): Construct. 2018-08-27T18:21:15.411Z,1535394075.411 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed](DEBUG): Construct. 2018-08-27T18:21:15.425Z,1535394075.425 [sample:SampleAtDepth:SetZeroRudderInDriftMode:B.Point](DEBUG): Construct. 2018-08-27T18:21:15.431Z,1535394075.431 [sample:SampleAtDepth:D.Pitch](DEBUG): Construct. 2018-08-27T18:21:15.523Z,1535394075.523 [sample:SampleAtDepth:D.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-08-27T18:21:15.547Z,1535394075.547 [sample:SampleAtDepth:SampleWrapper:B.Wait](DEBUG): Construct Wait. 2018-08-27T18:21:15.595Z,1535394075.595 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-08-27T18:21:15.602Z,1535394075.602 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-08-27T18:21:15.602Z,1535394075.602 [MissionManager](ERROR): Slate does not contain celsius 2018-08-27T18:21:15.619Z,1535394075.619 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-08-27T18:21:15.628Z,1535394075.628 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-08-27T18:21:15.641Z,1535394075.641 [MissionManager](ERROR): Slate does not contain celsius 2018-08-27T18:21:15.716Z,1535394075.716 [MissionManager](DEBUG): This mission is designed to be run in the test tank only and samples whichever sampler is installed once the vehicle reaches the target depth. How long to let the mission run. 90 Depth to sample at. 7 Number of samples to take. 1 Vehicle speed when approaching the target depth. Initialized to zero. 0 Vehicle speed during sampling: 0.0 for drift mode (prop off); 1.0 for donut mode (prop on). Initialized to zero. 0 Rudder angle during spiral or donut, but not in drift mode. 13 How long to wait between samples. This starts *before* the first sample to exercise the SettleTime setting in the insert aggregate. 3 2018-08-27T18:21:15.716Z,1535394075.716 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml 2018-08-27T18:21:24.369Z,1535394084.369 [CommandLine](IMPORTANT): got command set sample.MissionTimeout 3.000000 hour 2018-08-27T18:21:24.370Z,1535394084.370 [CommandLine](IMPORTANT): got command set sample.Depth 2.000000 meter 2018-08-27T18:21:24.371Z,1535394084.371 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second 2018-08-27T18:21:24.372Z,1535394084.372 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.Speed 0.000000 meter_per_second 2018-08-27T18:21:35.029Z,1535394095.029 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SpeedApproachingDepth 0.000000 meter_per_second 2018-08-27T18:21:35.030Z,1535394095.030 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SpeedSamplingAtDepth 0.000000 meter_per_second 2018-08-27T18:21:35.031Z,1535394095.031 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 2.000000 meter 2018-08-27T18:21:35.031Z,1535394095.031 [CommandLine](IMPORTANT): got command run 2018-08-27T18:21:35.033Z,1535394095.033 [CommandLine](IMPORTANT): Running 2018-08-27T18:21:35.161Z,1535394095.161 [Default] Stopped 2018-08-27T18:21:35.161Z,1535394095.161 [Default](DEBUG): Aggregate::uninitialize Default 2018-08-27T18:21:35.161Z,1535394095.161 [Default:B.GoToSurface] Stopped 2018-08-27T18:21:35.161Z,1535394095.161 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-08-27T18:21:35.161Z,1535394095.161 [Default:CheckIn] Stopped 2018-08-27T18:21:35.161Z,1535394095.161 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-27T18:21:35.161Z,1535394095.161 [Default:CheckIn:Read_GPS] Stopped 2018-08-27T18:21:35.162Z,1535394095.162 [MissionManager](IMPORTANT): Started mission sample 2018-08-27T18:21:35.162Z,1535394095.162 [sample] Running Loop=1 2018-08-27T18:21:35.162Z,1535394095.162 [sample](DEBUG): Aggregate::initialize sample 2018-08-27T18:21:35.162Z,1535394095.162 [sample:A.Pitch] Running Loop=1 2018-08-27T18:21:35.162Z,1535394095.162 [sample:A.Pitch](DEBUG): Initialize. 2018-08-27T18:21:35.163Z,1535394095.163 [sample:C] Running Loop=1 2018-08-27T18:21:35.165Z,1535394095.165 [sample:C] Stopped 2018-08-27T18:21:35.165Z,1535394095.165 [sample:D] Running Loop=1 2018-08-27T18:21:35.165Z,1535394095.165 [sample:A.Pitch] Running Loop=1 2018-08-27T18:21:35.526Z,1535394095.526 [sample:D] Stopped 2018-08-27T18:21:35.526Z,1535394095.526 [sample:E] Running Loop=1 2018-08-27T18:21:35.916Z,1535394095.916 [sample:E] Stopped 2018-08-27T18:21:35.916Z,1535394095.916 [sample:F] Running Loop=1 2018-08-27T18:21:36.317Z,1535394096.317 [sample:F] Stopped 2018-08-27T18:21:36.317Z,1535394096.317 [sample:G] Running Loop=1 2018-08-27T18:21:36.723Z,1535394096.723 [sample:G] Stopped 2018-08-27T18:21:36.723Z,1535394096.723 [sample:SampleRepeater] Running Loop=1 2018-08-27T18:21:36.723Z,1535394096.723 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater 2018-08-27T18:21:36.724Z,1535394096.724 [sample:SampleRepeater:Sample] Running Loop=1 2018-08-27T18:21:36.724Z,1535394096.724 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth] Running Loop=1 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode] Running Loop=1 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode](DEBUG): Aggregate::initialize sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:A.SetSpeed] Running Loop=1 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:A.SetSpeed](DEBUG): Initialize. 2018-08-27T18:21:37.130Z,1535394097.130 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:B.Buoyancy] Running Loop=1 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:B.Buoyancy](DEBUG): Initialize Buoyancy Component. 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:C.Point] Running Loop=1 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:C.Point](DEBUG): Initialize. 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode] Running Loop=1 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode](DEBUG): Aggregate::initialize sample:SampleAtDepth:SetZeroRudderInDriftMode 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed] Running Loop=1 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed](DEBUG): Initialize. 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode:B.Point] Running Loop=1 2018-08-27T18:21:37.131Z,1535394097.131 [sample:SampleAtDepth:SetZeroRudderInDriftMode:B.Point](DEBUG): Initialize. 2018-08-27T18:21:37.132Z,1535394097.132 [sample:SampleAtDepth:D.Pitch] Running Loop=1 2018-08-27T18:21:37.132Z,1535394097.132 [sample:SampleAtDepth:D.Pitch](DEBUG): Initialize. 2018-08-27T18:21:37.132Z,1535394097.132 [sample:SampleAtDepth:SetSpeedApproachDepth] Running Loop=1 2018-08-27T18:21:37.132Z,1535394097.132 [sample:SampleAtDepth:SetSpeedApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:SetSpeedApproachDepth 2018-08-27T18:21:37.132Z,1535394097.132 [sample:SampleAtDepth:SetSpeedApproachDepth:A] Running Loop=1 2018-08-27T18:21:37.169Z,1535394097.169 [sample:SampleAtDepth:SetZeroRudderInDriftMode] Running Loop=1 2018-08-27T18:21:37.169Z,1535394097.169 [sample:SampleAtDepth:SetZeroRudderInDriftMode:B.Point] Running Loop=1 2018-08-27T18:21:37.178Z,1535394097.178 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed] Running Loop=1 2018-08-27T18:21:37.187Z,1535394097.187 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode] Stopped 2018-08-27T18:21:37.187Z,1535394097.187 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode 2018-08-27T18:21:37.187Z,1535394097.187 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:A.SetSpeed] Stopped 2018-08-27T18:21:37.188Z,1535394097.188 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:A.SetSpeed](DEBUG): Uninitialize. 2018-08-27T18:21:37.188Z,1535394097.188 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:B.Buoyancy] Stopped 2018-08-27T18:21:37.188Z,1535394097.188 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2018-08-27T18:21:37.188Z,1535394097.188 [sample:SampleAtDepth:SetNeutralBuoyancyNonZeroRudderInSpiralOrDonutMode:C.Point] Stopped 2018-08-27T18:21:37.188Z,1535394097.188 [sample:SampleAtDepth:SetSpeedApproachDepth:A](INFO): Moving to 2.000000 m 2018-08-27T18:21:37.194Z,1535394097.194 [sample:SampleAtDepth:SetSpeedApproachDepth:A] Stopped 2018-08-27T18:21:37.194Z,1535394097.194 [sample:SampleAtDepth:SetSpeedApproachDepth:B] Running Loop=1 2018-08-27T18:21:37.561Z,1535394097.561 [sample:SampleAtDepth:SetSpeedApproachDepth:B] Stopped 2018-08-27T18:21:37.561Z,1535394097.561 [sample:SampleAtDepth:SetSpeedApproachDepth](INFO): Completed sample:SampleAtDepth:SetSpeedApproachDepth 2018-08-27T18:21:37.561Z,1535394097.561 [sample:SampleAtDepth:SetSpeedApproachDepth] Stopped 2018-08-27T18:21:37.561Z,1535394097.561 [sample:SampleAtDepth:SetSpeedApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SetSpeedApproachDepth 2018-08-27T18:21:50.167Z,1535394110.167 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 2.000000 meter 2018-08-27T18:21:50.168Z,1535394110.168 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread. 2018-08-27T18:21:50.514Z,1535394110.514 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-08-27T18:21:50.812Z,1535394110.812 [sample:SampleAtDepth:E] Running Loop=1 2018-08-27T18:21:51.034Z,1535394111.034 [Radio_Surface](INFO): Powering down 2018-08-27T18:21:51.156Z,1535394111.156 [sample:SampleAtDepth:E] Stopped 2018-08-27T18:21:51.156Z,1535394111.156 [sample:SampleAtDepth:SampleWrapper] Running Loop=1 2018-08-27T18:21:51.156Z,1535394111.156 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper 2018-08-27T18:21:51.156Z,1535394111.156 [sample:SampleAtDepth:SampleWrapper:A] Running Loop=1 2018-08-27T18:21:51.618Z,1535394111.618 [sample:SampleAtDepth:SampleWrapper:A](INFO): At 2.000000 m , settling for 0.050000 min 2018-08-27T18:21:51.619Z,1535394111.619 [sample:SampleAtDepth:SampleWrapper:A] Stopped 2018-08-27T18:21:51.619Z,1535394111.619 [sample:SampleAtDepth:SampleWrapper:B.Wait] Running Loop=1 2018-08-27T18:21:51.619Z,1535394111.619 [sample:SampleAtDepth:SampleWrapper:B.Wait](DEBUG): Initialize Wait Component. 2018-08-27T18:21:55.132Z,1535394115.132 [sample:SampleAtDepth:SampleWrapper:B.Wait](INFO): Done Waiting. 2018-08-27T18:21:55.132Z,1535394115.132 [sample:SampleAtDepth:SampleWrapper:B.Wait] Stopped 2018-08-27T18:21:55.132Z,1535394115.132 [sample:SampleAtDepth:SampleWrapper:B.Wait](DEBUG): Uninitialize Wait Component. 2018-08-27T18:21:55.132Z,1535394115.132 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1 2018-08-27T18:21:55.137Z,1535394115.137 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-08-27T18:21:55.137Z,1535394115.137 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1 2018-08-27T18:21:55.137Z,1535394115.137 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1 2018-08-27T18:21:55.137Z,1535394115.137 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-08-27T18:21:55.533Z,1535394115.533 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1 2018-08-27T18:21:55.930Z,1535394115.930 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2018-08-27T18:21:57.106Z,1535394117.106 [Radio_Surface](INFO): Powering up 2018-08-27T18:21:57.170Z,1535394117.170 [ESPComponent](INFO): powering up ESP 2018-08-27T18:21:57.170Z,1535394117.170 [ESPComponent](INFO): manually powering up ESP 2018-08-27T18:21:57.172Z,1535394117.172 [ESPComponent](IMPORTANT): Powered ESP with command: ! echo 1 > /dev/loadA6 2018-08-27T18:21:57.173Z,1535394117.173 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadA6 2018-08-27T18:21:57.198Z,1535394117.198 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2018-08-27T18:21:57.336Z,1535394117.336 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2018-08-27T18:21:57.585Z,1535394117.585 [ESPComponent](INFO): console: 2018-08-27T18:21:58.315Z,1535394118.315 [ESPComponent](INFO): console: 2018-08-27T18:21:58.722Z,1535394118.722 [ESPComponent](INFO): console:NAND: 256 MiB 2018-08-27T18:21:59.118Z,1535394119.118 [ESPComponent](INFO): console: BOOTMODE: SDMMC 2018-08-27T18:21:59.163Z,1535394119.163 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.431703 seconds old. 2018-08-27T18:21:59.515Z,1535394119.515 [ESPComponent](INFO): console: 2018-08-27T18:21:59.532Z,1535394119.532 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.800778 seconds old. 2018-08-27T18:21:59.920Z,1535394119.920 [ESPComponent](INFO): console: 2018-08-27T18:21:59.929Z,1535394119.929 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.197764 seconds old. 2018-08-27T18:22:00.336Z,1535394120.336 [ESPComponent](INFO): console: U-Boot 2009.11-mbariB (Dec 07 2017 - 19:07:59) 2018-08-27T18:22:00.345Z,1535394120.345 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.613660 seconds old. 2018-08-27T18:22:00.730Z,1535394120.730 [ESPComponent](INFO): console: 2018-08-27T18:22:00.738Z,1535394120.738 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.006914 seconds old. 2018-08-27T18:22:01.128Z,1535394121.128 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2018-08-27T18:22:01.144Z,1535394121.144 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.412548 seconds old. 2018-08-27T18:22:01.527Z,1535394121.527 [ESPComponent](INFO): console: flash params are already written into flash 2018-08-27T18:22:01.535Z,1535394121.535 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.803996 seconds old. 2018-08-27T18:22:01.916Z,1535394121.916 [ESPComponent](INFO): console: DRAM: 64 MB 2018-08-27T18:22:01.947Z,1535394121.947 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 3.215379 seconds old. 2018-08-27T18:22:02.314Z,1535394122.314 [ESPComponent](INFO): console: In: serial 2018-08-27T18:22:02.715Z,1535394122.715 [ESPComponent](INFO): console: Out: serial 2018-08-27T18:22:02.762Z,1535394122.762 [Radio_Surface](INFO): Powering down 2018-08-27T18:22:03.115Z,1535394123.115 [ESPComponent](INFO): console: Err: serial 2018-08-27T18:22:03.520Z,1535394123.520 [ESPComponent](INFO): console: Net: ks8851_mll 2018-08-27T18:22:03.920Z,1535394123.920 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2018-08-27T18:22:04.316Z,1535394124.316 [ESPComponent](INFO): console: mmc1 is available 2018-08-27T18:22:04.719Z,1535394124.719 [ESPComponent](INFO): console: reading uImage 2018-08-27T18:22:05.127Z,1535394125.127 [ESPComponent](INFO): console: 2018-08-27T18:22:05.528Z,1535394125.528 [ESPComponent](INFO): console: 1681208 bytes read 2018-08-27T18:22:05.930Z,1535394125.930 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2018-08-27T18:22:06.333Z,1535394126.333 [ESPComponent](INFO): console: Image Name: Linux-2.6.33-ea3131-mbari6 2018-08-27T18:22:06.735Z,1535394126.735 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2018-08-27T18:22:07.125Z,1535394127.125 [ESPComponent](INFO): console: Data Size: 1681144 Bytes = 1.6 MB 2018-08-27T18:22:07.527Z,1535394127.527 [ESPComponent](INFO): console: Load Address: 30008000 2018-08-27T18:22:07.915Z,1535394127.915 [ESPComponent](INFO): console: Entry Point: 30008000 2018-08-27T18:22:08.329Z,1535394128.329 [ESPComponent](INFO): console: Verifying Checksum ... OK 2018-08-27T18:22:08.715Z,1535394128.715 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2018-08-27T18:22:09.116Z,1535394129.116 [ESPComponent](INFO): console: OK 2018-08-27T18:22:09.519Z,1535394129.519 [ESPComponent](INFO): console: 2018-08-27T18:22:09.915Z,1535394129.915 [ESPComponent](INFO): console: Starting kernel ... 2018-08-27T18:22:10.318Z,1535394130.318 [ESPComponent](INFO): console: 2018-08-27T18:22:10.734Z,1535394130.734 [ESPComponent](INFO): console: Uncompressing Linux... done, booting the kernel. 2018-08-27T18:22:11.131Z,1535394131.131 [ESPComponent](INFO): console: [ 0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177 2018-08-27T18:22:11.543Z,1535394131.543 [ESPComponent](INFO): console: [ 0.00] CPU: VIVT data cache, VIVT instruction cache 2018-08-27T18:22:11.943Z,1535394131.943 [ESPComponent](INFO): console: [ 0.00] Machine: NXP EA313X 2018-08-27T18:22:12.325Z,1535394132.325 [ESPComponent](INFO): console: [ 0.00] Memory policy: ECC disabled, Data cache writeback 2018-08-27T18:22:12.728Z,1535394132.728 [ESPComponent](INFO): console: [ 0.00] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 16256 2018-08-27T18:22:13.119Z,1535394133.119 [ESPComponent](INFO): console: [ 0.24] Mount-cache hash table entries: 512 2018-08-27T18:22:13.511Z,1535394133.511 [ESPComponent](INFO): console: [ 0.29] MBARI ESP 3G 2018-08-27T18:22:13.918Z,1535394133.918 [ESPComponent](INFO): console: [ 0.39] bio: create slab at 0 2018-08-27T18:22:14.317Z,1535394134.317 [ESPComponent](INFO): console: [ 0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:14.724Z,1535394134.724 [ESPComponent](INFO): console: [ 0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:15.113Z,1535394135.113 [ESPComponent](INFO): console: [ 0.50] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:15.526Z,1535394135.526 [ESPComponent](INFO): console: [ 0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:15.929Z,1535394135.929 [ESPComponent](INFO): console: [ 0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:16.339Z,1535394136.339 [ESPComponent](INFO): console: [ 0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2018-08-27T18:22:16.735Z,1535394136.735 [ESPComponent](INFO): console: [ 0.56] NetWinder Floating Point Emulator V0.97 (double precision) 2018-08-27T18:22:17.129Z,1535394137.129 [ESPComponent](INFO): console: [ 0.58] yaffs Jul 6 2018 16:45:28 Installing. 2018-08-27T18:22:17.516Z,1535394137.516 [ESPComponent](INFO): console: [ 0.72] m25p80 spi0.3: m25p80 found s25sl032a flash 2018-08-27T18:22:17.906Z,1535394137.906 [ESPComponent](INFO): console: [ 2.19] VFS: Mounted root (ext2 filesystem) readonly on device 179:2. 2018-08-27T18:22:18.304Z,1535394138.304 [ESPComponent](INFO): console: 2018-08-27T18:22:18.705Z,1535394138.705 [ESPComponent](INFO): console:INIT: version 2.85 booting 2018-08-27T18:22:19.114Z,1535394139.114 [ESPComponent](INFO): console: 2018-08-27T18:22:19.509Z,1535394139.509 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2018-08-27T18:22:19.912Z,1535394139.912 [ESPComponent](INFO): console: ESPhonu 2018-08-27T18:22:20.307Z,1535394140.307 [ESPComponent](INFO): console: 2018-08-27T18:22:20.715Z,1535394140.715 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2018-08-27T18:22:21.124Z,1535394141.124 [ESPComponent](INFO): console: 2018-08-27T18:22:21.524Z,1535394141.524 [ESPComponent](INFO): console:Loading kernel modules 2018-08-27T18:22:21.932Z,1535394141.932 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2018-08-27T18:22:22.330Z,1535394142.330 [ESPComponent](INFO): console: mount: /dev/mmcblk0p2 already mounted or /card busy 2018-08-27T18:22:22.727Z,1535394142.727 [ESPComponent](INFO): console: Starting hotplug events dispatcher udevd 2018-08-27T18:22:23.105Z,1535394143.105 [ESPComponent](INFO): console: Set system clock to: Mon Aug 27 14:21:18 EDT 2018 2018-08-27T18:22:23.505Z,1535394143.505 [ESPComponent](INFO): console: Starting syslogd klogd... 2018-08-27T18:22:23.905Z,1535394143.905 [ESPComponent](INFO): console: Bringing up interface lo ... 2018-08-27T18:22:24.310Z,1535394144.310 [ESPComponent](INFO): console: lo IP=127.0.0.1 2018-08-27T18:22:24.705Z,1535394144.705 [ESPComponent](INFO): console: Packet forwarding enabled 2018-08-27T18:22:25.111Z,1535394145.111 [ESPComponent](INFO): console: Bringing up interface eth0 ... 2018-08-27T18:22:25.512Z,1535394145.512 [ESPComponent](INFO): console: Determining IP configuration for eth0....udhcpc (v1.11.2) started 2018-08-27T18:22:25.912Z,1535394145.912 [ESPComponent](INFO): console: Sending discover... 2018-08-27T18:22:26.325Z,1535394146.325 [ESPComponent](INFO): console: No lease, forking to background 2018-08-27T18:22:26.722Z,1535394146.722 [ESPComponent](INFO): console: Bringing up interface eth0:10 ... 2018-08-27T18:22:27.131Z,1535394147.131 [ESPComponent](INFO): console: eth0:10 IP=10.10.10.10 2018-08-27T18:22:27.527Z,1535394147.527 [ESPComponent](INFO): console: Bringing up interface ppp2 ... 2018-08-27T18:22:27.904Z,1535394147.904 [ESPComponent](INFO): console: Starting portmap... 2018-08-27T18:22:28.306Z,1535394148.306 [ESPComponent](INFO): console: Network unavailable: Local time is Mon Aug 27 14:21:24 EDT 2018 2018-08-27T18:22:28.708Z,1535394148.708 [ESPComponent](INFO): console: Starting thttpd... 2018-08-27T18:22:29.109Z,1535394149.109 [ESPComponent](INFO): console: 2018-08-27T18:22:29.511Z,1535394149.511 [ESPComponent](INFO): console: 2018-08-27T18:22:29.913Z,1535394149.913 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.37 -- 7/12/18 brent@mbari.org 2018-08-27T18:22:30.309Z,1535394150.309 [ESPComponent](INFO): console: 2018-08-27T18:22:30.777Z,1535394150.777 [ESPComponent](INFO): console:ESPhonu login: 2018-08-27T18:22:31.921Z,1535394151.921 [ESPComponent](IMPORTANT): ESP has connected as client 2018-08-27T18:22:32.726Z,1535394152.726 [ESPComponent](IMPORTANT): [sample #4] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2018-08-27T18:22:32.727Z,1535394152.727 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=4 2018-08-27T18:22:32.739Z,1535394152.739 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped 2018-08-27T18:22:32.740Z,1535394152.740 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1 2018-08-27T18:22:33.136Z,1535394153.136 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 2.000000 m inwater with nan ug/l chlorophyll fluorescence. 2018-08-27T18:22:33.140Z,1535394153.140 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped 2018-08-27T18:22:33.140Z,1535394153.140 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1 2018-08-27T18:22:33.516Z,1535394153.516 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PREPARING_SHOW_LOG 2018-08-27T18:22:33.534Z,1535394153.534 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2018-08-27T18:22:33.882Z,1535394153.882 [Radio_Surface](INFO): Powering up 2018-08-27T18:22:33.904Z,1535394153.904 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PREPARING_SHOW_STATUS 2018-08-27T18:22:35.916Z,1535394155.916 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_LOADING_CARTRIDGE 2018-08-27T18:22:39.538Z,1535394159.538 [Radio_Surface](INFO): Powering down 2018-08-27T18:22:40.674Z,1535394160.674 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:23:03.101Z,1535394183.101 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:23:03.102Z,1535394183.102 [BPC1] Communications Fault, FailCount= 4 2018-08-27T18:23:03.102Z,1535394183.102 [BPC1](ERROR): Communications Fault 2018-08-27T18:23:03.166Z,1535394183.166 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:23:04.357Z,1535394184.357 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:23:04.357Z,1535394184.357 [BPC1] No Fault, FailCount= 4 2018-08-27T18:23:13.485Z,1535394193.485 [Radio_Surface](INFO): Powering up 2018-08-27T18:23:14.317Z,1535394194.317 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_FILTERING 2018-08-27T18:23:16.704Z,1535394196.704 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_PAUSED 2018-08-27T18:23:19.154Z,1535394199.154 [Radio_Surface](INFO): Powering down 2018-08-27T18:23:41.074Z,1535394221.074 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:23:51.482Z,1535394231.482 [Radio_Surface](INFO): Powering up 2018-08-27T18:23:57.142Z,1535394237.142 [Radio_Surface](INFO): Powering down 2018-08-27T18:23:58.678Z,1535394238.678 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-27T18:24:15.474Z,1535394255.474 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.019455 2018-08-27T18:24:28.283Z,1535394268.283 [Radio_Surface](INFO): Powering up 2018-08-27T18:24:29.478Z,1535394269.478 [NAL9602](INFO): Powering down 2018-08-27T18:24:33.938Z,1535394273.938 [Radio_Surface](INFO): Powering down 2018-08-27T18:25:07.882Z,1535394307.882 [Radio_Surface](INFO): Powering up 2018-08-27T18:25:13.538Z,1535394313.538 [Radio_Surface](INFO): Powering down 2018-08-27T18:25:25.878Z,1535394325.878 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2018-08-27T18:25:25.878Z,1535394325.878 [DropWeight] Hardware Fault, FailCount= 1 2018-08-27T18:25:25.878Z,1535394325.878 [DropWeight](ERROR): Hardware Fault 2018-08-27T18:25:25.983Z,1535394325.983 [CommandLine](FAULT): Scheduling is paused 2018-08-27T18:25:25.983Z,1535394325.983 [CBIT](INFO): Critical error at 20180827T182525 2018-08-27T18:25:25.983Z,1535394325.983 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2018-08-27T18:25:25.990Z,1535394325.990 [CBIT](ERROR): Hardware Fault in component: DropWeight 2018-08-27T18:25:25.990Z,1535394325.990 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2018-08-27T18:25:26.335Z,1535394326.335 [MissionManager](INFO): MissionManager is completed. 2018-08-27T18:25:26.335Z,1535394326.335 [MissionManager](INFO): Uninitializing Mission sample 2018-08-27T18:25:26.335Z,1535394326.335 [sample] Stopped 2018-08-27T18:25:26.335Z,1535394326.335 [sample](DEBUG): Aggregate::uninitialize sample 2018-08-27T18:25:26.335Z,1535394326.335 [sample:A.Pitch] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SetZeroRudderInDriftMode] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SetZeroRudderInDriftMode](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SetZeroRudderInDriftMode 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SetZeroRudderInDriftMode:A.SetSpeed](DEBUG): Uninitialize. 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SetZeroRudderInDriftMode:B.Point] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:D.Pitch] Stopped 2018-08-27T18:25:26.336Z,1535394326.336 [sample:SampleAtDepth:SampleWrapper] Stopped 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleRepeater] Stopped 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleRepeater:Sample] Stopped 2018-08-27T18:25:26.337Z,1535394326.337 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample 2018-08-27T18:25:26.409Z,1535394326.409 [CBIT](INFO): Critical error at 20180827T182525 2018-08-27T18:25:26.719Z,1535394326.719 [MissionManager](IMPORTANT): Started mission Default 2018-08-27T18:25:26.719Z,1535394326.719 [Default] Running Loop=1 2018-08-27T18:25:26.719Z,1535394326.719 [Default](DEBUG): Aggregate::initialize Default 2018-08-27T18:25:26.719Z,1535394326.719 [Default:B.GoToSurface] Running Loop=1 2018-08-27T18:25:26.719Z,1535394326.719 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-08-27T18:25:26.720Z,1535394326.720 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-08-27T18:25:26.720Z,1535394326.720 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-08-27T18:25:26.755Z,1535394326.755 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-08-27T18:25:26.755Z,1535394326.755 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-08-27T18:25:26.756Z,1535394326.756 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2018-08-27T18:25:26.756Z,1535394326.756 [Default:A.Wait] Running Loop=1 2018-08-27T18:25:26.756Z,1535394326.756 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-08-27T18:25:40.083Z,1535394340.083 [Default:A.Wait](INFO): Done Waiting. 2018-08-27T18:25:40.083Z,1535394340.083 [Default:A.Wait] Stopped 2018-08-27T18:25:40.083Z,1535394340.083 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-08-27T18:25:41.621Z,1535394341.621 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:25:59.226Z,1535394359.226 [Radio_Surface](INFO): Powering up 2018-08-27T18:26:04.884Z,1535394364.884 [Radio_Surface](INFO): Powering down 2018-08-27T18:26:26.690Z,1535394386.690 [CBIT](IMPORTANT): Beginning ground fault scan 2018-08-27T18:26:26.868Z,1535394386.868 [Default:B.GoToSurface](ERROR): Pitch down timeout. Pitch: -2.59 2018-08-27T18:26:27.107Z,1535394387.107 [Radio_Surface](INFO): Powering up 2018-08-27T18:26:27.264Z,1535394387.264 [ElevatorOffsetCalculator](INFO): Removing expired estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -12.00 mm. 2018-08-27T18:26:37.346Z,1535394397.346 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): 0.017322 CHAN A1 (24V): -0.010621 CHAN A2 (12V): -0.001642 CHAN A3 (5V): -0.001830 CHAN B0 (3.3V): -0.000599 CHAN B1 (3.15aV): -0.000367 CHAN B2 (3.15bV): -0.001128 CHAN B3 (GND): -0.000737 OPEN: 0.005365 Full Scale Calc: 4.765 mA, -1.589 mA 2018-08-27T18:26:41.618Z,1535394401.618 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:27:42.018Z,1535394462.018 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:27:43.317Z,1535394463.317 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:27:43.317Z,1535394463.317 [Rowe_600LCM] No Fault, FailCount= 5 2018-08-27T18:27:43.621Z,1535394463.621 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:27:43.621Z,1535394463.621 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:27:43.622Z,1535394463.622 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:27:43.622Z,1535394463.622 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:27:47.824Z,1535394467.824 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:27:47.888Z,1535394467.888 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:27:47.890Z,1535394467.890 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:27:47.891Z,1535394467.891 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:27:47.892Z,1535394467.892 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:28:42.018Z,1535394522.018 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:28:45.722Z,1535394525.722 [Radio_Surface](INFO): Powering down 2018-08-27T18:28:51.781Z,1535394531.781 [Radio_Surface](INFO): Powering up 2018-08-27T18:29:25.735Z,1535394565.735 [Radio_Surface](INFO): Powering down 2018-08-27T18:29:31.794Z,1535394571.794 [Radio_Surface](INFO): Powering up 2018-08-27T18:29:42.418Z,1535394582.418 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:29:43.798Z,1535394583.798 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:29:43.798Z,1535394583.798 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-08-27T18:29:43.798Z,1535394583.798 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:29:44.090Z,1535394584.090 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:29:44.201Z,1535394584.201 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:29:44.315Z,1535394584.315 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:29:45.694Z,1535394585.694 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:29:45.695Z,1535394585.695 [Rowe_600LCM] No Fault, FailCount= 1 2018-08-27T18:29:45.929Z,1535394585.929 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:29:45.929Z,1535394585.929 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:29:45.930Z,1535394585.930 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:29:45.930Z,1535394585.930 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:29:50.182Z,1535394590.182 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:29:50.260Z,1535394590.260 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:29:50.262Z,1535394590.262 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:29:50.263Z,1535394590.263 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:29:50.264Z,1535394590.264 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:30:03.726Z,1535394603.726 [Radio_Surface](INFO): Powering down 2018-08-27T18:30:09.786Z,1535394609.786 [Radio_Surface](INFO): Powering up 2018-08-27T18:30:42.418Z,1535394642.418 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:31:06.872Z,1535394666.872 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:31:06.872Z,1535394666.872 [BPC1] Communications Fault, FailCount= 5 2018-08-27T18:31:06.872Z,1535394666.872 [BPC1](ERROR): Communications Fault 2018-08-27T18:31:06.965Z,1535394666.965 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:31:08.100Z,1535394668.100 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:31:08.100Z,1535394668.100 [BPC1] No Fault, FailCount= 5 2018-08-27T18:31:14.922Z,1535394674.922 [Radio_Surface](INFO): Powering down 2018-08-27T18:31:20.982Z,1535394680.982 [Radio_Surface](INFO): Powering up 2018-08-27T18:31:42.820Z,1535394702.820 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:31:46.187Z,1535394706.187 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:31:46.187Z,1535394706.187 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-08-27T18:31:46.187Z,1535394706.187 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:31:46.502Z,1535394706.502 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:31:46.589Z,1535394706.589 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:31:46.698Z,1535394706.698 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:31:48.122Z,1535394708.122 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:31:48.122Z,1535394708.122 [Rowe_600LCM] No Fault, FailCount= 2 2018-08-27T18:31:48.313Z,1535394708.313 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:31:48.313Z,1535394708.313 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:31:48.313Z,1535394708.313 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:31:48.314Z,1535394708.314 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:31:52.551Z,1535394712.551 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:31:52.632Z,1535394712.632 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:31:52.634Z,1535394712.634 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:31:52.635Z,1535394712.635 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:31:52.635Z,1535394712.635 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:32:43.618Z,1535394763.618 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:33:44.022Z,1535394824.022 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:33:48.363Z,1535394828.363 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:33:48.363Z,1535394828.363 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-08-27T18:33:48.363Z,1535394828.363 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:33:48.498Z,1535394828.498 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:33:48.765Z,1535394828.765 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:33:49.026Z,1535394829.026 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:33:50.499Z,1535394830.499 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:33:50.499Z,1535394830.499 [Rowe_600LCM] No Fault, FailCount= 3 2018-08-27T18:33:50.641Z,1535394830.641 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:33:50.641Z,1535394830.641 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:33:50.641Z,1535394830.641 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:33:50.642Z,1535394830.642 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:33:54.768Z,1535394834.768 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:33:54.916Z,1535394834.916 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:33:54.917Z,1535394834.917 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:33:54.918Z,1535394834.918 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:33:54.918Z,1535394834.918 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:34:44.418Z,1535394884.418 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:35:19.642Z,1535394919.642 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003383 2018-08-27T18:35:44.114Z,1535394944.114 [Radio_Surface](INFO): Powering down 2018-08-27T18:35:50.183Z,1535394950.183 [Radio_Surface](INFO): Powering up 2018-08-27T18:35:50.739Z,1535394950.739 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:35:50.739Z,1535394950.739 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-08-27T18:35:50.739Z,1535394950.739 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:35:50.910Z,1535394950.910 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:35:51.141Z,1535394951.141 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:35:51.456Z,1535394951.456 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:35:52.898Z,1535394952.898 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:35:52.898Z,1535394952.898 [Rowe_600LCM] No Fault, FailCount= 4 2018-08-27T18:35:53.069Z,1535394953.069 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:35:53.069Z,1535394953.069 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:35:53.070Z,1535394953.070 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:35:53.070Z,1535394953.070 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:35:57.202Z,1535394957.202 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:35:57.331Z,1535394957.331 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:35:57.333Z,1535394957.333 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:35:57.334Z,1535394957.334 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:35:57.334Z,1535394957.334 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:36:25.346Z,1535394985.346 [Radio_Surface](INFO): Powering down 2018-08-27T18:36:31.406Z,1535394991.406 [Radio_Surface](INFO): Powering up 2018-08-27T18:36:44.838Z,1535395004.838 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:37:09.270Z,1535395029.270 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:37:09.270Z,1535395029.270 [BPC1] Communications Fault, FailCount= 6 2018-08-27T18:37:09.270Z,1535395029.270 [BPC1](ERROR): Communications Fault 2018-08-27T18:37:09.399Z,1535395029.399 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:37:10.537Z,1535395030.537 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:37:10.537Z,1535395030.537 [BPC1] No Fault, FailCount= 6 2018-08-27T18:37:44.838Z,1535395064.838 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:37:53.534Z,1535395073.534 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:37:53.534Z,1535395073.534 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-08-27T18:37:53.534Z,1535395073.534 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:37:53.702Z,1535395073.702 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:37:53.702Z,1535395073.702 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-08-27T18:37:53.937Z,1535395073.937 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:37:54.061Z,1535395074.061 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:38:20.038Z,1535395100.038 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.399658 2018-08-27T18:39:26.493Z,1535395166.493 [VerticalControl](CRITICAL): Failure to ascend, stopping mission after 840.089417 seconds, depthRate=0.068723 m/s, pitch=-2.606931 deg. 2018-08-27T18:39:26.500Z,1535395166.500 [CBIT](INFO): Critical error at 20180827T183926 2018-08-27T18:39:29.710Z,1535395169.710 [Radio_Surface](INFO): Powering down 2018-08-27T18:39:35.769Z,1535395175.769 [Radio_Surface](INFO): Powering up 2018-08-27T18:39:45.238Z,1535395185.238 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:40:07.694Z,1535395207.694 [Radio_Surface](INFO): Powering down 2018-08-27T18:40:13.786Z,1535395213.786 [Radio_Surface](INFO): Powering up 2018-08-27T18:40:26.098Z,1535395226.098 [CBIT](INFO): Clearing failed state for component DropWeight 2018-08-27T18:40:26.098Z,1535395226.098 [DropWeight] No Fault, FailCount= 1 2018-08-27T18:40:45.238Z,1535395245.238 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:41:46.038Z,1535395306.038 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:42:06.887Z,1535395326.887 [Default:B.GoToSurface](CRITICAL): Surfacing timeout. Returning calc satisfied. 2018-08-27T18:42:06.888Z,1535395326.888 [Default:CheckIn] Running Loop=1 2018-08-27T18:42:06.888Z,1535395326.888 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-27T18:42:06.888Z,1535395326.888 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-27T18:42:06.898Z,1535395326.898 [CBIT](INFO): Critical error at 20180827T184206 2018-08-27T18:42:07.642Z,1535395327.642 [NAL9602](INFO): Powering up 2018-08-27T18:42:18.442Z,1535395338.442 [NAL9602](INFO): NAL9602 initialized 2018-08-27T18:42:19.242Z,1535395339.242 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-27T18:42:19.242Z,1535395339.242 [NAL9602] Data Fault, FailCount= 2 2018-08-27T18:42:19.243Z,1535395339.243 [NAL9602](ERROR): Data Fault 2018-08-27T18:42:19.339Z,1535395339.339 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-27T18:42:19.642Z,1535395339.642 [NAL9602](INFO): Powering down 2018-08-27T18:42:20.507Z,1535395340.507 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-27T18:42:20.507Z,1535395340.507 [NAL9602] No Fault, FailCount= 2 2018-08-27T18:42:46.038Z,1535395366.038 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:42:50.042Z,1535395370.042 [NAL9602](INFO): Powering up NAL9602 2018-08-27T18:43:00.842Z,1535395380.842 [NAL9602](INFO): NAL9602 initialized 2018-08-27T18:43:46.038Z,1535395426.038 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-27T18:44:20.882Z,1535395460.882 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003214 2018-08-27T18:44:26.558Z,1535395466.558 [VerticalControl](CRITICAL): Failure to ascend, dropping drop weight after 300.063446 seconds, depthRate=0.068723 m/s, pitch=-2.605544 deg. 2018-08-27T18:44:26.576Z,1535395466.576 [CBIT](INFO): Critical error at 20180827T184426 2018-08-27T18:44:27.682Z,1535395467.682 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2018-08-27T18:44:27.682Z,1535395467.682 [DropWeight] Hardware Fault, FailCount= 1 2018-08-27T18:44:27.682Z,1535395467.682 [DropWeight](ERROR): Hardware Fault 2018-08-27T18:44:27.784Z,1535395467.784 [CBIT](INFO): Critical error at 20180827T184427 2018-08-27T18:44:27.786Z,1535395467.786 [CBIT](ERROR): Hardware Fault in component: DropWeight 2018-08-27T18:44:27.787Z,1535395467.787 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2018-08-27T18:44:28.138Z,1535395468.138 [CBIT](INFO): Critical error at 20180827T184427 2018-08-27T18:45:06.918Z,1535395506.918 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:45:06.918Z,1535395506.918 [BPC1] Communications Fault, FailCount= 7 2018-08-27T18:45:06.918Z,1535395506.918 [BPC1](ERROR): Communications Fault 2018-08-27T18:45:06.945Z,1535395506.945 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:45:08.143Z,1535395508.143 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:45:08.143Z,1535395508.143 [BPC1] No Fault, FailCount= 7 2018-08-27T18:46:08.144Z,1535395568.144 [CommandLine](IMPORTANT): got command show stack 2018-08-27T18:46:08.144Z,1535395568.144 [CommandLine](IMPORTANT): Behavior Stack: 2018-08-27T18:46:08.154Z,1535395568.154 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface 2018-08-27T18:46:08.154Z,1535395568.154 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS 2018-08-27T18:47:07.002Z,1535395627.002 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-27T18:42:06.9Z 2018-08-27T18:47:07.002Z,1535395627.002 [Default:CheckIn:Read_GPS] Stopped 2018-08-27T18:47:07.002Z,1535395627.002 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-27T18:47:12.822Z,1535395632.822 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180827T163151/Courier0036.lzma 2018-08-27T18:47:13.620Z,1535395633.620 [DataOverHttps](INFO): Moved sent file to Logs/20180827T163151/Courier0036.lzma.bak 2018-08-27T18:47:13.620Z,1535395633.620 [DataOverHttps](INFO): SBD MOMSN=8448220 2018-08-27T18:47:24.047Z,1535395644.047 [DataOverHttps](INFO): Sending 359 bytes from file Logs/20180827T181904/Courier0000.lzma 2018-08-27T18:47:27.044Z,1535395647.044 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Courier0000.lzma.bak 2018-08-27T18:47:27.044Z,1535395647.044 [DataOverHttps](INFO): SBD MOMSN=8448222 2018-08-27T18:47:46.469Z,1535395666.469 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180827T181904/Courier0003.lzma 2018-08-27T18:47:47.244Z,1535395667.244 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Courier0003.lzma.bak 2018-08-27T18:47:47.244Z,1535395667.244 [DataOverHttps](INFO): SBD MOMSN=8448232 2018-08-27T18:47:57.800Z,1535395677.800 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:47:57.801Z,1535395677.801 [Rowe_600LCM] No Fault, FailCount= 5 2018-08-27T18:47:57.929Z,1535395677.929 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:47:57.929Z,1535395677.929 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:47:57.929Z,1535395677.929 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:47:57.930Z,1535395677.930 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:48:02.466Z,1535395682.466 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:48:02.600Z,1535395682.600 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:48:02.602Z,1535395682.602 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:48:02.603Z,1535395682.603 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:48:02.603Z,1535395682.603 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:48:07.286Z,1535395687.286 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-27T18:48:07.848Z,1535395687.848 [DataOverHttps](INFO): Sending 386 bytes from file Logs/20180827T163151/Express0037.lzma 2018-08-27T18:48:08.644Z,1535395688.644 [DataOverHttps](INFO): Moved sent file to Logs/20180827T163151/Express0037.lzma.bak 2018-08-27T18:48:08.644Z,1535395688.644 [DataOverHttps](INFO): SBD MOMSN=8448234 2018-08-27T18:48:28.233Z,1535395708.233 [DataOverHttps](INFO): Sending 1855 bytes from file Logs/20180827T181904/Express0001.lzma 2018-08-27T18:48:29.012Z,1535395709.012 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Express0001.lzma.bak 2018-08-27T18:48:29.012Z,1535395709.012 [DataOverHttps](INFO): SBD MOMSN=8448244 2018-08-27T18:48:37.614Z,1535395717.614 [NAL9602](INFO): Powering down 2018-08-27T18:48:46.483Z,1535395726.483 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20180827T181904/Express0004.lzma 2018-08-27T18:48:47.280Z,1535395727.280 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Express0004.lzma.bak 2018-08-27T18:48:47.281Z,1535395727.281 [DataOverHttps](INFO): SBD MOMSN=8448296 2018-08-27T18:48:49.189Z,1535395729.189 [Default:CheckIn:Read_Iridium] Stopped 2018-08-27T18:48:49.189Z,1535395729.189 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-27T18:48:49.189Z,1535395729.189 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-27T18:49:58.043Z,1535395798.043 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:49:58.043Z,1535395798.043 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-08-27T18:49:58.043Z,1535395798.043 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:49:58.156Z,1535395798.156 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:49:58.445Z,1535395798.445 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:49:58.762Z,1535395798.762 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:50:00.143Z,1535395800.143 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:50:00.143Z,1535395800.143 [Rowe_600LCM] No Fault, FailCount= 1 2018-08-27T18:50:00.377Z,1535395800.377 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:50:00.377Z,1535395800.377 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:50:00.378Z,1535395800.378 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:50:00.378Z,1535395800.378 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:50:04.637Z,1535395804.637 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:50:04.699Z,1535395804.699 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:50:04.701Z,1535395804.701 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:50:04.702Z,1535395804.702 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:50:04.703Z,1535395804.703 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:51:26.858Z,1535395886.858 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:51:26.858Z,1535395886.858 [BPC1] Communications Fault, FailCount= 8 2018-08-27T18:51:26.858Z,1535395886.858 [BPC1](ERROR): Communications Fault 2018-08-27T18:51:26.885Z,1535395886.885 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:51:28.103Z,1535395888.103 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:51:28.103Z,1535395888.103 [BPC1] No Fault, FailCount= 8 2018-08-27T18:52:00.853Z,1535395920.853 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:52:00.854Z,1535395920.854 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-08-27T18:52:00.854Z,1535395920.854 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:52:00.884Z,1535395920.884 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:52:01.257Z,1535395921.257 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:52:01.367Z,1535395921.367 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:52:02.846Z,1535395922.846 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:52:02.846Z,1535395922.846 [Rowe_600LCM] No Fault, FailCount= 2 2018-08-27T18:52:02.981Z,1535395922.981 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:52:02.981Z,1535395922.981 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:52:02.982Z,1535395922.982 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:52:02.982Z,1535395922.982 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:52:07.115Z,1535395927.115 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:52:07.283Z,1535395927.283 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:52:07.285Z,1535395927.285 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:52:07.286Z,1535395927.286 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:52:07.286Z,1535395927.286 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:53:49.668Z,1535396029.668 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-27T18:53:49.669Z,1535396029.669 [Default:CheckIn:C.Wait] Stopped 2018-08-27T18:53:49.669Z,1535396029.669 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-27T18:53:49.669Z,1535396029.669 [Default:CheckIn:D] Running Loop=1 2018-08-27T18:53:50.066Z,1535396030.066 [Default:CheckIn:D] Stopped 2018-08-27T18:53:50.067Z,1535396030.067 [Default:CheckIn:E] Running Loop=1 2018-08-27T18:53:50.457Z,1535396030.457 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.389111 min 2018-08-27T18:53:50.458Z,1535396030.458 [Default:CheckIn:E] Stopped 2018-08-27T18:53:50.458Z,1535396030.458 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-27T18:53:50.459Z,1535396030.459 [Default:CheckIn] Stopped 2018-08-27T18:53:50.459Z,1535396030.459 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-27T18:53:50.459Z,1535396030.459 [Default:CheckIn](INFO): Running loop #2 2018-08-27T18:53:50.460Z,1535396030.460 [Default:CheckIn] Running Loop=2 2018-08-27T18:53:50.460Z,1535396030.460 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-27T18:53:50.460Z,1535396030.460 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-27T18:53:54.088Z,1535396034.088 [NAL9602](INFO): Powering up 2018-08-27T18:54:03.028Z,1535396043.028 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:54:03.028Z,1535396043.028 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-08-27T18:54:03.028Z,1535396043.028 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:54:03.319Z,1535396043.319 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:54:03.434Z,1535396043.434 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:54:03.529Z,1535396043.529 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:54:05.067Z,1535396045.067 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:54:05.067Z,1535396045.067 [Rowe_600LCM] No Fault, FailCount= 3 2018-08-27T18:54:05.145Z,1535396045.145 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:54:05.145Z,1535396045.145 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:54:05.146Z,1535396045.146 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:54:05.146Z,1535396045.146 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:54:05.250Z,1535396045.250 [NAL9602](INFO): NAL9602 initialized 2018-08-27T18:54:06.070Z,1535396046.070 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-27T18:54:06.070Z,1535396046.070 [NAL9602] Data Fault, FailCount= 3 2018-08-27T18:54:06.070Z,1535396046.070 [NAL9602](ERROR): Data Fault 2018-08-27T18:54:06.366Z,1535396046.366 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-27T18:54:06.448Z,1535396046.448 [NAL9602](INFO): Powering down 2018-08-27T18:54:07.329Z,1535396047.329 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-27T18:54:07.329Z,1535396047.329 [NAL9602] No Fault, FailCount= 3 2018-08-27T18:54:09.333Z,1535396049.333 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:54:09.467Z,1535396049.467 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:54:09.469Z,1535396049.469 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:54:09.470Z,1535396049.470 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:54:09.471Z,1535396049.471 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:54:36.854Z,1535396076.854 [NAL9602](INFO): Powering up NAL9602 2018-08-27T18:54:48.065Z,1535396088.065 [NAL9602](INFO): NAL9602 initialized 2018-08-27T18:56:05.193Z,1535396165.193 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:56:05.193Z,1535396165.193 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-08-27T18:56:05.193Z,1535396165.193 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:56:05.490Z,1535396165.490 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:56:05.597Z,1535396165.597 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:56:05.685Z,1535396165.685 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:56:07.082Z,1535396167.082 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T18:56:07.082Z,1535396167.082 [Rowe_600LCM] No Fault, FailCount= 4 2018-08-27T18:56:07.301Z,1535396167.301 [Rowe_600LCM](INFO): Initializing 2018-08-27T18:56:07.301Z,1535396167.301 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T18:56:07.302Z,1535396167.302 [Rowe_600LCM](INFO): LCM OK 2018-08-27T18:56:07.302Z,1535396167.302 [Rowe_600LCM](INFO): Powering up 2018-08-27T18:56:11.542Z,1535396171.542 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T18:56:11.622Z,1535396171.622 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T18:56:11.623Z,1535396171.623 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T18:56:11.624Z,1535396171.624 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T18:56:11.625Z,1535396171.625 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T18:57:18.264Z,1535396238.264 [NAL9602](INFO): SBD MO Status=2, MOMSN=24176, MT Status=2, MTMSN=0 2018-08-27T18:57:18.264Z,1535396238.264 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-27T18:57:29.086Z,1535396249.086 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T18:57:29.086Z,1535396249.086 [BPC1] Communications Fault, FailCount= 9 2018-08-27T18:57:29.086Z,1535396249.086 [BPC1](ERROR): Communications Fault 2018-08-27T18:57:29.149Z,1535396249.149 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T18:57:30.376Z,1535396250.376 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T18:57:30.376Z,1535396250.376 [BPC1] No Fault, FailCount= 9 2018-08-27T18:57:43.855Z,1535396263.855 [NAL9602](INFO): SBD MO Status=2, MOMSN=24176, MT Status=2, MTMSN=0 2018-08-27T18:57:43.855Z,1535396263.855 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-27T18:58:07.611Z,1535396287.611 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T18:58:07.611Z,1535396287.611 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-08-27T18:58:07.611Z,1535396287.611 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T18:58:07.900Z,1535396287.900 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T18:58:07.905Z,1535396287.905 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-08-27T18:58:08.013Z,1535396288.013 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T18:58:08.115Z,1535396288.115 [Rowe_600LCM](INFO): Powering down 2018-08-27T18:58:50.668Z,1535396330.668 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-27T18:53:50.5Z 2018-08-27T18:58:50.670Z,1535396330.670 [Default:CheckIn:Read_GPS] Stopped 2018-08-27T18:58:50.670Z,1535396330.670 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-27T18:58:56.992Z,1535396336.992 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180827T181904/Courier0006.lzma 2018-08-27T18:58:57.779Z,1535396337.779 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Courier0006.lzma.bak 2018-08-27T18:58:57.780Z,1535396337.780 [DataOverHttps](INFO): SBD MOMSN=8448298 2018-08-27T18:59:03.353Z,1535396343.353 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PROCESSING 2018-08-27T18:59:05.432Z,1535396345.432 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_PROCESSED 2018-08-27T18:59:09.020Z,1535396349.020 [DataOverHttps](INFO): Sending 373 bytes from file Logs/20180827T181904/Express0007.lzma 2018-08-27T18:59:09.816Z,1535396349.816 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Express0007.lzma.bak 2018-08-27T18:59:09.817Z,1535396349.817 [DataOverHttps](INFO): SBD MOMSN=8448300 2018-08-27T18:59:11.591Z,1535396351.591 [Default:CheckIn:Read_Iridium] Stopped 2018-08-27T18:59:11.591Z,1535396351.591 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-27T18:59:11.591Z,1535396351.591 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-27T18:59:27.731Z,1535396367.731 [CBIT](INFO): Clearing failed state for component DropWeight 2018-08-27T18:59:27.731Z,1535396367.731 [DropWeight] No Fault, FailCount= 1 2018-08-27T18:59:29.226Z,1535396369.226 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2018-08-27T18:59:29.226Z,1535396369.226 [DropWeight] Hardware Fault, FailCount= 1 2018-08-27T18:59:29.226Z,1535396369.226 [DropWeight](ERROR): Hardware Fault 2018-08-27T18:59:29.307Z,1535396369.307 [CBIT](INFO): Critical error at 20180827T185929 2018-08-27T18:59:29.313Z,1535396369.313 [CBIT](ERROR): Hardware Fault in component: DropWeight 2018-08-27T18:59:29.314Z,1535396369.314 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2018-08-27T18:59:29.691Z,1535396369.691 [CBIT](INFO): Critical error at 20180827T185929 2018-08-27T18:59:54.426Z,1535396394.426 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-27T19:00:25.234Z,1535396425.234 [NAL9602](INFO): Powering down 2018-08-27T19:04:12.098Z,1535396652.098 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-27T19:04:12.098Z,1535396652.098 [Default:CheckIn:C.Wait] Stopped 2018-08-27T19:04:12.098Z,1535396652.098 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-27T19:04:12.099Z,1535396652.099 [Default:CheckIn:D] Running Loop=1 2018-08-27T19:04:12.499Z,1535396652.499 [Default:CheckIn:D] Stopped 2018-08-27T19:04:12.499Z,1535396652.499 [Default:CheckIn:E] Running Loop=1 2018-08-27T19:04:15.602Z,1535396655.602 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.762996 min 2018-08-27T19:04:15.602Z,1535396655.602 [Default:CheckIn:E] Stopped 2018-08-27T19:04:15.602Z,1535396655.602 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn] Stopped 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn](INFO): Running loop #3 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn] Running Loop=3 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-27T19:04:15.603Z,1535396655.603 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-27T19:04:16.062Z,1535396656.062 [NAL9602](INFO): Powering up 2018-08-27T19:04:27.254Z,1535396667.254 [NAL9602](INFO): NAL9602 initialized 2018-08-27T19:04:59.254Z,1535396699.254 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-08-27T19:04:59.329Z,1535396699.329 [NAL9602](FAULT): received: +CSQ:0 OK176, 2, 0, 0, 0 OK 2018-08-27T19:04:59.329Z,1535396699.329 [NAL9602] Data Fault, FailCount= 4 2018-08-27T19:04:59.329Z,1535396699.329 [NAL9602](ERROR): Data Fault 2018-08-27T19:04:59.412Z,1535396699.412 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-27T19:04:59.654Z,1535396699.654 [NAL9602](INFO): Powering down 2018-08-27T19:05:00.510Z,1535396700.510 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-27T19:05:00.510Z,1535396700.510 [NAL9602] No Fault, FailCount= 4 2018-08-27T19:05:03.285Z,1535396703.285 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T19:05:03.285Z,1535396703.285 [BPC1] Communications Fault, FailCount= 10 2018-08-27T19:05:03.285Z,1535396703.285 [BPC1](ERROR): Communications Fault 2018-08-27T19:05:03.337Z,1535396703.337 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T19:05:03.337Z,1535396703.337 [CBIT](CRITICAL): Communications Fault in component: BPC1 2018-08-27T19:05:03.715Z,1535396703.715 [CBIT](INFO): Critical error at 20180827T190503 2018-08-27T19:05:29.714Z,1535396729.714 [NAL9602](INFO): Powering up NAL9602 2018-08-27T19:05:40.910Z,1535396740.910 [NAL9602](INFO): NAL9602 initialized 2018-08-27T19:05:41.734Z,1535396741.734 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-27T19:05:41.734Z,1535396741.734 [NAL9602] Data Fault, FailCount= 5 2018-08-27T19:05:41.734Z,1535396741.734 [NAL9602](ERROR): Data Fault 2018-08-27T19:05:41.862Z,1535396741.862 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-27T19:05:41.862Z,1535396741.862 [CBIT](CRITICAL): Data Fault in component: NAL9602 2018-08-27T19:05:42.110Z,1535396742.110 [NAL9602](INFO): Powering down 2018-08-27T19:05:42.234Z,1535396742.234 [CBIT](INFO): Critical error at 20180827T190541 2018-08-27T19:07:41.787Z,1535396861.787 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-27T19:07:41.787Z,1535396861.787 [NAL9602] No Fault, FailCount= 5 2018-08-27T19:07:42.134Z,1535396862.134 [NAL9602](INFO): Powering up NAL9602 2018-08-27T19:07:52.942Z,1535396872.942 [NAL9602](INFO): NAL9602 initialized 2018-08-27T19:08:07.804Z,1535396887.804 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T19:08:07.804Z,1535396887.804 [Rowe_600LCM] No Fault, FailCount= 5 2018-08-27T19:08:07.937Z,1535396887.937 [Rowe_600LCM](INFO): Initializing 2018-08-27T19:08:07.937Z,1535396887.937 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T19:08:07.937Z,1535396887.937 [Rowe_600LCM](INFO): LCM OK 2018-08-27T19:08:07.937Z,1535396887.937 [Rowe_600LCM](INFO): Powering up 2018-08-27T19:08:12.060Z,1535396892.060 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T19:08:12.131Z,1535396892.131 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T19:08:12.132Z,1535396892.132 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T19:08:12.133Z,1535396892.133 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T19:08:12.134Z,1535396892.134 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T19:08:45.052Z,1535396925.052 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.378005 seconds old. 2018-08-27T19:08:45.455Z,1535396925.455 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.780566 seconds old. 2018-08-27T19:08:45.855Z,1535396925.855 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.180965 seconds old. 2018-08-27T19:08:46.300Z,1535396926.300 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.625012 seconds old. 2018-08-27T19:08:46.656Z,1535396926.656 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.981752 seconds old. 2018-08-27T19:08:47.055Z,1535396927.055 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.380756 seconds old. 2018-08-27T19:08:47.465Z,1535396927.465 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.790432 seconds old. 2018-08-27T19:08:47.868Z,1535396927.868 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 3.194181 seconds old. 2018-08-27T19:08:48.327Z,1535396928.327 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 3.653008 seconds old. 2018-08-27T19:08:48.655Z,1535396928.655 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 3.981030 seconds old. 2018-08-27T19:08:49.062Z,1535396929.062 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 4.387805 seconds old. 2018-08-27T19:08:49.465Z,1535396929.465 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 4.790401 seconds old. 2018-08-27T19:09:16.152Z,1535396956.152 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-27T19:04:15.6Z 2018-08-27T19:09:16.152Z,1535396956.152 [Default:CheckIn:Read_GPS] Stopped 2018-08-27T19:09:16.153Z,1535396956.153 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-27T19:09:17.446Z,1535396957.446 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20180827T181904/Courier0009.lzma 2018-08-27T19:09:18.341Z,1535396958.341 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Courier0009.lzma.bak 2018-08-27T19:09:18.341Z,1535396958.341 [DataOverHttps](INFO): SBD MOMSN=8448311 2018-08-27T19:09:29.975Z,1535396969.975 [DataOverHttps](INFO): Sending 319 bytes from file Logs/20180827T181904/Express0010.lzma 2018-08-27T19:09:30.771Z,1535396970.771 [DataOverHttps](INFO): Moved sent file to Logs/20180827T181904/Express0010.lzma.bak 2018-08-27T19:09:30.772Z,1535396970.772 [DataOverHttps](INFO): SBD MOMSN=8448317 2018-08-27T19:09:30.794Z,1535396970.794 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-27T19:09:32.774Z,1535396972.774 [Default:CheckIn:Read_Iridium] Stopped 2018-08-27T19:09:32.774Z,1535396972.774 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-27T19:09:32.774Z,1535396972.774 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-27T19:10:02.906Z,1535397002.906 [NAL9602](INFO): Powering down 2018-08-27T19:10:03.460Z,1535397003.460 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T19:10:03.460Z,1535397003.460 [BPC1] No Fault, FailCount= 10 2018-08-27T19:10:08.544Z,1535397008.544 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T19:10:08.544Z,1535397008.544 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-08-27T19:10:08.544Z,1535397008.544 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T19:10:08.598Z,1535397008.598 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T19:10:08.949Z,1535397008.949 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T19:10:09.109Z,1535397009.109 [Rowe_600LCM](INFO): Powering down 2018-08-27T19:10:10.619Z,1535397010.619 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T19:10:10.619Z,1535397010.619 [Rowe_600LCM] No Fault, FailCount= 1 2018-08-27T19:10:10.737Z,1535397010.737 [Rowe_600LCM](INFO): Initializing 2018-08-27T19:10:10.737Z,1535397010.737 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T19:10:10.738Z,1535397010.738 [Rowe_600LCM](INFO): LCM OK 2018-08-27T19:10:10.738Z,1535397010.738 [Rowe_600LCM](INFO): Powering up 2018-08-27T19:10:14.861Z,1535397014.861 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T19:10:15.020Z,1535397015.020 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T19:10:15.021Z,1535397015.021 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T19:10:15.022Z,1535397015.022 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T19:10:15.023Z,1535397015.023 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T19:10:28.942Z,1535397028.942 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_STOPPING 2018-08-27T19:10:55.296Z,1535397055.296 [ESPComponent](IMPORTANT): [sample #4] ESP sampling sequence completed normally. 2018-08-27T19:10:55.296Z,1535397055.296 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=4 2018-08-27T19:10:55.696Z,1535397055.696 [ESPComponent](IMPORTANT): [sample #4] ESP log summary report (2 messages): @14:21:51.62 Selecting Cartridge 35 @14:57:54.63 Sampled 1000.1ml 2018-08-27T19:10:55.696Z,1535397055.696 [ESPComponent](INFO): powering down ESP 2018-08-27T19:12:10.899Z,1535397130.899 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T19:12:10.899Z,1535397130.899 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-08-27T19:12:10.899Z,1535397130.899 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T19:12:11.261Z,1535397131.261 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T19:12:11.301Z,1535397131.301 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T19:12:11.414Z,1535397131.414 [Rowe_600LCM](INFO): Powering down 2018-08-27T19:12:12.881Z,1535397132.881 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T19:12:12.881Z,1535397132.881 [Rowe_600LCM] No Fault, FailCount= 2 2018-08-27T19:12:13.029Z,1535397133.029 [Rowe_600LCM](INFO): Initializing 2018-08-27T19:12:13.029Z,1535397133.029 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T19:12:13.030Z,1535397133.030 [Rowe_600LCM](INFO): LCM OK 2018-08-27T19:12:13.030Z,1535397133.030 [Rowe_600LCM](INFO): Powering up 2018-08-27T19:12:17.155Z,1535397137.155 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T19:12:17.320Z,1535397137.320 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T19:12:17.321Z,1535397137.321 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T19:12:17.322Z,1535397137.322 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T19:12:17.323Z,1535397137.323 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T19:14:13.669Z,1535397253.669 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T19:14:13.669Z,1535397253.669 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-08-27T19:14:13.669Z,1535397253.669 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T19:14:13.975Z,1535397253.975 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T19:14:14.073Z,1535397254.073 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T19:14:14.271Z,1535397254.271 [Rowe_600LCM](INFO): Powering down 2018-08-27T19:14:15.682Z,1535397255.682 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-08-27T19:14:15.682Z,1535397255.682 [Rowe_600LCM] No Fault, FailCount= 3 2018-08-27T19:14:15.885Z,1535397255.885 [Rowe_600LCM](INFO): Initializing 2018-08-27T19:14:15.885Z,1535397255.885 [Rowe_600LCM](INFO): Checking LCM 2018-08-27T19:14:15.886Z,1535397255.886 [Rowe_600LCM](INFO): LCM OK 2018-08-27T19:14:15.886Z,1535397255.886 [Rowe_600LCM](INFO): Powering up 2018-08-27T19:14:20.100Z,1535397260.100 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-08-27T19:14:20.165Z,1535397260.165 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-08-27T19:14:20.167Z,1535397260.167 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-08-27T19:14:20.167Z,1535397260.167 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-08-27T19:14:20.168Z,1535397260.168 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-08-27T19:14:29.569Z,1535397269.569 [CBIT](INFO): Clearing failed state for component DropWeight 2018-08-27T19:14:29.569Z,1535397269.569 [DropWeight] No Fault, FailCount= 1 2018-08-27T19:14:31.094Z,1535397271.094 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2018-08-27T19:14:31.094Z,1535397271.094 [DropWeight] Hardware Fault, FailCount= 1 2018-08-27T19:14:31.094Z,1535397271.094 [DropWeight](ERROR): Hardware Fault 2018-08-27T19:14:31.202Z,1535397271.202 [CBIT](INFO): Critical error at 20180827T191431 2018-08-27T19:14:31.205Z,1535397271.205 [CBIT](ERROR): Hardware Fault in component: DropWeight 2018-08-27T19:14:31.205Z,1535397271.205 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2018-08-27T19:14:31.579Z,1535397271.579 [CBIT](INFO): Critical error at 20180827T191431 2018-08-27T19:14:33.137Z,1535397273.137 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-27T19:14:33.137Z,1535397273.137 [Default:CheckIn:C.Wait] Stopped 2018-08-27T19:14:33.138Z,1535397273.138 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-27T19:14:33.138Z,1535397273.138 [Default:CheckIn:D] Running Loop=1 2018-08-27T19:14:33.543Z,1535397273.543 [Default:CheckIn:D] Stopped 2018-08-27T19:14:33.543Z,1535397273.543 [Default:CheckIn:E] Running Loop=1 2018-08-27T19:14:33.944Z,1535397273.944 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.113733 min 2018-08-27T19:14:33.944Z,1535397273.944 [Default:CheckIn:E] Stopped 2018-08-27T19:14:33.944Z,1535397273.944 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn] Stopped 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn](INFO): Running loop #4 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn] Running Loop=4 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-27T19:14:33.945Z,1535397273.945 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-27T19:14:34.698Z,1535397274.698 [NAL9602](INFO): Powering up 2018-08-27T19:14:45.835Z,1535397285.835 [NAL9602](INFO): NAL9602 initialized 2018-08-27T19:15:17.825Z,1535397317.825 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-08-27T19:15:17.909Z,1535397317.909 [NAL9602](FAULT): received: +CSQ:0 OK176, 2, 0, 0, 0 OK 2018-08-27T19:15:17.909Z,1535397317.909 [NAL9602] Data Fault, FailCount= 1 2018-08-27T19:15:17.909Z,1535397317.909 [NAL9602](ERROR): Data Fault 2018-08-27T19:15:18.040Z,1535397318.040 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-27T19:15:18.222Z,1535397318.222 [NAL9602](INFO): Powering down 2018-08-27T19:15:19.097Z,1535397319.097 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-27T19:15:19.097Z,1535397319.097 [NAL9602] No Fault, FailCount= 1 2018-08-27T19:15:48.538Z,1535397348.538 [NAL9602](INFO): Powering up NAL9602 2018-08-27T19:15:58.311Z,1535397358.311 [CommandLine](IMPORTANT): got command show stack 2018-08-27T19:15:58.311Z,1535397358.311 [CommandLine](IMPORTANT): Behavior Stack: 2018-08-27T19:15:58.311Z,1535397358.311 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface 2018-08-27T19:15:58.311Z,1535397358.311 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS 2018-08-27T19:15:59.561Z,1535397359.561 [CommandLine](IMPORTANT): got command failComponent 2018-08-27T19:15:59.738Z,1535397359.738 [NAL9602](INFO): NAL9602 initialized 2018-08-27T19:15:59.792Z,1535397359.792 [CommandLine](IMPORTANT): Failed components: 2018-08-27T19:15:59.792Z,1535397359.792 [CommandLine](IMPORTANT): DropWeight: Hardware Fault 2018-08-27T19:16:04.170Z,1535397364.170 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-27T19:16:04.170Z,1535397364.170 [BPC1] Communications Fault, FailCount= 1 2018-08-27T19:16:04.170Z,1535397364.170 [BPC1](ERROR): Communications Fault 2018-08-27T19:16:04.230Z,1535397364.230 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-27T19:16:05.404Z,1535397365.404 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-27T19:16:05.409Z,1535397365.409 [BPC1] No Fault, FailCount= 1 2018-08-27T19:16:11.752Z,1535397371.752 [CommandLine](IMPORTANT): got command configSet DropWeight.loadAtStartup 0.000000 bool persist 2018-08-27T19:16:11.753Z,1535397371.753 [CommandLine](IMPORTANT): configSet DropWeight.loadAtStartup requires a restart to take effect. 2018-08-27T19:16:15.452Z,1535397375.452 [CommandLine](IMPORTANT): got command restart application 2018-08-27T19:16:16.271Z,1535397376.271 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-08-27T19:16:16.271Z,1535397376.271 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-08-27T19:16:16.272Z,1535397376.272 [Rowe_600LCM](ERROR): Communications Fault 2018-08-27T19:16:16.461Z,1535397376.461 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:16.461Z,1535397376.461 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.621Z,1535397376.621 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-08-27T19:16:16.621Z,1535397376.621 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.622Z,1535397376.622 [CommandLine](INFO): Join timeout helper Thread ID is 1810 2018-08-27T19:16:16.624Z,1535397376.624 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-08-27T19:16:16.624Z,1535397376.624 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.624Z,1535397376.624 [NavChartDb](INFO): Join timeout helper Thread ID is 1811 2018-08-27T19:16:16.641Z,1535397376.641 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-08-27T19:16:16.661Z,1535397376.661 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:16.661Z,1535397376.661 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.669Z,1535397376.669 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-08-27T19:16:16.669Z,1535397376.669 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.669Z,1535397376.669 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1812 2018-08-27T19:16:16.673Z,1535397376.673 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T19:16:16.776Z,1535397376.776 [Rowe_600LCM](INFO): Powering down 2018-08-27T19:16:16.781Z,1535397376.781 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:16.782Z,1535397376.782 [WetLabsBB2FL](INFO): Powering down 2018-08-27T19:16:16.782Z,1535397376.782 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.797Z,1535397376.797 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-08-27T19:16:16.797Z,1535397376.797 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.798Z,1535397376.798 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1814 2018-08-27T19:16:16.833Z,1535397376.833 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:16.923Z,1535397376.923 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-08-27T19:16:16.923Z,1535397376.923 [CTD_Seabird](INFO): Powering down 2018-08-27T19:16:16.925Z,1535397376.925 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.926Z,1535397376.926 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler 2018-08-27T19:16:16.926Z,1535397376.926 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:16.928Z,1535397376.928 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 1816 2018-08-27T19:16:17.181Z,1535397377.181 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:17.181Z,1535397377.181 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-08-27T19:16:17.272Z,1535397377.272 [Rowe_600LCM](INFO): Powering down 2018-08-27T19:16:17.274Z,1535397377.274 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.282Z,1535397377.282 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-08-27T19:16:17.282Z,1535397377.282 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.283Z,1535397377.283 [Radio_Surface](INFO): Join timeout helper Thread ID is 1818 2018-08-27T19:16:17.285Z,1535397377.285 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:17.285Z,1535397377.285 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.307Z,1535397377.307 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-08-27T19:16:17.307Z,1535397377.307 [logger ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.307Z,1535397377.307 [logger](INFO): Join timeout helper Thread ID is 1819 2018-08-27T19:16:17.307Z,1535397377.307 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:17.308Z,1535397377.308 [logger ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.309Z,1535397377.309 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-08-27T19:16:17.309Z,1535397377.309 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.309Z,1535397377.309 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-08-27T19:16:17.310Z,1535397377.310 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.310Z,1535397377.310 [controlThread](INFO): Join timeout helper Thread ID is 1820 2018-08-27T19:16:17.329Z,1535397377.329 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-27T19:16:17.329Z,1535397377.329 [controlThread](DEBUG): Uninitializing ControlThread 2018-08-27T19:16:17.331Z,1535397377.331 [NAL9602](INFO): Powering down 2018-08-27T19:16:17.332Z,1535397377.332 [PNI_TCM](INFO): Powering down 2018-08-27T19:16:17.422Z,1535397377.422 [Aanderaa_O2](INFO): Powering down 2018-08-27T19:16:17.425Z,1535397377.425 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-08-27T19:16:17.427Z,1535397377.427 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-08-27T19:16:17.428Z,1535397377.428 [MissionManager](INFO): Uninitializing Mission Default 2018-08-27T19:16:17.428Z,1535397377.428 [Default] Stopped 2018-08-27T19:16:17.428Z,1535397377.428 [Default](DEBUG): Aggregate::uninitialize Default 2018-08-27T19:16:17.428Z,1535397377.428 [Default:B.GoToSurface] Stopped 2018-08-27T19:16:17.428Z,1535397377.428 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-08-27T19:16:17.428Z,1535397377.428 [Default:CheckIn] Stopped 2018-08-27T19:16:17.429Z,1535397377.429 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-27T19:16:17.429Z,1535397377.429 [Default:CheckIn:Read_GPS] Stopped 2018-08-27T19:16:17.434Z,1535397377.434 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-08-27T19:16:17.434Z,1535397377.434 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-08-27T19:16:17.434Z,1535397377.434 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-08-27T19:16:17.435Z,1535397377.435 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-08-27T19:16:17.435Z,1535397377.435 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-08-27T19:16:17.435Z,1535397377.435 [BuoyancyServo](INFO): Powering down 2018-08-27T19:16:17.449Z,1535397377.449 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-08-27T19:16:17.449Z,1535397377.449 [ElevatorServo](INFO): Powering down 2018-08-27T19:16:17.450Z,1535397377.450 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-08-27T19:16:17.451Z,1535397377.451 [MassServo](INFO): Powering down 2018-08-27T19:16:17.452Z,1535397377.452 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-08-27T19:16:17.452Z,1535397377.452 [RudderServo](INFO): Powering down 2018-08-27T19:16:17.455Z,1535397377.455 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-08-27T19:16:17.455Z,1535397377.455 [ThrusterServo](INFO): Powering down 2018-08-27T19:16:17.456Z,1535397377.456 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-08-27T19:16:17.457Z,1535397377.457 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-08-27T19:16:17.457Z,1535397377.457 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-08-27T19:16:17.458Z,1535397377.458 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.567Z,1535397377.567 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.574Z,1535397377.574 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.613Z,1535397377.613 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.686Z,1535397377.686 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.734Z,1535397377.734 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-27T19:16:17.795Z,1535397377.795 [logger ThreadHandler](INFO): Thread cancelled.