2019-08-22T17:34:41.313Z,1566495281.313 [Supervisor](DEBUG): Initializing supervisor.
2019-08-22T17:34:41.315Z,1566495281.315 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-08-22T17:34:41.316Z,1566495281.316 [SyncHandler](INFO): Protected caller Thread ID is 995
2019-08-22T17:34:41.316Z,1566495281.316 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-08-22T17:34:41.317Z,1566495281.317 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-08-22T17:34:41.318Z,1566495281.318 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 996
2019-08-22T17:34:41.320Z,1566495281.320 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-08-22T17:34:41.332Z,1566495281.332 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-08-22T17:34:41.333Z,1566495281.333 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-08-22T17:34:41.333Z,1566495281.333 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 997
2019-08-22T17:34:41.334Z,1566495281.334 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-08-22T17:34:41.335Z,1566495281.335 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-08-22T17:34:41.336Z,1566495281.336 [logger ThreadHandler](INFO): Protected caller Thread ID is 998
2019-08-22T17:34:41.338Z,1566495281.338 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-08-22T17:34:41.338Z,1566495281.338 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-08-22T17:34:41.339Z,1566495281.339 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-08-22T17:34:41.435Z,1566495281.435 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-08-22T17:34:41.436Z,1566495281.436 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-08-22T17:34:41.666Z,1566495281.666 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-08-22T17:34:41.667Z,1566495281.667 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-08-22T17:34:41.950Z,1566495281.950 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-08-22T17:34:41.951Z,1566495281.951 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-08-22T17:34:42.516Z,1566495282.516 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-08-22T17:34:42.516Z,1566495282.516 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-08-22T17:34:42.959Z,1566495282.959 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-08-22T17:34:42.960Z,1566495282.960 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-08-22T17:34:43.436Z,1566495283.436 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-08-22T17:34:43.437Z,1566495283.437 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-08-22T17:34:43.743Z,1566495283.743 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-08-22T17:34:43.744Z,1566495283.744 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-08-22T17:34:44.077Z,1566495284.077 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-08-22T17:34:44.077Z,1566495284.077 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-08-22T17:34:44.474Z,1566495284.474 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-08-22T17:34:44.474Z,1566495284.474 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-08-22T17:34:44.624Z,1566495284.624 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-08-22T17:34:44.625Z,1566495284.625 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-08-22T17:34:44.729Z,1566495284.729 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-08-22T17:34:44.730Z,1566495284.730 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-08-22T17:34:44.811Z,1566495284.811 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-08-22T17:34:44.913Z,1566495284.913 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-08-22T17:34:44.913Z,1566495284.913 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-08-22T17:34:45.110Z,1566495285.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-08-22T17:34:45.110Z,1566495285.110 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-08-22T17:34:45.317Z,1566495285.317 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-08-22T17:34:45.319Z,1566495285.319 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-08-22T17:34:45.320Z,1566495285.320 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-08-22T17:34:45.403Z,1566495285.403 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-08-22T17:34:45.632Z,1566495285.632 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-08-22T17:34:45.633Z,1566495285.633 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-08-22T17:34:45.730Z,1566495285.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-08-22T17:34:45.902Z,1566495285.902 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-08-22T17:34:46.115Z,1566495286.115 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-08-22T17:34:46.201Z,1566495286.201 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-08-22T17:34:46.304Z,1566495286.304 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-08-22T17:34:46.398Z,1566495286.398 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-08-22T17:34:46.558Z,1566495286.558 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-08-22T17:34:46.670Z,1566495286.670 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-08-22T17:34:46.920Z,1566495286.920 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2019-08-22T17:34:46.921Z,1566495286.921 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-08-22T17:34:46.923Z,1566495286.923 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-08-22T17:34:47.210Z,1566495287.210 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-08-22T17:34:47.210Z,1566495287.210 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-08-22T17:34:47.539Z,1566495287.539 [BuoyancyServo] Loaded
2019-08-22T17:34:47.539Z,1566495287.539 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-08-22T17:34:47.555Z,1566495287.555 [ElevatorServo] Loaded
2019-08-22T17:34:47.555Z,1566495287.555 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-08-22T17:34:47.626Z,1566495287.626 [MassServo] Loaded
2019-08-22T17:34:47.626Z,1566495287.626 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-08-22T17:34:47.647Z,1566495287.647 [RudderServo] Loaded
2019-08-22T17:34:47.647Z,1566495287.647 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-08-22T17:34:47.684Z,1566495287.684 [ThrusterServo] Loaded
2019-08-22T17:34:47.684Z,1566495287.684 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-08-22T17:34:47.685Z,1566495287.685 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-08-22T17:34:47.685Z,1566495287.685 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-08-22T17:34:47.818Z,1566495287.818 [SBIT](DEBUG): Construct Startup Built In Test.
2019-08-22T17:34:47.847Z,1566495287.847 [SBIT] Loaded
2019-08-22T17:34:47.847Z,1566495287.847 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-08-22T17:34:47.848Z,1566495287.848 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-08-22T17:34:47.876Z,1566495287.876 [IBIT] Loaded
2019-08-22T17:34:47.876Z,1566495287.876 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-08-22T17:34:47.879Z,1566495287.879 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-08-22T17:34:48.265Z,1566495288.265 [CBIT] Loaded
2019-08-22T17:34:48.266Z,1566495288.266 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-08-22T17:34:48.266Z,1566495288.266 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-08-22T17:34:48.266Z,1566495288.266 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-08-22T17:34:48.447Z,1566495288.447 [Aanderaa_O2] Loaded
2019-08-22T17:34:48.448Z,1566495288.448 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-08-22T17:34:48.457Z,1566495288.457 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-08-22T17:34:48.463Z,1566495288.463 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-08-22T17:34:48.464Z,1566495288.464 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-08-22T17:34:48.469Z,1566495288.469 [CTD_Seabird](INFO): created writer for : depth
2019-08-22T17:34:48.470Z,1566495288.470 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-08-22T17:34:48.475Z,1566495288.475 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-08-22T17:34:48.476Z,1566495288.476 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-08-22T17:34:48.481Z,1566495288.481 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-08-22T17:34:48.481Z,1566495288.481 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-08-22T17:34:48.487Z,1566495288.487 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-08-22T17:34:48.487Z,1566495288.487 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-08-22T17:34:48.493Z,1566495288.493 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-08-22T17:34:48.493Z,1566495288.493 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-08-22T17:34:48.498Z,1566495288.498 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-08-22T17:34:48.525Z,1566495288.525 [CTD_Seabird] Loaded
2019-08-22T17:34:48.525Z,1566495288.525 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-08-22T17:34:48.526Z,1566495288.526 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066B4E0
2019-08-22T17:34:48.526Z,1566495288.526 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1077
2019-08-22T17:34:48.556Z,1566495288.556 [ESPComponent] Loaded
2019-08-22T17:34:48.557Z,1566495288.557 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-08-22T17:34:48.571Z,1566495288.571 [PAR_Licor] Loaded
2019-08-22T17:34:48.571Z,1566495288.571 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-08-22T17:34:48.618Z,1566495288.618 [WetLabsBB2FL] Loaded
2019-08-22T17:34:48.619Z,1566495288.619 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-08-22T17:34:48.620Z,1566495288.620 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069B4E0
2019-08-22T17:34:48.620Z,1566495288.620 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1078
2019-08-22T17:34:48.621Z,1566495288.621 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-08-22T17:34:48.621Z,1566495288.621 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-08-22T17:34:48.662Z,1566495288.662 [DepthRateCalculator] Loaded
2019-08-22T17:34:48.663Z,1566495288.663 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-08-22T17:34:48.668Z,1566495288.668 [PitchRateCalculator] Loaded
2019-08-22T17:34:48.669Z,1566495288.669 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-08-22T17:34:48.684Z,1566495288.684 [SpeedCalculator] Loaded
2019-08-22T17:34:48.685Z,1566495288.685 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-08-22T17:34:48.706Z,1566495288.706 [TempGradientCalculator] Loaded
2019-08-22T17:34:48.706Z,1566495288.706 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-08-22T17:34:48.712Z,1566495288.712 [YawRateCalculator] Loaded
2019-08-22T17:34:48.712Z,1566495288.712 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-08-22T17:34:48.745Z,1566495288.745 [ElevatorOffsetCalculator] Loaded
2019-08-22T17:34:48.745Z,1566495288.745 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-08-22T17:34:48.746Z,1566495288.746 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-08-22T17:34:48.746Z,1566495288.746 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-08-22T17:34:48.778Z,1566495288.778 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-08-22T17:34:48.778Z,1566495288.778 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-08-22T17:34:48.880Z,1566495288.880 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-08-22T17:34:48.881Z,1566495288.881 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-08-22T17:34:48.902Z,1566495288.902 [NavChart] Loaded
2019-08-22T17:34:48.902Z,1566495288.902 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-08-22T17:34:48.906Z,1566495288.906 [UniversalFixResidualReporter] Loaded
2019-08-22T17:34:48.906Z,1566495288.906 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-08-22T17:34:48.907Z,1566495288.907 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-08-22T17:34:48.907Z,1566495288.907 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-08-22T17:34:49.256Z,1566495289.256 [AHRS_M2] Loaded
2019-08-22T17:34:49.256Z,1566495289.256 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-08-22T17:34:49.332Z,1566495289.332 [DataOverHttps] Loaded
2019-08-22T17:34:49.332Z,1566495289.332 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-08-22T17:34:49.334Z,1566495289.334 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409744E0
2019-08-22T17:34:49.334Z,1566495289.334 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1079
2019-08-22T17:34:49.347Z,1566495289.347 [Depth_Keller] Loaded
2019-08-22T17:34:49.347Z,1566495289.347 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-08-22T17:34:49.352Z,1566495289.352 [DropWeight] Loaded
2019-08-22T17:34:49.352Z,1566495289.352 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-08-22T17:34:49.482Z,1566495289.482 [DVL_micro] Loaded
2019-08-22T17:34:49.482Z,1566495289.482 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2019-08-22T17:34:49.572Z,1566495289.572 [NAL9602] Loaded
2019-08-22T17:34:49.572Z,1566495289.572 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-08-22T17:34:49.577Z,1566495289.577 [Onboard] Loaded
2019-08-22T17:34:49.578Z,1566495289.578 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-08-22T17:34:49.581Z,1566495289.581 [Radio_Surface] Loaded
2019-08-22T17:34:49.581Z,1566495289.581 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-08-22T17:34:49.582Z,1566495289.582 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A44E0
2019-08-22T17:34:49.583Z,1566495289.583 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1080
2019-08-22T17:34:49.710Z,1566495289.710 [DAT] Loaded
2019-08-22T17:34:49.711Z,1566495289.711 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-08-22T17:34:50.995Z,1566495290.995 [BPC1] Loaded
2019-08-22T17:34:50.995Z,1566495290.995 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-08-22T17:34:50.996Z,1566495290.996 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-08-22T17:34:50.996Z,1566495290.996 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-08-22T17:34:51.066Z,1566495291.066 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-08-22T17:34:51.066Z,1566495291.066 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-08-22T17:34:51.132Z,1566495291.132 [VerticalControl](DEBUG): Construct VerticalControl.
2019-08-22T17:34:51.216Z,1566495291.216 [VerticalControl] Loaded
2019-08-22T17:34:51.216Z,1566495291.216 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-08-22T17:34:51.217Z,1566495291.217 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-08-22T17:34:51.275Z,1566495291.275 [HorizontalControl] Loaded
2019-08-22T17:34:51.275Z,1566495291.275 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-08-22T17:34:51.276Z,1566495291.276 [SpeedControl](DEBUG): Construct SpeedControl.
2019-08-22T17:34:51.277Z,1566495291.277 [SpeedControl] Loaded
2019-08-22T17:34:51.278Z,1566495291.278 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-08-22T17:34:51.278Z,1566495291.278 [LoopControl](DEBUG): Construct LoopControl.
2019-08-22T17:34:51.279Z,1566495291.279 [LoopControl] Loaded
2019-08-22T17:34:51.279Z,1566495291.279 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-08-22T17:34:51.279Z,1566495291.279 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-08-22T17:34:51.280Z,1566495291.280 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-08-22T17:34:51.293Z,1566495291.293 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-08-22T17:34:51.294Z,1566495291.294 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-08-22T17:34:51.581Z,1566495291.581 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-08-22T17:34:51.585Z,1566495291.585 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-08-22T17:34:51.586Z,1566495291.586 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-08-22T17:34:51.592Z,1566495291.592 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-08-22T17:34:51.593Z,1566495291.593 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADF4E0
2019-08-22T17:34:51.594Z,1566495291.594 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1081
2019-08-22T17:34:51.598Z,1566495291.598 [Supervisor](INFO): Main Thread ID is 802
2019-08-22T17:34:51.599Z,1566495291.599 [Supervisor](DEBUG): Running supervisor.
2019-08-22T17:34:51.599Z,1566495291.599 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1082
2019-08-22T17:34:51.603Z,1566495291.603 [controlThread ThreadHandler](INFO): Handler Thread ID is 1083
2019-08-22T17:34:51.603Z,1566495291.603 [controlThread](DEBUG): Initializing ControlThread
2019-08-22T17:34:51.605Z,1566495291.605 [SBIT](INFO): Initialize SBIT Component.
2019-08-22T17:34:51.605Z,1566495291.605 [SBIT](IMPORTANT): git: 2019-08-13
2019-08-22T17:34:51.605Z,1566495291.605 [SBIT](INFO): git hash: 6b080875362fb71081cecd990260e30fa66d1cc0
2019-08-22T17:34:51.606Z,1566495291.606 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-08-22T17:34:51.607Z,1566495291.607 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-08-22T17:34:51.608Z,1566495291.608 [SBIT](INFO): Beginning SBIT in 24.000000 seconds.
2019-08-22T17:34:51.609Z,1566495291.609 [IBIT](INFO): Initialize IBIT Component.
2019-08-22T17:34:51.610Z,1566495291.610 [CBIT](DEBUG): Initialize CBIT Component.
2019-08-22T17:34:51.611Z,1566495291.611 [logger ThreadHandler](INFO): Handler Thread ID is 1084
2019-08-22T17:34:51.621Z,1566495291.621 [CBIT](DEBUG): Initialized mux pins.
2019-08-22T17:34:51.621Z,1566495291.621 [CBIT](DEBUG): Initializing the watchdog timer.
2019-08-22T17:34:51.629Z,1566495291.629 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1085
2019-08-22T17:34:51.630Z,1566495291.630 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-08-22T17:34:51.633Z,1566495291.633 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-08-22T17:34:51.635Z,1566495291.635 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1087
2019-08-22T17:34:51.636Z,1566495291.636 [WetLabsBB2FL](INFO): Powering down
2019-08-22T17:34:51.645Z,1566495291.645 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-08-22T17:34:51.645Z,1566495291.645 [CBIT](DEBUG): Initializing heartbeat.
2019-08-22T17:34:51.665Z,1566495291.665 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1088
2019-08-22T17:34:51.666Z,1566495291.666 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-08-22T17:34:51.677Z,1566495291.677 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1089
2019-08-22T17:34:51.693Z,1566495291.693 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1090
2019-08-22T17:34:51.696Z,1566495291.696 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-08-22T17:34:51.697Z,1566495291.697 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-08-22T17:34:51.697Z,1566495291.697 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-08-22T17:34:51.698Z,1566495291.698 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-08-22T17:34:51.698Z,1566495291.698 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-08-22T17:34:51.698Z,1566495291.698 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-08-22T17:34:51.698Z,1566495291.698 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-08-22T17:34:51.698Z,1566495291.698 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-08-22T17:34:51.699Z,1566495291.699 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-08-22T17:34:51.700Z,1566495291.700 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-08-22T17:34:51.700Z,1566495291.700 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-08-22T17:34:51.717Z,1566495291.717 [CBIT](DEBUG): Deactivating GF circuits.
2019-08-22T17:34:51.717Z,1566495291.717 [CBIT](DEBUG): Deactivating emergency mode.
2019-08-22T17:34:51.753Z,1566495291.753 [CBIT](DEBUG): Backplane powered.
2019-08-22T17:34:51.778Z,1566495291.778 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-08-22T17:34:51.778Z,1566495291.778 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-08-22T17:34:51.779Z,1566495291.779 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-08-22T17:34:51.779Z,1566495291.779 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-08-22T17:34:51.780Z,1566495291.780 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-08-22T17:34:51.780Z,1566495291.780 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-08-22T17:34:51.789Z,1566495291.789 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-08-22T17:34:51.790Z,1566495291.790 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-08-22T17:34:51.794Z,1566495291.794 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-08-22T17:34:51.795Z,1566495291.795 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-08-22T17:34:51.796Z,1566495291.796 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-08-22T17:34:51.797Z,1566495291.796 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-08-22T17:34:51.806Z,1566495291.806 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-08-22T17:34:51.832Z,1566495291.832 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-22T17:34:51.887Z,1566495291.887 [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-08-22T17:34:51.887Z,1566495291.887 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-08-22T17:34:51.959Z,1566495291.959 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-08-22T17:34:51.960Z,1566495291.960 [Default:A.Wait](DEBUG): Construct Wait.
2019-08-22T17:34:51.978Z,1566495291.978 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-08-22T17:34:52.013Z,1566495292.013 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-08-22T17:34:52.015Z,1566495292.015 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-08-22T17:34:52.037Z,1566495292.037 [Default:E.Execute](DEBUG): Construct Execute.
2019-08-22T17:34:52.040Z,1566495292.040 [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-08-22T17:34:52.061Z,1566495292.061 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,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-08-22T17:34:52.081Z,1566495292.081 [Radio_Surface](INFO): Powering up
2019-08-22T17:34:52.098Z,1566495292.098 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-08-22T17:34:52.150Z,1566495292.150 [Depth_Keller](ERROR): Pressure reading out of range: 1895.684326 decibar
2019-08-22T17:34:52.173Z,1566495292.173 [DVL_micro](INFO): Initializing
2019-08-22T17:34:52.199Z,1566495292.199 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-08-22T17:34:52.199Z,1566495292.199 [DAT](INFO): Powering up
2019-08-22T17:34:52.199Z,1566495292.199 [DAT](DEBUG): Initializing DAT.
2019-08-22T17:34:52.212Z,1566495292.212 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-08-22T17:34:52.281Z,1566495292.281 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-08-22T17:34:52.316Z,1566495292.316 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:52.325Z,1566495292.325 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-08-22T17:34:52.327Z,1566495292.327 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:52.339Z,1566495292.339 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-08-22T17:34:52.340Z,1566495292.340 [MassServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:52.349Z,1566495292.349 [MassServo](DEBUG): Initializing MassServo.
2019-08-22T17:34:52.350Z,1566495292.350 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:52.357Z,1566495292.357 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-22T17:34:52.358Z,1566495292.358 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:52.365Z,1566495292.365 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-08-22T17:34:53.257Z,1566495293.257 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-08-22T17:34:53.257Z,1566495293.257 [RudderServo](FAULT): Rudder failed to initialize
2019-08-22T17:34:53.257Z,1566495293.257 [RudderServo] Communications Fault, FailCount= 1
2019-08-22T17:34:53.257Z,1566495293.257 [RudderServo](ERROR): Communications Fault
2019-08-22T17:34:53.368Z,1566495293.368 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-08-22T17:34:53.574Z,1566495293.574 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-22T17:34:53.574Z,1566495293.574 [RudderServo](INFO): Powering down
2019-08-22T17:34:54.236Z,1566495294.236 [RudderServo](DEBUG): Initializing EZServoServo.
2019-08-22T17:34:54.370Z,1566495294.370 [RudderServo](DEBUG): Initializing RudderServo.
2019-08-22T17:34:54.374Z,1566495294.374 [CBIT](INFO): Clearing failed state for component RudderServo
2019-08-22T17:34:54.374Z,1566495294.374 [RudderServo] No Fault, FailCount= 1
2019-08-22T17:34:55.513Z,1566495295.513 [Aanderaa_O2](INFO): Powering down
2019-08-22T17:35:07.542Z,1566495307.542 [DAT](INFO): setting local address to 3
2019-08-22T17:35:07.942Z,1566495307.942 [DAT](INFO): set local address to 3
2019-08-22T17:35:16.055Z,1566495316.055 [SBIT](IMPORTANT): Beginning Startup BIT
2019-08-22T17:35:16.062Z,1566495316.062 [CBIT](IMPORTANT): Beginning ground fault scan
2019-08-22T17:35:19.851Z,1566495319.851 [NAL9602](INFO): Powering up NAL9602
2019-08-22T17:35:26.814Z,1566495326.814 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.064751
CHAN A1 (24V): 0.082591
CHAN A2 (12V): 0.043072
CHAN A3 (5V): 0.006463
CHAN B0 (3.3V): 0.003422
CHAN B1 (3.15aV): 0.003261
CHAN B2 (3.15bV): 0.003191
CHAN B3 (GND): -0.001598
OPEN: 0.007951
Full Scale Calc: 4.765 mA, -1.589 mA
2019-08-22T17:35:30.808Z,1566495330.808 [NAL9602](INFO): NAL9602 initialized
2019-08-22T17:35:31.581Z,1566495331.581 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:42.604Z,1566495342.604 [NAL9602](INFO): SBD MO Status=0, MOMSN=32523, MT Status=0, MTMSN=0
2019-08-22T17:35:42.604Z,1566495342.604 [NAL9602](INFO): No messages in MT queue
2019-08-22T17:35:43.437Z,1566495343.437 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:45.845Z,1566495345.845 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:48.680Z,1566495348.680 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:51.904Z,1566495351.904 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:54.737Z,1566495354.737 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:35:57.969Z,1566495357.969 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:00.893Z,1566495360.893 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:04.117Z,1566495364.117 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:06.953Z,1566495366.953 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:09.781Z,1566495369.781 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:10.215Z,1566495370.215 [SBIT](IMPORTANT): SBIT PASSED
2019-08-22T17:36:10.315Z,1566495370.315 [CommandLine](IMPORTANT): got command configSet list
2019-08-22T17:36:10.315Z,1566495370.315 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-22T17:36:10.316Z,1566495370.316 [CommandLine](IMPORTANT): No configSet variables persisted
2019-08-22T17:36:10.618Z,1566495370.618 [MissionManager](IMPORTANT): Started mission Startup
2019-08-22T17:36:10.619Z,1566495370.619 [Startup] Running Loop=1
2019-08-22T17:36:10.619Z,1566495370.619 [Startup](DEBUG): Aggregate::initialize Startup
2019-08-22T17:36:10.619Z,1566495370.619 [Startup:A.GoToSurface] Running Loop=1
2019-08-22T17:36:10.619Z,1566495370.619 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-22T17:36:10.620Z,1566495370.620 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-22T17:36:10.620Z,1566495370.620 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-22T17:36:10.620Z,1566495370.620 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-22T17:36:10.621Z,1566495370.621 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-22T17:36:10.621Z,1566495370.621 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-22T17:36:10.623Z,1566495370.623 [Startup:StartupSatComms] Running Loop=1
2019-08-22T17:36:10.623Z,1566495370.623 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-08-22T17:36:10.623Z,1566495370.623 [Startup:StartupSatComms:A] Running Loop=1
2019-08-22T17:36:11.006Z,1566495371.006 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-08-22T17:36:13.013Z,1566495373.013 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:36:13.409Z,1566495373.409 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173609.00,A,4149.82614,N,08324.67503,W,1.030,117.09,220819,,,A*71
2019-08-22T17:36:13.412Z,1566495373.412 [NAL9602](INFO): GPS fix at 20190822T173609: (41.830436, -83.411250)
2019-08-22T17:36:13.495Z,1566495373.495 [Startup:StartupSatComms:A] Stopped
2019-08-22T17:36:13.495Z,1566495373.495 [Startup:StartupSatComms:B] Running Loop=1
2019-08-22T17:36:13.912Z,1566495373.912 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-22T17:36:25.234Z,1566495385.234 [DVL_micro](ERROR): only read 42 of 46 data items
2019-08-22T17:36:25.234Z,1566495385.234 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 280 326 2 3 3 2 -108.1 -62.7 389.9 2 -33. 389.9 2 -108 -62 389 2 -33 -120 357 -1.98.0 28.0 0.005 35.0 1489 112
2019-08-22T17:36:46.406Z,1566495406.406 [NAL9602](INFO): SBD MO Status=2, MOMSN=32524, MT Status=2, MTMSN=0
2019-08-22T17:36:46.406Z,1566495406.406 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-22T17:37:07.050Z,1566495427.050 [NAL9602](INFO): SBD MO Status=1, MOMSN=32524, MT Status=0, MTMSN=0
2019-08-22T17:37:07.121Z,1566495427.121 [NAL9602](INFO): Sent 25 bytes from file Logs/20190822T172255/Courier0010.lzma
2019-08-22T17:37:07.121Z,1566495427.121 [NAL9602](INFO): Packets left to send: 0
2019-08-22T17:37:13.800Z,1566495433.800 [Startup:StartupSatComms:B](INFO): Timed out from 2019-08-22T17:36:13.5Z
2019-08-22T17:37:13.800Z,1566495433.800 [Startup:StartupSatComms:B] Stopped
2019-08-22T17:37:13.800Z,1566495433.800 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-08-22T17:37:13.800Z,1566495433.800 [Startup:StartupSatComms] Stopped
2019-08-22T17:37:13.800Z,1566495433.800 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-08-22T17:37:13.801Z,1566495433.801 [Startup](INFO): Completed Startup
2019-08-22T17:37:13.802Z,1566495433.802 [MissionManager](INFO): Startup is completed.
2019-08-22T17:37:13.802Z,1566495433.802 [MissionManager](INFO): Uninitializing Mission Startup
2019-08-22T17:37:13.802Z,1566495433.802 [Startup] Stopped
2019-08-22T17:37:13.802Z,1566495433.802 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-08-22T17:37:13.802Z,1566495433.802 [Startup:A.GoToSurface] Stopped
2019-08-22T17:37:13.802Z,1566495433.802 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-22T17:37:14.298Z,1566495434.298 [MissionManager](IMPORTANT): Started mission Default
2019-08-22T17:37:14.298Z,1566495434.298 [Default] Running Loop=1
2019-08-22T17:37:14.298Z,1566495434.298 [Default](DEBUG): Aggregate::initialize Default
2019-08-22T17:37:14.298Z,1566495434.298 [Default:B.GoToSurface] Running Loop=1
2019-08-22T17:37:14.298Z,1566495434.298 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-08-22T17:37:14.299Z,1566495434.299 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-08-22T17:37:14.299Z,1566495434.299 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-08-22T17:37:14.300Z,1566495434.300 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-08-22T17:37:14.309Z,1566495434.309 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-08-22T17:37:14.309Z,1566495434.309 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-08-22T17:37:14.310Z,1566495434.310 [Default:A.Wait] Running Loop=1
2019-08-22T17:37:14.310Z,1566495434.310 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-08-22T17:37:15.009Z,1566495435.009 [NAL9602](INFO): SBD MO Status=1, MOMSN=32525, MT Status=0, MTMSN=0
2019-08-22T17:37:15.057Z,1566495435.057 [NAL9602](INFO): Sent 213 bytes from file Logs/20190822T173441/Courier0000.lzma
2019-08-22T17:37:15.057Z,1566495435.057 [NAL9602](INFO): Packets left to send: 0
2019-08-22T17:37:27.621Z,1566495447.621 [Default:A.Wait](INFO): Done Waiting.
2019-08-22T17:37:27.621Z,1566495447.621 [Default:A.Wait] Stopped
2019-08-22T17:37:27.621Z,1566495447.621 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T17:37:28.024Z,1566495448.024 [Default:CheckIn] Running Loop=1
2019-08-22T17:37:28.024Z,1566495448.024 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T17:37:28.024Z,1566495448.024 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T17:37:28.429Z,1566495448.429 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-08-22T17:37:29.653Z,1566495449.653 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:37:30.030Z,1566495450.030 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173725.00,A,4149.68865,N,08324.70083,W,0.311,240.82,220819,,,A*7A
2019-08-22T17:37:30.032Z,1566495450.032 [NAL9602](INFO): GPS fix at 20190822T173725: (41.828144, -83.411681)
2019-08-22T17:37:30.056Z,1566495450.056 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T17:37:30.056Z,1566495450.056 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T17:37:30.476Z,1566495450.476 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-08-22T17:37:39.767Z,1566495459.767 [DVL_micro](ERROR): only read 36 of 46 data items
2019-08-22T17:37:39.767Z,1566495459.767 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 271 421 3 2 173.5 -116 2 201.4 42.6 430.6 2 173 -110 430 2 201 42 430 2 -0.59 -2.02 44.5 -3.0 28.0 .0 1489 115
2019-08-22T17:37:56.728Z,1566495476.728 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:37:56.728Z,1566495476.728 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:37:56.728Z,1566495476.728 [DVL_micro](ERROR): Data Fault
2019-08-22T17:37:56.762Z,1566495476.762 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:37:57.209Z,1566495477.209 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:37:57.212Z,1566495477.212 [NAL9602](INFO): SBD MO Status=2, MOMSN=32526, MT Status=2, MTMSN=0
2019-08-22T17:37:57.212Z,1566495477.212 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-22T17:37:57.976Z,1566495477.976 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:37:57.977Z,1566495477.977 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:37:58.347Z,1566495478.347 [DVL_micro](INFO): Initializing
2019-08-22T17:38:21.254Z,1566495501.254 [NAL9602](INFO): SBD MO Status=2, MOMSN=32526, MT Status=2, MTMSN=0
2019-08-22T17:38:21.254Z,1566495501.254 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-22T17:38:33.223Z,1566495513.223 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005069
2019-08-22T17:38:38.868Z,1566495518.868 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190822T173441/Courier0004.lzma
2019-08-22T17:38:39.674Z,1566495519.674 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0004.lzma.bak
2019-08-22T17:38:39.675Z,1566495519.675 [DataOverHttps](INFO): SBD MOMSN=11668842
2019-08-22T17:38:47.848Z,1566495527.848 [NAL9602](INFO): SBD MO Status=2, MOMSN=32526, MT Status=2, MTMSN=0
2019-08-22T17:38:47.848Z,1566495527.848 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-22T17:38:52.508Z,1566495532.508 [DataOverHttps](INFO): Sending 100 bytes from file Logs/20190822T172255/Express0011.lzma
2019-08-22T17:38:53.314Z,1566495533.314 [DataOverHttps](INFO): Moved sent file to Logs/20190822T172255/Express0011.lzma.bak
2019-08-22T17:38:53.314Z,1566495533.314 [DataOverHttps](INFO): SBD MOMSN=11668848
2019-08-22T17:39:07.070Z,1566495547.070 [DataOverHttps](INFO): Sending 728 bytes from file Logs/20190822T173441/Express0001.lzma
2019-08-22T17:39:07.874Z,1566495547.874 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0001.lzma.bak
2019-08-22T17:39:07.874Z,1566495547.874 [DataOverHttps](INFO): SBD MOMSN=11668855
2019-08-22T17:39:18.530Z,1566495558.530 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T17:39:20.242Z,1566495560.242 [DataOverHttps](INFO): Sending 108 bytes from file Logs/20190822T173441/Express0005.lzma
2019-08-22T17:39:21.042Z,1566495561.042 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0005.lzma.bak
2019-08-22T17:39:21.042Z,1566495561.042 [DataOverHttps](INFO): SBD MOMSN=11668870
2019-08-22T17:39:22.600Z,1566495562.600 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T17:39:22.600Z,1566495562.600 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T17:39:22.600Z,1566495562.600 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T17:40:34.096Z,1566495634.096 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-08-22T17:41:02.950Z,1566495662.950 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:41:02.950Z,1566495662.950 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:41:02.950Z,1566495662.950 [DVL_micro](ERROR): Data Fault
2019-08-22T17:41:03.017Z,1566495663.017 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:41:03.413Z,1566495663.413 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:41:04.224Z,1566495664.224 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:41:04.229Z,1566495664.229 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:41:04.574Z,1566495664.574 [DVL_micro](INFO): Initializing
2019-08-22T17:42:33.072Z,1566495753.072 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-22T17:42:33.077Z,1566495753.077 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-08-22T17:42:33.077Z,1566495753.077 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-08-22T17:42:33.080Z,1566495753.080 [BPC1](INFO): Received data from all battery sticks.
2019-08-22T17:44:08.784Z,1566495848.784 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:44:08.784Z,1566495848.784 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:44:08.784Z,1566495848.784 [DVL_micro](ERROR): Data Fault
2019-08-22T17:44:08.816Z,1566495848.816 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:44:09.265Z,1566495849.265 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:44:10.044Z,1566495850.044 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:44:10.044Z,1566495850.044 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:44:10.412Z,1566495850.412 [DVL_micro](INFO): Initializing
2019-08-22T17:44:23.383Z,1566495863.383 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T17:44:23.384Z,1566495863.384 [Default:CheckIn:C.Wait] Stopped
2019-08-22T17:44:23.384Z,1566495863.384 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T17:44:23.384Z,1566495863.384 [Default:CheckIn:D] Running Loop=1
2019-08-22T17:44:23.766Z,1566495863.766 [Default:CheckIn:D] Stopped
2019-08-22T17:44:23.766Z,1566495863.766 [Default:CheckIn:E] Running Loop=1
2019-08-22T17:44:24.183Z,1566495864.183 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.157799 min 
2019-08-22T17:44:24.183Z,1566495864.183 [Default:CheckIn:E] Stopped
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn] Stopped
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn](INFO): Running loop #2
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn] Running Loop=2
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T17:44:24.184Z,1566495864.184 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T17:44:25.773Z,1566495865.773 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:44:26.176Z,1566495866.176 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174422.00,A,4149.68480,N,08324.70279,W,0.486,190.36,220819,,,A*71
2019-08-22T17:44:26.178Z,1566495866.178 [NAL9602](INFO): GPS fix at 20190822T174422: (41.828080, -83.411713)
2019-08-22T17:44:26.208Z,1566495866.208 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T17:44:26.208Z,1566495866.208 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T17:44:34.093Z,1566495874.093 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190822T173441/Courier0007.lzma
2019-08-22T17:44:35.580Z,1566495875.580 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0007.lzma.bak
2019-08-22T17:44:35.580Z,1566495875.580 [DataOverHttps](INFO): SBD MOMSN=11668912
2019-08-22T17:44:48.332Z,1566495888.332 [NAL9602](INFO): SBD MO Status=1, MOMSN=32526, MT Status=0, MTMSN=0
2019-08-22T17:44:48.332Z,1566495888.332 [NAL9602](INFO): No messages in MT queue
2019-08-22T17:44:48.609Z,1566495888.609 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20190822T173441/Express0008.lzma
2019-08-22T17:44:49.414Z,1566495889.414 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0008.lzma.bak
2019-08-22T17:44:49.415Z,1566495889.415 [DataOverHttps](INFO): SBD MOMSN=11668915
2019-08-22T17:44:51.206Z,1566495891.206 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T17:44:51.206Z,1566495891.206 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T17:44:51.206Z,1566495891.206 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T17:45:19.036Z,1566495919.036 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T17:47:14.580Z,1566496034.580 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:47:14.580Z,1566496034.580 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:47:14.580Z,1566496034.580 [DVL_micro](ERROR): Data Fault
2019-08-22T17:47:14.620Z,1566496034.620 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:47:15.061Z,1566496035.061 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:47:15.840Z,1566496035.840 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:47:15.840Z,1566496035.840 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:47:16.198Z,1566496036.198 [DVL_micro](INFO): Initializing
2019-08-22T17:49:06.011Z,1566496146.011 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T174901
2019-08-22T17:49:12.761Z,1566496152.761 [DataOverHttps](INFO): Received command:configSet BPC1.batteryMissingStickThreshold 2 count persist;configSet BuoyancyServo.fastPumpDepth 6 meter persist;configSet CBIT.stopDepth 10 meter persist;configSet CTD_Seabird.minSalinityBound 0.01 practical_salinity_unit persist
2019-08-22T17:49:13.578Z,1566496153.578 [CommandLine](IMPORTANT): got command configSet BPC1.batteryMissingStickThreshold 2.000000 count persist
2019-08-22T17:49:13.580Z,1566496153.580 [CommandLine](IMPORTANT): got command configSet BuoyancyServo.fastPumpDepth 6.000000 meter persist
2019-08-22T17:49:13.583Z,1566496153.583 [CommandLine](IMPORTANT): got command configSet CBIT.stopDepth 10.000000 meter persist
2019-08-22T17:49:13.585Z,1566496153.585 [CommandLine](IMPORTANT): got command configSet CTD_Seabird.minSalinityBound 0.010000 practical_salinity_unit persist
2019-08-22T17:49:51.774Z,1566496191.774 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T17:49:51.774Z,1566496191.774 [Default:CheckIn:C.Wait] Stopped
2019-08-22T17:49:51.774Z,1566496191.774 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T17:49:51.774Z,1566496191.774 [Default:CheckIn:D] Running Loop=1
2019-08-22T17:49:52.163Z,1566496192.163 [Default:CheckIn:D] Stopped
2019-08-22T17:49:52.163Z,1566496192.163 [Default:CheckIn:E] Running Loop=1
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.631082 min 
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn:E] Stopped
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn] Stopped
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T17:49:52.568Z,1566496192.568 [Default:CheckIn](INFO): Running loop #3
2019-08-22T17:49:52.569Z,1566496192.569 [Default:CheckIn] Running Loop=3
2019-08-22T17:49:52.569Z,1566496192.569 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T17:49:52.569Z,1566496192.569 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T17:49:54.173Z,1566496194.173 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:49:54.595Z,1566496194.595 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174950.00,A,4149.68541,N,08324.70296,W,0.058,176.25,220819,,,A*79
2019-08-22T17:49:54.597Z,1566496194.597 [NAL9602](INFO): GPS fix at 20190822T174950: (41.828090, -83.411716)
2019-08-22T17:49:54.620Z,1566496194.620 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T17:49:54.620Z,1566496194.620 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T17:50:00.544Z,1566496200.544 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190822T173441/Courier0010.lzma
2019-08-22T17:50:01.350Z,1566496201.350 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0010.lzma.bak
2019-08-22T17:50:01.350Z,1566496201.350 [DataOverHttps](INFO): SBD MOMSN=11668946
2019-08-22T17:50:07.092Z,1566496207.092 [NAL9602](INFO): SBD MO Status=1, MOMSN=32527, MT Status=0, MTMSN=0
2019-08-22T17:50:07.092Z,1566496207.092 [NAL9602](INFO): No messages in MT queue
2019-08-22T17:50:15.502Z,1566496215.502 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190822T173441/Courier0013.lzma
2019-08-22T17:50:16.310Z,1566496216.310 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0013.lzma.bak
2019-08-22T17:50:16.310Z,1566496216.310 [DataOverHttps](INFO): SBD MOMSN=11668949
2019-08-22T17:50:20.450Z,1566496220.450 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:50:20.450Z,1566496220.450 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:50:20.450Z,1566496220.450 [DVL_micro](ERROR): Data Fault
2019-08-22T17:50:20.522Z,1566496220.522 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:50:20.913Z,1566496220.913 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:50:21.704Z,1566496221.704 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:50:21.709Z,1566496221.709 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:50:22.056Z,1566496222.056 [DVL_micro](INFO): Initializing
2019-08-22T17:50:30.113Z,1566496230.113 [DataOverHttps](INFO): Sending 400 bytes from file Logs/20190822T173441/Express0011.lzma
2019-08-22T17:50:30.918Z,1566496230.918 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0011.lzma.bak
2019-08-22T17:50:30.918Z,1566496230.918 [DataOverHttps](INFO): SBD MOMSN=11668951
2019-08-22T17:50:37.842Z,1566496237.842 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T17:50:40.694Z,1566496240.694 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T175036
2019-08-22T17:50:45.760Z,1566496245.760 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190822T173441/Express0015.lzma
2019-08-22T17:50:45.762Z,1566496245.762 [DataOverHttps](INFO): Received command:configSet DVL_micro.loadAtStartup 0 bool persist;
2019-08-22T17:50:46.073Z,1566496246.073 [CommandLine](IMPORTANT): got command configSet DVL_micro.loadAtStartup 0.000000 bool persist
2019-08-22T17:50:46.074Z,1566496246.074 [CommandLine](IMPORTANT): configSet DVL_micro.loadAtStartup requires a restart to take effect.
2019-08-22T17:50:46.566Z,1566496246.566 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0015.lzma.bak
2019-08-22T17:50:46.566Z,1566496246.566 [DataOverHttps](INFO): SBD MOMSN=11668961
2019-08-22T17:50:59.080Z,1566496259.080 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Courier0014.lzma
2019-08-22T17:51:00.723Z,1566496260.723 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0014.lzma.bak
2019-08-22T17:51:00.723Z,1566496260.723 [DataOverHttps](INFO): SBD MOMSN=11668964
2019-08-22T17:51:12.804Z,1566496272.804 [DataOverHttps](INFO): Sending 24 bytes from file Logs/20190822T173441/Express0016.lzma
2019-08-22T17:51:13.610Z,1566496273.610 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0016.lzma.bak
2019-08-22T17:51:13.611Z,1566496273.611 [DataOverHttps](INFO): SBD MOMSN=11668966
2019-08-22T17:51:25.640Z,1566496285.640 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190822T173441/Express0020.lzma
2019-08-22T17:51:26.446Z,1566496286.446 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0020.lzma.bak
2019-08-22T17:51:26.446Z,1566496286.446 [DataOverHttps](INFO): SBD MOMSN=11668968
2019-08-22T17:51:27.972Z,1566496287.972 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T17:51:27.972Z,1566496287.972 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T17:51:27.972Z,1566496287.972 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T17:52:09.855Z,1566496329.855 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T175205
2019-08-22T17:52:14.985Z,1566496334.985 [DataOverHttps](INFO): Received command:configSet VerticalControl.buoyancyNeutral 325 cc persist;configSet VerticalControl.elevDeadband 0.1 degree persist;configSet VerticalControl.kiDepthBuoy 0.3 reciprocal_second persist;
2019-08-22T17:52:15.762Z,1566496335.762 [CommandLine](IMPORTANT): got command configSet VerticalControl.buoyancyNeutral 325.000000 cubic_centimeter persist
2019-08-22T17:52:15.764Z,1566496335.764 [CommandLine](IMPORTANT): got command configSet VerticalControl.elevDeadband 0.100000 degree persist
2019-08-22T17:52:15.767Z,1566496335.767 [CommandLine](IMPORTANT): got command configSet VerticalControl.kiDepthBuoy 0.300000 reciprocal_second persist
2019-08-22T17:53:26.306Z,1566496406.306 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:53:26.306Z,1566496406.306 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:53:26.306Z,1566496406.306 [DVL_micro](ERROR): Data Fault
2019-08-22T17:53:26.337Z,1566496406.337 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:53:26.781Z,1566496406.781 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:53:27.562Z,1566496407.562 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:53:27.562Z,1566496407.562 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:53:27.930Z,1566496407.930 [DVL_micro](INFO): Initializing
2019-08-22T17:53:48.015Z,1566496428.015 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T175343
2019-08-22T17:53:53.141Z,1566496433.141 [DataOverHttps](INFO): Received command:configSet VerticalControl.kiPitchMass 0.00075 reciprocal_second persist;configSet VerticalControl.massDeadband 0.25 millimeter persist;configSet VerticalControl.massDefault 11 millimeter persist;
2019-08-22T17:53:53.884Z,1566496433.884 [CommandLine](IMPORTANT): got command configSet VerticalControl.kiPitchMass 0.000750 reciprocal_second persist
2019-08-22T17:53:53.889Z,1566496433.889 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDeadband 0.250000 millimeter persist
2019-08-22T17:53:53.892Z,1566496433.892 [CommandLine](IMPORTANT): got command configSet VerticalControl.massDefault 11.000000 millimeter persist
2019-08-22T17:56:28.604Z,1566496588.604 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T17:56:28.604Z,1566496588.604 [Default:CheckIn:C.Wait] Stopped
2019-08-22T17:56:28.604Z,1566496588.604 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T17:56:28.605Z,1566496588.605 [Default:CheckIn:D] Running Loop=1
2019-08-22T17:56:28.997Z,1566496588.997 [Default:CheckIn:D] Stopped
2019-08-22T17:56:28.997Z,1566496588.997 [Default:CheckIn:E] Running Loop=1
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.244975 min 
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn:E] Stopped
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn] Stopped
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn](INFO): Running loop #4
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn] Running Loop=4
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T17:56:29.380Z,1566496589.380 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T17:56:30.977Z,1566496590.977 [NAL9602](DEBUG): Fix Requested
2019-08-22T17:56:31.374Z,1566496591.374 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175626.00,A,4149.69078,N,08324.70447,W,0.097,176.25,220819,,,A*71
2019-08-22T17:56:31.376Z,1566496591.376 [NAL9602](INFO): GPS fix at 20190822T175626: (41.828180, -83.411741)
2019-08-22T17:56:31.398Z,1566496591.398 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T17:56:31.399Z,1566496591.399 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T17:56:32.186Z,1566496592.186 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:56:32.186Z,1566496592.186 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:56:32.186Z,1566496592.186 [DVL_micro](ERROR): Data Fault
2019-08-22T17:56:32.228Z,1566496592.228 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:56:32.653Z,1566496592.653 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:56:33.440Z,1566496593.440 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:56:33.440Z,1566496593.440 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:56:33.798Z,1566496593.798 [DVL_micro](INFO): Initializing
2019-08-22T17:56:38.649Z,1566496598.649 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190822T173441/Courier0019.lzma
2019-08-22T17:56:39.455Z,1566496599.455 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0019.lzma.bak
2019-08-22T17:56:39.455Z,1566496599.455 [DataOverHttps](IMPORTANT): SBD MOMSN=11669056, MTMSN=20190822T175634
2019-08-22T17:56:45.237Z,1566496605.237 [DataOverHttps](INFO): Received command:configSet Express none CTD_Seabird.bin_median_sea_water_salinity persist;configSet Express linearApproximation CTD_Seabird.sea_water_electrical_conductivity 0.001000 siemens_per_meter persist;
2019-08-22T17:56:49.789Z,1566496609.789 [CommandLine](IMPORTANT): got command configSet Express none CTD_Seabird.bin_median_sea_water_salinity persist
2019-08-22T17:56:49.792Z,1566496609.792 [CommandLine](IMPORTANT): got command configSet Express linearApproximation CTD_Seabird.sea_water_electrical_conductivity 0.001000 siemens_per_meter persist
2019-08-22T17:56:57.392Z,1566496617.392 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Courier0022.lzma
2019-08-22T17:56:58.198Z,1566496618.198 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0022.lzma.bak
2019-08-22T17:56:58.199Z,1566496618.199 [DataOverHttps](INFO): SBD MOMSN=11669060
2019-08-22T17:57:08.153Z,1566496628.153 [NAL9602](INFO): SBD MO Status=2, MOMSN=32528, MT Status=2, MTMSN=0
2019-08-22T17:57:08.153Z,1566496628.153 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-08-22T17:57:09.788Z,1566496629.788 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Courier0024.lzma
2019-08-22T17:57:10.594Z,1566496630.594 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0024.lzma.bak
2019-08-22T17:57:10.594Z,1566496630.594 [DataOverHttps](INFO): SBD MOMSN=11669064
2019-08-22T17:57:19.868Z,1566496639.868 [NAL9602](INFO): SBD MO Status=1, MOMSN=32528, MT Status=0, MTMSN=0
2019-08-22T17:57:19.868Z,1566496639.868 [NAL9602](INFO): No messages in MT queue
2019-08-22T17:57:23.013Z,1566496643.013 [DataOverHttps](INFO): Sending 465 bytes from file Logs/20190822T173441/Express0021.lzma
2019-08-22T17:57:23.819Z,1566496643.819 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0021.lzma.bak
2019-08-22T17:57:23.819Z,1566496643.819 [DataOverHttps](IMPORTANT): SBD MOMSN=11669067, MTMSN=20190822T175718
2019-08-22T17:57:29.917Z,1566496649.917 [DataOverHttps](INFO): Received command:configSet Express linearApproximation mass_concentration_of_oxygen_in_sea_water 750.000000 microgram_per_liter persist;
2019-08-22T17:57:31.344Z,1566496651.344 [CommandLine](IMPORTANT): got command configSet Express linearApproximation mass_concentration_of_oxygen_in_sea_water 750.000000 microgram_per_liter persist
2019-08-22T17:57:36.888Z,1566496656.888 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190822T173441/Express0022.lzma
2019-08-22T17:57:37.694Z,1566496657.694 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0022.lzma.bak
2019-08-22T17:57:37.695Z,1566496657.695 [DataOverHttps](INFO): SBD MOMSN=11669087
2019-08-22T17:57:50.560Z,1566496670.560 [NAL9602](INFO): Not Powering down - fast GPS
2019-08-22T17:57:50.710Z,1566496670.710 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Courier0028.lzma
2019-08-22T17:57:51.518Z,1566496671.518 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0028.lzma.bak
2019-08-22T17:57:51.519Z,1566496671.519 [DataOverHttps](INFO): SBD MOMSN=11669095
2019-08-22T17:58:03.564Z,1566496683.564 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Express0023.lzma
2019-08-22T17:58:04.370Z,1566496684.370 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0023.lzma.bak
2019-08-22T17:58:04.371Z,1566496684.371 [DataOverHttps](INFO): SBD MOMSN=11669097
2019-08-22T17:58:17.956Z,1566496697.956 [DataOverHttps](INFO): Sending 82 bytes from file Logs/20190822T173441/Express0024.lzma
2019-08-22T17:58:18.762Z,1566496698.762 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0024.lzma.bak
2019-08-22T17:58:18.763Z,1566496698.763 [DataOverHttps](INFO): SBD MOMSN=11669113
2019-08-22T17:58:25.666Z,1566496705.666 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T175820
2019-08-22T17:58:34.985Z,1566496714.985 [DataOverHttps](INFO): Sending 260 bytes from file Logs/20190822T173441/Express0026.lzma
2019-08-22T17:58:34.988Z,1566496714.988 [DataOverHttps](INFO): Received command:configSet list
2019-08-22T17:58:35.050Z,1566496715.050 [CommandLine](IMPORTANT): got command configSet list
2019-08-22T17:58:35.050Z,1566496715.050 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-08-22T17:58:35.051Z,1566496715.051 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2019-08-22T17:58:35.051Z,1566496715.051 [CommandLine](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter;

2019-08-22T17:58:35.051Z,1566496715.051 [CommandLine](IMPORTANT): CBIT.stopDepth=10 meter;

2019-08-22T17:58:35.051Z,1566496715.051 [CommandLine](IMPORTANT): CTD_Seabird.minSalinityBound=0.01 practical_salinity_unit;

2019-08-22T17:58:35.051Z,1566496715.051 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): Express linearApproximation CTD_Seabird.sea_water_electrical_conductivity 0.001000 siemens_per_meter;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_oxygen_in_sea_water 750.000000 microgram_per_liter;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=325 cubic_centimeter;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.elevDeadband=0.1 degree;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.kiDepthBuoy=0.3 reciprocal_second;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.kiPitchMass=0.00075 reciprocal_second;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.massDeadband=0.25 millimeter;

2019-08-22T17:58:35.052Z,1566496715.052 [CommandLine](IMPORTANT): VerticalControl.massDefault=11 millimeter;

2019-08-22T17:58:35.925Z,1566496715.925 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0026.lzma.bak
2019-08-22T17:58:35.926Z,1566496715.926 [DataOverHttps](INFO): SBD MOMSN=11669116
2019-08-22T17:58:47.628Z,1566496727.628 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190822T173441/Courier0031.lzma
2019-08-22T17:58:48.447Z,1566496728.447 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0031.lzma.bak
2019-08-22T17:58:48.448Z,1566496728.448 [DataOverHttps](INFO): SBD MOMSN=11669129
2019-08-22T17:59:02.060Z,1566496742.060 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190822T173441/Express0029.lzma
2019-08-22T17:59:02.866Z,1566496742.866 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0029.lzma.bak
2019-08-22T17:59:02.867Z,1566496742.867 [DataOverHttps](INFO): SBD MOMSN=11669131
2019-08-22T17:59:15.081Z,1566496755.081 [DataOverHttps](INFO): Sending 590 bytes from file Logs/20190822T173441/Express0032.lzma
2019-08-22T17:59:15.886Z,1566496755.886 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0032.lzma.bak
2019-08-22T17:59:15.887Z,1566496755.887 [DataOverHttps](INFO): SBD MOMSN=11669135
2019-08-22T17:59:17.491Z,1566496757.491 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T17:59:17.491Z,1566496757.491 [Default:CheckIn:C.Wait] Running Loop=1
2019-08-22T17:59:17.491Z,1566496757.491 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-08-22T17:59:38.046Z,1566496778.046 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T17:59:38.046Z,1566496778.046 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T17:59:38.046Z,1566496778.046 [DVL_micro](ERROR): Data Fault
2019-08-22T17:59:38.077Z,1566496778.077 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T17:59:38.513Z,1566496778.513 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T17:59:39.288Z,1566496779.288 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T17:59:39.288Z,1566496779.288 [DVL_micro] No Fault, FailCount= 1
2019-08-22T17:59:39.675Z,1566496779.675 [DVL_micro](INFO): Initializing
2019-08-22T18:02:43.912Z,1566496963.912 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-08-22T18:02:43.912Z,1566496963.912 [DVL_micro] Data Fault, FailCount= 1
2019-08-22T18:02:43.912Z,1566496963.912 [DVL_micro](ERROR): Data Fault
2019-08-22T18:02:43.945Z,1566496963.945 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-08-22T18:02:44.389Z,1566496964.389 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T18:02:45.330Z,1566496965.330 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-08-22T18:02:45.330Z,1566496965.330 [DVL_micro] No Fault, FailCount= 1
2019-08-22T18:02:45.544Z,1566496965.544 [DVL_micro](INFO): Initializing
2019-08-22T18:04:18.075Z,1566497058.075 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-08-22T18:04:18.076Z,1566497058.076 [Default:CheckIn:C.Wait] Stopped
2019-08-22T18:04:18.076Z,1566497058.076 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-08-22T18:04:18.076Z,1566497058.076 [Default:CheckIn:D] Running Loop=1
2019-08-22T18:04:18.474Z,1566497058.474 [Default:CheckIn:D] Stopped
2019-08-22T18:04:18.474Z,1566497058.474 [Default:CheckIn:E] Running Loop=1
2019-08-22T18:04:18.888Z,1566497058.888 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.069594 min 
2019-08-22T18:04:18.888Z,1566497058.888 [Default:CheckIn:E] Stopped
2019-08-22T18:04:18.888Z,1566497058.888 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-08-22T18:04:18.888Z,1566497058.888 [Default:CheckIn] Stopped
2019-08-22T18:04:18.888Z,1566497058.888 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T18:04:18.889Z,1566497058.889 [Default:CheckIn](INFO): Running loop #5
2019-08-22T18:04:18.889Z,1566497058.889 [Default:CheckIn] Running Loop=5
2019-08-22T18:04:18.889Z,1566497058.889 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-08-22T18:04:18.889Z,1566497058.889 [Default:CheckIn:Read_GPS] Running Loop=1
2019-08-22T18:04:20.481Z,1566497060.481 [NAL9602](DEBUG): Fix Requested
2019-08-22T18:04:20.880Z,1566497060.880 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180415.00,A,4149.68767,N,08324.70562,W,0.039,191.23,220819,,,A*7C
2019-08-22T18:04:20.882Z,1566497060.882 [NAL9602](INFO): GPS fix at 20190822T180415: (41.828128, -83.411760)
2019-08-22T18:04:20.904Z,1566497060.904 [Default:CheckIn:Read_GPS] Stopped
2019-08-22T18:04:20.904Z,1566497060.904 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-08-22T18:04:26.868Z,1566497066.868 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190822T173441/Courier0034.lzma
2019-08-22T18:04:27.674Z,1566497067.674 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Courier0034.lzma.bak
2019-08-22T18:04:27.675Z,1566497067.675 [DataOverHttps](INFO): SBD MOMSN=11669202
2019-08-22T18:04:32.293Z,1566497072.293 [NAL9602](INFO): SBD MO Status=1, MOMSN=32529, MT Status=0, MTMSN=0
2019-08-22T18:04:32.294Z,1566497072.294 [NAL9602](INFO): No messages in MT queue
2019-08-22T18:04:37.286Z,1566497077.286 [DataOverHttps](IMPORTANT): SBD MTMSN=20190822T180431
2019-08-22T18:04:42.449Z,1566497082.449 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20190822T173441/Express0035.lzma
2019-08-22T18:04:42.451Z,1566497082.451 [DataOverHttps](INFO): Received command:restart app
2019-08-22T18:04:42.505Z,1566497082.505 [CommandLine](IMPORTANT): got command restart application
2019-08-22T18:04:43.254Z,1566497083.254 [DataOverHttps](INFO): Moved sent file to Logs/20190822T173441/Express0035.lzma.bak
2019-08-22T18:04:43.255Z,1566497083.255 [DataOverHttps](INFO): SBD MOMSN=11669207
2019-08-22T18:04:43.509Z,1566497083.509 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-08-22T18:04:43.509Z,1566497083.509 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:43.510Z,1566497083.510 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:43.625Z,1566497083.625 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-08-22T18:04:43.625Z,1566497083.625 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:43.626Z,1566497083.626 [CommandLine](INFO): Join timeout helper Thread ID is 1265
2019-08-22T18:04:43.626Z,1566497083.626 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-08-22T18:04:43.626Z,1566497083.626 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:43.627Z,1566497083.627 [NavChartDb](INFO): Join timeout helper Thread ID is 1266
2019-08-22T18:04:43.753Z,1566497083.753 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:43.753Z,1566497083.753 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:43.769Z,1566497083.769 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-08-22T18:04:43.769Z,1566497083.769 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:43.769Z,1566497083.769 [Radio_Surface](INFO): Join timeout helper Thread ID is 1267
2019-08-22T18:04:44.109Z,1566497084.109 [Radio_Surface](INFO): Powering down
2019-08-22T18:04:44.110Z,1566497084.110 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:44.110Z,1566497084.110 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.121Z,1566497084.121 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-08-22T18:04:44.121Z,1566497084.121 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.121Z,1566497084.121 [DataOverHttps](INFO): Join timeout helper Thread ID is 1268
2019-08-22T18:04:44.152Z,1566497084.152 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2019-08-22T18:04:44.152Z,1566497084.152 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:44.152Z,1566497084.152 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.169Z,1566497084.169 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-08-22T18:04:44.169Z,1566497084.169 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.169Z,1566497084.169 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1269
2019-08-22T18:04:44.425Z,1566497084.425 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:44.426Z,1566497084.426 [WetLabsBB2FL](INFO): Powering down
2019-08-22T18:04:44.426Z,1566497084.426 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.434Z,1566497084.434 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-08-22T18:04:44.434Z,1566497084.434 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:44.434Z,1566497084.434 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1270
2019-08-22T18:04:45.069Z,1566497085.069 [CTD_Seabird](INFO): Powering down
2019-08-22T18:04:45.081Z,1566497085.081 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:45.081Z,1566497085.081 [CTD_Seabird](INFO): Powering down
2019-08-22T18:04:45.093Z,1566497085.093 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.106Z,1566497085.106 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-08-22T18:04:45.106Z,1566497085.106 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.106Z,1566497085.106 [logger](INFO): Join timeout helper Thread ID is 1271
2019-08-22T18:04:45.158Z,1566497085.158 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:45.158Z,1566497085.158 [logger ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.170Z,1566497085.170 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-08-22T18:04:45.170Z,1566497085.170 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.170Z,1566497085.170 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-08-22T18:04:45.170Z,1566497085.170 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.170Z,1566497085.170 [controlThread](INFO): Join timeout helper Thread ID is 1272
2019-08-22T18:04:45.189Z,1566497085.189 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-08-22T18:04:45.190Z,1566497085.190 [controlThread](DEBUG): Uninitializing ControlThread
2019-08-22T18:04:45.190Z,1566497085.190 [Aanderaa_O2](INFO): Powering down
2019-08-22T18:04:45.215Z,1566497085.215 [AHRS_M2](INFO): Powering down
2019-08-22T18:04:45.357Z,1566497085.357 [DVL_micro](INFO): uninitialize:Powering down
2019-08-22T18:04:45.358Z,1566497085.358 [NAL9602](INFO): Powering down
2019-08-22T18:04:45.359Z,1566497085.359 [DAT](INFO): Powering down
2019-08-22T18:04:45.478Z,1566497085.478 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-08-22T18:04:45.479Z,1566497085.479 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-08-22T18:04:45.479Z,1566497085.479 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-08-22T18:04:45.479Z,1566497085.479 [MissionManager](INFO): Uninitializing Mission Default
2019-08-22T18:04:45.480Z,1566497085.480 [Default] Stopped
2019-08-22T18:04:45.480Z,1566497085.480 [Default](DEBUG): Aggregate::uninitialize Default
2019-08-22T18:04:45.480Z,1566497085.480 [Default:B.GoToSurface] Stopped
2019-08-22T18:04:45.480Z,1566497085.480 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-08-22T18:04:45.480Z,1566497085.480 [Default:CheckIn] Stopped
2019-08-22T18:04:45.480Z,1566497085.480 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-08-22T18:04:45.480Z,1566497085.480 [Default:CheckIn:Read_Iridium] Stopped
2019-08-22T18:04:45.482Z,1566497085.482 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-08-22T18:04:45.483Z,1566497085.483 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-08-22T18:04:45.483Z,1566497085.483 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-08-22T18:04:45.483Z,1566497085.483 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-08-22T18:04:45.483Z,1566497085.483 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-08-22T18:04:45.483Z,1566497085.483 [BuoyancyServo](INFO): Powering down
2019-08-22T18:04:45.497Z,1566497085.497 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-08-22T18:04:45.497Z,1566497085.497 [ElevatorServo](INFO): Powering down
2019-08-22T18:04:45.498Z,1566497085.498 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-08-22T18:04:45.498Z,1566497085.498 [MassServo](INFO): Powering down
2019-08-22T18:04:45.499Z,1566497085.499 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-08-22T18:04:45.499Z,1566497085.499 [RudderServo](INFO): Powering down
2019-08-22T18:04:45.500Z,1566497085.500 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-08-22T18:04:45.500Z,1566497085.500 [ThrusterServo](INFO): Powering down
2019-08-22T18:04:45.500Z,1566497085.500 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-08-22T18:04:45.501Z,1566497085.501 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-08-22T18:04:45.501Z,1566497085.501 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-08-22T18:04:45.501Z,1566497085.501 [CBIT](DEBUG): Powering off loads.
2019-08-22T18:04:45.513Z,1566497085.513 [CBIT](DEBUG): Disabling WDT.
2019-08-22T18:04:45.525Z,1566497085.525 [CBIT](DEBUG): Opening all GF detection circuits.
2019-08-22T18:04:45.526Z,1566497085.526 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.560Z,1566497085.560 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.564Z,1566497085.564 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.627Z,1566497085.627 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.635Z,1566497085.635 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.685Z,1566497085.685 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-08-22T18:04:45.748Z,1566497085.748 [logger ThreadHandler](INFO): Thread cancelled.