2019-12-06T19:21:39.862Z,1575660099.862 [Supervisor](DEBUG): Initializing supervisor.
2019-12-06T19:21:39.865Z,1575660099.865 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-12-06T19:21:39.866Z,1575660099.866 [SyncHandler](INFO): Protected caller Thread ID is 9856
2019-12-06T19:21:39.866Z,1575660099.866 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-12-06T19:21:39.867Z,1575660099.867 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-12-06T19:21:39.868Z,1575660099.868 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 9857
2019-12-06T19:21:39.871Z,1575660099.871 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-12-06T19:21:39.883Z,1575660099.883 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-12-06T19:21:39.884Z,1575660099.884 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-12-06T19:21:39.884Z,1575660099.884 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 9858
2019-12-06T19:21:39.885Z,1575660099.885 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-12-06T19:21:39.886Z,1575660099.886 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-12-06T19:21:39.886Z,1575660099.886 [logger ThreadHandler](INFO): Protected caller Thread ID is 9859
2019-12-06T19:21:39.888Z,1575660099.888 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-12-06T19:21:39.889Z,1575660099.889 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-12-06T19:21:39.890Z,1575660099.890 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-12-06T19:21:39.986Z,1575660099.986 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-12-06T19:21:39.987Z,1575660099.987 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-12-06T19:21:40.569Z,1575660100.569 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-12-06T19:21:40.570Z,1575660100.570 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-12-06T19:21:40.670Z,1575660100.670 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-12-06T19:21:40.671Z,1575660100.671 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-12-06T19:21:40.772Z,1575660100.772 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-12-06T19:21:40.773Z,1575660100.773 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-12-06T19:21:40.854Z,1575660100.854 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-12-06T19:21:40.991Z,1575660100.991 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-12-06T19:21:40.992Z,1575660100.992 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-12-06T19:21:41.346Z,1575660101.346 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-12-06T19:21:41.347Z,1575660101.347 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-12-06T19:21:41.784Z,1575660101.784 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-12-06T19:21:41.785Z,1575660101.785 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-12-06T19:21:41.929Z,1575660101.929 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-12-06T19:21:41.930Z,1575660101.930 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-12-06T19:21:42.114Z,1575660102.114 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-12-06T19:21:42.114Z,1575660102.114 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-12-06T19:21:42.561Z,1575660102.561 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-12-06T19:21:42.562Z,1575660102.562 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-12-06T19:21:42.767Z,1575660102.767 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-12-06T19:21:42.768Z,1575660102.768 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-12-06T19:21:42.962Z,1575660102.962 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-12-06T19:21:42.963Z,1575660102.963 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-12-06T19:21:43.357Z,1575660103.357 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-12-06T19:21:43.357Z,1575660103.357 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-12-06T19:21:43.670Z,1575660103.670 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-12-06T19:21:43.672Z,1575660103.672 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-12-06T19:21:43.673Z,1575660103.673 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-12-06T19:21:43.757Z,1575660103.757 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-12-06T19:21:43.907Z,1575660103.907 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-12-06T19:21:44.014Z,1575660104.014 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-12-06T19:21:44.099Z,1575660104.099 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-12-06T19:21:44.193Z,1575660104.193 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-12-06T19:21:44.381Z,1575660104.381 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-12-06T19:21:44.688Z,1575660104.688 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-12-06T19:21:44.688Z,1575660104.688 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-12-06T19:21:44.832Z,1575660104.832 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-12-06T19:21:45.087Z,1575660105.087 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-12-06T19:21:45.335Z,1575660105.335 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-12-06T19:21:45.535Z,1575660105.535 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2019-12-06T19:21:45.535Z,1575660105.535 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-12-06T19:21:45.663Z,1575660105.663 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-12-06T19:21:45.714Z,1575660105.714 [VerticalControl](DEBUG): Construct VerticalControl.
2019-12-06T19:21:45.828Z,1575660105.828 [VerticalControl] Loaded
2019-12-06T19:21:45.829Z,1575660105.829 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-12-06T19:21:45.830Z,1575660105.830 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-12-06T19:21:45.913Z,1575660105.913 [HorizontalControl] Loaded
2019-12-06T19:21:45.913Z,1575660105.913 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-12-06T19:21:45.914Z,1575660105.914 [SpeedControl](DEBUG): Construct SpeedControl.
2019-12-06T19:21:45.919Z,1575660105.919 [SpeedControl] Loaded
2019-12-06T19:21:45.920Z,1575660105.920 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-12-06T19:21:45.920Z,1575660105.920 [LoopControl](DEBUG): Construct LoopControl.
2019-12-06T19:21:45.921Z,1575660105.921 [LoopControl] Loaded
2019-12-06T19:21:45.921Z,1575660105.921 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-12-06T19:21:45.922Z,1575660105.922 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-12-06T19:21:45.922Z,1575660105.922 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-12-06T19:21:45.964Z,1575660105.964 [DepthRateCalculator] Loaded
2019-12-06T19:21:45.964Z,1575660105.964 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-12-06T19:21:45.969Z,1575660105.969 [PitchRateCalculator] Loaded
2019-12-06T19:21:45.970Z,1575660105.970 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-12-06T19:21:45.985Z,1575660105.985 [SpeedCalculator] Loaded
2019-12-06T19:21:45.985Z,1575660105.985 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-12-06T19:21:46.007Z,1575660106.007 [TempGradientCalculator] Loaded
2019-12-06T19:21:46.007Z,1575660106.007 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-12-06T19:21:46.012Z,1575660106.012 [YawRateCalculator] Loaded
2019-12-06T19:21:46.013Z,1575660106.013 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-12-06T19:21:46.042Z,1575660106.042 [ElevatorOffsetCalculator] Loaded
2019-12-06T19:21:46.042Z,1575660106.042 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-12-06T19:21:46.043Z,1575660106.043 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-12-06T19:21:46.043Z,1575660106.043 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-12-06T19:21:46.077Z,1575660106.077 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-12-06T19:21:46.078Z,1575660106.078 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-12-06T19:21:46.166Z,1575660106.166 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-12-06T19:21:46.167Z,1575660106.167 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-12-06T19:21:46.482Z,1575660106.482 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-12-06T19:21:46.483Z,1575660106.483 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-12-06T19:21:46.583Z,1575660106.583 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-12-06T19:21:46.583Z,1575660106.583 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-12-06T19:21:46.879Z,1575660106.879 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-12-06T19:21:46.884Z,1575660106.884 [AHRS_M2](INFO): created writer for : platform_orientation
2019-12-06T19:21:46.886Z,1575660106.886 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-12-06T19:21:46.892Z,1575660106.892 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-12-06T19:21:46.892Z,1575660106.892 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-12-06T19:21:46.897Z,1575660106.897 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-12-06T19:21:46.898Z,1575660106.898 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-12-06T19:21:46.903Z,1575660106.903 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-12-06T19:21:46.976Z,1575660106.976 [AHRS_M2] Loaded
2019-12-06T19:21:46.976Z,1575660106.976 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-12-06T19:21:47.057Z,1575660107.057 [DataOverHttps] Loaded
2019-12-06T19:21:47.057Z,1575660107.057 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-12-06T19:21:47.058Z,1575660107.058 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408E34E0
2019-12-06T19:21:47.059Z,1575660107.059 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 9939
2019-12-06T19:21:47.072Z,1575660107.072 [Depth_Keller] Loaded
2019-12-06T19:21:47.072Z,1575660107.072 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-12-06T19:21:47.171Z,1575660107.171 [NAL9602] Loaded
2019-12-06T19:21:47.172Z,1575660107.172 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-12-06T19:21:47.210Z,1575660107.210 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now
2019-12-06T19:21:47.210Z,1575660107.210 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now
2019-12-06T19:21:47.211Z,1575660107.211 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now
2019-12-06T19:21:47.211Z,1575660107.211 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full
2019-12-06T19:21:47.212Z,1575660107.212 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now
2019-12-06T19:21:47.212Z,1575660107.212 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now
2019-12-06T19:21:47.213Z,1575660107.213 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now
2019-12-06T19:21:47.213Z,1575660107.213 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full
2019-12-06T19:21:47.213Z,1575660107.213 [Onboard] Loaded
2019-12-06T19:21:47.214Z,1575660107.214 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-12-06T19:21:47.217Z,1575660107.217 [Radio_Surface] Loaded
2019-12-06T19:21:47.217Z,1575660107.217 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-12-06T19:21:47.218Z,1575660107.218 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409134E0
2019-12-06T19:21:47.219Z,1575660107.219 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 9940
2019-12-06T19:21:47.353Z,1575660107.353 [DAT] Loaded
2019-12-06T19:21:47.354Z,1575660107.354 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-12-06T19:21:48.855Z,1575660108.855 [BPC1] Loaded
2019-12-06T19:21:48.855Z,1575660108.855 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-12-06T19:21:48.856Z,1575660108.856 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-12-06T19:21:48.856Z,1575660108.856 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-12-06T19:21:48.962Z,1575660108.962 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-12-06T19:21:48.963Z,1575660108.963 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-12-06T19:21:48.984Z,1575660108.984 [NavChart] Loaded
2019-12-06T19:21:48.984Z,1575660108.984 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-12-06T19:21:48.988Z,1575660108.988 [UniversalFixResidualReporter] Loaded
2019-12-06T19:21:48.988Z,1575660108.988 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-12-06T19:21:48.989Z,1575660108.989 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-12-06T19:21:48.989Z,1575660108.989 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-12-06T19:21:49.126Z,1575660109.126 [SBIT](DEBUG): Construct Startup Built In Test.
2019-12-06T19:21:49.137Z,1575660109.137 [SBIT] Loaded
2019-12-06T19:21:49.137Z,1575660109.137 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-12-06T19:21:49.138Z,1575660109.138 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-12-06T19:21:49.150Z,1575660109.150 [IBIT] Loaded
2019-12-06T19:21:49.151Z,1575660109.151 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-12-06T19:21:49.154Z,1575660109.154 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-12-06T19:21:49.291Z,1575660109.291 [CBIT] Loaded
2019-12-06T19:21:49.291Z,1575660109.291 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-12-06T19:21:49.291Z,1575660109.291 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-12-06T19:21:49.292Z,1575660109.292 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-12-06T19:21:49.397Z,1575660109.397 [BuoyancyServo] Loaded
2019-12-06T19:21:49.397Z,1575660109.397 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-12-06T19:21:49.408Z,1575660109.408 [ElevatorServo] Loaded
2019-12-06T19:21:49.408Z,1575660109.408 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-12-06T19:21:49.419Z,1575660109.419 [MassServo] Loaded
2019-12-06T19:21:49.419Z,1575660109.419 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-12-06T19:21:49.430Z,1575660109.430 [RudderServo] Loaded
2019-12-06T19:21:49.431Z,1575660109.431 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-12-06T19:21:49.441Z,1575660109.441 [ThrusterServo] Loaded
2019-12-06T19:21:49.442Z,1575660109.442 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-12-06T19:21:49.442Z,1575660109.442 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-12-06T19:21:49.443Z,1575660109.443 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-12-06T19:21:49.456Z,1575660109.456 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-12-06T19:21:49.457Z,1575660109.457 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-12-06T19:21:49.679Z,1575660109.679 [BackSeatDriver] Loaded
2019-12-06T19:21:49.679Z,1575660109.679 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread.
2019-12-06T19:21:49.680Z,1575660109.680 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40AA24E0
2019-12-06T19:21:49.681Z,1575660109.681 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 9941
2019-12-06T19:21:49.690Z,1575660109.690 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-12-06T19:21:49.695Z,1575660109.695 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-12-06T19:21:49.696Z,1575660109.696 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-12-06T19:21:49.701Z,1575660109.701 [CTD_Seabird](INFO): created writer for : depth
2019-12-06T19:21:49.701Z,1575660109.701 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-12-06T19:21:49.706Z,1575660109.706 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-12-06T19:21:49.707Z,1575660109.707 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-12-06T19:21:49.712Z,1575660109.712 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-12-06T19:21:49.713Z,1575660109.713 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-12-06T19:21:49.718Z,1575660109.718 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-12-06T19:21:49.719Z,1575660109.719 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-12-06T19:21:49.724Z,1575660109.724 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-12-06T19:21:49.725Z,1575660109.725 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-12-06T19:21:49.730Z,1575660109.730 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-12-06T19:21:49.757Z,1575660109.757 [CTD_Seabird] Loaded
2019-12-06T19:21:49.757Z,1575660109.757 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-12-06T19:21:49.758Z,1575660109.758 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40AD24E0
2019-12-06T19:21:49.759Z,1575660109.759 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 9942
2019-12-06T19:21:49.790Z,1575660109.790 [ESPComponent] Loaded
2019-12-06T19:21:49.791Z,1575660109.791 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-12-06T19:21:49.797Z,1575660109.797 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470
2019-12-06T19:21:49.797Z,1575660109.797 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470
2019-12-06T19:21:49.801Z,1575660109.801 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650
2019-12-06T19:21:49.801Z,1575660109.801 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650
2019-12-06T19:21:49.806Z,1575660109.806 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl
2019-12-06T19:21:49.806Z,1575660109.806 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl
2019-12-06T19:21:49.810Z,1575660109.810 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm
2019-12-06T19:21:49.811Z,1575660109.811 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm
2019-12-06T19:21:49.815Z,1575660109.815 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm
2019-12-06T19:21:49.815Z,1575660109.815 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm
2019-12-06T19:21:49.820Z,1575660109.820 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm
2019-12-06T19:21:49.820Z,1575660109.820 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm
2019-12-06T19:21:49.824Z,1575660109.824 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm
2019-12-06T19:21:49.824Z,1575660109.824 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm
2019-12-06T19:21:49.829Z,1575660109.829 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.834Z,1575660109.834 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.834Z,1575660109.834 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.834Z,1575660109.834 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.839Z,1575660109.839 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.839Z,1575660109.839 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.843Z,1575660109.843 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.843Z,1575660109.843 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-12-06T19:21:49.848Z,1575660109.848 [WetLabsBB2FL] Loaded
2019-12-06T19:21:49.848Z,1575660109.848 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-12-06T19:21:49.849Z,1575660109.849 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B024E0
2019-12-06T19:21:49.849Z,1575660109.849 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 9943
2019-12-06T19:21:49.850Z,1575660109.850 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-12-06T19:21:49.860Z,1575660109.860 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-12-06T19:21:49.861Z,1575660109.861 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-12-06T19:21:49.871Z,1575660109.871 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-12-06T19:21:49.875Z,1575660109.875 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B324E0
2019-12-06T19:21:49.876Z,1575660109.876 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 9944
2019-12-06T19:21:49.888Z,1575660109.888 [Supervisor](INFO): Main Thread ID is 9855
2019-12-06T19:21:49.888Z,1575660109.888 [Supervisor](DEBUG): Running supervisor.
2019-12-06T19:21:49.889Z,1575660109.889 [CommandLine ThreadHandler](INFO): Handler Thread ID is 9945
2019-12-06T19:21:49.889Z,1575660109.889 [controlThread ThreadHandler](INFO): Handler Thread ID is 9946
2019-12-06T19:21:49.890Z,1575660109.890 [controlThread](DEBUG): Initializing ControlThread
2019-12-06T19:21:49.891Z,1575660109.891 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-12-06T19:21:49.892Z,1575660109.892 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-12-06T19:21:49.893Z,1575660109.893 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-12-06T19:21:49.893Z,1575660109.893 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-12-06T19:21:49.894Z,1575660109.894 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-12-06T19:21:49.894Z,1575660109.894 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-12-06T19:21:49.894Z,1575660109.894 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-12-06T19:21:49.895Z,1575660109.895 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-12-06T19:21:49.895Z,1575660109.895 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-12-06T19:21:49.895Z,1575660109.895 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-12-06T19:21:49.898Z,1575660109.898 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-12-06T19:21:49.899Z,1575660109.899 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-12-06T19:21:49.899Z,1575660109.899 [SBIT](INFO): Initialize SBIT Component.
2019-12-06T19:21:49.900Z,1575660109.900 [SBIT](IMPORTANT): git: 2019-12-03-13-g91b37b6
2019-12-06T19:21:49.900Z,1575660109.900 [SBIT](INFO): git hash: 91b37b6d5b16b0b47a85c8648b8a97e3e3149dc5
2019-12-06T19:21:49.900Z,1575660109.900 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-12-06T19:21:49.900Z,1575660109.900 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-12-06T19:21:49.902Z,1575660109.902 [SBIT](INFO): Beginning SBIT in 39.000000 seconds.
2019-12-06T19:21:49.902Z,1575660109.902 [IBIT](INFO): Initialize IBIT Component.
2019-12-06T19:21:49.903Z,1575660109.903 [CBIT](DEBUG): Initialize CBIT Component.
2019-12-06T19:21:49.906Z,1575660109.906 [logger ThreadHandler](INFO): Handler Thread ID is 9947
2019-12-06T19:21:49.917Z,1575660109.917 [CBIT](DEBUG): Initialized mux pins.
2019-12-06T19:21:49.917Z,1575660109.917 [CBIT](DEBUG): Initializing the watchdog timer.
2019-12-06T19:21:49.925Z,1575660109.925 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 9948
2019-12-06T19:21:49.926Z,1575660109.926 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-12-06T19:21:49.937Z,1575660109.937 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 9949
2019-12-06T19:21:49.941Z,1575660109.941 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-12-06T19:21:49.941Z,1575660109.941 [CBIT](DEBUG): Initializing heartbeat.
2019-12-06T19:21:49.949Z,1575660109.949 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 9950
2019-12-06T19:21:49.970Z,1575660109.970 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 9951
2019-12-06T19:21:49.970Z,1575660109.970 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-12-06T19:21:49.973Z,1575660109.973 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-12-06T19:21:49.975Z,1575660109.975 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 9953
2019-12-06T19:21:49.976Z,1575660109.976 [WetLabsBB2FL](INFO): Powering down
2019-12-06T19:21:50.005Z,1575660110.005 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 9954
2019-12-06T19:21:50.009Z,1575660110.009 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-12-06T19:21:50.009Z,1575660110.009 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-12-06T19:21:50.009Z,1575660110.009 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-12-06T19:21:50.009Z,1575660110.009 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-12-06T19:21:50.010Z,1575660110.010 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-12-06T19:21:50.011Z,1575660110.011 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-12-06T19:21:50.011Z,1575660110.011 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-12-06T19:21:50.011Z,1575660110.011 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-12-06T19:21:50.011Z,1575660110.011 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-12-06T19:21:50.011Z,1575660110.011 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-12-06T19:21:50.012Z,1575660110.012 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-12-06T19:21:50.013Z,1575660110.013 [CBIT](DEBUG): Deactivating GF circuits.
2019-12-06T19:21:50.013Z,1575660110.013 [CBIT](DEBUG): Deactivating emergency mode.
2019-12-06T19:21:50.049Z,1575660110.049 [CBIT](DEBUG): Backplane powered.
2019-12-06T19:21:50.051Z,1575660110.051 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-12-06T19:21:50.062Z,1575660110.062 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-12-06T19:21:50.073Z,1575660110.073 [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-12-06T19:21:50.074Z,1575660110.074 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-12-06T19:21:50.142Z,1575660110.142 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-12-06T19:21:50.143Z,1575660110.143 [Default:A.Wait](DEBUG): Construct Wait.
2019-12-06T19:21:50.165Z,1575660110.165 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-12-06T19:21:50.210Z,1575660110.210 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-12-06T19:21:50.212Z,1575660110.212 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-12-06T19:21:50.234Z,1575660110.234 [Default:E.Execute](DEBUG): Construct Execute.
2019-12-06T19:21:50.237Z,1575660110.237 [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-12-06T19:21:50.256Z,1575660110.256 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,NAL9602,Onboard,DAT,BPC1,ESPComponent,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-12-06T19:21:50.261Z,1575660110.261 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-12-06T19:21:50.306Z,1575660110.306 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2019-12-06T19:21:50.327Z,1575660110.327 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-12-06T19:21:50.327Z,1575660110.327 [DAT](INFO): Powering up
2019-12-06T19:21:50.328Z,1575660110.328 [DAT](DEBUG): Initializing DAT.
2019-12-06T19:21:50.341Z,1575660110.341 [Radio_Surface](INFO): Powering up
2019-12-06T19:21:50.390Z,1575660110.390 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-12-06T19:21:50.405Z,1575660110.405 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-12-06T19:21:50.431Z,1575660110.431 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:50.441Z,1575660110.441 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-12-06T19:21:50.443Z,1575660110.443 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:50.453Z,1575660110.453 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-12-06T19:21:50.454Z,1575660110.454 [MassServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:50.465Z,1575660110.465 [MassServo](DEBUG): Initializing MassServo.
2019-12-06T19:21:50.466Z,1575660110.466 [RudderServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:50.478Z,1575660110.478 [RudderServo](DEBUG): Initializing RudderServo.
2019-12-06T19:21:50.479Z,1575660110.479 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:50.493Z,1575660110.493 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-12-06T19:21:50.717Z,1575660110.717 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-12-06T19:21:51.429Z,1575660111.429 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-12-06T19:21:51.429Z,1575660111.429 [RudderServo](FAULT): Rudder failed to initialize
2019-12-06T19:21:51.429Z,1575660111.429 [RudderServo] Communications Fault, FailCount= 1
2019-12-06T19:21:51.429Z,1575660111.429 [RudderServo](ERROR): Communications Fault
2019-12-06T19:21:51.540Z,1575660111.540 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-12-06T19:21:51.698Z,1575660111.698 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-12-06T19:21:51.698Z,1575660111.698 [RudderServo](INFO): Powering down
2019-12-06T19:21:52.386Z,1575660112.386 [RudderServo](DEBUG): Initializing EZServoServo.
2019-12-06T19:21:52.506Z,1575660112.506 [RudderServo](DEBUG): Initializing RudderServo.
2019-12-06T19:21:52.510Z,1575660112.510 [CBIT](INFO): Clearing failed state for component RudderServo
2019-12-06T19:21:52.510Z,1575660112.510 [RudderServo] No Fault, FailCount= 1
2019-12-06T19:22:00.887Z,1575660120.887 [DAT](DEBUG): 
2019-12-06T19:22:00.888Z,1575660120.888 [DAT](DEBUG): Teledyne Benthos DAT-900 Series
2019-12-06T19:22:02.074Z,1575660122.074 [DAT](DEBUG): MF Frequency Band
2019-12-06T19:22:02.075Z,1575660122.075 [DAT](DEBUG): Directional Acoustic Transponder version 8.12.21
2019-12-06T19:22:02.076Z,1575660122.076 [DAT](DEBUG): Dec  6 2019 19:22:08 
2019-12-06T19:22:02.889Z,1575660122.889 [DAT](DEBUG): Features enabled [Bearing]
2019-12-06T19:22:02.891Z,1575660122.891 [DAT](DEBUG): CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2019-12-06T19:22:02.891Z,1575660122.891 [DAT](INFO): commRate: 800
2019-12-06T19:22:03.285Z,1575660123.285 [DAT](INFO): entering command mode
2019-12-06T19:22:03.689Z,1575660123.689 [DAT](DEBUG): checking for command mode acknowledgment
2019-12-06T19:22:04.102Z,1575660124.102 [DAT](DEBUG): checking for command mode acknowledgment
2019-12-06T19:22:04.102Z,1575660124.102 [DAT](INFO): command mode acknowledged
2019-12-06T19:22:04.103Z,1575660124.103 [DAT](INFO): setting verbose to 3
2019-12-06T19:22:04.497Z,1575660124.497 [DAT](DEBUG): checking for verbose setting acknowledgment
2019-12-06T19:22:04.498Z,1575660124.498 [DAT](INFO): set verbose to 3
2019-12-06T19:22:04.901Z,1575660124.901 [DAT](INFO): setting transmit power to 8
2019-12-06T19:22:04.916Z,1575660124.916 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004630
2019-12-06T19:22:05.309Z,1575660125.309 [DAT](DEBUG): checking for transmit power setting acknowledgment
2019-12-06T19:22:05.709Z,1575660125.709 [DAT](DEBUG): checking for transmit power setting acknowledgment
2019-12-06T19:22:05.710Z,1575660125.710 [DAT](INFO): set transmit power to 8
2019-12-06T19:22:06.117Z,1575660126.117 [DAT](INFO): setting local address to 9
2019-12-06T19:22:06.524Z,1575660126.524 [DAT](DEBUG): checking for local address setting acknowledgment
2019-12-06T19:22:06.922Z,1575660126.922 [DAT](DEBUG): checking for local address setting acknowledgment
2019-12-06T19:22:06.923Z,1575660126.923 [DAT](INFO): set local address to 9
2019-12-06T19:22:17.412Z,1575660137.412 [NAL9602](INFO): Powering up NAL9602
2019-12-06T19:22:28.334Z,1575660148.334 [NAL9602](INFO): NAL9602 initialized
2019-12-06T19:22:29.603Z,1575660149.603 [SBIT](IMPORTANT): Beginning Startup BIT
2019-12-06T19:22:29.617Z,1575660149.617 [CBIT](IMPORTANT): Beginning ground fault scan
2019-12-06T19:22:40.765Z,1575660160.765 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011243
CHAN A1 (24V): -0.001088
CHAN A2 (12V): -0.006824
CHAN A3 (5V): -0.002534
CHAN B0 (3.3V): 0.000417
CHAN B1 (3.15aV): -0.000189
CHAN B2 (3.15bV): -0.000090
CHAN B3 (GND): 0.002019
OPEN: 0.005212
Full Scale Calc: 4.765 mA, -1.589 mA
2019-12-06T19:22:45.439Z,1575660165.439 [CommandLine](IMPORTANT): got command show variable address
2019-12-06T19:22:45.442Z,1575660165.442 [CommandLine](IMPORTANT): acoustic_contact_address (unknown)
2019-12-06T19:22:45.463Z,1575660165.463 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count)
2019-12-06T19:22:45.463Z,1575660165.463 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.sbdAddress (enum)
2019-12-06T19:22:45.464Z,1575660165.464 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.transponderAddress (enum)
2019-12-06T19:22:45.509Z,1575660165.509 [CommandLine](IMPORTANT): DAT.localAddress (count)
2019-12-06T19:22:45.509Z,1575660165.509 [CommandLine](IMPORTANT): DAT.sbdAddress (enum)
2019-12-06T19:22:45.510Z,1575660165.510 [CommandLine](IMPORTANT): DAT.transponderAddress (enum)
2019-12-06T19:22:45.517Z,1575660165.517 [CommandLine](IMPORTANT): Micromodem.localAddress (enum)
2019-12-06T19:22:45.518Z,1575660165.518 [CommandLine](IMPORTANT): Micromodem.destinationAddress (enum)
2019-12-06T19:22:45.854Z,1575660165.854 [CommandLine](IMPORTANT): DAT.remoteAddress (enum)
2019-12-06T19:22:45.854Z,1575660165.854 [CommandLine](IMPORTANT): DAT.localAddressReading (enum)
2019-12-06T19:22:50.023Z,1575660170.023 [CommandLine](IMPORTANT): got command get DAT.localAddress
2019-12-06T19:22:50.023Z,1575660170.023 [CommandLine](IMPORTANT): DAT.localAddress 9 count
2019-12-06T19:23:02.279Z,1575660182.279 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-12-06T19:23:23.338Z,1575660203.338 [SBIT](IMPORTANT): SBIT PASSED
2019-12-06T19:23:23.378Z,1575660203.378 [CommandLine](IMPORTANT): got command configSet list
2019-12-06T19:23:23.379Z,1575660203.379 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-12-06T19:23:23.379Z,1575660203.379 [CommandLine](IMPORTANT): CBIT.gf24Offset=143 microampere;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): DAT.verbosity=3 count;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=0.5 minute;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup=0 bool;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=198 cubic_centimeter;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter;

2019-12-06T19:23:23.380Z,1575660203.380 [CommandLine](IMPORTANT): WetLabsUBAT.loadAtStartup=0 bool;

2019-12-06T19:23:23.730Z,1575660203.730 [MissionManager](IMPORTANT): Started mission Startup
2019-12-06T19:23:23.730Z,1575660203.730 [Startup] Running Loop=1
2019-12-06T19:23:23.730Z,1575660203.730 [Startup](DEBUG): Aggregate::initialize Startup
2019-12-06T19:23:23.730Z,1575660203.730 [Startup:A.GoToSurface] Running Loop=1
2019-12-06T19:23:23.730Z,1575660203.730 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-12-06T19:23:23.731Z,1575660203.731 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-12-06T19:23:23.731Z,1575660203.731 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-12-06T19:23:23.732Z,1575660203.732 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-12-06T19:23:23.732Z,1575660203.732 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-12-06T19:23:23.733Z,1575660203.733 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-12-06T19:23:23.735Z,1575660203.735 [Startup:StartupSatComms] Running Loop=1
2019-12-06T19:23:23.735Z,1575660203.735 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-12-06T19:23:23.735Z,1575660203.735 [Startup:StartupSatComms:A] Running Loop=1
2019-12-06T19:23:24.151Z,1575660204.151 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-12-06T19:24:23.915Z,1575660263.915 [Startup:StartupSatComms:A](INFO): Timed out from 2019-12-06T19:23:23.7Z
2019-12-06T19:24:23.915Z,1575660263.915 [Startup:StartupSatComms:A] Stopped
2019-12-06T19:24:23.915Z,1575660263.915 [Startup:StartupSatComms:B] Running Loop=1
2019-12-06T19:24:24.304Z,1575660264.304 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-12-06T19:24:31.229Z,1575660271.229 [DataOverHttps](INFO): Sending 234 bytes from file Logs/20191202T194021/Express0044.lzma
2019-12-06T19:24:33.235Z,1575660273.235 [DataOverHttps](INFO): Moved sent file to Logs/20191202T194021/Express0044.lzma.bak
2019-12-06T19:24:33.235Z,1575660273.235 [DataOverHttps](INFO): SBD MOMSN=12124289
2019-12-06T19:24:50.118Z,1575660290.118 [DataOverHttps](INFO): Sending 1085 bytes from file Logs/20191206T192139/Express0001.lzma
2019-12-06T19:24:50.171Z,1575660290.171 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-12-06T19:24:50.171Z,1575660290.171 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:24:50.202Z,1575660290.202 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:24:50.578Z,1575660290.578 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:24:50.579Z,1575660290.579 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-12-06T19:24:52.122Z,1575660292.122 [DataOverHttps](INFO): Moved sent file to Logs/20191206T192139/Express0001.lzma.bak
2019-12-06T19:24:52.122Z,1575660292.122 [DataOverHttps](INFO): SBD MOMSN=12124295
2019-12-06T19:24:53.413Z,1575660293.413 [Startup:StartupSatComms:B] Stopped
2019-12-06T19:24:53.413Z,1575660293.413 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-12-06T19:24:53.413Z,1575660293.413 [Startup:StartupSatComms] Stopped
2019-12-06T19:24:53.413Z,1575660293.413 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-12-06T19:24:53.414Z,1575660293.414 [Startup](INFO): Completed Startup
2019-12-06T19:24:53.414Z,1575660293.414 [MissionManager](INFO): Startup is completed.
2019-12-06T19:24:53.414Z,1575660293.414 [MissionManager](INFO): Uninitializing Mission Startup
2019-12-06T19:24:53.415Z,1575660293.415 [Startup] Stopped
2019-12-06T19:24:53.415Z,1575660293.415 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-12-06T19:24:53.415Z,1575660293.415 [Startup:A.GoToSurface] Stopped
2019-12-06T19:24:53.415Z,1575660293.415 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-12-06T19:24:53.806Z,1575660293.806 [MissionManager](IMPORTANT): Started mission Default
2019-12-06T19:24:53.807Z,1575660293.807 [Default] Running Loop=1
2019-12-06T19:24:53.807Z,1575660293.807 [Default](DEBUG): Aggregate::initialize Default
2019-12-06T19:24:53.807Z,1575660293.807 [Default:B.GoToSurface] Running Loop=1
2019-12-06T19:24:53.807Z,1575660293.807 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-12-06T19:24:53.807Z,1575660293.807 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-12-06T19:24:53.807Z,1575660293.807 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-12-06T19:24:53.808Z,1575660293.808 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-12-06T19:24:53.808Z,1575660293.808 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-12-06T19:24:53.808Z,1575660293.808 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-12-06T19:24:53.809Z,1575660293.809 [Default:A.Wait] Running Loop=1
2019-12-06T19:24:53.809Z,1575660293.809 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-12-06T19:25:07.128Z,1575660307.128 [Default:A.Wait](INFO): Done Waiting.
2019-12-06T19:25:07.128Z,1575660307.128 [Default:A.Wait] Stopped
2019-12-06T19:25:07.128Z,1575660307.128 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-12-06T19:25:07.532Z,1575660307.532 [Default:CheckIn] Running Loop=1
2019-12-06T19:25:07.532Z,1575660307.532 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-12-06T19:25:07.533Z,1575660307.533 [Default:CheckIn:Read_GPS] Running Loop=1
2019-12-06T19:25:07.958Z,1575660307.958 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-12-06T19:25:12.432Z,1575660312.432 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2019-12-06T19:25:18.921Z,1575660318.921 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-12-06T19:25:48.390Z,1575660348.390 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-12-06T19:27:21.822Z,1575660441.822 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:27:21.823Z,1575660441.823 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:27:21.837Z,1575660441.837 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
    xmlns:Sensor="Tethys/Sensor"
    xmlns:Units="Tethys/Units"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                        Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd
                        Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd"
    Id="senddata_direct_test">

    <SendData Service="Direct" Destination="modem:8:_.pressure">
        <Sensor:Onboard.Pressure/><Units:atmosphere/>
    </SendData>
    
    <SendData Service="Direct" Destination="modem:8:_.temperature">
        <Sensor:Onboard.Temperature/><Units:celsius/>
    </SendData>
    
    <SendData Service="Direct" Destination="modem:8:_.humidity">
        <Sensor:Onboard.Humidity/><Units:percent/>
    </SendData>

</Mission>


2019-12-06T19:27:21.839Z,1575660441.839 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:27:22.065Z,1575660442.065 [Default] Stopped
2019-12-06T19:27:22.065Z,1575660442.065 [Default](DEBUG): Aggregate::uninitialize Default
2019-12-06T19:27:22.065Z,1575660442.065 [Default:B.GoToSurface] Stopped
2019-12-06T19:27:22.065Z,1575660442.065 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-12-06T19:27:22.065Z,1575660442.065 [Default:CheckIn] Stopped
2019-12-06T19:27:22.066Z,1575660442.066 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-12-06T19:27:22.066Z,1575660442.066 [Default:CheckIn:Read_GPS] Stopped
2019-12-06T19:27:22.066Z,1575660442.066 [MissionManager](IMPORTANT): Started mission senddata_direct_test
2019-12-06T19:27:22.066Z,1575660442.066 [senddata_direct_test] Running Loop=1
2019-12-06T19:27:22.066Z,1575660442.066 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test
2019-12-06T19:27:22.066Z,1575660442.066 [senddata_direct_test:A] Running Loop=1
2019-12-06T19:27:22.066Z,1575660442.066 [senddata_direct_test:A] Stopped
2019-12-06T19:27:22.067Z,1575660442.067 [senddata_direct_test:B] Running Loop=1
2019-12-06T19:27:22.462Z,1575660442.462 [DAT](INFO): modem://8: set _.pressure 51025.421875 pascal
2019-12-06T19:27:22.462Z,1575660442.462 [DAT](INFO): #Outgoing data=1
2019-12-06T19:27:22.462Z,1575660442.462 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:27:22.474Z,1575660442.474 [senddata_direct_test:B] Stopped
2019-12-06T19:27:22.474Z,1575660442.474 [senddata_direct_test:C] Running Loop=1
2019-12-06T19:27:22.869Z,1575660442.869 [DAT](INFO): setting remote address to 8
2019-12-06T19:27:22.887Z,1575660442.887 [senddata_direct_test:C] Stopped
2019-12-06T19:27:22.887Z,1575660442.887 [senddata_direct_test](INFO): Completed senddata_direct_test
2019-12-06T19:27:22.887Z,1575660442.887 [MissionManager](INFO): senddata_direct_test is completed.
2019-12-06T19:27:22.887Z,1575660442.887 [MissionManager](INFO): Uninitializing Mission senddata_direct_test
2019-12-06T19:27:22.887Z,1575660442.887 [senddata_direct_test] Stopped
2019-12-06T19:27:22.888Z,1575660442.888 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test
2019-12-06T19:27:23.275Z,1575660443.275 [DAT](DEBUG): checking for remote address setting acknowledgment
2019-12-06T19:27:23.276Z,1575660443.276 [DAT](INFO): set remote address to 8
2019-12-06T19:27:23.277Z,1575660443.277 [DAT](INFO): entering online mode
2019-12-06T19:27:23.285Z,1575660443.285 [MissionManager](IMPORTANT): Started mission Default
2019-12-06T19:27:23.285Z,1575660443.285 [Default] Running Loop=1
2019-12-06T19:27:23.286Z,1575660443.286 [Default](DEBUG): Aggregate::initialize Default
2019-12-06T19:27:23.286Z,1575660443.286 [Default:B.GoToSurface] Running Loop=1
2019-12-06T19:27:23.286Z,1575660443.286 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-12-06T19:27:23.286Z,1575660443.286 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-12-06T19:27:23.286Z,1575660443.286 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-12-06T19:27:23.287Z,1575660443.287 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-12-06T19:27:23.287Z,1575660443.287 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-12-06T19:27:23.287Z,1575660443.287 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-12-06T19:27:23.288Z,1575660443.288 [Default:A.Wait] Running Loop=1
2019-12-06T19:27:23.288Z,1575660443.288 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-12-06T19:27:23.672Z,1575660443.672 [DAT](DEBUG): checking for online mode acknowledgment
2019-12-06T19:27:23.689Z,1575660443.689 [DAT](INFO): online mode acknowledged
2019-12-06T19:27:23.689Z,1575660443.689 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:27:26.919Z,1575660446.919 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:27:37.3559

2019-12-06T19:27:26.919Z,1575660446.919 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:27:31.738Z,1575660451.738 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-12-06T19:27:36.618Z,1575660456.618 [Default:A.Wait](INFO): Done Waiting.
2019-12-06T19:27:36.618Z,1575660456.618 [Default:A.Wait] Stopped
2019-12-06T19:27:36.618Z,1575660456.618 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-12-06T19:27:37.038Z,1575660457.038 [Default:CheckIn] Running Loop=1
2019-12-06T19:27:37.038Z,1575660457.038 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-12-06T19:27:37.038Z,1575660457.038 [Default:CheckIn:Read_GPS] Running Loop=1
2019-12-06T19:27:43.886Z,1575660463.886 [DAT](FAULT): Ack receipt timeout failure.
2019-12-06T19:27:43.886Z,1575660463.886 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:27:44.288Z,1575660464.288 [DAT](INFO): modem://8: set _.temperature 23.937250 celsius
2019-12-06T19:27:44.289Z,1575660464.289 [DAT](INFO): #Outgoing data=1
2019-12-06T19:27:44.289Z,1575660464.289 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:27:44.695Z,1575660464.695 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:27:47.931Z,1575660467.931 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:27:58.3558

2019-12-06T19:27:47.931Z,1575660467.931 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:27:51.156Z,1575660471.156 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-12-06T19:27:51.156Z,1575660471.156 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:27:51.166Z,1575660471.166 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:27:51.575Z,1575660471.575 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:27:51.575Z,1575660471.575 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-12-06T19:27:59.240Z,1575660479.240 [DAT](INFO): DAT read: Rx Time:19:28:08.9262

2019-12-06T19:27:59.240Z,1575660479.240 [DAT](INFO): received an acoustic signal
2019-12-06T19:28:00.060Z,1575660480.060 [DAT](INFO): DAT read: 19:28:08.9262 LVL=  9536, 10849, 10722, 13139, AGC= 68, IDX= 439,-0.21,-0.110, 1.556, 1.377, 1.758, PHS=-1.834,-0.173,-0.310, RAW= 274.2,  27.2, CAL= 278.1,  33.2, ROT= 216.9, -33.2

2019-12-06T19:28:00.063Z,1575660480.063 [DAT](INFO): got valid direction response:
 19:28:08.9262 LVL=  9536, 10849, 10722, 13139, AGC= 68, IDX= 439,-0.21,-0.110, 1.556, 1.377, 1.758, PHS=-1.834,-0.173,-0.310, RAW= 274.2,  27.2, CAL= 278.1,  33.2, ROT= 216.9, -33.2

2019-12-06T19:28:00.064Z,1575660480.064 [DAT](INFO): DAT read: 

2019-12-06T19:28:00.064Z,1575660480.064 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:28:00.065Z,1575660480.065 [DAT](INFO): Got DATA 2
2019-12-06T19:28:00.066Z,1575660480.066 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:28:00.066Z,1575660480.066 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:28:00.066Z,1575660480.066 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): DAT read: CRC:Pass MPD:08.4 PSNR:12.1 AGC:74 SPD:+00.0 CCERR:009

2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): Got ack
2019-12-06T19:28:00.068Z,1575660480.068 [DAT](INFO): DAT read: 

2019-12-06T19:28:00.069Z,1575660480.069 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:28:00.069Z,1575660480.069 [DAT](INFO): Read direction message, but no range.
2019-12-06T19:28:00.447Z,1575660480.447 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:28:00.837Z,1575660480.837 [DAT](INFO): modem://8: set _.humidity 13.160786 percent
2019-12-06T19:28:00.837Z,1575660480.837 [DAT](INFO): #Outgoing data=2
2019-12-06T19:28:00.838Z,1575660480.838 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:28:01.252Z,1575660481.252 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:28:04.478Z,1575660484.478 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:28:14.9057

2019-12-06T19:28:04.478Z,1575660484.478 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:28:12.167Z,1575660492.167 [DAT](INFO): DAT read: Rx Time:19:28:21.7763

2019-12-06T19:28:12.167Z,1575660492.167 [DAT](INFO): received an acoustic signal
2019-12-06T19:28:12.986Z,1575660492.986 [DAT](INFO): DAT read: 19:28:21.7763 LVL=  9872, 11137,  9122, 14323, AGC= 68, IDX= 440, 0.20, 1.642,-2.867,-3.023,-2.672, PHS=-1.935,-0.166,-0.280, RAW= 273.3,  26.1, CAL= 276.8,  32.2, ROT= 218.2, -32.2

2019-12-06T19:28:12.987Z,1575660492.987 [DAT](INFO): got valid direction response:
 19:28:21.7763 LVL=  9872, 11137,  9122, 14323, AGC= 68, IDX= 440, 0.20, 1.642,-2.867,-3.023,-2.672, PHS=-1.935,-0.166,-0.280, RAW= 273.3,  26.1, CAL= 276.8,  32.2, ROT= 218.2, -32.2

2019-12-06T19:28:12.987Z,1575660492.987 [DAT](INFO): DAT read: 

2019-12-06T19:28:12.988Z,1575660492.988 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:28:12.988Z,1575660492.988 [DAT](INFO): Got DATA 2
2019-12-06T19:28:12.989Z,1575660492.989 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:28:12.989Z,1575660492.989 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:28:12.989Z,1575660492.989 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): DAT read: CRC:Pass MPD:09.9 PSNR:12.5 AGC:74 SPD:+00.0 CCERR:009

2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): Got ack
2019-12-06T19:28:12.991Z,1575660492.991 [DAT](INFO): DAT read: 

2019-12-06T19:28:12.992Z,1575660492.992 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:28:12.992Z,1575660492.992 [DAT](INFO): Read direction message, but no range.
2019-12-06T19:28:13.365Z,1575660493.365 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:28:13.774Z,1575660493.774 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:28:14.182Z,1575660494.182 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:28:17.417Z,1575660497.417 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:28:27.8557

2019-12-06T19:28:17.417Z,1575660497.417 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:28:24.704Z,1575660504.704 [DAT](INFO): DAT read: Rx Time:19:28:34.6264

2019-12-06T19:28:24.704Z,1575660504.704 [DAT](INFO): received an acoustic signal
2019-12-06T19:28:25.905Z,1575660505.905 [DAT](INFO): DAT read: 19:28:34.6264 LVL= 10928, 12081, 10194, 14291, AGC= 70, IDX= 186,-0.15,-0.006, 1.411, 1.303, 1.698, PHS=-1.670,-0.259,-0.323, RAW= 272.3,  30.0, CAL= 277.3,  36.4, ROT= 217.7, -36.4

2019-12-06T19:28:25.906Z,1575660505.906 [DAT](INFO): got valid direction response:
 19:28:34.6264 LVL= 10928, 12081, 10194, 14291, AGC= 70, IDX= 186,-0.15,-0.006, 1.411, 1.303, 1.698, PHS=-1.670,-0.259,-0.323, RAW= 272.3,  30.0, CAL= 277.3,  36.4, ROT= 217.7, -36.4

2019-12-06T19:28:25.906Z,1575660505.906 [DAT](INFO): DAT read: 

2019-12-06T19:28:25.907Z,1575660505.907 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:28:25.907Z,1575660505.907 [DAT](INFO): Got DATA 2
2019-12-06T19:28:25.908Z,1575660505.908 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:28:25.908Z,1575660505.908 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:28:25.909Z,1575660505.909 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:28:25.910Z,1575660505.910 [DAT](INFO): DAT read: CRC:Pass MPD:17.9 PSNR:11.6 AGC:73 SPD:+00.0 CCERR:009

2019-12-06T19:28:25.911Z,1575660505.911 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:25.911Z,1575660505.911 [DAT](INFO): Got CRC:Pass
2019-12-06T19:28:25.911Z,1575660505.911 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:28:25.911Z,1575660505.911 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:28:25.911Z,1575660505.911 [DAT](INFO): Got ack
2019-12-06T19:28:25.911Z,1575660505.911 [DAT](INFO): DAT read: 

2019-12-06T19:28:25.912Z,1575660505.912 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:28:25.912Z,1575660505.912 [DAT](INFO): Read direction message, but no range.
2019-12-06T19:28:26.294Z,1575660506.294 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:30:19.828Z,1575660619.828 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:30:30.1054

2019-12-06T19:30:19.829Z,1575660619.829 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:19:30:30.1054

2019-12-06T19:30:49.322Z,1575660649.322 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-12-06T19:30:49.324Z,1575660649.324 [BPC1](INFO): Received data from all battery sticks.
2019-12-06T19:30:51.352Z,1575660651.352 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:31:01.4550

2019-12-06T19:30:51.353Z,1575660651.353 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:19:31:01.4550

2019-12-06T19:30:52.148Z,1575660652.148 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-12-06T19:30:52.165Z,1575660652.165 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:30:52.182Z,1575660652.182 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:30:52.581Z,1575660652.581 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:30:52.581Z,1575660652.581 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-12-06T19:31:20.834Z,1575660680.834 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:31:31.2049

2019-12-06T19:31:20.834Z,1575660680.834 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:19:31:31.2049

2019-12-06T19:31:31.744Z,1575660691.744 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:31:42.0550

2019-12-06T19:31:31.744Z,1575660691.744 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:19:31:42.0550

2019-12-06T19:32:29.495Z,1575660749.495 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-12-06T19:32:29.495Z,1575660749.495 [NAL9602] Data Fault, FailCount= 1
2019-12-06T19:32:29.495Z,1575660749.495 [NAL9602](ERROR): Data Fault
2019-12-06T19:32:29.524Z,1575660749.524 [CBIT](ERROR): Data Fault in component: NAL9602
2019-12-06T19:32:29.890Z,1575660749.890 [NAL9602](INFO): Powering down
2019-12-06T19:32:30.730Z,1575660750.730 [CBIT](INFO): Clearing failed state for component NAL9602
2019-12-06T19:32:30.731Z,1575660750.731 [NAL9602] No Fault, FailCount= 1
2019-12-06T19:32:37.190Z,1575660757.190 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-12-06T19:27:37.0Z
2019-12-06T19:32:37.190Z,1575660757.190 [Default:CheckIn:Read_GPS] Stopped
2019-12-06T19:32:37.190Z,1575660757.190 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-12-06T19:32:37.598Z,1575660757.598 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-12-06T19:32:38.716Z,1575660758.716 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20191206T192139/Courier0004.lzma
2019-12-06T19:32:40.638Z,1575660760.638 [DataOverHttps](INFO): Moved sent file to Logs/20191206T192139/Courier0004.lzma.bak
2019-12-06T19:32:40.638Z,1575660760.638 [DataOverHttps](INFO): SBD MOMSN=12124398
2019-12-06T19:32:57.005Z,1575660777.005 [DataOverHttps](INFO): Sending 308 bytes from file Logs/20191206T192139/Express0005.lzma
2019-12-06T19:32:59.010Z,1575660779.010 [DataOverHttps](INFO): Moved sent file to Logs/20191206T192139/Express0005.lzma.bak
2019-12-06T19:32:59.010Z,1575660779.010 [DataOverHttps](INFO): SBD MOMSN=12124410
2019-12-06T19:33:00.242Z,1575660780.242 [NAL9602](INFO): Powering up NAL9602
2019-12-06T19:33:00.278Z,1575660780.278 [Default:CheckIn:Read_Iridium] Stopped
2019-12-06T19:33:00.279Z,1575660780.279 [Default:CheckIn:C.Wait] Running Loop=1
2019-12-06T19:33:00.279Z,1575660780.279 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-12-06T19:33:11.182Z,1575660791.182 [NAL9602](INFO): NAL9602 initialized
2019-12-06T19:33:18.442Z,1575660798.442 [CommandLine](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:33:18.442Z,1575660798.442 [MissionManager](INFO): Loading Mission: ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:33:18.524Z,1575660798.524 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
    xmlns:Sensor="Tethys/Sensor"
    xmlns:Units="Tethys/Units"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                        Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd
                        Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd"
    Id="senddata_direct_test">

    <SendData Service="Direct" Destination="modem:8:_.pressure">
        <Sensor:Onboard.Pressure/><Units:atmosphere/>
    </SendData>
    
    <SendData Service="Direct" Destination="modem:8:_.temperature">
        <Sensor:Onboard.Temperature/><Units:celsius/>
    </SendData>
    
    <SendData Service="Direct" Destination="modem:8:_.humidity">
        <Sensor:Onboard.Humidity/><Units:percent/>
    </SendData>

</Mission>


2019-12-06T19:33:18.895Z,1575660798.895 [Default] Stopped
2019-12-06T19:33:18.895Z,1575660798.895 [Default](DEBUG): Aggregate::uninitialize Default
2019-12-06T19:33:18.895Z,1575660798.895 [Default:B.GoToSurface] Stopped
2019-12-06T19:33:18.895Z,1575660798.895 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-12-06T19:33:18.895Z,1575660798.895 [Default:CheckIn] Stopped
2019-12-06T19:33:18.895Z,1575660798.895 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-12-06T19:33:18.895Z,1575660798.895 [Default:CheckIn:C.Wait] Stopped
2019-12-06T19:33:18.895Z,1575660798.895 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-12-06T19:33:18.895Z,1575660798.895 [MissionManager](IMPORTANT): Started mission senddata_direct_test
2019-12-06T19:33:18.896Z,1575660798.896 [senddata_direct_test] Running Loop=1
2019-12-06T19:33:18.896Z,1575660798.896 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test
2019-12-06T19:33:18.896Z,1575660798.896 [senddata_direct_test:A] Running Loop=1
2019-12-06T19:33:18.896Z,1575660798.896 [senddata_direct_test:A] Stopped
2019-12-06T19:33:18.896Z,1575660798.896 [senddata_direct_test:B] Running Loop=1
2019-12-06T19:33:18.942Z,1575660798.942 [CommandLine](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml
2019-12-06T19:33:19.274Z,1575660799.274 [DAT](INFO): modem://8: set _.pressure 51786.378906 pascal
2019-12-06T19:33:19.274Z,1575660799.274 [DAT](INFO): #Outgoing data=1
2019-12-06T19:33:19.274Z,1575660799.274 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:33:19.286Z,1575660799.286 [senddata_direct_test:B] Stopped
2019-12-06T19:33:19.286Z,1575660799.286 [senddata_direct_test:C] Running Loop=1
2019-12-06T19:33:19.682Z,1575660799.682 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:33:19.717Z,1575660799.717 [senddata_direct_test:C] Stopped
2019-12-06T19:33:19.717Z,1575660799.717 [senddata_direct_test](INFO): Completed senddata_direct_test
2019-12-06T19:33:19.717Z,1575660799.717 [MissionManager](INFO): senddata_direct_test is completed.
2019-12-06T19:33:19.717Z,1575660799.717 [MissionManager](INFO): Uninitializing Mission senddata_direct_test
2019-12-06T19:33:19.718Z,1575660799.718 [senddata_direct_test] Stopped
2019-12-06T19:33:19.718Z,1575660799.718 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test
2019-12-06T19:33:20.099Z,1575660800.099 [MissionManager](IMPORTANT): Started mission Default
2019-12-06T19:33:20.099Z,1575660800.099 [Default] Running Loop=1
2019-12-06T19:33:20.100Z,1575660800.100 [Default](DEBUG): Aggregate::initialize Default
2019-12-06T19:33:20.100Z,1575660800.100 [Default:B.GoToSurface] Running Loop=1
2019-12-06T19:33:20.100Z,1575660800.100 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-12-06T19:33:20.100Z,1575660800.100 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-12-06T19:33:20.100Z,1575660800.100 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-12-06T19:33:20.101Z,1575660800.101 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-12-06T19:33:20.101Z,1575660800.101 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-12-06T19:33:20.102Z,1575660800.102 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-12-06T19:33:20.102Z,1575660800.102 [Default:A.Wait] Running Loop=1
2019-12-06T19:33:20.102Z,1575660800.102 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-12-06T19:33:22.924Z,1575660802.924 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:33:33.3545

2019-12-06T19:33:22.924Z,1575660802.924 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:33:30.191Z,1575660810.191 [DAT](INFO): DAT read: Rx Time:19:33:40.0281

2019-12-06T19:33:30.191Z,1575660810.191 [DAT](INFO): received an acoustic signal
2019-12-06T19:33:31.011Z,1575660811.011 [DAT](INFO): DAT read: 

2019-12-06T19:33:31.012Z,1575660811.012 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:33:31.012Z,1575660811.012 [DAT](INFO): Got DATA 2
2019-12-06T19:33:31.013Z,1575660811.013 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:33:31.013Z,1575660811.013 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:33:31.014Z,1575660811.014 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:33:31.015Z,1575660811.015 [DAT](INFO): DAT read: CRC:Pass MPD:10.1 PSNR:11.8 AGC:71 SPD:-00.1 CCERR:009

2019-12-06T19:33:31.015Z,1575660811.015 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:31.015Z,1575660811.015 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:31.015Z,1575660811.015 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:33:31.015Z,1575660811.015 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:33:31.015Z,1575660811.015 [DAT](INFO): Got ack
2019-12-06T19:33:31.016Z,1575660811.016 [DAT](INFO): DAT read: 

2019-12-06T19:33:31.016Z,1575660811.016 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:33:31.407Z,1575660811.407 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:33:31.812Z,1575660811.812 [DAT](INFO): modem://8: set _.temperature 24.219263 celsius
2019-12-06T19:33:31.813Z,1575660811.813 [DAT](INFO): #Outgoing data=1
2019-12-06T19:33:31.813Z,1575660811.813 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:33:32.211Z,1575660812.211 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:33:33.426Z,1575660813.426 [Default:A.Wait](INFO): Done Waiting.
2019-12-06T19:33:33.426Z,1575660813.426 [Default:A.Wait] Stopped
2019-12-06T19:33:33.426Z,1575660813.426 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-12-06T19:33:33.842Z,1575660813.842 [Default:CheckIn] Running Loop=1
2019-12-06T19:33:33.842Z,1575660813.842 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-12-06T19:33:33.842Z,1575660813.842 [Default:CheckIn:Read_GPS] Running Loop=1
2019-12-06T19:33:35.444Z,1575660815.444 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:33:45.9045

2019-12-06T19:33:35.445Z,1575660815.445 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:33:42.726Z,1575660822.726 [DAT](INFO): DAT read: Rx Time:19:33:52.6281

2019-12-06T19:33:42.726Z,1575660822.726 [DAT](INFO): received an acoustic signal
2019-12-06T19:33:43.536Z,1575660823.536 [DAT](INFO): DAT read: 

2019-12-06T19:33:43.537Z,1575660823.537 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:33:43.538Z,1575660823.538 [DAT](INFO): Got DATA 2
2019-12-06T19:33:43.539Z,1575660823.539 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:33:43.539Z,1575660823.539 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:33:43.539Z,1575660823.539 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:33:43.540Z,1575660823.540 [DAT](INFO): DAT read: CRC:Pass MPD:08.2 PSNR:09.7 AGC:70 SPD:-00.3 CCERR:008

2019-12-06T19:33:43.541Z,1575660823.541 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:43.541Z,1575660823.541 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:43.541Z,1575660823.541 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:33:43.541Z,1575660823.541 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:33:43.541Z,1575660823.541 [DAT](INFO): Got ack
2019-12-06T19:33:43.541Z,1575660823.541 [DAT](INFO): DAT read: 

2019-12-06T19:33:43.542Z,1575660823.542 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:33:43.924Z,1575660823.924 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:33:44.327Z,1575660824.327 [DAT](INFO): modem://8: set _.humidity 13.124161 percent
2019-12-06T19:33:44.328Z,1575660824.328 [DAT](INFO): #Outgoing data=1
2019-12-06T19:33:44.328Z,1575660824.328 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2019-12-06T19:33:44.756Z,1575660824.756 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2019-12-06T19:33:47.963Z,1575660827.963 [DAT](INFO): DAT read: Forwarding Delay UpTx time:19:33:58.4044

2019-12-06T19:33:47.963Z,1575660827.963 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2019-12-06T19:33:53.220Z,1575660833.220 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-12-06T19:33:53.220Z,1575660833.220 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:33:53.229Z,1575660833.229 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:33:53.637Z,1575660833.637 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:33:53.637Z,1575660833.637 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-12-06T19:33:55.252Z,1575660835.252 [DAT](INFO): DAT read: Rx Time:19:34:05.0283

2019-12-06T19:33:55.252Z,1575660835.252 [DAT](INFO): received an acoustic signal
2019-12-06T19:33:56.037Z,1575660836.037 [DAT](INFO): DAT read: 

2019-12-06T19:33:56.038Z,1575660836.038 [DAT](INFO): DAT read: DATA(0002):~~

2019-12-06T19:33:56.038Z,1575660836.038 [DAT](INFO): Got DATA 2
2019-12-06T19:33:56.039Z,1575660836.039 [DAT](INFO): DAT read: Source:008  Destination:009

2019-12-06T19:33:56.039Z,1575660836.039 [DAT](INFO): Got Src/Dest after DATA 
2019-12-06T19:33:56.040Z,1575660836.040 [DAT](INFO): DATA Src=8, Dst=9
2019-12-06T19:33:56.041Z,1575660836.041 [DAT](INFO): DAT read: CRC:Pass MPD:08.2 PSNR:11.4 AGC:71 SPD:-00.1 CCERR:009

2019-12-06T19:33:56.041Z,1575660836.041 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:56.042Z,1575660836.042 [DAT](INFO): Got CRC:Pass
2019-12-06T19:33:56.042Z,1575660836.042 [DAT](INFO): Incoming data is intended for us
2019-12-06T19:33:56.042Z,1575660836.042 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2019-12-06T19:33:56.042Z,1575660836.042 [DAT](INFO): Got ack
2019-12-06T19:33:56.042Z,1575660836.042 [DAT](INFO): DAT read: 

2019-12-06T19:33:56.043Z,1575660836.043 [DAT](INFO): DAT read: <EOP>

2019-12-06T19:33:56.447Z,1575660836.447 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2019-12-06T19:36:54.227Z,1575661014.227 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-12-06T19:36:54.227Z,1575661014.227 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:36:54.237Z,1575661014.237 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:36:54.641Z,1575661014.641 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:36:54.641Z,1575661014.641 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-12-06T19:38:34.006Z,1575661114.006 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-12-06T19:33:33.8Z
2019-12-06T19:38:34.006Z,1575661114.006 [Default:CheckIn:Read_GPS] Stopped
2019-12-06T19:38:34.006Z,1575661114.006 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-12-06T19:38:41.484Z,1575661121.484 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20191206T192139/Express0008.lzma
2019-12-06T19:38:43.490Z,1575661123.490 [DataOverHttps](INFO): Moved sent file to Logs/20191206T192139/Express0008.lzma.bak
2019-12-06T19:38:43.491Z,1575661123.491 [DataOverHttps](INFO): SBD MOMSN=12124560
2019-12-06T19:38:44.990Z,1575661124.990 [Default:CheckIn:Read_Iridium] Stopped
2019-12-06T19:38:44.990Z,1575661124.990 [Default:CheckIn:C.Wait] Running Loop=1
2019-12-06T19:38:44.990Z,1575661124.990 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-12-06T19:39:55.281Z,1575661195.281 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-12-06T19:39:55.281Z,1575661195.281 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:39:55.291Z,1575661195.291 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:39:55.694Z,1575661195.694 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:39:55.695Z,1575661195.695 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-12-06T19:42:56.277Z,1575661376.277 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2019-12-06T19:42:56.277Z,1575661376.277 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:42:56.294Z,1575661376.294 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:42:56.709Z,1575661376.709 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:42:56.709Z,1575661376.709 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2019-12-06T19:43:12.810Z,1575661392.810 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-12-06T19:43:12.810Z,1575661392.810 [NAL9602] Data Fault, FailCount= 2
2019-12-06T19:43:12.810Z,1575661392.810 [NAL9602](ERROR): Data Fault
2019-12-06T19:43:12.894Z,1575661392.894 [CBIT](ERROR): Data Fault in component: NAL9602
2019-12-06T19:43:13.214Z,1575661393.214 [NAL9602](INFO): Powering down
2019-12-06T19:43:14.070Z,1575661394.070 [CBIT](INFO): Clearing failed state for component NAL9602
2019-12-06T19:43:14.070Z,1575661394.070 [NAL9602] No Fault, FailCount= 2
2019-12-06T19:43:43.518Z,1575661423.518 [NAL9602](INFO): Powering up NAL9602
2019-12-06T19:43:45.562Z,1575661425.562 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-12-06T19:43:45.562Z,1575661425.562 [Default:CheckIn:C.Wait] Stopped
2019-12-06T19:43:45.562Z,1575661425.562 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-12-06T19:43:45.563Z,1575661425.563 [Default:CheckIn:D] Running Loop=1
2019-12-06T19:43:45.965Z,1575661425.965 [Default:CheckIn:D] Stopped
2019-12-06T19:43:45.965Z,1575661425.965 [Default:CheckIn:E] Running Loop=1
2019-12-06T19:43:46.373Z,1575661426.373 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.431091 min 
2019-12-06T19:43:46.373Z,1575661426.373 [Default:CheckIn:E] Stopped
2019-12-06T19:43:46.373Z,1575661426.373 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-12-06T19:43:46.373Z,1575661426.373 [Default:CheckIn] Stopped
2019-12-06T19:43:46.373Z,1575661426.373 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-12-06T19:43:46.374Z,1575661426.374 [Default:CheckIn](INFO): Running loop #2
2019-12-06T19:43:46.374Z,1575661426.374 [Default:CheckIn] Running Loop=2
2019-12-06T19:43:46.374Z,1575661426.374 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-12-06T19:43:46.374Z,1575661426.374 [Default:CheckIn:Read_GPS] Running Loop=1
2019-12-06T19:43:54.426Z,1575661434.426 [NAL9602](INFO): NAL9602 initialized
2019-12-06T19:45:56.951Z,1575661556.951 [CommandLine](IMPORTANT): got command restart application
2019-12-06T19:45:57.292Z,1575661557.292 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2019-12-06T19:45:57.292Z,1575661557.292 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-12-06T19:45:57.302Z,1575661557.302 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-12-06T19:45:57.713Z,1575661557.713 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-12-06T19:45:57.713Z,1575661557.713 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2019-12-06T19:45:57.957Z,1575661557.957 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-12-06T19:45:57.957Z,1575661557.957 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:57.957Z,1575661557.957 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.005Z,1575661558.005 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-12-06T19:45:58.005Z,1575661558.005 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.006Z,1575661558.006 [CommandLine](INFO): Join timeout helper Thread ID is 325
2019-12-06T19:45:58.006Z,1575661558.006 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-12-06T19:45:58.006Z,1575661558.006 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.007Z,1575661558.007 [NavChartDb](INFO): Join timeout helper Thread ID is 326
2019-12-06T19:45:58.173Z,1575661558.173 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:58.174Z,1575661558.174 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.189Z,1575661558.189 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-12-06T19:45:58.189Z,1575661558.189 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.189Z,1575661558.189 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 327
2019-12-06T19:45:58.409Z,1575661558.409 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:58.410Z,1575661558.410 [WetLabsBB2FL](INFO): Powering down
2019-12-06T19:45:58.410Z,1575661558.410 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.429Z,1575661558.429 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-12-06T19:45:58.429Z,1575661558.429 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.429Z,1575661558.429 [CTD_Seabird](INFO): Join timeout helper Thread ID is 328
2019-12-06T19:45:58.945Z,1575661558.945 [CTD_Seabird](INFO): Powering down
2019-12-06T19:45:58.957Z,1575661558.957 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:58.957Z,1575661558.957 [CTD_Seabird](INFO): Powering down
2019-12-06T19:45:58.969Z,1575661558.969 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.982Z,1575661558.982 [ComponentRegistry](INFO): Shutting down BackSeatDriver ThreadHandler
2019-12-06T19:45:58.982Z,1575661558.982 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:58.982Z,1575661558.982 [BackSeatDriver](INFO): Join timeout helper Thread ID is 329
2019-12-06T19:45:59.385Z,1575661559.385 [BackSeatDriver ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:59.385Z,1575661559.385 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:59.394Z,1575661559.394 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-12-06T19:45:59.394Z,1575661559.394 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:59.394Z,1575661559.394 [Radio_Surface](INFO): Join timeout helper Thread ID is 330
2019-12-06T19:45:59.789Z,1575661559.789 [Radio_Surface](INFO): Powering down
2019-12-06T19:45:59.790Z,1575661559.790 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:45:59.790Z,1575661559.790 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:59.806Z,1575661559.806 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-12-06T19:45:59.806Z,1575661559.806 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:45:59.806Z,1575661559.806 [DataOverHttps](INFO): Join timeout helper Thread ID is 331
2019-12-06T19:46:00.613Z,1575661560.613 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:46:00.613Z,1575661560.613 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:00.631Z,1575661560.631 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-12-06T19:46:00.632Z,1575661560.632 [logger ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:00.632Z,1575661560.632 [logger](INFO): Join timeout helper Thread ID is 332
2019-12-06T19:46:00.641Z,1575661560.641 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:46:00.641Z,1575661560.641 [logger ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:00.650Z,1575661560.650 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-12-06T19:46:00.650Z,1575661560.650 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:00.650Z,1575661560.650 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-12-06T19:46:00.650Z,1575661560.650 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:00.650Z,1575661560.650 [controlThread](INFO): Join timeout helper Thread ID is 333
2019-12-06T19:46:00.881Z,1575661560.881 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-12-06T19:46:00.881Z,1575661560.881 [controlThread](DEBUG): Uninitializing ControlThread
2019-12-06T19:46:00.881Z,1575661560.881 [AHRS_M2](INFO): Powering down
2019-12-06T19:46:00.953Z,1575661560.953 [NAL9602](INFO): Powering down
2019-12-06T19:46:00.955Z,1575661560.955 [DAT](INFO): Powering down
2019-12-06T19:46:01.074Z,1575661561.074 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-12-06T19:46:01.075Z,1575661561.075 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-12-06T19:46:01.075Z,1575661561.075 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-12-06T19:46:01.075Z,1575661561.075 [MissionManager](INFO): Uninitializing Mission Default
2019-12-06T19:46:01.076Z,1575661561.076 [Default] Stopped
2019-12-06T19:46:01.076Z,1575661561.076 [Default](DEBUG): Aggregate::uninitialize Default
2019-12-06T19:46:01.076Z,1575661561.076 [Default:B.GoToSurface] Stopped
2019-12-06T19:46:01.076Z,1575661561.076 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-12-06T19:46:01.076Z,1575661561.076 [Default:CheckIn] Stopped
2019-12-06T19:46:01.076Z,1575661561.076 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-12-06T19:46:01.076Z,1575661561.076 [Default:CheckIn:Read_GPS] Stopped
2019-12-06T19:46:01.078Z,1575661561.078 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-12-06T19:46:01.079Z,1575661561.079 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-12-06T19:46:01.079Z,1575661561.079 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-12-06T19:46:01.079Z,1575661561.079 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-12-06T19:46:01.079Z,1575661561.079 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-12-06T19:46:01.080Z,1575661561.080 [BuoyancyServo](INFO): Powering down
2019-12-06T19:46:01.093Z,1575661561.093 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-12-06T19:46:01.093Z,1575661561.093 [ElevatorServo](INFO): Powering down
2019-12-06T19:46:01.094Z,1575661561.094 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-12-06T19:46:01.094Z,1575661561.094 [MassServo](INFO): Powering down
2019-12-06T19:46:01.095Z,1575661561.095 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-12-06T19:46:01.095Z,1575661561.095 [RudderServo](INFO): Powering down
2019-12-06T19:46:01.095Z,1575661561.095 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-12-06T19:46:01.096Z,1575661561.096 [ThrusterServo](INFO): Powering down
2019-12-06T19:46:01.096Z,1575661561.096 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-12-06T19:46:01.097Z,1575661561.097 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-12-06T19:46:01.097Z,1575661561.097 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-12-06T19:46:01.097Z,1575661561.097 [CBIT](DEBUG): Powering off loads.
2019-12-06T19:46:01.109Z,1575661561.109 [CBIT](DEBUG): Disabling WDT.
2019-12-06T19:46:01.121Z,1575661561.121 [CBIT](DEBUG): Opening all GF detection circuits.
2019-12-06T19:46:01.122Z,1575661561.122 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.219Z,1575661561.219 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.226Z,1575661561.226 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.293Z,1575661561.293 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.297Z,1575661561.297 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.300Z,1575661561.300 [BackSeatDriver ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.316Z,1575661561.316 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-12-06T19:46:01.374Z,1575661561.374 [logger ThreadHandler](INFO): Thread cancelled.