2019-10-02T20:53:40.333Z,1570049620.333 [Supervisor](DEBUG): Initializing supervisor.
2019-10-02T20:53:40.336Z,1570049620.336 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-10-02T20:53:40.336Z,1570049620.336 [SyncHandler](INFO): Protected caller Thread ID is 9267
2019-10-02T20:53:40.337Z,1570049620.337 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-10-02T20:53:40.338Z,1570049620.338 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-10-02T20:53:40.338Z,1570049620.338 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 9268
2019-10-02T20:53:40.341Z,1570049620.341 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-10-02T20:53:40.352Z,1570049620.352 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-10-02T20:53:40.353Z,1570049620.353 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-10-02T20:53:40.353Z,1570049620.353 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 9269
2019-10-02T20:53:40.354Z,1570049620.354 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-10-02T20:53:40.355Z,1570049620.355 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-10-02T20:53:40.355Z,1570049620.355 [logger ThreadHandler](INFO): Protected caller Thread ID is 9270
2019-10-02T20:53:40.357Z,1570049620.357 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-10-02T20:53:40.358Z,1570049620.358 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-10-02T20:53:40.359Z,1570049620.359 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-10-02T20:53:40.840Z,1570049620.840 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-10-02T20:53:40.841Z,1570049620.841 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-10-02T20:53:40.984Z,1570049620.984 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-10-02T20:53:40.984Z,1570049620.984 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-10-02T20:53:41.064Z,1570049621.064 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-10-02T20:53:41.161Z,1570049621.161 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-10-02T20:53:41.162Z,1570049621.162 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-10-02T20:53:41.255Z,1570049621.255 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-10-02T20:53:41.256Z,1570049621.256 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-10-02T20:53:41.637Z,1570049621.637 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-10-02T20:53:41.638Z,1570049621.638 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-10-02T20:53:41.739Z,1570049621.739 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-10-02T20:53:41.739Z,1570049621.739 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-10-02T20:53:42.198Z,1570049622.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-10-02T20:53:42.199Z,1570049622.199 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-10-02T20:53:42.474Z,1570049622.474 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-10-02T20:53:42.474Z,1570049622.474 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-10-02T20:53:42.776Z,1570049622.776 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-10-02T20:53:42.776Z,1570049622.776 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-10-02T20:53:42.986Z,1570049622.986 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-10-02T20:53:42.987Z,1570049622.987 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-10-02T20:53:43.127Z,1570049623.127 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-10-02T20:53:43.128Z,1570049623.128 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-10-02T20:53:43.744Z,1570049623.744 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-10-02T20:53:43.745Z,1570049623.745 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-10-02T20:53:44.091Z,1570049624.091 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-10-02T20:53:44.091Z,1570049624.091 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-10-02T20:53:44.296Z,1570049624.296 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-10-02T20:53:44.298Z,1570049624.298 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-triton/
2019-10-02T20:53:44.299Z,1570049624.299 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/vehicle.cfg
2019-10-02T20:53:44.498Z,1570049624.498 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/secure.cfg
2019-10-02T20:53:44.581Z,1570049624.581 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Science.cfg
2019-10-02T20:53:44.713Z,1570049624.713 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Simulator.cfg
2019-10-02T20:53:44.798Z,1570049624.798 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Battery.cfg
2019-10-02T20:53:45.026Z,1570049625.026 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-10-02T20:53:45.027Z,1570049625.027 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/logger.cfg
2019-10-02T20:53:45.120Z,1570049625.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Servo.cfg
2019-10-02T20:53:45.291Z,1570049625.291 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Navigation.cfg
2019-10-02T20:53:45.566Z,1570049625.566 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Sensor.cfg
2019-10-02T20:53:45.812Z,1570049625.812 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Control.cfg
2019-10-02T20:53:45.952Z,1570049625.952 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/BIT.cfg
2019-10-02T20:53:46.252Z,1570049626.252 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-triton/root/
2019-10-02T20:53:46.252Z,1570049626.252 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-10-02T20:53:46.261Z,1570049626.261 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-10-02T20:53:46.274Z,1570049626.274 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-10-02T20:53:46.275Z,1570049626.275 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-10-02T20:53:46.343Z,1570049626.343 [VerticalControl](DEBUG): Construct VerticalControl.
2019-10-02T20:53:46.456Z,1570049626.456 [VerticalControl] Loaded
2019-10-02T20:53:46.456Z,1570049626.456 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-10-02T20:53:46.457Z,1570049626.457 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-10-02T20:53:46.527Z,1570049626.527 [HorizontalControl] Loaded
2019-10-02T20:53:46.527Z,1570049626.527 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-10-02T20:53:46.528Z,1570049626.528 [SpeedControl](DEBUG): Construct SpeedControl.
2019-10-02T20:53:46.533Z,1570049626.533 [SpeedControl] Loaded
2019-10-02T20:53:46.534Z,1570049626.534 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-10-02T20:53:46.535Z,1570049626.535 [LoopControl](DEBUG): Construct LoopControl.
2019-10-02T20:53:46.535Z,1570049626.535 [LoopControl] Loaded
2019-10-02T20:53:46.535Z,1570049626.535 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-10-02T20:53:46.536Z,1570049626.536 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-10-02T20:53:46.536Z,1570049626.536 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-10-02T20:53:46.639Z,1570049626.639 [BuoyancyServo] Loaded
2019-10-02T20:53:46.640Z,1570049626.640 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-10-02T20:53:46.651Z,1570049626.651 [ElevatorServo] Loaded
2019-10-02T20:53:46.651Z,1570049626.651 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-10-02T20:53:46.662Z,1570049626.662 [MassServo] Loaded
2019-10-02T20:53:46.662Z,1570049626.662 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-10-02T20:53:46.673Z,1570049626.673 [RudderServo] Loaded
2019-10-02T20:53:46.673Z,1570049626.673 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-10-02T20:53:46.684Z,1570049626.684 [ThrusterServo] Loaded
2019-10-02T20:53:46.684Z,1570049626.684 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-10-02T20:53:46.685Z,1570049626.685 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-10-02T20:53:46.685Z,1570049626.685 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-10-02T20:53:46.726Z,1570049626.726 [DepthRateCalculator] Loaded
2019-10-02T20:53:46.726Z,1570049626.726 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-10-02T20:53:46.731Z,1570049626.731 [PitchRateCalculator] Loaded
2019-10-02T20:53:46.732Z,1570049626.732 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-10-02T20:53:46.747Z,1570049626.747 [SpeedCalculator] Loaded
2019-10-02T20:53:46.747Z,1570049626.747 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-10-02T20:53:46.768Z,1570049626.768 [TempGradientCalculator] Loaded
2019-10-02T20:53:46.768Z,1570049626.768 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-10-02T20:53:46.774Z,1570049626.774 [YawRateCalculator] Loaded
2019-10-02T20:53:46.774Z,1570049626.774 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-10-02T20:53:46.804Z,1570049626.804 [ElevatorOffsetCalculator] Loaded
2019-10-02T20:53:46.804Z,1570049626.804 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-10-02T20:53:46.804Z,1570049626.804 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-10-02T20:53:46.805Z,1570049626.805 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-10-02T20:53:46.908Z,1570049626.908 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-10-02T20:53:46.909Z,1570049626.909 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-10-02T20:53:46.929Z,1570049626.929 [NavChart] Loaded
2019-10-02T20:53:46.930Z,1570049626.930 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-10-02T20:53:46.934Z,1570049626.934 [UniversalFixResidualReporter] Loaded
2019-10-02T20:53:46.934Z,1570049626.934 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-10-02T20:53:46.934Z,1570049626.934 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-10-02T20:53:46.935Z,1570049626.935 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-10-02T20:53:47.186Z,1570049627.186 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-10-02T20:53:47.191Z,1570049627.191 [AHRS_M2](INFO): created writer for : platform_orientation
2019-10-02T20:53:47.193Z,1570049627.193 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-10-02T20:53:47.198Z,1570049627.198 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-10-02T20:53:47.199Z,1570049627.199 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-10-02T20:53:47.204Z,1570049627.204 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-10-02T20:53:47.204Z,1570049627.204 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-10-02T20:53:47.210Z,1570049627.210 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-10-02T20:53:47.281Z,1570049627.281 [AHRS_M2] Loaded
2019-10-02T20:53:47.282Z,1570049627.282 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-10-02T20:53:47.356Z,1570049627.356 [DataOverHttps] Loaded
2019-10-02T20:53:47.357Z,1570049627.357 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-10-02T20:53:47.358Z,1570049627.358 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408024E0
2019-10-02T20:53:47.358Z,1570049627.358 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 9350
2019-10-02T20:53:47.371Z,1570049627.371 [Depth_Keller] Loaded
2019-10-02T20:53:47.372Z,1570049627.372 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-10-02T20:53:47.377Z,1570049627.377 [DropWeight] Loaded
2019-10-02T20:53:47.377Z,1570049627.377 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-10-02T20:53:47.474Z,1570049627.474 [NAL9602] Loaded
2019-10-02T20:53:47.474Z,1570049627.474 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-10-02T20:53:47.490Z,1570049627.490 [Onboard] Loaded
2019-10-02T20:53:47.490Z,1570049627.490 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-10-02T20:53:47.494Z,1570049627.494 [Radio_Surface] Loaded
2019-10-02T20:53:47.494Z,1570049627.494 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-10-02T20:53:47.495Z,1570049627.495 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408324E0
2019-10-02T20:53:47.495Z,1570049627.495 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 9351
2019-10-02T20:53:47.623Z,1570049627.623 [DAT] Loaded
2019-10-02T20:53:47.623Z,1570049627.623 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-10-02T20:53:49.144Z,1570049629.144 [BPC1] Loaded
2019-10-02T20:53:49.144Z,1570049629.144 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-10-02T20:53:49.145Z,1570049629.145 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-10-02T20:53:49.145Z,1570049629.145 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-10-02T20:53:49.215Z,1570049629.215 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-10-02T20:53:49.215Z,1570049629.215 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-10-02T20:53:49.317Z,1570049629.317 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-10-02T20:53:49.318Z,1570049629.318 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-10-02T20:53:49.354Z,1570049629.354 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-10-02T20:53:49.354Z,1570049629.354 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-10-02T20:53:49.536Z,1570049629.536 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-10-02T20:53:49.541Z,1570049629.541 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-10-02T20:53:49.542Z,1570049629.542 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-10-02T20:53:49.547Z,1570049629.547 [CTD_Seabird](INFO): created writer for : depth
2019-10-02T20:53:49.547Z,1570049629.547 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-10-02T20:53:49.552Z,1570049629.552 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-10-02T20:53:49.553Z,1570049629.553 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-10-02T20:53:49.558Z,1570049629.558 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-10-02T20:53:49.559Z,1570049629.559 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-10-02T20:53:49.564Z,1570049629.564 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-10-02T20:53:49.565Z,1570049629.565 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-10-02T20:53:49.570Z,1570049629.570 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-10-02T20:53:49.571Z,1570049629.571 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-10-02T20:53:49.576Z,1570049629.576 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-10-02T20:53:49.576Z,1570049629.576 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): mass_concentration_of_oxygen_in_sea_water
2019-10-02T20:53:49.582Z,1570049629.582 [CTD_Seabird](INFO): created writer for : mass_concentration_of_oxygen_in_sea_water
2019-10-02T20:53:49.582Z,1570049629.582 [CTD_Seabird](DEBUG): LcmSlateWriter::add(DAtaURI): CTD_Seabird.sea_water_dissolved_oxygen_freq
2019-10-02T20:53:49.583Z,1570049629.583 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): dataName: sea_water_dissolved_oxygen_freq
2019-10-02T20:53:49.616Z,1570049629.616 [CTD_Seabird] Loaded
2019-10-02T20:53:49.616Z,1570049629.616 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-10-02T20:53:49.617Z,1570049629.617 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409C94E0
2019-10-02T20:53:49.618Z,1570049629.618 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 9352
2019-10-02T20:53:49.648Z,1570049629.648 [ESPComponent] Loaded
2019-10-02T20:53:49.649Z,1570049629.649 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-10-02T20:53:49.663Z,1570049629.663 [PAR_Licor] Loaded
2019-10-02T20:53:49.663Z,1570049629.663 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-10-02T20:53:49.711Z,1570049629.711 [WetLabsBB2FL] Loaded
2019-10-02T20:53:49.712Z,1570049629.712 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-10-02T20:53:49.713Z,1570049629.713 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409F94E0
2019-10-02T20:53:49.713Z,1570049629.713 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 9353
2019-10-02T20:53:49.714Z,1570049629.714 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-10-02T20:53:49.714Z,1570049629.714 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-10-02T20:53:50.013Z,1570049630.013 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-10-02T20:53:50.013Z,1570049630.013 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-10-02T20:53:50.151Z,1570049630.151 [SBIT](DEBUG): Construct Startup Built In Test.
2019-10-02T20:53:50.162Z,1570049630.162 [SBIT] Loaded
2019-10-02T20:53:50.163Z,1570049630.163 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-10-02T20:53:50.163Z,1570049630.163 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-10-02T20:53:50.175Z,1570049630.175 [IBIT] Loaded
2019-10-02T20:53:50.175Z,1570049630.175 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-10-02T20:53:50.178Z,1570049630.178 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-10-02T20:53:50.316Z,1570049630.316 [CBIT] Loaded
2019-10-02T20:53:50.317Z,1570049630.317 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-10-02T20:53:50.317Z,1570049630.317 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-10-02T20:53:50.351Z,1570049630.351 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-10-02T20:53:50.352Z,1570049630.352 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-10-02T20:53:50.373Z,1570049630.373 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-10-02T20:53:50.375Z,1570049630.375 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD84E0
2019-10-02T20:53:50.375Z,1570049630.375 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 9354
2019-10-02T20:53:50.380Z,1570049630.380 [Supervisor](INFO): Main Thread ID is 9266
2019-10-02T20:53:50.380Z,1570049630.380 [Supervisor](DEBUG): Running supervisor.
2019-10-02T20:53:50.405Z,1570049630.405 [CommandLine ThreadHandler](INFO): Handler Thread ID is 9355
2019-10-02T20:53:50.421Z,1570049630.421 [controlThread ThreadHandler](INFO): Handler Thread ID is 9356
2019-10-02T20:53:50.422Z,1570049630.422 [controlThread](DEBUG): Initializing ControlThread
2019-10-02T20:53:50.422Z,1570049630.422 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-10-02T20:53:50.424Z,1570049630.424 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-10-02T20:53:50.424Z,1570049630.424 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-10-02T20:53:50.425Z,1570049630.425 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-10-02T20:53:50.426Z,1570049630.426 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-10-02T20:53:50.426Z,1570049630.426 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-10-02T20:53:50.426Z,1570049630.426 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-10-02T20:53:50.427Z,1570049630.427 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-10-02T20:53:50.427Z,1570049630.427 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-10-02T20:53:50.428Z,1570049630.428 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-10-02T20:53:50.429Z,1570049630.429 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-10-02T20:53:50.429Z,1570049630.429 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-10-02T20:53:50.437Z,1570049630.437 [SBIT](INFO): Initialize SBIT Component.
2019-10-02T20:53:50.438Z,1570049630.438 [SBIT](IMPORTANT): git: 2019-09-23-triton4
2019-10-02T20:53:50.438Z,1570049630.438 [SBIT](INFO): git hash: 44996ebdb3f43e0ac5b405bbdb4f589f752fd91c
2019-10-02T20:53:50.438Z,1570049630.438 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-10-02T20:53:50.439Z,1570049630.439 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-10-02T20:53:50.440Z,1570049630.440 [SBIT](INFO): Beginning SBIT in 24.000000 seconds.
2019-10-02T20:53:50.441Z,1570049630.441 [IBIT](INFO): Initialize IBIT Component.
2019-10-02T20:53:50.442Z,1570049630.442 [CBIT](DEBUG): Initialize CBIT Component.
2019-10-02T20:53:50.443Z,1570049630.443 [logger ThreadHandler](INFO): Handler Thread ID is 9357
2019-10-02T20:53:50.444Z,1570049630.444 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 9358
2019-10-02T20:53:50.449Z,1570049630.449 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-10-02T20:53:50.453Z,1570049630.453 [CBIT](DEBUG): Initialized mux pins.
2019-10-02T20:53:50.453Z,1570049630.453 [CBIT](DEBUG): Initializing the watchdog timer.
2019-10-02T20:53:50.466Z,1570049630.466 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 9359
2019-10-02T20:53:50.473Z,1570049630.473 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 9360
2019-10-02T20:53:50.474Z,1570049630.474 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-10-02T20:53:50.477Z,1570049630.477 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-10-02T20:53:50.477Z,1570049630.477 [CBIT](DEBUG): Initializing heartbeat.
2019-10-02T20:53:50.478Z,1570049630.478 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-10-02T20:53:50.479Z,1570049630.479 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 9362
2019-10-02T20:53:50.480Z,1570049630.480 [WetLabsBB2FL](INFO): Powering down
2019-10-02T20:53:50.512Z,1570049630.512 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 9363
2019-10-02T20:53:50.515Z,1570049630.515 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-10-02T20:53:50.515Z,1570049630.515 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-10-02T20:53:50.516Z,1570049630.516 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-10-02T20:53:50.516Z,1570049630.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-10-02T20:53:50.516Z,1570049630.516 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-10-02T20:53:50.516Z,1570049630.516 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-10-02T20:53:50.516Z,1570049630.516 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-10-02T20:53:50.522Z,1570049630.522 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-10-02T20:53:50.522Z,1570049630.522 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-10-02T20:53:50.522Z,1570049630.522 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-10-02T20:53:50.522Z,1570049630.522 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-10-02T20:53:50.522Z,1570049630.522 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-10-02T20:53:50.523Z,1570049630.523 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-10-02T20:53:50.523Z,1570049630.523 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-10-02T20:53:50.523Z,1570049630.523 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-10-02T20:53:50.523Z,1570049630.523 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-10-02T20:53:50.549Z,1570049630.549 [CBIT](DEBUG): Deactivating GF circuits.
2019-10-02T20:53:50.549Z,1570049630.549 [CBIT](DEBUG): Deactivating emergency mode.
2019-10-02T20:53:50.585Z,1570049630.585 [CBIT](DEBUG): Backplane powered.
2019-10-02T20:53:50.586Z,1570049630.586 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-10-02T20:53:50.596Z,1570049630.596 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-02T20:53:50.615Z,1570049630.615 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-10-02T20:53:50.615Z,1570049630.615 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-10-02T20:53:50.683Z,1570049630.683 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-10-02T20:53:50.684Z,1570049630.684 [Default:A.Wait](DEBUG): Construct Wait.
2019-10-02T20:53:50.686Z,1570049630.686 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-02T20:53:50.729Z,1570049630.729 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-10-02T20:53:50.731Z,1570049630.731 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-10-02T20:53:50.736Z,1570049630.736 [Default:E.Execute](DEBUG): Construct Execute.
2019-10-02T20:53:50.750Z,1570049630.750 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

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

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-10-02T20:53:50.778Z,1570049630.778 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,BPC1,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-10-02T20:53:50.785Z,1570049630.785 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-10-02T20:53:50.850Z,1570049630.850 [Depth_Keller](ERROR): Pressure reading out of range: 1925.893799 decibar
2019-10-02T20:53:50.869Z,1570049630.869 [Radio_Surface](INFO): Powering up
2019-10-02T20:53:50.877Z,1570049630.877 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-10-02T20:53:50.877Z,1570049630.877 [DAT](INFO): Powering up
2019-10-02T20:53:50.877Z,1570049630.877 [DAT](DEBUG): Initializing DAT.
2019-10-02T20:53:50.910Z,1570049630.910 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-10-02T20:53:50.943Z,1570049630.943 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-10-02T20:53:50.991Z,1570049630.991 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-10-02T20:53:50.997Z,1570049630.997 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-10-02T20:53:50.999Z,1570049630.999 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-10-02T20:53:51.009Z,1570049631.009 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-10-02T20:53:51.010Z,1570049631.010 [MassServo](DEBUG): Initializing EZServoServo.
2019-10-02T20:53:51.021Z,1570049631.021 [MassServo](DEBUG): Initializing MassServo.
2019-10-02T20:53:51.022Z,1570049631.022 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-02T20:53:51.033Z,1570049631.033 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-02T20:53:51.034Z,1570049631.034 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-10-02T20:53:51.045Z,1570049631.045 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-10-02T20:54:04.542Z,1570049644.542 [DAT](INFO): setting local address to 5
2019-10-02T20:54:04.945Z,1570049644.945 [DAT](INFO): set local address to 5
2019-10-02T20:54:06.334Z,1570049646.334 [CommandLine](IMPORTANT): got command failComponent
2019-10-02T20:54:06.334Z,1570049646.334 [CommandLine](IMPORTANT): Failed components:
2019-10-02T20:54:06.334Z,1570049646.334 [CommandLine](IMPORTANT): No failed Components.
2019-10-02T20:54:06.538Z,1570049646.538 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004457
2019-10-02T20:54:15.087Z,1570049655.087 [SBIT](IMPORTANT): Beginning Startup BIT
2019-10-02T20:54:15.099Z,1570049655.099 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T20:54:17.602Z,1570049657.602 [NAL9602](INFO): Powering up NAL9602
2019-10-02T20:54:26.150Z,1570049666.150 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.006714
CHAN A1 (24V): -0.004920
CHAN A2 (12V): -0.004985
CHAN A3 (5V): -0.003192
CHAN B0 (3.3V): -0.001829
CHAN B1 (3.15aV): -0.000640
CHAN B2 (3.15bV): -0.000704
CHAN B3 (GND): 0.003343
OPEN: 0.005170
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T20:54:28.502Z,1570049668.502 [NAL9602](INFO): NAL9602 initialized
2019-10-02T20:54:29.325Z,1570049669.325 [NAL9602](DEBUG): Fix Requested
2019-10-02T20:54:29.721Z,1570049669.721 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205422.00,A,3648.16269,N,12147.27810,W,2.391,0.00,021019,,,A*73
2019-10-02T20:54:29.724Z,1570049669.724 [NAL9602](INFO): GPS fix at 20191002T205422: (36.802712, -121.787968)
2019-10-02T20:54:37.029Z,1570049677.029 [CommandLine](IMPORTANT): got command failComponent
2019-10-02T20:54:37.030Z,1570049677.030 [CommandLine](IMPORTANT): Failed components:
2019-10-02T20:54:37.030Z,1570049677.030 [CommandLine](IMPORTANT): No failed Components.
2019-10-02T20:54:44.990Z,1570049684.990 [CommandLine](IMPORTANT): got command get Onboard.Pressure
2019-10-02T20:54:44.990Z,1570049684.990 [CommandLine](IMPORTANT): Onboard.Pressure 55609.578125 Pa
2019-10-02T20:54:52.839Z,1570049692.839 [CommandLine](IMPORTANT): got command get Onboard.Humidity
2019-10-02T20:54:52.839Z,1570049692.839 [CommandLine](IMPORTANT): Onboard.Humidity 10.633622 %
2019-10-02T20:55:08.773Z,1570049708.773 [SBIT](IMPORTANT): SBIT PASSED
2019-10-02T20:55:08.858Z,1570049708.858 [CommandLine](IMPORTANT): got command configSet list
2019-10-02T20:55:08.858Z,1570049708.858 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-10-02T20:55:08.859Z,1570049708.859 [CommandLine](IMPORTANT): CBIT.gf24Offset=155 microampere;

2019-10-02T20:55:08.859Z,1570049708.859 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-10-02T20:55:08.860Z,1570049708.860 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-10-02T20:55:08.860Z,1570049708.860 [CommandLine](IMPORTANT): Express linearApproximation DVL_micro.height_above_sea_floor 5.000000 meter;

2019-10-02T20:55:08.860Z,1570049708.860 [CommandLine](IMPORTANT): VerticalControl.massDefault=-1 millimeter;

2019-10-02T20:55:09.152Z,1570049709.152 [MissionManager](IMPORTANT): Started mission Startup
2019-10-02T20:55:09.153Z,1570049709.153 [Startup] Running Loop=1
2019-10-02T20:55:09.153Z,1570049709.153 [Startup](DEBUG): Aggregate::initialize Startup
2019-10-02T20:55:09.153Z,1570049709.153 [Startup:A.GoToSurface] Running Loop=1
2019-10-02T20:55:09.153Z,1570049709.153 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-02T20:55:09.154Z,1570049709.154 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-02T20:55:09.154Z,1570049709.154 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-02T20:55:09.155Z,1570049709.155 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-02T20:55:09.155Z,1570049709.155 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-02T20:55:09.155Z,1570049709.155 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-02T20:55:09.157Z,1570049709.157 [Startup:StartupSatComms] Running Loop=1
2019-10-02T20:55:09.157Z,1570049709.157 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-10-02T20:55:09.157Z,1570049709.157 [Startup:StartupSatComms:A] Running Loop=1
2019-10-02T20:55:09.565Z,1570049709.565 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-10-02T20:56:09.337Z,1570049769.337 [Startup:StartupSatComms:A](INFO): Timed out from 2019-10-02T20:55:09.2Z
2019-10-02T20:56:09.337Z,1570049769.337 [Startup:StartupSatComms:A] Stopped
2019-10-02T20:56:09.337Z,1570049769.337 [Startup:StartupSatComms:B] Running Loop=1
2019-10-02T20:56:09.741Z,1570049769.741 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-02T20:56:17.897Z,1570049777.897 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190926T180146/Courier0031.lzma
2019-10-02T20:56:19.903Z,1570049779.903 [DataOverHttps](INFO): Moved sent file to Logs/20190926T180146/Courier0031.lzma.bak
2019-10-02T20:56:19.903Z,1570049779.903 [DataOverHttps](INFO): SBD MOMSN=11840758
2019-10-02T20:56:38.420Z,1570049798.420 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20191002T205340/Courier0000.lzma
2019-10-02T20:56:40.426Z,1570049800.426 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0000.lzma.bak
2019-10-02T20:56:40.426Z,1570049800.426 [DataOverHttps](INFO): SBD MOMSN=11840760
2019-10-02T20:57:07.628Z,1570049827.628 [DataOverHttps](INFO): Sending 167 bytes from file Logs/20190926T180146/Express0032.lzma
2019-10-02T20:57:09.545Z,1570049829.545 [Startup:StartupSatComms:B](INFO): Timed out from 2019-10-02T20:56:09.3Z
2019-10-02T20:57:09.545Z,1570049829.545 [Startup:StartupSatComms:B] Stopped
2019-10-02T20:57:09.545Z,1570049829.545 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-10-02T20:57:09.545Z,1570049829.545 [Startup:StartupSatComms] Stopped
2019-10-02T20:57:09.545Z,1570049829.545 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-10-02T20:57:09.546Z,1570049829.546 [Startup](INFO): Completed Startup
2019-10-02T20:57:09.546Z,1570049829.546 [MissionManager](INFO): Startup is completed.
2019-10-02T20:57:09.546Z,1570049829.546 [MissionManager](INFO): Uninitializing Mission Startup
2019-10-02T20:57:09.546Z,1570049829.546 [Startup] Stopped
2019-10-02T20:57:09.546Z,1570049829.546 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-10-02T20:57:09.546Z,1570049829.546 [Startup:A.GoToSurface] Stopped
2019-10-02T20:57:09.546Z,1570049829.546 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-02T20:57:09.634Z,1570049829.634 [DataOverHttps](INFO): Moved sent file to Logs/20190926T180146/Express0032.lzma.bak
2019-10-02T20:57:09.634Z,1570049829.634 [DataOverHttps](INFO): SBD MOMSN=11840764
2019-10-02T20:57:09.964Z,1570049829.964 [MissionManager](IMPORTANT): Started mission Default
2019-10-02T20:57:09.964Z,1570049829.964 [Default] Running Loop=1
2019-10-02T20:57:09.965Z,1570049829.965 [Default](DEBUG): Aggregate::initialize Default
2019-10-02T20:57:09.965Z,1570049829.965 [Default:B.GoToSurface] Running Loop=1
2019-10-02T20:57:09.965Z,1570049829.965 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-02T20:57:09.965Z,1570049829.965 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-02T20:57:09.966Z,1570049829.966 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-02T20:57:09.966Z,1570049829.966 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-02T20:57:09.966Z,1570049829.966 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-02T20:57:09.966Z,1570049829.966 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-02T20:57:09.967Z,1570049829.967 [Default:A.Wait] Running Loop=1
2019-10-02T20:57:09.967Z,1570049829.967 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-02T20:57:23.289Z,1570049843.289 [Default:A.Wait](INFO): Done Waiting.
2019-10-02T20:57:23.289Z,1570049843.289 [Default:A.Wait] Stopped
2019-10-02T20:57:23.289Z,1570049843.289 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T20:57:23.684Z,1570049843.684 [Default:CheckIn] Running Loop=1
2019-10-02T20:57:23.684Z,1570049843.684 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T20:57:23.684Z,1570049843.684 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T20:57:24.084Z,1570049844.084 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-10-02T20:58:36.795Z,1570049916.795 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T20:58:43.679Z,1570049923.679 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T20:58:59.835Z,1570049939.835 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T20:59:14.838Z,1570049954.838 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T20:59:30.130Z,1570049970.130 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T20:59:32.126Z,1570049972.126 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T20:59:32.941Z,1570049972.941 [NAL9602](DEBUG): Fix Requested
2019-10-02T20:59:33.340Z,1570049973.340 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205925.00,A,3648.15592,N,12147.27491,W,0.486,66.30,021019,,,A*4C
2019-10-02T20:59:33.342Z,1570049973.342 [NAL9602](INFO): GPS fix at 20191002T205925: (36.802599, -121.787915)
2019-10-02T20:59:33.387Z,1570049973.387 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T20:59:33.387Z,1570049973.387 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T20:59:33.782Z,1570049973.782 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-02T20:59:43.112Z,1570049983.112 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191002T205340/Courier0004.lzma
2019-10-02T20:59:45.118Z,1570049985.118 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0004.lzma.bak
2019-10-02T20:59:45.119Z,1570049985.119 [DataOverHttps](INFO): SBD MOMSN=11840768
2019-10-02T20:59:45.474Z,1570049985.474 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:00:00.831Z,1570050000.831 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:00:05.262Z,1570050005.262 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T21:00:08.922Z,1570050008.922 [DataOverHttps](INFO): Sending 944 bytes from file Logs/20191002T205340/Express0001.lzma
2019-10-02T21:00:10.926Z,1570050010.926 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0001.lzma.bak
2019-10-02T21:00:10.926Z,1570050010.926 [DataOverHttps](INFO): SBD MOMSN=11840771
2019-10-02T21:00:16.185Z,1570050016.185 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:00:31.541Z,1570050031.541 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:00:31.928Z,1570050031.928 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20191002T205340/Express0005.lzma
2019-10-02T21:00:33.934Z,1570050033.934 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0005.lzma.bak
2019-10-02T21:00:33.934Z,1570050033.934 [DataOverHttps](INFO): SBD MOMSN=11840799
2019-10-02T21:00:37.637Z,1570050037.637 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T21:00:37.637Z,1570050037.637 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T21:00:37.637Z,1570050037.637 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T21:00:47.300Z,1570050047.300 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:02:15.834Z,1570050135.834 [CommandLine](IMPORTANT): got command failComponent
2019-10-02T21:02:15.834Z,1570050135.834 [CommandLine](IMPORTANT): Failed components:
2019-10-02T21:02:15.834Z,1570050135.834 [CommandLine](IMPORTANT): No failed Components.
2019-10-02T21:05:38.266Z,1570050338.266 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T21:05:38.266Z,1570050338.266 [Default:CheckIn:C.Wait] Stopped
2019-10-02T21:05:38.266Z,1570050338.266 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T21:05:38.267Z,1570050338.267 [Default:CheckIn:D] Running Loop=1
2019-10-02T21:05:38.671Z,1570050338.671 [Default:CheckIn:D] Stopped
2019-10-02T21:05:38.671Z,1570050338.671 [Default:CheckIn:E] Running Loop=1
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.478438 min 
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn:E] Stopped
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn] Stopped
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn](INFO): Running loop #2
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn] Running Loop=2
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T21:05:39.042Z,1570050339.042 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T21:05:40.625Z,1570050340.625 [NAL9602](DEBUG): Fix Requested
2019-10-02T21:05:41.020Z,1570050341.020 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210533.00,A,3648.16301,N,12147.27973,W,0.175,312.91,021019,,,A*7F
2019-10-02T21:05:41.022Z,1570050341.022 [NAL9602](INFO): GPS fix at 20191002T210533: (36.802717, -121.787995)
2019-10-02T21:05:41.097Z,1570050341.097 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T21:05:41.097Z,1570050341.097 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T21:05:43.384Z,1570050343.384 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191002T205340/Courier0007.lzma
2019-10-02T21:05:45.394Z,1570050345.394 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0007.lzma.bak
2019-10-02T21:05:45.394Z,1570050345.394 [DataOverHttps](INFO): SBD MOMSN=11840811
2019-10-02T21:06:05.301Z,1570050365.301 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20191002T205340/Express0008.lzma
2019-10-02T21:06:07.306Z,1570050367.306 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0008.lzma.bak
2019-10-02T21:06:07.307Z,1570050367.307 [DataOverHttps](INFO): SBD MOMSN=11840814
2019-10-02T21:06:11.040Z,1570050371.040 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T21:06:11.040Z,1570050371.040 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T21:06:11.040Z,1570050371.040 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T21:06:15.043Z,1570050375.043 [NAL9602](INFO): SBD MO Status=2, MOMSN=2081, MT Status=2, MTMSN=0
2019-10-02T21:06:15.044Z,1570050375.044 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:06:37.668Z,1570050397.668 [NAL9602](INFO): SBD MO Status=2, MOMSN=2081, MT Status=2, MTMSN=0
2019-10-02T21:06:37.668Z,1570050397.668 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:06:52.211Z,1570050412.211 [NAL9602](INFO): SBD MO Status=1, MOMSN=2081, MT Status=0, MTMSN=0
2019-10-02T21:06:52.212Z,1570050412.212 [NAL9602](INFO): No messages in MT queue
2019-10-02T21:07:22.918Z,1570050442.918 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T21:08:14.261Z,1570050494.261 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:08:29.994Z,1570050509.994 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:08:45.349Z,1570050525.349 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:09:00.717Z,1570050540.717 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:09:16.074Z,1570050556.074 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:09:31.421Z,1570050571.421 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:09:46.777Z,1570050586.777 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:10:02.137Z,1570050602.137 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:10:17.477Z,1570050617.477 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:10:32.423Z,1570050632.423 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:11:11.673Z,1570050671.673 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T21:11:11.674Z,1570050671.674 [Default:CheckIn:C.Wait] Stopped
2019-10-02T21:11:11.674Z,1570050671.674 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T21:11:11.674Z,1570050671.674 [Default:CheckIn:D] Running Loop=1
2019-10-02T21:11:12.058Z,1570050672.058 [Default:CheckIn:D] Stopped
2019-10-02T21:11:12.059Z,1570050672.059 [Default:CheckIn:E] Running Loop=1
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 14.034899 min 
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn:E] Stopped
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn] Stopped
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn](INFO): Running loop #3
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn] Running Loop=3
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T21:11:12.470Z,1570050672.470 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T21:11:14.049Z,1570050674.049 [NAL9602](DEBUG): Fix Requested
2019-10-02T21:11:14.444Z,1570050674.444 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211106.00,A,3648.16326,N,12147.28713,W,0.097,312.91,021019,,,A*73
2019-10-02T21:11:14.446Z,1570050674.446 [NAL9602](INFO): GPS fix at 20191002T211106: (36.802721, -121.788119)
2019-10-02T21:11:14.470Z,1570050674.470 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T21:11:14.470Z,1570050674.470 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T21:11:24.616Z,1570050684.616 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191002T205340/Courier0010.lzma
2019-10-02T21:11:26.622Z,1570050686.622 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0010.lzma.bak
2019-10-02T21:11:26.622Z,1570050686.622 [DataOverHttps](INFO): SBD MOMSN=11840821
2019-10-02T21:11:46.248Z,1570050706.248 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191002T205340/Express0011.lzma
2019-10-02T21:11:48.254Z,1570050708.254 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0011.lzma.bak
2019-10-02T21:11:48.255Z,1570050708.255 [DataOverHttps](INFO): SBD MOMSN=11840824
2019-10-02T21:11:52.197Z,1570050712.197 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T21:11:52.198Z,1570050712.198 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T21:11:52.198Z,1570050712.198 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T21:13:23.318Z,1570050803.318 [NAL9602](INFO): SBD MO Status=2, MOMSN=2082, MT Status=2, MTMSN=0
2019-10-02T21:13:23.319Z,1570050803.319 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:13:48.914Z,1570050828.914 [CommandLine](IMPORTANT): got command failComponent
2019-10-02T21:13:48.914Z,1570050828.914 [CommandLine](IMPORTANT): Failed components:
2019-10-02T21:13:48.914Z,1570050828.914 [CommandLine](IMPORTANT): No failed Components.
2019-10-02T21:13:51.372Z,1570050831.372 [CommandLine](IMPORTANT): got command gfscan
2019-10-02T21:13:51.643Z,1570050831.643 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T21:14:02.550Z,1570050842.550 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.015452
CHAN A1 (24V): 0.029870
CHAN A2 (12V): 0.010783
CHAN A3 (5V): 0.001989
CHAN B0 (3.3V): 0.002601
CHAN B1 (3.15aV): 0.002456
CHAN B2 (3.15bV): 0.001956
CHAN B3 (GND): -0.000794
OPEN: 0.005900
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T21:14:06.143Z,1570050846.143 [NAL9602](INFO): SBD MO Status=2, MOMSN=2082, MT Status=2, MTMSN=0
2019-10-02T21:14:06.143Z,1570050846.143 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:14:18.667Z,1570050858.667 [CommandLine](IMPORTANT): got command show variable dvl_micro
2019-10-02T21:14:18.721Z,1570050858.721 [CommandLine](IMPORTANT): DVL_micro.loadControl (none)
2019-10-02T21:14:18.722Z,1570050858.722 [CommandLine](IMPORTANT): DVL_micro.uart (none)
2019-10-02T21:14:18.722Z,1570050858.722 [CommandLine](IMPORTANT): DVL_micro.baud (bit_per_second)
2019-10-02T21:14:18.829Z,1570050858.829 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup (bool)
2019-10-02T21:14:18.830Z,1570050858.830 [CommandLine](IMPORTANT): DVL_micro.simulateHardware (bool)
2019-10-02T21:14:18.830Z,1570050858.830 [CommandLine](IMPORTANT): DVL_micro.magDeviation (degree)
2019-10-02T21:14:18.830Z,1570050858.830 [CommandLine](IMPORTANT): DVL_micro.pitchOffset (degree)
2019-10-02T21:14:18.831Z,1570050858.831 [CommandLine](IMPORTANT): DVL_micro.power (watt)
2019-10-02T21:14:18.831Z,1570050858.831 [CommandLine](IMPORTANT): DVL_micro.rollOffset (degree)
2019-10-02T21:14:18.898Z,1570050858.898 [CommandLine](IMPORTANT): DVL_micro.simulatedHardware (bool)
2019-10-02T21:14:23.511Z,1570050863.511 [NAL9602](INFO): SBD MO Status=2, MOMSN=2082, MT Status=2, MTMSN=0
2019-10-02T21:14:23.511Z,1570050863.511 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:14:28.904Z,1570050868.904 [CommandLine](IMPORTANT): got command get DVL_micro.loadAtStartup
2019-10-02T21:14:28.905Z,1570050868.905 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup 0 bool
2019-10-02T21:14:42.337Z,1570050882.337 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB4
2019-10-02T21:14:44.535Z,1570050884.535 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB3
2019-10-02T21:14:47.787Z,1570050887.787 [CommandLine](IMPORTANT): got command gfscan
2019-10-02T21:14:47.874Z,1570050887.874 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T21:14:58.701Z,1570050898.701 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.043922
CHAN A1 (24V): 0.069965
CHAN A2 (12V): 0.027454
CHAN A3 (5V): 0.004190
CHAN B0 (3.3V): 0.001246
CHAN B1 (3.15aV): 0.001352
CHAN B2 (3.15bV): 0.001782
CHAN B3 (GND): -0.008334
OPEN: 0.007733
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T21:15:47.547Z,1570050947.547 [NAL9602](INFO): SBD MO Status=2, MOMSN=2082, MT Status=2, MTMSN=0
2019-10-02T21:15:47.548Z,1570050947.548 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:15:51.204Z,1570050951.204 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-10-02T21:16:01.283Z,1570050961.283 [NAL9602](INFO): SBD MO Status=1, MOMSN=2082, MT Status=0, MTMSN=0
2019-10-02T21:16:01.284Z,1570050961.284 [NAL9602](INFO): No messages in MT queue
2019-10-02T21:16:31.986Z,1570050991.986 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T21:16:52.697Z,1570051012.697 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T21:16:52.697Z,1570051012.697 [Default:CheckIn:C.Wait] Stopped
2019-10-02T21:16:52.697Z,1570051012.697 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T21:16:52.697Z,1570051012.697 [Default:CheckIn:D] Running Loop=1
2019-10-02T21:16:53.098Z,1570051013.098 [Default:CheckIn:D] Stopped
2019-10-02T21:16:53.098Z,1570051013.098 [Default:CheckIn:E] Running Loop=1
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.718890 min 
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn:E] Stopped
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn] Stopped
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn](INFO): Running loop #4
2019-10-02T21:16:53.511Z,1570051013.511 [Default:CheckIn] Running Loop=4
2019-10-02T21:16:53.512Z,1570051013.512 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T21:16:53.512Z,1570051013.512 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T21:16:55.053Z,1570051015.053 [NAL9602](DEBUG): Fix Requested
2019-10-02T21:16:55.444Z,1570051015.444 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211647.00,A,3648.16268,N,12147.28773,W,0.661,312.91,021019,,,D*76
2019-10-02T21:16:55.446Z,1570051015.446 [NAL9602](INFO): GPS fix at 20191002T211647: (36.802711, -121.788129)
2019-10-02T21:16:55.512Z,1570051015.512 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T21:16:55.521Z,1570051015.521 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T21:17:00.766Z,1570051020.766 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191002T205340/Courier0013.lzma
2019-10-02T21:17:02.774Z,1570051022.774 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0013.lzma.bak
2019-10-02T21:17:02.774Z,1570051022.774 [DataOverHttps](INFO): SBD MOMSN=11840833
2019-10-02T21:17:16.881Z,1570051036.881 [NAL9602](INFO): SBD MO Status=2, MOMSN=2083, MT Status=2, MTMSN=0
2019-10-02T21:17:16.881Z,1570051036.881 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:17:22.497Z,1570051042.497 [DataOverHttps](INFO): Sending 667 bytes from file Logs/20191002T205340/Express0014.lzma
2019-10-02T21:17:24.502Z,1570051044.502 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0014.lzma.bak
2019-10-02T21:17:24.502Z,1570051044.502 [DataOverHttps](INFO): SBD MOMSN=11840836
2019-10-02T21:17:28.281Z,1570051048.281 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T21:17:28.281Z,1570051048.281 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T21:17:28.281Z,1570051048.281 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T21:17:37.487Z,1570051057.487 [NAL9602](INFO): SBD MO Status=2, MOMSN=2083, MT Status=2, MTMSN=0
2019-10-02T21:17:37.487Z,1570051057.487 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-02T21:17:42.758Z,1570051062.758 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:17:49.201Z,1570051069.201 [NAL9602](INFO): SBD MO Status=1, MOMSN=2083, MT Status=0, MTMSN=0
2019-10-02T21:17:49.201Z,1570051069.201 [NAL9602](INFO): No messages in MT queue
2019-10-02T21:17:49.631Z,1570051069.631 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:18:05.038Z,1570051085.038 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:18:05.654Z,1570051085.654 [CommandLine](IMPORTANT): got command gfscan
2019-10-02T21:18:05.840Z,1570051085.840 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T21:18:16.738Z,1570051096.738 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.045995
CHAN A1 (24V): 0.072440
CHAN A2 (12V): 0.029357
CHAN A3 (5V): 0.006839
CHAN B0 (3.3V): 0.004730
CHAN B1 (3.15aV): 0.004504
CHAN B2 (3.15bV): 0.004550
CHAN B3 (GND): -0.004455
OPEN: 0.009393
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T21:18:19.906Z,1570051099.906 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T21:18:19.923Z,1570051099.923 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:18:30.116Z,1570051110.116 [CommandLine](IMPORTANT): got command maintain clear
2019-10-02T21:18:36.089Z,1570051116.089 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:18:51.438Z,1570051131.438 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:19:06.793Z,1570051146.793 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:19:21.737Z,1570051161.737 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:19:34.146Z,1570051174.146 [DataOverHttps](IMPORTANT): SBD MTMSN=20191002T211925
2019-10-02T21:19:37.105Z,1570051177.105 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:19:41.625Z,1570051181.625 [DataOverHttps](INFO): Received command:load Maintenance/tank_ballast_and_trim.xml;set ballast_and_trim.MissionTimeout 60 minute;set ballast_and_trim.EstimationTimeout 35 minute;set ballast_and_trim.WaitToFloat 1 minute;run 
2019-10-02T21:19:41.666Z,1570051181.666 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/tank_ballast_and_trim.xml
2019-10-02T21:19:41.666Z,1570051181.666 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/tank_ballast_and_trim.xml
2019-10-02T21:19:41.729Z,1570051181.729 [MissionManager](INFO): DefineArg ballast_and_trim.MissionTimeout = 120.000000 min
2019-10-02T21:19:41.732Z,1570051181.732 [MissionManager](INFO): DefineArg ballast_and_trim.SkipComms = 0 bool
2019-10-02T21:19:41.735Z,1570051181.735 [MissionManager](INFO): DefineArg ballast_and_trim.Depth1 = 7.000000 m
2019-10-02T21:19:41.738Z,1570051181.738 [MissionManager](INFO): DefineArg ballast_and_trim.Depth2 = nan m
2019-10-02T21:19:41.740Z,1570051181.740 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 0.100000 m
2019-10-02T21:19:41.743Z,1570051181.743 [MissionManager](INFO): DefineArg ballast_and_trim.SurfaceThreshold = 2.500000 m
2019-10-02T21:19:41.802Z,1570051181.802 [MissionManager](INFO): DefineArg ballast_and_trim.MaxWaitOnSurface = 20.000000 min
2019-10-02T21:19:41.806Z,1570051181.806 [MissionManager](INFO): DefineArg ballast_and_trim.SettleTime = 10.000000 min
2019-10-02T21:19:41.829Z,1570051181.829 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationTimeout = 45.000000 min
2019-10-02T21:19:41.832Z,1570051181.832 [MissionManager](INFO): DefineArg ballast_and_trim.MinEstimationTime = 10.000000 min
2019-10-02T21:19:41.835Z,1570051181.835 [MissionManager](INFO): DefineArg ballast_and_trim.MassEstimationErrorBound = 0.250000 mm
2019-10-02T21:19:41.867Z,1570051181.867 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyEstimationErrorBound = 15.000000 cc
2019-10-02T21:19:41.871Z,1570051181.871 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationConfidence = 99.900000 %
2019-10-02T21:19:41.949Z,1570051181.949 [MissionManager](INFO): DefineArg ballast_and_trim.WaitToFloat = 5.000000 min
2019-10-02T21:19:41.950Z,1570051181.950 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml
2019-10-02T21:19:42.467Z,1570051182.467 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUS = 0 bool
2019-10-02T21:19:42.490Z,1570051182.490 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUSmaxPitch = 60.000000 arcdeg
2019-10-02T21:19:42.493Z,1570051182.493 [MissionManager](INFO): DefineArg ballast_and_trim:Science.SampleISUSminPitch = -60.000000 arcdeg
2019-10-02T21:19:42.496Z,1570051182.496 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectChlActive = 0 bool
2019-10-02T21:19:42.499Z,1570051182.499 [MissionManager](INFO): DefineArg ballast_and_trim:Science.TimeWindowPeakReport = nan min
2019-10-02T21:19:42.502Z,1570051182.502 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestChlPeakReportActive = 0 bool
2019-10-02T21:19:42.504Z,1570051182.504 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PatchTracking = 0 bool
2019-10-02T21:19:42.507Z,1570051182.507 [MissionManager](INFO): DefineArg ballast_and_trim:Science.FilterWidthHorizontal = 3.000000 count
2019-10-02T21:19:42.510Z,1570051182.510 [MissionManager](INFO): DefineArg ballast_and_trim:Science.NumProfilesSlidingwindow = 100.000000 count
2019-10-02T21:19:42.513Z,1570051182.513 [MissionManager](INFO): DefineArg ballast_and_trim:Science.OffPeakFractionHorizontal = 80.000000 %
2019-10-02T21:19:42.516Z,1570051182.516 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectNO3Active = 0 bool
2019-10-02T21:19:42.518Z,1570051182.518 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectOilActive = 0 bool
2019-10-02T21:19:42.555Z,1570051182.555 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectFDOMActive = 0 bool
2019-10-02T21:19:42.558Z,1570051182.558 [MissionManager](INFO): DefineArg ballast_and_trim:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2019-10-02T21:19:42.561Z,1570051182.561 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledAanderaaO2 = 0.000000 bool
2019-10-02T21:19:42.564Z,1570051182.564 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledNeilBrown = 0.000000 bool
2019-10-02T21:19:42.589Z,1570051182.589 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledSeabird = 1.000000 bool
2019-10-02T21:19:42.592Z,1570051182.592 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledTurbulence_NPS = 0.000000 bool
2019-10-02T21:19:42.604Z,1570051182.604 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsBB2FL = 1.000000 bool
2019-10-02T21:19:42.608Z,1570051182.608 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool
2019-10-02T21:19:42.611Z,1570051182.611 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsUBAT = 0.000000 bool
2019-10-02T21:19:42.640Z,1570051182.640 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledISUS = 0.000000 bool
2019-10-02T21:19:42.643Z,1570051182.643 [MissionManager](INFO): DefineArg ballast_and_trim:Science.LowPassWindowLength = 20.000000 count
2019-10-02T21:19:42.646Z,1570051182.646 [MissionManager](INFO): DefineArg ballast_and_trim:Science.MedianFilterLen = 5.000000 count
2019-10-02T21:19:42.672Z,1570051182.672 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakChlShallowBound = nan m
2019-10-02T21:19:42.675Z,1570051182.675 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakChlDeepBound = nan m
2019-10-02T21:19:42.678Z,1570051182.678 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakShallowBound = nan m
2019-10-02T21:19:42.693Z,1570051182.693 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDeepBound = nan m
2019-10-02T21:19:42.696Z,1570051182.696 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChl = 0.000000 ug/l
2019-10-02T21:19:42.699Z,1570051182.699 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlDepth = 0.000000 m
2019-10-02T21:19:42.702Z,1570051182.702 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlTemperature = 0.000000 degC
2019-10-02T21:19:42.763Z,1570051182.763 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLatitude = nan arcdeg
2019-10-02T21:19:42.766Z,1570051182.766 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLongitude = nan arcdeg
2019-10-02T21:19:42.789Z,1570051182.789 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3 = 0.000000 umol/l
2019-10-02T21:19:42.792Z,1570051182.792 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Depth = 0.000000 m
2019-10-02T21:19:42.795Z,1570051182.795 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Latitude = nan arcdeg
2019-10-02T21:19:42.822Z,1570051182.822 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Longitude = nan arcdeg
2019-10-02T21:19:42.826Z,1570051182.826 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChl = 0.000000 m
2019-10-02T21:19:42.841Z,1570051182.841 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDepth = 0.000000 m
2019-10-02T21:19:42.844Z,1570051182.844 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLatitude = nan arcdeg
2019-10-02T21:19:42.848Z,1570051182.848 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLongitude = nan arcdeg
2019-10-02T21:19:42.851Z,1570051182.851 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDistance = nan m
2019-10-02T21:19:42.874Z,1570051182.874 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOil = 0.000000 kg/m3
2019-10-02T21:19:42.877Z,1570051182.877 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilDepth = 0.000000 m
2019-10-02T21:19:42.881Z,1570051182.881 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLatitude = nan arcdeg
2019-10-02T21:19:42.884Z,1570051182.884 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLongitude = nan arcdeg
2019-10-02T21:19:42.916Z,1570051182.916 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOM = 0.000000 ppb
2019-10-02T21:19:42.920Z,1570051182.920 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMDepth = 0.000000 m
2019-10-02T21:19:42.923Z,1570051182.923 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLatitude = nan arcdeg
2019-10-02T21:19:42.937Z,1570051182.937 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLongitude = nan arcdeg
2019-10-02T21:19:42.940Z,1570051182.940 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchFDOMDistance = nan m
2019-10-02T21:19:42.994Z,1570051182.994 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-10-02T21:19:43.028Z,1570051183.028 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2019-10-02T21:19:43.046Z,1570051183.046 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-10-02T21:19:43.096Z,1570051183.096 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-10-02T21:19:43.178Z,1570051183.178 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2019-10-02T21:19:43.213Z,1570051183.213 [MissionManager](INFO): Inserting Stack: Missions/Insert/BallastAndTrim.xml
2019-10-02T21:19:43.443Z,1570051183.443 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepth = 25.000000 m
2019-10-02T21:19:43.456Z,1570051183.456 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSpeed = 0.000000 m/s
2019-10-02T21:19:43.467Z,1570051183.467 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthRate = 0.400000 m/s
2019-10-02T21:19:43.483Z,1570051183.483 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachPitchLimit = 20.000000 arcdeg
2019-10-02T21:19:43.496Z,1570051183.496 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSettleTimePreDive = 0.000000 min
2019-10-02T21:19:43.500Z,1570051183.500 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = 20.000000 min
2019-10-02T21:19:43.571Z,1570051183.571 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = 10.000000 min
2019-10-02T21:19:43.582Z,1570051183.582 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = 45.000000 min
2019-10-02T21:19:43.593Z,1570051183.593 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = 10.000000 min
2019-10-02T21:19:43.596Z,1570051183.596 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = 0.250000 mm
2019-10-02T21:19:43.607Z,1570051183.607 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = 15.000000 cc
2019-10-02T21:19:43.615Z,1570051183.615 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = 99.900000 %
2019-10-02T21:19:43.626Z,1570051183.626 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = 1.000000 m
2019-10-02T21:19:43.633Z,1570051183.633 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertKiDepthBuoy = 0.300000 1/s
2019-10-02T21:19:43.636Z,1570051183.636 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertMassDeadband = 0.250000 mm
2019-10-02T21:19:43.683Z,1570051183.683 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Construct.
2019-10-02T21:19:43.706Z,1570051183.706 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Construct Buoyancy.
2019-10-02T21:19:43.710Z,1570051183.710 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Construct.
2019-10-02T21:19:43.746Z,1570051183.746 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Construct Wait.
2019-10-02T21:19:43.750Z,1570051183.750 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Construct.
2019-10-02T21:19:43.753Z,1570051183.753 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Construct.
2019-10-02T21:19:43.777Z,1570051183.777 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-10-02T21:19:43.781Z,1570051183.781 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2019-10-02T21:19:43.783Z,1570051183.783 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Construct.
2019-10-02T21:19:43.803Z,1570051183.803 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Construct Wait.
2019-10-02T21:19:43.806Z,1570051183.806 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](DEBUG): Construct BallastAndTrim.
2019-10-02T21:19:43.899Z,1570051183.899 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = reader:ballast_and_trim.DepthDeadband
2019-10-02T21:19:43.901Z,1570051183.901 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = reader:ballast_and_trim.MaxWaitOnSurface
2019-10-02T21:19:43.903Z,1570051183.903 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = reader:ballast_and_trim.SettleTime
2019-10-02T21:19:43.904Z,1570051183.904 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = reader:ballast_and_trim.EstimationTimeout
2019-10-02T21:19:43.906Z,1570051183.906 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = reader:ballast_and_trim.MinEstimationTime
2019-10-02T21:19:43.908Z,1570051183.908 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = reader:ballast_and_trim.MassEstimationErrorBound
2019-10-02T21:19:43.976Z,1570051183.976 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = reader:ballast_and_trim.BuoyEstimationErrorBound
2019-10-02T21:19:43.977Z,1570051183.977 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = reader:ballast_and_trim.EstimationConfidence
2019-10-02T21:19:44.040Z,1570051184.040 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Construct Buoyancy.
2019-10-02T21:19:44.043Z,1570051184.043 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Construct Wait.
2019-10-02T21:19:44.098Z,1570051184.098 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="ballast_and_trim">

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:minute/><Value>120</Value></DefineArg>

    <DefineArg Name="SkipComms"><Description>
        Skip communications at start of mission.
    </Description><False/></DefineArg>

    <DefineArg Name="Depth1"><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="Depth2"><Units:meter/><Value>NaN</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Units:meter/><Value>0.1</Value></DefineArg>

    <DefineArg Name="SurfaceThreshold"><Description>
        Surface threshold depth.
    </Description><Units:meter/><Value>2.5</Value></DefineArg>

    <DefineArg Name="MaxWaitOnSurface"><Description>
        Maximum wait time for the vehicle to go under the surface (i.e., reach
        the surface threshold depth).
    </Description><Units:minute/><Value>20</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait after reaching target depth before starting ballast and
        trim.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="EstimationTimeout"><Description>
        Timeout for ballast and trim estimation.
    </Description><Units:minute/><Value>45</Value></DefineArg>

    <DefineArg Name="MinEstimationTime"><Description>
        Minimum time to run ballast and trim estimation before determining
        convergence (must be shorter than timeout).
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="MassEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:millimeter/><Value>0.25</Value></DefineArg>

    <DefineArg Name="BuoyEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:cubic_centimeter/><Value>15</Value></DefineArg>

    <DefineArg Name="EstimationConfidence"><Description>
        Confidence level that the estimator has reached the desired error range
        (larger values take longer to converge).
    </Description><Units:percent/><Value>99.9</Value></DefineArg>

    <DefineArg Name="WaitToFloat"><Units:minute/><Value>5</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Insert Filename="Insert/Science.xml"/>

    <Aggregate Id="RunBallastAndTrim">

        <Insert Filename="Insert/BallastAndTrim.xml">
            <RedefineArg Name="InsertDepthDeadband"><Arg Name="DepthDeadband"/></RedefineArg>
            <RedefineArg Name="InsertApproachDepthTimeout"><Arg Name="MaxWaitOnSurface"/></RedefineArg>
            <RedefineArg Name="InsertSettleTime"><Arg Name="SettleTime"/></RedefineArg>
            <RedefineArg Name="EstTimeout"><Arg Name="EstimationTimeout"/></RedefineArg>
            <RedefineArg Name="MinEstTime"><Arg Name="MinEstimationTime"/></RedefineArg>
            <RedefineArg Name="MassEstErrorBound"><Arg Name="MassEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="BuoyEstErrorBound"><Arg Name="BuoyEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="EstConfidence"><Arg Name="EstimationConfidence"/></RedefineArg>
        </Insert>
        
        <Aggregate Id="Depth1">

            <Sequence/>
            
            <Break>
                <IsNaN>
                    <Arg Name="Depth1"/>
                </IsNaN>
            </Break>
            
            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>
            
            <Call RefId="BallastAndTrim"/>
            
        </Aggregate>

        <Aggregate Id="Depth2">

            <Sequence/>

            <Break>
                <IsNaN>
                    <Arg Name="Depth2"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="Float_Up">

        <Description>
            Float to surface instead of driving.
        </Description>

        <Sequence/>

        <Break>
            <Universal:depth/>
            <Lt><Control:VerticalControl.surfaceThreshold/></Lt>
        </Break>

        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyDefault/></Setting>
        </Guidance:Buoyancy>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="WaitToFloat"/></Setting>
        </Guidance:Wait>

    </Aggregate>

</Mission>


2019-10-02T21:19:44.098Z,1570051184.098 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/tank_ballast_and_trim.xml
2019-10-02T21:19:52.696Z,1570051192.696 [CommandLine](IMPORTANT): got command set ballast_and_trim.MissionTimeout 60.000000 minute
2019-10-02T21:19:52.708Z,1570051192.708 [CommandLine](IMPORTANT): got command set ballast_and_trim.EstimationTimeout 35.000000 minute
2019-10-02T21:19:52.708Z,1570051192.708 [CommandLine](IMPORTANT): got command set ballast_and_trim.WaitToFloat 1.000000 minute
2019-10-02T21:19:52.709Z,1570051192.709 [CommandLine](IMPORTANT): got command run 
2019-10-02T21:19:52.712Z,1570051192.712 [CommandLine](IMPORTANT): Running 
2019-10-02T21:19:52.966Z,1570051192.966 [Default] Stopped
2019-10-02T21:19:52.966Z,1570051192.966 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-02T21:19:52.966Z,1570051192.966 [Default:B.GoToSurface] Stopped
2019-10-02T21:19:52.966Z,1570051192.966 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-02T21:19:52.966Z,1570051192.966 [Default:CheckIn] Stopped
2019-10-02T21:19:52.966Z,1570051192.966 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T21:19:52.966Z,1570051192.966 [Default:CheckIn:C.Wait] Stopped
2019-10-02T21:19:52.966Z,1570051192.966 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T21:19:52.966Z,1570051192.966 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim](DEBUG): Aggregate::initialize ballast_and_trim
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science](DEBUG): Aggregate::initialize ballast_and_trim:Science
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:A] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:B] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:C] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:D] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:E] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:F] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:G] Running Loop=1
2019-10-02T21:19:52.967Z,1570051192.967 [ballast_and_trim:Science:H] Running Loop=1
2019-10-02T21:19:52.968Z,1570051192.968 [ballast_and_trim:Science:Read_Oil] Running Loop=1
2019-10-02T21:19:52.968Z,1570051192.968 [ballast_and_trim:Science:PeakDetectChl] Running Loop=1
2019-10-02T21:19:52.968Z,1570051192.968 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectChl
2019-10-02T21:19:52.968Z,1570051192.968 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2019-10-02T21:19:52.968Z,1570051192.968 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-10-02T21:19:52.970Z,1570051192.970 [ballast_and_trim:Science:HighestChlPeakReport] Running Loop=1
2019-10-02T21:19:52.970Z,1570051192.970 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestChlPeakReport
2019-10-02T21:19:52.970Z,1570051192.970 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2019-10-02T21:19:52.970Z,1570051192.970 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2019-10-02T21:19:52.971Z,1570051192.971 [ballast_and_trim:Science:PeakDetectNO3] Running Loop=1
2019-10-02T21:19:52.971Z,1570051192.971 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectNO3
2019-10-02T21:19:52.971Z,1570051192.971 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2019-10-02T21:19:52.971Z,1570051192.971 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-10-02T21:19:52.973Z,1570051192.973 [ballast_and_trim:Science:PeakDetectOil] Running Loop=1
2019-10-02T21:19:52.973Z,1570051192.973 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectOil
2019-10-02T21:19:52.973Z,1570051192.973 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2019-10-02T21:19:52.973Z,1570051192.973 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-10-02T21:19:52.975Z,1570051192.975 [ballast_and_trim:Science:PeakDetectFDOM] Running Loop=1
2019-10-02T21:19:52.975Z,1570051192.975 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectFDOM
2019-10-02T21:19:52.975Z,1570051192.975 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2019-10-02T21:19:52.975Z,1570051192.975 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2019-10-02T21:19:52.977Z,1570051192.977 [ballast_and_trim:RunBallastAndTrim] Running Loop=1
2019-10-02T21:19:52.978Z,1570051192.978 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim
2019-10-02T21:19:52.978Z,1570051192.978 [ballast_and_trim:RunBallastAndTrim:Depth1] Running Loop=1
2019-10-02T21:19:52.978Z,1570051192.978 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1
2019-10-02T21:19:52.978Z,1570051192.978 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Running Loop=1
2019-10-02T21:19:52.979Z,1570051192.979 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Stopped
2019-10-02T21:19:52.979Z,1570051192.979 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Running Loop=1
2019-10-02T21:19:52.979Z,1570051192.979 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2019-10-02T21:19:52.979Z,1570051192.979 [ballast_and_trim:Science] Running Loop=1
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectFDOM] Stopped
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectFDOM
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectOil] Stopped
2019-10-02T21:19:52.980Z,1570051192.980 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectOil
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectNO3] Stopped
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectNO3
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:HighestChlPeakReport] Stopped
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestChlPeakReport
2019-10-02T21:19:52.981Z,1570051192.981 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:PeakDetectChl] Stopped
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectChl
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:Read_Oil] Stopped
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:H] Stopped
2019-10-02T21:19:52.982Z,1570051192.982 [ballast_and_trim:Science:G] Running Loop=1
2019-10-02T21:19:52.983Z,1570051192.983 [ballast_and_trim:Science:G](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2019-10-02T21:19:52.983Z,1570051192.983 [ballast_and_trim:Science:F] Stopped
2019-10-02T21:19:52.983Z,1570051192.983 [ballast_and_trim:Science:E] Stopped
2019-10-02T21:19:52.983Z,1570051192.983 [ballast_and_trim:Science:D] Running Loop=1
2019-10-02T21:19:52.984Z,1570051192.984 [ballast_and_trim:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2019-10-02T21:19:52.984Z,1570051192.984 [ballast_and_trim:Science:D](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2019-10-02T21:19:52.984Z,1570051192.984 [ballast_and_trim:Science:C] Running Loop=1
2019-10-02T21:19:52.985Z,1570051192.985 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2019-10-02T21:19:52.986Z,1570051192.986 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2019-10-02T21:19:52.986Z,1570051192.986 [ballast_and_trim:Science:B] Stopped
2019-10-02T21:19:52.986Z,1570051192.986 [ballast_and_trim:Science:A] Stopped
2019-10-02T21:19:53.006Z,1570051193.006 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-10-02T21:19:53.253Z,1570051193.253 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2019-10-02T21:19:53.280Z,1570051193.280 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G](INFO): Going to target depth. Speed set to 0.000000 m/s 
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:G] Stopped
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Initialize.
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Running Loop=1
2019-10-02T21:19:53.287Z,1570051193.287 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Running Loop=1
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Initialize.
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Running Loop=1
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Running Loop=1
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2019-10-02T21:19:53.288Z,1570051193.288 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2019-10-02T21:19:53.293Z,1570051193.293 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2019-10-02T21:19:53.293Z,1570051193.293 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2019-10-02T21:19:53.293Z,1570051193.293 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2019-10-02T21:19:53.294Z,1570051193.294 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2019-10-02T21:19:53.346Z,1570051193.346 [WetLabsBB2FL](INFO): Opening uart, block timeout 10ths=2
2019-10-02T21:19:53.346Z,1570051193.346 [WetLabsBB2FL](INFO): Powering up
2019-10-02T21:19:53.690Z,1570051193.690 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Stopped
2019-10-02T21:19:53.690Z,1570051193.690 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Stopped
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Running Loop=1
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Initialize.
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Running Loop=1
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Stopped
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Stopped
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Stopped
2019-10-02T21:19:53.691Z,1570051193.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-10-02T21:19:53.692Z,1570051193.692 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Stopped
2019-10-02T21:19:53.692Z,1570051193.692 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2019-10-02T21:19:54.094Z,1570051194.094 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2019-10-02T21:19:54.094Z,1570051194.094 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2019-10-02T21:19:54.095Z,1570051194.095 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Stopped
2019-10-02T21:19:54.095Z,1570051194.095 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Running Loop=1
2019-10-02T21:19:54.095Z,1570051194.095 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Initialize.
2019-10-02T21:19:56.018Z,1570051196.018 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2019-10-02T21:19:58.028Z,1570051198.028 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012918 psu
2019-10-02T21:19:59.031Z,1570051199.031 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:00.035Z,1570051200.035 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:01.042Z,1570051201.042 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:02.043Z,1570051202.043 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:03.047Z,1570051203.047 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:04.051Z,1570051204.051 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:05.055Z,1570051205.055 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:06.059Z,1570051206.059 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012864 psu
2019-10-02T21:20:07.063Z,1570051207.063 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012810 psu
2019-10-02T21:20:08.067Z,1570051208.067 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012810 psu
2019-10-02T21:20:08.424Z,1570051208.424 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T21:20:09.071Z,1570051209.071 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012811 psu
2019-10-02T21:20:10.075Z,1570051210.075 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012811 psu
2019-10-02T21:20:11.114Z,1570051211.114 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012811 psu
2019-10-02T21:20:12.118Z,1570051212.118 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012811 psu
2019-10-02T21:20:13.110Z,1570051213.110 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012758 psu
2019-10-02T21:20:14.118Z,1570051214.118 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012435 psu
2019-10-02T21:20:15.118Z,1570051215.118 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012165 psu
2019-10-02T21:20:16.114Z,1570051216.114 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012057 psu
2019-10-02T21:20:17.114Z,1570051217.114 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012004 psu
2019-10-02T21:20:18.111Z,1570051218.111 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011896 psu
2019-10-02T21:20:19.111Z,1570051219.111 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011843 psu
2019-10-02T21:20:20.115Z,1570051220.115 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011681 psu
2019-10-02T21:20:21.121Z,1570051221.121 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011358 psu
2019-10-02T21:20:22.127Z,1570051222.127 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011197 psu
2019-10-02T21:20:23.127Z,1570051223.127 [CTD_Seabird](ERROR): Salinity reading out of range: 0.011090 psu
2019-10-02T21:20:24.131Z,1570051224.131 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010875 psu
2019-10-02T21:20:25.135Z,1570051225.135 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010767 psu
2019-10-02T21:20:26.140Z,1570051226.140 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010714 psu
2019-10-02T21:20:27.143Z,1570051227.143 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010606 psu
2019-10-02T21:20:28.147Z,1570051228.147 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010553 psu
2019-10-02T21:20:29.151Z,1570051229.151 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010499 psu
2019-10-02T21:20:30.155Z,1570051230.155 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010392 psu
2019-10-02T21:20:31.161Z,1570051231.161 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010231 psu
2019-10-02T21:20:32.163Z,1570051232.163 [CTD_Seabird](ERROR): Salinity reading out of range: 0.010285 psu
2019-10-02T21:20:33.168Z,1570051233.168 [CTD_Seabird](ERROR): Salinity reading out of range: 0.012707 psu
2019-10-02T21:20:34.171Z,1570051234.171 [CTD_Seabird](ERROR): Salinity reading out of range: 1.317144 psu
2019-10-02T21:20:35.176Z,1570051235.176 [CTD_Seabird](ERROR): Salinity reading out of range: 27.249390 psu
2019-10-02T21:20:56.838Z,1570051256.838 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=63.115967
2019-10-02T21:21:31.063Z,1570051291.063 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004390
2019-10-02T21:22:27.281Z,1570051347.281 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T21:22:31.297Z,1570051351.297 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.238781
2019-10-02T21:22:54.845Z,1570051374.845 [Radio_Surface](INFO): Powering down
2019-10-02T21:23:02.421Z,1570051382.421 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T21:23:03.425Z,1570051383.425 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-10-02T21:24:13.179Z,1570051453.179 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Stopped
2019-10-02T21:24:13.180Z,1570051453.180 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2019-10-02T21:24:13.180Z,1570051453.180 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Stopped
2019-10-02T21:24:13.180Z,1570051453.180 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2019-10-02T21:24:13.180Z,1570051453.180 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Stopped
2019-10-02T21:24:13.180Z,1570051453.180 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Uninitialize.
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Stopped
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Stopped
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Running Loop=1
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2019-10-02T21:24:13.181Z,1570051453.181 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2019-10-02T21:24:13.182Z,1570051453.182 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Initialize.
2019-10-02T21:24:13.182Z,1570051453.182 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2019-10-02T21:24:13.182Z,1570051453.182 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Initialize.
2019-10-02T21:24:13.182Z,1570051453.182 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Running Loop=1
2019-10-02T21:24:13.598Z,1570051453.598 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C](INFO): Waiting for the vehicle to settle. Depth = 7.047149 m 
2019-10-02T21:24:13.598Z,1570051453.598 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:C] Stopped
2019-10-02T21:24:13.598Z,1570051453.598 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Running Loop=1
2019-10-02T21:24:13.599Z,1570051453.599 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Initialize Wait Component.
2019-10-02T21:24:13.599Z,1570051453.599 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Running Loop=1
2019-10-02T21:24:13.599Z,1570051453.599 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Running Loop=1
2019-10-02T21:24:51.634Z,1570051491.634 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-10-02T21:24:51.638Z,1570051491.638 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2019-10-02T21:34:14.277Z,1570052054.277 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](INFO): Done Waiting.
2019-10-02T21:34:14.277Z,1570052054.277 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait] Stopped
2019-10-02T21:34:14.277Z,1570052054.277 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T21:34:14.278Z,1570052054.278 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Running Loop=1
2019-10-02T21:34:14.690Z,1570052054.690 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E](INFO): Running ballast and trim. Depth = 6.983338 m 
2019-10-02T21:34:14.691Z,1570052054.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:E] Stopped
2019-10-02T21:34:14.691Z,1570052054.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Running Loop=1
2019-10-02T21:34:14.691Z,1570052054.691 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Initializing BallastAndTrim.
2019-10-02T22:09:15.219Z,1570054155.219 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): BallastAndTrim completed. Estimation time: 35.00 minutes (time-out limit reached).
2019-10-02T22:09:15.220Z,1570054155.220 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): Estimated buoyancyNeutral: 237.608973 +/- 7.831541 cc (conf. level 99.90%, sigma: 17.810400 cc).
2019-10-02T22:09:15.221Z,1570054155.221 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](IMPORTANT): Estimated massDefault: 4.631097 +/- 0.631789 mm (conf. level 99.90%, sigma: 1.436806 mm).
2019-10-02T22:09:15.221Z,1570054155.221 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.] Stopped
2019-10-02T22:09:15.222Z,1570054155.222 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](INFO): Uninitializing BallastAndTrim.
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth] Stopped
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed] Stopped
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Uninitialize.
2019-10-02T22:09:15.223Z,1570054155.223 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch] Stopped
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Stopped
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Stopped
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Stopped
2019-10-02T22:09:15.224Z,1570054155.224 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Stopped
2019-10-02T22:09:15.225Z,1570054155.225 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Stopped
2019-10-02T22:09:15.225Z,1570054155.225 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Stopped
2019-10-02T22:09:15.225Z,1570054155.225 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Stopped
2019-10-02T22:09:15.633Z,1570054155.633 [ballast_and_trim:RunBallastAndTrim:Depth1:B](INFO): Completed ballast_and_trim:RunBallastAndTrim:Depth1:B
2019-10-02T22:09:15.633Z,1570054155.633 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Stopped
2019-10-02T22:09:15.633Z,1570054155.633 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2019-10-02T22:09:15.633Z,1570054155.633 [ballast_and_trim:RunBallastAndTrim:Depth1](INFO): Completed ballast_and_trim:RunBallastAndTrim:Depth1
2019-10-02T22:09:15.634Z,1570054155.634 [ballast_and_trim:RunBallastAndTrim:Depth1] Stopped
2019-10-02T22:09:15.634Z,1570054155.634 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1
2019-10-02T22:09:15.634Z,1570054155.634 [ballast_and_trim:RunBallastAndTrim:Depth2] Running Loop=1
2019-10-02T22:09:15.634Z,1570054155.634 [ballast_and_trim:RunBallastAndTrim:Depth2](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth2
2019-10-02T22:09:15.634Z,1570054155.634 [ballast_and_trim:RunBallastAndTrim:Depth2:A] Running Loop=1
2019-10-02T22:09:16.041Z,1570054156.041 [ballast_and_trim:RunBallastAndTrim:Depth2] Stopped
2019-10-02T22:09:16.041Z,1570054156.041 [ballast_and_trim:RunBallastAndTrim:Depth2](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth2
2019-10-02T22:09:16.041Z,1570054156.041 [ballast_and_trim:RunBallastAndTrim:Depth2:A] Stopped
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:RunBallastAndTrim](INFO): Completed ballast_and_trim:RunBallastAndTrim
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:RunBallastAndTrim] Stopped
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:Float_Up] Running Loop=1
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:Float_Up](DEBUG): Aggregate::initialize ballast_and_trim:Float_Up
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:Float_Up:A.Buoyancy] Running Loop=1
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Initialize Buoyancy Component.
2019-10-02T22:09:16.042Z,1570054156.042 [ballast_and_trim:Float_Up:B.Wait] Running Loop=1
2019-10-02T22:09:16.043Z,1570054156.043 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:09:16.490Z,1570054156.490 [ballast_and_trim:Float_Up:A.Buoyancy] Running Loop=1
2019-10-02T22:10:16.686Z,1570054216.686 [ballast_and_trim:Float_Up:B.Wait](INFO): Done Waiting.
2019-10-02T22:10:16.686Z,1570054216.686 [ballast_and_trim:Float_Up:B.Wait] Stopped
2019-10-02T22:10:16.686Z,1570054216.686 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:10:16.687Z,1570054216.687 [ballast_and_trim:Float_Up](INFO): Completed ballast_and_trim:Float_Up
2019-10-02T22:10:16.687Z,1570054216.687 [ballast_and_trim:Float_Up] Stopped
2019-10-02T22:10:16.687Z,1570054216.687 [ballast_and_trim:Float_Up](DEBUG): Aggregate::uninitialize ballast_and_trim:Float_Up
2019-10-02T22:10:16.688Z,1570054216.688 [ballast_and_trim:Float_Up:A.Buoyancy] Stopped
2019-10-02T22:10:16.688Z,1570054216.688 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2019-10-02T22:10:16.690Z,1570054216.690 [ballast_and_trim](INFO): Completed ballast_and_trim
2019-10-02T22:10:16.690Z,1570054216.690 [MissionManager](INFO): ballast_and_trim is completed.
2019-10-02T22:10:16.690Z,1570054216.690 [MissionManager](INFO): Uninitializing Mission ballast_and_trim
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim] Stopped
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim](DEBUG): Aggregate::uninitialize ballast_and_trim
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim:Science] Stopped
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim:Science](DEBUG): Aggregate::uninitialize ballast_and_trim:Science
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim:Science:C] Stopped
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim:Science:D] Stopped
2019-10-02T22:10:16.691Z,1570054216.691 [ballast_and_trim:Science:G] Stopped
2019-10-02T22:10:17.102Z,1570054217.102 [MissionManager](IMPORTANT): Started mission Default
2019-10-02T22:10:17.102Z,1570054217.102 [Default] Running Loop=1
2019-10-02T22:10:17.102Z,1570054217.102 [Default](DEBUG): Aggregate::initialize Default
2019-10-02T22:10:17.102Z,1570054217.102 [Default:B.GoToSurface] Running Loop=1
2019-10-02T22:10:17.103Z,1570054217.103 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-02T22:10:17.103Z,1570054217.103 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-02T22:10:17.103Z,1570054217.103 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-02T22:10:17.103Z,1570054217.103 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-02T22:10:17.104Z,1570054217.104 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-02T22:10:17.104Z,1570054217.104 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-02T22:10:17.104Z,1570054217.104 [Default:A.Wait] Running Loop=1
2019-10-02T22:10:17.104Z,1570054217.104 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:10:17.109Z,1570054217.109 [WetLabsBB2FL](INFO): Powering down
2019-10-02T22:10:17.511Z,1570054217.511 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -32.00 mm (1 active estimators).
2019-10-02T22:10:17.845Z,1570054217.845 [Radio_Surface](INFO): Powering up
2019-10-02T22:10:23.481Z,1570054223.481 [DataOverHttps](INFO): Radio surface powered ON.
2019-10-02T22:10:30.138Z,1570054230.138 [Default:A.Wait](INFO): Done Waiting.
2019-10-02T22:10:30.138Z,1570054230.138 [Default:A.Wait] Stopped
2019-10-02T22:10:30.139Z,1570054230.139 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:10:53.605Z,1570054253.605 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T22:11:08.117Z,1570054268.117 [Default:CheckIn] Running Loop=1
2019-10-02T22:11:08.117Z,1570054268.117 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T22:11:08.117Z,1570054268.117 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T22:11:09.705Z,1570054269.705 [NAL9602](DEBUG): Fix Requested
2019-10-02T22:11:28.747Z,1570054288.747 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T22:12:03.889Z,1570054323.889 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T22:12:29.329Z,1570054349.329 [BuoyancyServo](ERROR): getPosition uart error serial timeout
2019-10-02T22:12:29.329Z,1570054349.329 [BuoyancyServo](FAULT): Buoyancy getPosition uart error.serial timeout
2019-10-02T22:12:29.329Z,1570054349.329 [BuoyancyServo] Communications Fault, FailCount= 1
2019-10-02T22:12:29.329Z,1570054349.329 [BuoyancyServo](ERROR): Communications Fault
2019-10-02T22:12:29.334Z,1570054349.334 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-10-02T22:12:31.051Z,1570054351.051 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-10-02T22:12:31.052Z,1570054351.052 [BuoyancyServo](INFO): Powering down
2019-10-02T22:12:31.470Z,1570054351.470 [BuoyancyServo](FAULT): LCB fault:  Current Limiter Activated.
2019-10-02T22:12:31.470Z,1570054351.470 [BuoyancyServo] Hardware Fault, FailCount= 1
2019-10-02T22:12:31.470Z,1570054351.470 [BuoyancyServo](ERROR): Hardware Fault
2019-10-02T22:12:31.890Z,1570054351.890 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-10-02T22:12:31.890Z,1570054351.890 [BuoyancyServo] No Fault, FailCount= 1
2019-10-02T22:12:32.262Z,1570054352.262 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-10-02T22:12:32.263Z,1570054352.263 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-10-02T22:12:39.029Z,1570054359.029 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T22:13:14.181Z,1570054394.181 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-02T22:13:47.917Z,1570054427.917 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003200
2019-10-02T22:16:08.410Z,1570054568.410 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T22:11:08.1Z
2019-10-02T22:16:08.410Z,1570054568.410 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T22:16:08.410Z,1570054568.410 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T22:16:12.010Z,1570054572.010 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T22:16:17.628Z,1570054577.628 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20191002T205340/Courier0016.lzma
2019-10-02T22:16:19.634Z,1570054579.634 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0016.lzma.bak
2019-10-02T22:16:19.634Z,1570054579.634 [DataOverHttps](INFO): SBD MOMSN=11840915
2019-10-02T22:16:37.961Z,1570054597.961 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0019.lzma
2019-10-02T22:16:39.966Z,1570054599.966 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0019.lzma.bak
2019-10-02T22:16:39.966Z,1570054599.966 [DataOverHttps](INFO): SBD MOMSN=11840917
2019-10-02T22:16:42.710Z,1570054602.710 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T22:17:11.138Z,1570054631.138 [DataOverHttps](INFO): Sending 1145 bytes from file Logs/20191002T205340/Express0017.lzma
2019-10-02T22:17:13.142Z,1570054633.142 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0017.lzma.bak
2019-10-02T22:17:13.143Z,1570054633.143 [DataOverHttps](INFO): SBD MOMSN=11840922
2019-10-02T22:17:35.800Z,1570054655.800 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191002T205340/Express0020.lzma
2019-10-02T22:17:37.806Z,1570054657.806 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0020.lzma.bak
2019-10-02T22:17:37.807Z,1570054657.807 [DataOverHttps](INFO): SBD MOMSN=11840948
2019-10-02T22:17:41.828Z,1570054661.828 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T22:17:41.828Z,1570054661.828 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T22:17:41.828Z,1570054661.828 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:17:53.518Z,1570054673.518 [DataOverHttps](IMPORTANT): SBD MTMSN=20191002T221744
2019-10-02T22:18:00.844Z,1570054680.844 [DataOverHttps](INFO): Received command:gfscan
2019-10-02T22:18:00.866Z,1570054680.866 [CommandLine](IMPORTANT): got command gfscan
2019-10-02T22:18:01.169Z,1570054681.169 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T22:18:12.077Z,1570054692.077 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.076308
CHAN A1 (24V): 0.106632
CHAN A2 (12V): 0.051870
CHAN A3 (5V): 0.022156
CHAN B0 (3.3V): 0.017621
CHAN B1 (3.15aV): 0.018573
CHAN B2 (3.15bV): 0.018582
CHAN B3 (GND): 0.005458
OPEN: 0.014725
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T22:19:00.513Z,1570054740.513 [CommandLine](IMPORTANT): got command ! echo i > /dev/loadB4
2019-10-02T22:19:03.553Z,1570054743.553 [CommandLine](IMPORTANT): got command gfscan
2019-10-02T22:19:03.822Z,1570054743.822 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-02T22:19:14.740Z,1570054754.740 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.009475
CHAN A1 (24V): 0.019441
CHAN A2 (12V): 0.005156
CHAN A3 (5V): 0.000719
CHAN B0 (3.3V): 0.001221
CHAN B1 (3.15aV): 0.000958
CHAN B2 (3.15bV): 0.001647
CHAN B3 (GND): -0.000422
OPEN: 0.005954
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-02T22:19:35.057Z,1570054775.057 [CommandLine](IMPORTANT): got command get VerticalControl.massPositionLimitFwd
2019-10-02T22:19:35.057Z,1570054775.057 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd 30.000000 mm
2019-10-02T22:19:40.671Z,1570054780.671 [CommandLine](IMPORTANT): got command get VerticalControl.massPositionLimitAft
2019-10-02T22:19:40.671Z,1570054780.671 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft -32.000000 mm
2019-10-02T22:22:42.382Z,1570054962.382 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T22:22:42.382Z,1570054962.382 [Default:CheckIn:C.Wait] Stopped
2019-10-02T22:22:42.382Z,1570054962.382 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:22:42.383Z,1570054962.383 [Default:CheckIn:D] Running Loop=1
2019-10-02T22:22:42.798Z,1570054962.798 [Default:CheckIn:D] Stopped
2019-10-02T22:22:42.798Z,1570054962.798 [Default:CheckIn:E] Running Loop=1
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.428254 min 
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn:E] Stopped
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn] Stopped
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn](INFO): Running loop #2
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn] Running Loop=2
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T22:22:43.218Z,1570054963.218 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T22:22:44.782Z,1570054964.782 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-02T22:22:44.782Z,1570054964.782 [NAL9602] Data Fault, FailCount= 1
2019-10-02T22:22:44.782Z,1570054964.782 [NAL9602](ERROR): Data Fault
2019-10-02T22:22:44.878Z,1570054964.878 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-02T22:22:45.178Z,1570054965.178 [NAL9602](INFO): Powering down
2019-10-02T22:22:45.582Z,1570054965.582 [NAL9602](FAULT): LCB fault:  Software Overcurrent.
2019-10-02T22:22:45.582Z,1570054965.582 [NAL9602] Hardware Fault, FailCount= 1
2019-10-02T22:22:45.582Z,1570054965.582 [NAL9602](ERROR): Hardware Fault
2019-10-02T22:22:46.071Z,1570054966.071 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-02T22:22:46.071Z,1570054966.071 [NAL9602] No Fault, FailCount= 1
2019-10-02T22:23:15.475Z,1570054995.475 [NAL9602](INFO): Powering up NAL9602
2019-10-02T22:23:26.384Z,1570055006.384 [NAL9602](INFO): NAL9602 initialized
2019-10-02T22:23:27.213Z,1570055007.213 [NAL9602](DEBUG): Fix Requested
2019-10-02T22:27:43.442Z,1570055263.442 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T22:22:43.2Z
2019-10-02T22:27:43.442Z,1570055263.442 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T22:27:43.442Z,1570055263.442 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T22:27:52.444Z,1570055272.444 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0022.lzma
2019-10-02T22:27:54.450Z,1570055274.450 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0022.lzma.bak
2019-10-02T22:27:54.451Z,1570055274.451 [DataOverHttps](INFO): SBD MOMSN=11840975
2019-10-02T22:28:15.984Z,1570055295.984 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0025.lzma
2019-10-02T22:28:17.990Z,1570055297.990 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0025.lzma.bak
2019-10-02T22:28:17.991Z,1570055297.991 [DataOverHttps](INFO): SBD MOMSN=11840982
2019-10-02T22:28:29.444Z,1570055309.444 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T22:28:38.038Z,1570055318.038 [DataOverHttps](INFO): Sending 654 bytes from file Logs/20191002T205340/Express0023.lzma
2019-10-02T22:28:40.042Z,1570055320.042 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0023.lzma.bak
2019-10-02T22:28:40.043Z,1570055320.043 [DataOverHttps](INFO): SBD MOMSN=11840984
2019-10-02T22:29:00.154Z,1570055340.154 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T22:29:02.192Z,1570055342.192 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20191002T205340/Express0024.lzma
2019-10-02T22:29:24.277Z,1570055364.277 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2019-10-02T22:29:36.804Z,1570055376.804 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20191002T205340/Express0024.lzma
2019-10-02T22:29:38.810Z,1570055378.810 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0024.lzma.bak
2019-10-02T22:29:38.811Z,1570055378.811 [DataOverHttps](INFO): SBD MOMSN=11841006
2019-10-02T22:29:46.637Z,1570055386.637 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:29:53.498Z,1570055393.498 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:29:57.540Z,1570055397.540 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Express0026.lzma
2019-10-02T22:29:59.546Z,1570055399.546 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0026.lzma.bak
2019-10-02T22:29:59.546Z,1570055399.546 [DataOverHttps](INFO): SBD MOMSN=11841009
2019-10-02T22:30:03.336Z,1570055403.336 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T22:30:03.336Z,1570055403.336 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T22:30:03.336Z,1570055403.336 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:30:08.847Z,1570055408.847 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:30:26.221Z,1570055426.221 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:30:44.403Z,1570055444.403 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:31:02.186Z,1570055462.186 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:31:17.167Z,1570055477.167 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:31:34.295Z,1570055494.295 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:31:48.707Z,1570055508.707 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:31:51.475Z,1570055511.475 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:32:03.596Z,1570055523.596 [BPC1](ERROR): BPC1B got IPBS message with 3 sticks (min is 7).
2019-10-02T22:32:03.596Z,1570055523.596 [BPC1](ERROR): BPC1B failed to parse battery stick message.
2019-10-02T22:33:13.121Z,1570055593.121 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:34:24.236Z,1570055664.236 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:35:03.798Z,1570055703.798 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T22:35:03.798Z,1570055703.798 [Default:CheckIn:C.Wait] Stopped
2019-10-02T22:35:03.798Z,1570055703.798 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:35:03.799Z,1570055703.799 [Default:CheckIn:D] Running Loop=1
2019-10-02T22:35:04.189Z,1570055704.189 [Default:CheckIn:D] Stopped
2019-10-02T22:35:04.190Z,1570055704.190 [Default:CheckIn:E] Running Loop=1
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.784782 min 
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn:E] Stopped
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn] Stopped
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn](INFO): Running loop #3
2019-10-02T22:35:04.658Z,1570055704.658 [Default:CheckIn] Running Loop=3
2019-10-02T22:35:04.659Z,1570055704.659 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T22:35:04.659Z,1570055704.659 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T22:35:06.180Z,1570055706.180 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-02T22:35:06.180Z,1570055706.180 [NAL9602] Data Fault, FailCount= 2
2019-10-02T22:35:06.180Z,1570055706.180 [NAL9602](ERROR): Data Fault
2019-10-02T22:35:06.250Z,1570055706.250 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-02T22:35:06.590Z,1570055706.590 [NAL9602](INFO): Powering down
2019-10-02T22:35:07.425Z,1570055707.425 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-02T22:35:07.425Z,1570055707.425 [NAL9602] No Fault, FailCount= 2
2019-10-02T22:35:30.447Z,1570055730.447 [BPC1](ERROR): BPC1B: No match for serial number 0000 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-10-02T22:35:36.882Z,1570055736.882 [NAL9602](INFO): Powering up NAL9602
2019-10-02T22:35:42.679Z,1570055742.679 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:35:47.790Z,1570055747.790 [NAL9602](INFO): NAL9602 initialized
2019-10-02T22:35:48.617Z,1570055748.617 [NAL9602](DEBUG): Fix Requested
2019-10-02T22:36:06.862Z,1570055766.862 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:36:27.417Z,1570055787.417 [BPC1](ERROR): BPC1B: No match for serial number 0000 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-10-02T22:36:54.979Z,1570055814.979 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:37:06.649Z,1570055826.649 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:37:38.975Z,1570055858.975 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:38:36.733Z,1570055916.733 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:39:42.146Z,1570055982.146 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:39:51.085Z,1570055991.085 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:40:00.306Z,1570056000.306 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:40:04.759Z,1570056004.759 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T22:35:04.7Z
2019-10-02T22:40:04.759Z,1570056004.759 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T22:40:04.759Z,1570056004.759 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T22:40:16.980Z,1570056016.980 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0027.lzma
2019-10-02T22:40:17.731Z,1570056017.731 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:40:18.993Z,1570056018.993 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0027.lzma.bak
2019-10-02T22:40:18.993Z,1570056018.993 [DataOverHttps](INFO): SBD MOMSN=11841204
2019-10-02T22:40:33.504Z,1570056033.504 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:40:33.935Z,1570056033.935 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:40:46.321Z,1570056046.321 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20191002T205340/Express0029.lzma
2019-10-02T22:40:48.552Z,1570056048.552 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0029.lzma.bak
2019-10-02T22:40:48.552Z,1570056048.552 [DataOverHttps](INFO): SBD MOMSN=11841206
2019-10-02T22:40:50.790Z,1570056050.790 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T22:40:51.221Z,1570056051.221 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:40:54.912Z,1570056054.912 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T22:40:54.912Z,1570056054.912 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T22:40:54.912Z,1570056054.912 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:41:09.393Z,1570056069.393 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:41:21.494Z,1570056081.494 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T22:41:26.398Z,1570056086.398 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:41:44.542Z,1570056104.542 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:42:11.255Z,1570056131.255 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:43:00.169Z,1570056180.169 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:43:21.910Z,1570056201.910 [BPC1](ERROR): BPC1B: No match for serial number 0000 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-10-02T22:43:25.994Z,1570056205.994 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:44:20.528Z,1570056260.528 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:44:25.350Z,1570056265.350 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:44:52.455Z,1570056292.455 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:44:58.117Z,1570056298.117 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:45:55.461Z,1570056355.461 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T22:45:55.461Z,1570056355.461 [Default:CheckIn:C.Wait] Stopped
2019-10-02T22:45:55.461Z,1570056355.461 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:45:55.462Z,1570056355.462 [Default:CheckIn:D] Running Loop=1
2019-10-02T22:45:55.876Z,1570056355.876 [Default:CheckIn:D] Stopped
2019-10-02T22:45:55.876Z,1570056355.876 [Default:CheckIn:E] Running Loop=1
2019-10-02T22:45:56.277Z,1570056356.277 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.646228 min 
2019-10-02T22:45:56.277Z,1570056356.277 [Default:CheckIn:E] Stopped
2019-10-02T22:45:56.277Z,1570056356.277 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T22:45:56.277Z,1570056356.277 [Default:CheckIn] Stopped
2019-10-02T22:45:56.277Z,1570056356.277 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T22:45:56.278Z,1570056356.278 [Default:CheckIn](INFO): Running loop #4
2019-10-02T22:45:56.278Z,1570056356.278 [Default:CheckIn] Running Loop=4
2019-10-02T22:45:56.278Z,1570056356.278 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T22:45:56.278Z,1570056356.278 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T22:45:57.846Z,1570056357.846 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-02T22:45:57.846Z,1570056357.846 [NAL9602] Data Fault, FailCount= 3
2019-10-02T22:45:57.846Z,1570056357.846 [NAL9602](ERROR): Data Fault
2019-10-02T22:45:58.064Z,1570056358.064 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-02T22:45:58.250Z,1570056358.250 [NAL9602](INFO): Powering down
2019-10-02T22:45:59.186Z,1570056359.186 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-02T22:45:59.186Z,1570056359.186 [NAL9602] No Fault, FailCount= 3
2019-10-02T22:46:28.550Z,1570056388.550 [NAL9602](INFO): Powering up NAL9602
2019-10-02T22:46:39.462Z,1570056399.462 [NAL9602](INFO): NAL9602 initialized
2019-10-02T22:46:40.277Z,1570056400.277 [NAL9602](DEBUG): Fix Requested
2019-10-02T22:47:06.601Z,1570056426.601 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:48:15.694Z,1570056495.694 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:48:42.763Z,1570056522.763 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:49:11.782Z,1570056551.782 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:49:19.063Z,1570056559.063 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:49:24.367Z,1570056564.367 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:49:37.648Z,1570056577.648 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:49:54.672Z,1570056594.672 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:50:11.988Z,1570056611.988 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:50:30.157Z,1570056630.157 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:50:47.530Z,1570056647.530 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:50:56.445Z,1570056656.445 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T22:45:56.3Z
2019-10-02T22:50:56.445Z,1570056656.445 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T22:50:56.446Z,1570056656.446 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T22:51:04.100Z,1570056664.100 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:51:08.621Z,1570056668.621 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0031.lzma
2019-10-02T22:51:10.630Z,1570056670.630 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0031.lzma.bak
2019-10-02T22:51:10.631Z,1570056670.631 [DataOverHttps](INFO): SBD MOMSN=11841233
2019-10-02T22:51:21.878Z,1570056681.878 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2019-10-02T22:51:39.577Z,1570056699.577 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191002T205340/Express0032.lzma
2019-10-02T22:51:41.583Z,1570056701.583 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0032.lzma.bak
2019-10-02T22:51:41.583Z,1570056701.583 [DataOverHttps](INFO): SBD MOMSN=11841235
2019-10-02T22:51:42.458Z,1570056702.458 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T22:51:47.419Z,1570056707.419 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T22:51:47.419Z,1570056707.419 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T22:51:47.419Z,1570056707.419 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T22:51:51.786Z,1570056711.786 [BPC1](ERROR): BPC1B: No match for serial number 0000 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2019-10-02T22:52:13.166Z,1570056733.166 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T22:53:15.860Z,1570056795.860 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:53:26.758Z,1570056806.758 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:53:40.897Z,1570056820.897 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:53:50.000Z,1570056831.000 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:54:02.316Z,1570056842.316 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:54:07.562Z,1570056847.562 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-10-02T22:54:31.456Z,1570056871.456 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:55:29.175Z,1570056929.175 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-02T22:55:52.553Z,1570056952.553 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-10-02T22:55:52.555Z,1570056952.555 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2019-10-02T22:56:47.918Z,1570057007.918 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T22:56:47.918Z,1570057007.918 [Default:CheckIn:C.Wait] Stopped
2019-10-02T22:56:47.918Z,1570057007.918 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T22:56:47.918Z,1570057007.918 [Default:CheckIn:D] Running Loop=1
2019-10-02T22:56:48.351Z,1570057008.351 [Default:CheckIn:D] Stopped
2019-10-02T22:56:48.351Z,1570057008.351 [Default:CheckIn:E] Running Loop=1
2019-10-02T22:56:48.742Z,1570057008.742 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.520813 min 
2019-10-02T22:56:48.742Z,1570057008.742 [Default:CheckIn:E] Stopped
2019-10-02T22:56:48.742Z,1570057008.742 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T22:56:48.742Z,1570057008.742 [Default:CheckIn] Stopped
2019-10-02T22:56:48.743Z,1570057008.743 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T22:56:48.743Z,1570057008.743 [Default:CheckIn](INFO): Running loop #5
2019-10-02T22:56:48.743Z,1570057008.743 [Default:CheckIn] Running Loop=5
2019-10-02T22:56:48.743Z,1570057008.743 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T22:56:48.743Z,1570057008.743 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T22:56:50.306Z,1570057010.306 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-02T22:56:50.306Z,1570057010.306 [NAL9602] Data Fault, FailCount= 4
2019-10-02T22:56:50.306Z,1570057010.306 [NAL9602](ERROR): Data Fault
2019-10-02T22:56:50.401Z,1570057010.401 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-02T22:56:50.710Z,1570057010.710 [NAL9602](INFO): Powering down
2019-10-02T22:56:51.603Z,1570057011.603 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-02T22:56:51.603Z,1570057011.603 [NAL9602] No Fault, FailCount= 4
2019-10-02T22:57:21.014Z,1570057041.014 [NAL9602](INFO): Powering up NAL9602
2019-10-02T22:57:31.918Z,1570057051.918 [NAL9602](INFO): NAL9602 initialized
2019-10-02T22:57:32.737Z,1570057052.737 [NAL9602](DEBUG): Fix Requested
2019-10-02T23:01:48.897Z,1570057308.897 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T22:56:48.7Z
2019-10-02T23:01:48.897Z,1570057308.897 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T23:01:48.897Z,1570057308.897 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T23:02:00.656Z,1570057320.656 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20191002T205340/Courier0034.lzma
2019-10-02T23:02:02.662Z,1570057322.662 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0034.lzma.bak
2019-10-02T23:02:02.663Z,1570057322.663 [DataOverHttps](INFO): SBD MOMSN=11841580
2019-10-02T23:02:24.985Z,1570057344.985 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20191002T205340/Express0035.lzma
2019-10-02T23:02:26.990Z,1570057346.990 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0035.lzma.bak
2019-10-02T23:02:26.991Z,1570057346.991 [DataOverHttps](INFO): SBD MOMSN=11841582
2019-10-02T23:02:30.925Z,1570057350.925 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T23:02:30.926Z,1570057350.926 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T23:02:30.926Z,1570057350.926 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T23:02:34.918Z,1570057354.918 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T23:03:05.621Z,1570057385.621 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T23:07:31.501Z,1570057651.501 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T23:07:31.501Z,1570057651.501 [Default:CheckIn:C.Wait] Stopped
2019-10-02T23:07:31.501Z,1570057651.501 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T23:07:31.502Z,1570057651.502 [Default:CheckIn:D] Running Loop=1
2019-10-02T23:07:31.936Z,1570057651.936 [Default:CheckIn:D] Stopped
2019-10-02T23:07:31.936Z,1570057651.936 [Default:CheckIn:E] Running Loop=1
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.247221 min 
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn:E] Stopped
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn] Stopped
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn](INFO): Running loop #6
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn] Running Loop=6
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T23:07:32.302Z,1570057652.302 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T23:07:33.886Z,1570057653.886 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-02T23:07:33.886Z,1570057653.886 [NAL9602] Data Fault, FailCount= 5
2019-10-02T23:07:33.886Z,1570057653.886 [NAL9602](ERROR): Data Fault
2019-10-02T23:07:33.919Z,1570057653.919 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-02T23:07:33.919Z,1570057653.919 [CBIT](CRITICAL): Data Fault in component: NAL9602
2019-10-02T23:07:34.300Z,1570057654.300 [NAL9602](INFO): Powering down
2019-10-02T23:07:34.338Z,1570057654.338 [CommandLine](FAULT): Scheduling is paused
2019-10-02T23:07:34.339Z,1570057654.339 [CBIT](INFO): Critical error at 20191002T230733
2019-10-02T23:07:34.339Z,1570057654.339 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-10-02T23:09:33.906Z,1570057773.906 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-02T23:09:33.906Z,1570057773.906 [NAL9602] No Fault, FailCount= 5
2019-10-02T23:09:34.274Z,1570057774.274 [NAL9602](INFO): Powering up NAL9602
2019-10-02T23:09:45.190Z,1570057785.190 [NAL9602](INFO): NAL9602 initialized
2019-10-02T23:09:46.005Z,1570057786.005 [NAL9602](DEBUG): Fix Requested
2019-10-02T23:12:32.481Z,1570057952.481 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T23:07:32.3Z
2019-10-02T23:12:32.481Z,1570057952.481 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T23:12:32.482Z,1570057952.482 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T23:12:41.304Z,1570057961.304 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20191002T205340/Courier0037.lzma
2019-10-02T23:12:43.601Z,1570057963.601 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0037.lzma.bak
2019-10-02T23:12:43.602Z,1570057963.602 [DataOverHttps](INFO): SBD MOMSN=11841605
2019-10-02T23:13:04.805Z,1570057984.805 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20191002T205340/Express0038.lzma
2019-10-02T23:13:06.807Z,1570057986.807 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0038.lzma.bak
2019-10-02T23:13:06.807Z,1570057986.807 [DataOverHttps](INFO): SBD MOMSN=11841610
2019-10-02T23:13:10.454Z,1570057990.454 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T23:13:10.454Z,1570057990.454 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T23:13:10.454Z,1570057990.454 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T23:14:48.190Z,1570058088.190 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T23:15:18.887Z,1570058118.887 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T23:18:11.023Z,1570058291.023 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-02T23:18:11.023Z,1570058291.023 [Default:CheckIn:C.Wait] Stopped
2019-10-02T23:18:11.023Z,1570058291.023 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T23:18:11.024Z,1570058291.024 [Default:CheckIn:D] Running Loop=1
2019-10-02T23:18:11.437Z,1570058291.437 [Default:CheckIn:D] Stopped
2019-10-02T23:18:11.437Z,1570058291.437 [Default:CheckIn:E] Running Loop=1
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 67.905579 min 
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn:E] Stopped
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn] Stopped
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T23:18:11.872Z,1570058291.872 [Default:CheckIn](INFO): Running loop #7
2019-10-02T23:18:11.873Z,1570058291.873 [Default:CheckIn] Running Loop=7
2019-10-02T23:18:11.873Z,1570058291.873 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-02T23:18:11.873Z,1570058291.873 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-02T23:18:13.429Z,1570058293.429 [NAL9602](DEBUG): Fix Requested
2019-10-02T23:23:11.000Z,1570058592.000 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-02T23:18:11.9Z
2019-10-02T23:23:11.000Z,1570058592.000 [Default:CheckIn:Read_GPS] Stopped
2019-10-02T23:23:12.000Z,1570058592.000 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-02T23:23:16.018Z,1570058596.018 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-02T23:23:28.264Z,1570058608.264 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191002T205340/Courier0040.lzma
2019-10-02T23:23:30.270Z,1570058610.270 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Courier0040.lzma.bak
2019-10-02T23:23:30.271Z,1570058610.271 [DataOverHttps](INFO): SBD MOMSN=11841644
2019-10-02T23:23:46.717Z,1570058626.717 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-02T23:23:53.297Z,1570058633.297 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191002T205340/Express0041.lzma
2019-10-02T23:23:55.302Z,1570058635.302 [DataOverHttps](INFO): Moved sent file to Logs/20191002T205340/Express0041.lzma.bak
2019-10-02T23:23:55.303Z,1570058635.303 [DataOverHttps](INFO): SBD MOMSN=11841646
2019-10-02T23:23:58.874Z,1570058638.874 [Default:CheckIn:Read_Iridium] Stopped
2019-10-02T23:23:58.874Z,1570058638.874 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-02T23:23:58.874Z,1570058638.874 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-02T23:26:15.768Z,1570058775.768 [CommandLine](IMPORTANT): got command restart application
2019-10-02T23:26:16.777Z,1570058776.777 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:16.777Z,1570058776.777 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:16.905Z,1570058776.905 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-10-02T23:26:16.905Z,1570058776.905 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:16.906Z,1570058776.906 [CommandLine](INFO): Join timeout helper Thread ID is 534
2019-10-02T23:26:16.906Z,1570058776.906 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-10-02T23:26:16.906Z,1570058776.906 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:16.907Z,1570058776.907 [NavChartDb](INFO): Join timeout helper Thread ID is 535
2019-10-02T23:26:16.934Z,1570058776.934 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:16.935Z,1570058776.935 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:16.949Z,1570058776.949 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-10-02T23:26:16.949Z,1570058776.949 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:16.949Z,1570058776.949 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 536
2019-10-02T23:26:17.001Z,1570058777.001 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:17.001Z,1570058777.001 [WetLabsBB2FL](INFO): Powering down
2019-10-02T23:26:17.002Z,1570058777.002 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.009Z,1570058777.009 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-10-02T23:26:17.009Z,1570058777.009 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.009Z,1570058777.009 [CTD_Seabird](INFO): Join timeout helper Thread ID is 537
2019-10-02T23:26:17.010Z,1570058777.010 [CTD_Seabird](INFO): Powering down
2019-10-02T23:26:17.021Z,1570058777.021 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:17.021Z,1570058777.021 [CTD_Seabird](INFO): Powering down
2019-10-02T23:26:17.037Z,1570058777.037 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.037Z,1570058777.037 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-10-02T23:26:17.037Z,1570058777.037 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.038Z,1570058777.038 [Radio_Surface](INFO): Join timeout helper Thread ID is 538
2019-10-02T23:26:17.345Z,1570058777.345 [Radio_Surface](INFO): Powering down
2019-10-02T23:26:17.346Z,1570058777.346 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:17.346Z,1570058777.346 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.362Z,1570058777.362 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-10-02T23:26:17.362Z,1570058777.362 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:17.362Z,1570058777.362 [DataOverHttps](INFO): Join timeout helper Thread ID is 539
2019-10-02T23:26:18.245Z,1570058778.245 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:18.245Z,1570058778.245 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.254Z,1570058778.254 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-10-02T23:26:18.254Z,1570058778.254 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.254Z,1570058778.254 [logger](INFO): Join timeout helper Thread ID is 540
2019-10-02T23:26:18.273Z,1570058778.273 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:18.273Z,1570058778.273 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.275Z,1570058778.275 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-10-02T23:26:18.275Z,1570058778.275 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.275Z,1570058778.275 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-10-02T23:26:18.275Z,1570058778.275 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.275Z,1570058778.275 [controlThread](INFO): Join timeout helper Thread ID is 541
2019-10-02T23:26:18.316Z,1570058778.316 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-02T23:26:18.316Z,1570058778.316 [controlThread](DEBUG): Uninitializing ControlThread
2019-10-02T23:26:18.316Z,1570058778.316 [AHRS_M2](INFO): Powering down
2019-10-02T23:26:18.389Z,1570058778.389 [NAL9602](INFO): Powering down
2019-10-02T23:26:18.391Z,1570058778.391 [DAT](INFO): Powering down
2019-10-02T23:26:18.530Z,1570058778.530 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-10-02T23:26:18.531Z,1570058778.531 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-10-02T23:26:18.532Z,1570058778.532 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-10-02T23:26:18.532Z,1570058778.532 [MissionManager](INFO): Uninitializing Mission Default
2019-10-02T23:26:18.532Z,1570058778.532 [Default] Stopped
2019-10-02T23:26:18.533Z,1570058778.533 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-02T23:26:18.533Z,1570058778.533 [Default:B.GoToSurface] Stopped
2019-10-02T23:26:18.533Z,1570058778.533 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-02T23:26:18.533Z,1570058778.533 [Default:CheckIn] Stopped
2019-10-02T23:26:18.533Z,1570058778.533 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-02T23:26:18.533Z,1570058778.533 [Default:CheckIn:C.Wait] Stopped
2019-10-02T23:26:18.533Z,1570058778.533 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-02T23:26:18.535Z,1570058778.535 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-10-02T23:26:18.536Z,1570058778.536 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-10-02T23:26:18.536Z,1570058778.536 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-10-02T23:26:18.536Z,1570058778.536 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-10-02T23:26:18.537Z,1570058778.537 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-10-02T23:26:18.537Z,1570058778.537 [BuoyancyServo](INFO): Powering down
2019-10-02T23:26:18.549Z,1570058778.549 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-10-02T23:26:18.549Z,1570058778.549 [ElevatorServo](INFO): Powering down
2019-10-02T23:26:18.550Z,1570058778.550 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-10-02T23:26:18.550Z,1570058778.550 [MassServo](INFO): Powering down
2019-10-02T23:26:18.551Z,1570058778.551 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-02T23:26:18.551Z,1570058778.551 [RudderServo](INFO): Powering down
2019-10-02T23:26:18.551Z,1570058778.551 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-10-02T23:26:18.552Z,1570058778.552 [ThrusterServo](INFO): Powering down
2019-10-02T23:26:18.552Z,1570058778.552 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-10-02T23:26:18.553Z,1570058778.553 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-10-02T23:26:18.553Z,1570058778.553 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-10-02T23:26:18.553Z,1570058778.553 [CBIT](DEBUG): Powering off loads.
2019-10-02T23:26:18.565Z,1570058778.565 [CBIT](DEBUG): Disabling WDT.
2019-10-02T23:26:18.577Z,1570058778.577 [CBIT](DEBUG): Opening all GF detection circuits.
2019-10-02T23:26:18.578Z,1570058778.578 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.670Z,1570058778.670 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.677Z,1570058778.677 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.729Z,1570058778.729 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.733Z,1570058778.733 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.775Z,1570058778.775 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-02T23:26:18.846Z,1570058778.846 [logger ThreadHandler](INFO): Thread cancelled.