2019-05-28T17:11:32.805Z,1559063492.805 [Supervisor](DEBUG): Initializing supervisor.
2019-05-28T17:11:32.807Z,1559063492.807 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-28T17:11:32.808Z,1559063492.808 [SyncHandler](INFO): Protected caller Thread ID is 807
2019-05-28T17:11:32.808Z,1559063492.808 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-28T17:11:32.809Z,1559063492.809 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-28T17:11:32.810Z,1559063492.810 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 808
2019-05-28T17:11:32.812Z,1559063492.812 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-28T17:11:32.824Z,1559063492.824 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-28T17:11:32.825Z,1559063492.825 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-28T17:11:32.825Z,1559063492.825 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 809
2019-05-28T17:11:32.826Z,1559063492.826 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-28T17:11:32.827Z,1559063492.827 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-28T17:11:32.827Z,1559063492.827 [logger ThreadHandler](INFO): Protected caller Thread ID is 810
2019-05-28T17:11:32.829Z,1559063492.829 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-28T17:11:32.830Z,1559063492.830 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-28T17:11:32.833Z,1559063492.833 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-28T17:11:32.929Z,1559063492.929 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-28T17:11:32.931Z,1559063492.931 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-28T17:11:33.135Z,1559063493.135 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-28T17:11:33.137Z,1559063493.137 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-28T17:11:33.274Z,1559063493.274 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-28T17:11:33.276Z,1559063493.276 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-28T17:11:33.818Z,1559063493.818 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-28T17:11:33.820Z,1559063493.820 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-28T17:11:34.278Z,1559063494.278 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-28T17:11:34.279Z,1559063494.279 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-28T17:11:34.749Z,1559063494.749 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-28T17:11:34.751Z,1559063494.751 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-28T17:11:35.057Z,1559063495.057 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-28T17:11:35.059Z,1559063495.059 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-28T17:11:35.394Z,1559063495.394 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-28T17:11:35.396Z,1559063495.396 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-28T17:11:35.793Z,1559063495.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-28T17:11:35.794Z,1559063495.794 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-28T17:11:35.946Z,1559063495.946 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-28T17:11:35.947Z,1559063495.947 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-28T17:11:36.053Z,1559063496.053 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-28T17:11:36.053Z,1559063496.053 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-28T17:11:36.156Z,1559063496.156 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-28T17:11:36.614Z,1559063496.614 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-28T17:11:36.614Z,1559063496.614 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-28T17:11:36.811Z,1559063496.811 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-28T17:11:36.812Z,1559063496.812 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-28T17:11:37.019Z,1559063497.019 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-28T17:11:37.021Z,1559063497.021 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2019-05-28T17:11:37.024Z,1559063497.024 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2019-05-28T17:11:37.108Z,1559063497.108 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2019-05-28T17:11:37.335Z,1559063497.335 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-28T17:11:37.337Z,1559063497.337 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2019-05-28T17:11:37.433Z,1559063497.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2019-05-28T17:11:37.598Z,1559063497.598 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2019-05-28T17:11:37.802Z,1559063497.802 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2019-05-28T17:11:37.888Z,1559063497.888 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2019-05-28T17:11:37.986Z,1559063497.986 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2019-05-28T17:11:38.080Z,1559063498.080 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2019-05-28T17:11:38.233Z,1559063498.233 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2019-05-28T17:11:38.337Z,1559063498.337 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2019-05-28T17:11:38.436Z,1559063498.436 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-05-28T17:11:38.439Z,1559063498.439 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-28T17:11:38.566Z,1559063498.566 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-28T17:11:38.567Z,1559063498.567 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-28T17:11:38.723Z,1559063498.723 [BuoyancyServo] Loaded
2019-05-28T17:11:38.723Z,1559063498.723 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-28T17:11:38.739Z,1559063498.739 [ElevatorServo] Loaded
2019-05-28T17:11:38.739Z,1559063498.739 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-28T17:11:38.753Z,1559063498.753 [MassServo] Loaded
2019-05-28T17:11:38.753Z,1559063498.753 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-28T17:11:38.768Z,1559063498.768 [RudderServo] Loaded
2019-05-28T17:11:38.769Z,1559063498.769 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-28T17:11:38.783Z,1559063498.783 [ThrusterServo] Loaded
2019-05-28T17:11:38.783Z,1559063498.783 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-28T17:11:38.784Z,1559063498.784 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-28T17:11:38.784Z,1559063498.784 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-28T17:11:38.942Z,1559063498.942 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-28T17:11:38.972Z,1559063498.972 [SBIT] Loaded
2019-05-28T17:11:38.972Z,1559063498.972 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-28T17:11:38.973Z,1559063498.973 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-28T17:11:38.000Z,1559063499.000 [IBIT] Loaded
2019-05-28T17:11:39.000Z,1559063499.000 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-28T17:11:39.003Z,1559063499.003 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-28T17:11:39.434Z,1559063499.434 [CBIT] Loaded
2019-05-28T17:11:39.434Z,1559063499.434 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-28T17:11:39.435Z,1559063499.435 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-28T17:11:39.436Z,1559063499.436 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-28T17:11:39.692Z,1559063499.692 [Aanderaa_O2] Loaded
2019-05-28T17:11:39.692Z,1559063499.692 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-05-28T17:11:39.702Z,1559063499.702 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-05-28T17:11:39.707Z,1559063499.707 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-05-28T17:11:39.709Z,1559063499.709 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-05-28T17:11:39.713Z,1559063499.713 [CTD_Seabird](INFO): created writer for : depth
2019-05-28T17:11:39.714Z,1559063499.714 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-05-28T17:11:39.719Z,1559063499.719 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-05-28T17:11:39.720Z,1559063499.720 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-05-28T17:11:39.725Z,1559063499.725 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-05-28T17:11:39.725Z,1559063499.725 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-05-28T17:11:39.731Z,1559063499.731 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-05-28T17:11:39.731Z,1559063499.731 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-05-28T17:11:39.737Z,1559063499.737 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-05-28T17:11:39.737Z,1559063499.737 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-05-28T17:11:39.742Z,1559063499.742 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-05-28T17:11:39.768Z,1559063499.768 [CTD_Seabird] Loaded
2019-05-28T17:11:39.768Z,1559063499.768 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-05-28T17:11:39.770Z,1559063499.770 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4066A4E0
2019-05-28T17:11:39.770Z,1559063499.770 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 890
2019-05-28T17:11:39.800Z,1559063499.800 [ESPComponent] Loaded
2019-05-28T17:11:39.800Z,1559063499.800 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2019-05-28T17:11:39.814Z,1559063499.814 [PAR_Licor] Loaded
2019-05-28T17:11:39.814Z,1559063499.814 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-05-28T17:11:39.862Z,1559063499.862 [WetLabsBB2FL] Loaded
2019-05-28T17:11:39.862Z,1559063499.862 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-05-28T17:11:39.863Z,1559063499.863 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 4069A4E0
2019-05-28T17:11:39.863Z,1559063499.863 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 891
2019-05-28T17:11:39.864Z,1559063499.864 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-28T17:11:39.866Z,1559063499.866 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-28T17:11:39.920Z,1559063499.920 [DepthRateCalculator] Loaded
2019-05-28T17:11:39.920Z,1559063499.920 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-28T17:11:39.926Z,1559063499.926 [PitchRateCalculator] Loaded
2019-05-28T17:11:39.926Z,1559063499.926 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-28T17:11:39.942Z,1559063499.942 [SpeedCalculator] Loaded
2019-05-28T17:11:39.943Z,1559063499.943 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-28T17:11:39.963Z,1559063499.963 [TempGradientCalculator] Loaded
2019-05-28T17:11:39.964Z,1559063499.964 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-28T17:11:39.969Z,1559063499.969 [YawRateCalculator] Loaded
2019-05-28T17:11:39.970Z,1559063499.970 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-28T17:11:40.002Z,1559063500.002 [ElevatorOffsetCalculator] Loaded
2019-05-28T17:11:40.003Z,1559063500.003 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-28T17:11:40.003Z,1559063500.003 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-28T17:11:40.004Z,1559063500.004 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-28T17:11:40.051Z,1559063500.051 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-28T17:11:40.052Z,1559063500.052 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-28T17:11:40.172Z,1559063500.172 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-28T17:11:40.172Z,1559063500.172 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-28T17:11:40.193Z,1559063500.193 [NavChart] Loaded
2019-05-28T17:11:40.193Z,1559063500.193 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-28T17:11:40.198Z,1559063500.198 [UniversalFixResidualReporter] Loaded
2019-05-28T17:11:40.198Z,1559063500.198 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-28T17:11:40.198Z,1559063500.198 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-28T17:11:40.199Z,1559063500.199 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-28T17:11:40.878Z,1559063500.878 [AHRS_M2] Loaded
2019-05-28T17:11:40.878Z,1559063500.878 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-28T17:11:41.021Z,1559063501.021 [DataOverHttps] Loaded
2019-05-28T17:11:41.021Z,1559063501.021 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-28T17:11:41.022Z,1559063501.022 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409734E0
2019-05-28T17:11:41.023Z,1559063501.023 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 892
2019-05-28T17:11:41.036Z,1559063501.036 [Depth_Keller] Loaded
2019-05-28T17:11:41.036Z,1559063501.036 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-28T17:11:41.041Z,1559063501.041 [DropWeight] Loaded
2019-05-28T17:11:41.041Z,1559063501.041 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-28T17:11:41.170Z,1559063501.170 [DVL_micro] Loaded
2019-05-28T17:11:41.170Z,1559063501.170 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2019-05-28T17:11:41.260Z,1559063501.260 [NAL9602] Loaded
2019-05-28T17:11:41.261Z,1559063501.261 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-28T17:11:41.266Z,1559063501.266 [Onboard] Loaded
2019-05-28T17:11:41.266Z,1559063501.266 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-28T17:11:41.269Z,1559063501.269 [Radio_Surface] Loaded
2019-05-28T17:11:41.270Z,1559063501.270 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-28T17:11:41.271Z,1559063501.271 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409A34E0
2019-05-28T17:11:41.271Z,1559063501.271 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 893
2019-05-28T17:11:41.398Z,1559063501.398 [DAT] Loaded
2019-05-28T17:11:41.398Z,1559063501.398 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-05-28T17:11:42.993Z,1559063502.993 [BPC1] Loaded
2019-05-28T17:11:42.993Z,1559063502.993 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-28T17:11:42.993Z,1559063502.993 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-28T17:11:42.994Z,1559063502.994 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-28T17:11:43.105Z,1559063503.105 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-28T17:11:43.105Z,1559063503.105 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-28T17:11:43.196Z,1559063503.196 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-28T17:11:43.280Z,1559063503.280 [VerticalControl] Loaded
2019-05-28T17:11:43.280Z,1559063503.280 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-28T17:11:43.281Z,1559063503.281 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-28T17:11:43.338Z,1559063503.338 [HorizontalControl] Loaded
2019-05-28T17:11:43.338Z,1559063503.338 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-28T17:11:43.339Z,1559063503.339 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-28T17:11:43.341Z,1559063503.341 [SpeedControl] Loaded
2019-05-28T17:11:43.341Z,1559063503.341 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-28T17:11:43.342Z,1559063503.342 [LoopControl](DEBUG): Construct LoopControl.
2019-05-28T17:11:43.342Z,1559063503.342 [LoopControl] Loaded
2019-05-28T17:11:43.343Z,1559063503.343 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-28T17:11:43.343Z,1559063503.343 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-28T17:11:43.344Z,1559063503.344 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-28T17:11:43.368Z,1559063503.368 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-28T17:11:43.368Z,1559063503.368 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-28T17:11:43.703Z,1559063503.703 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-28T17:11:43.707Z,1559063503.707 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-28T17:11:43.708Z,1559063503.708 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-28T17:11:43.715Z,1559063503.715 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-28T17:11:43.716Z,1559063503.716 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADE4E0
2019-05-28T17:11:43.716Z,1559063503.716 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 894
2019-05-28T17:11:43.721Z,1559063503.721 [Supervisor](INFO): Main Thread ID is 803
2019-05-28T17:11:43.721Z,1559063503.721 [Supervisor](DEBUG): Running supervisor.
2019-05-28T17:11:43.721Z,1559063503.721 [CommandLine ThreadHandler](INFO): Handler Thread ID is 895
2019-05-28T17:11:43.724Z,1559063503.724 [controlThread ThreadHandler](INFO): Handler Thread ID is 896
2019-05-28T17:11:43.724Z,1559063503.724 [controlThread](DEBUG): Initializing ControlThread
2019-05-28T17:11:43.726Z,1559063503.726 [SBIT](INFO): Initialize SBIT Component.
2019-05-28T17:11:43.726Z,1559063503.726 [SBIT](IMPORTANT): git: 2019-05-21
2019-05-28T17:11:43.727Z,1559063503.727 [SBIT](INFO): git hash: d33b11e57afc4926c4e35bc3081773f5ba5b446b
2019-05-28T17:11:43.727Z,1559063503.727 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-28T17:11:43.728Z,1559063503.728 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-28T17:11:43.729Z,1559063503.729 [SBIT](INFO): Beginning SBIT in 24.000000 seconds.
2019-05-28T17:11:43.730Z,1559063503.730 [IBIT](INFO): Initialize IBIT Component.
2019-05-28T17:11:43.731Z,1559063503.731 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-28T17:11:43.732Z,1559063503.732 [logger ThreadHandler](INFO): Handler Thread ID is 897
2019-05-28T17:11:43.745Z,1559063503.745 [CBIT](DEBUG): Initialized mux pins.
2019-05-28T17:11:43.745Z,1559063503.745 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-05-28T17:11:43.745Z,1559063503.745 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-28T17:11:43.757Z,1559063503.757 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 898
2019-05-28T17:11:43.758Z,1559063503.758 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-05-28T17:11:43.761Z,1559063503.761 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-05-28T17:11:43.763Z,1559063503.763 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 900
2019-05-28T17:11:43.764Z,1559063503.764 [WetLabsBB2FL](INFO): Powering down
2019-05-28T17:11:43.769Z,1559063503.769 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2019-05-28T17:11:43.769Z,1559063503.769 [CBIT](DEBUG): Initializing heartbeat.
2019-05-28T17:11:43.793Z,1559063503.793 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 901
2019-05-28T17:11:43.794Z,1559063503.794 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-28T17:11:43.805Z,1559063503.805 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 902
2019-05-28T17:11:43.817Z,1559063503.817 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 903
2019-05-28T17:11:43.826Z,1559063503.826 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-28T17:11:43.826Z,1559063503.826 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-28T17:11:43.827Z,1559063503.827 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-28T17:11:43.828Z,1559063503.828 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-28T17:11:43.829Z,1559063503.829 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-28T17:11:43.829Z,1559063503.829 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-28T17:11:43.841Z,1559063503.841 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-28T17:11:43.841Z,1559063503.841 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-28T17:11:43.877Z,1559063503.877 [CBIT](DEBUG): Backplane powered.
2019-05-28T17:11:43.881Z,1559063503.881 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-28T17:11:43.881Z,1559063503.881 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-28T17:11:43.882Z,1559063503.882 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-28T17:11:43.882Z,1559063503.882 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-28T17:11:43.883Z,1559063503.883 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-28T17:11:43.883Z,1559063503.883 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-28T17:11:43.884Z,1559063503.884 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-28T17:11:43.885Z,1559063503.885 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-28T17:11:43.896Z,1559063503.896 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-28T17:11:43.905Z,1559063503.905 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-28T17:11:43.906Z,1559063503.906 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-28T17:11:43.907Z,1559063503.907 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-28T17:11:43.907Z,1559063503.907 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-28T17:11:43.942Z,1559063503.942 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T17:11:43.981Z,1559063503.981 [MissionManager](DEBUG):
2019-05-28T17:11:43.982Z,1559063503.982 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-28T17:11:44.032Z,1559063504.032 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-28T17:11:44.045Z,1559063504.045 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-28T17:11:44.047Z,1559063504.047 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T17:11:44.067Z,1559063504.067 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-28T17:11:44.097Z,1559063504.097 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-28T17:11:44.103Z,1559063504.103 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-28T17:11:44.122Z,1559063504.122 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2019-05-28T17:11:44.127Z,1559063504.127 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-28T17:11:44.173Z,1559063504.173 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-28T17:11:44.209Z,1559063504.209 [Radio_Surface](INFO): Powering up
2019-05-28T17:11:44.410Z,1559063504.410 [DVL_micro](INFO): Initializing
2019-05-28T17:11:44.435Z,1559063504.435 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-05-28T17:11:44.435Z,1559063504.435 [DAT](INFO): Powering up
2019-05-28T17:11:44.435Z,1559063504.435 [DAT](DEBUG): Initializing DAT.
2019-05-28T17:11:44.521Z,1559063504.521 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-05-28T17:11:44.549Z,1559063504.549 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-28T17:11:44.561Z,1559063504.561 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-28T17:11:44.563Z,1559063504.563 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-28T17:11:44.573Z,1559063504.573 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-28T17:11:44.574Z,1559063504.574 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-28T17:11:44.585Z,1559063504.585 [MassServo](DEBUG): Initializing MassServo.
2019-05-28T17:11:44.586Z,1559063504.586 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-28T17:11:44.597Z,1559063504.597 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-28T17:11:44.598Z,1559063504.598 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-28T17:11:44.612Z,1559063504.612 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-28T17:11:44.615Z,1559063504.615 [CommandLine](FAULT): Scheduling is paused
2019-05-28T17:11:44.616Z,1559063504.616 [CBIT](INFO): Critical error at 20190528T171143
2019-05-28T17:11:44.616Z,1559063504.616 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-05-28T17:11:47.573Z,1559063507.573 [Aanderaa_O2](INFO): Powering down
2019-05-28T17:11:50.846Z,1559063510.846 [DVL_micro](ERROR): only read 42 of 46 data items
2019-05-28T17:11:50.846Z,1559063510.846 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 2157 135 -56 25 2 3 2 2 2953.6 146.8 609.6 2 14.9 609.6146 609 24 609 2 -3.73 1.82 84.9 -3.0 24.3 0.005 35.0 1489 67
2019-05-28T17:11:59.698Z,1559063519.698 [DAT](INFO): setting local address to 3
2019-05-28T17:12:00.098Z,1559063520.098 [DAT](INFO): set local address to 3
2019-05-28T17:12:08.207Z,1559063528.207 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-28T17:12:08.251Z,1559063528.251 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-28T17:12:11.519Z,1559063531.519 [NAL9602](INFO): Powering up NAL9602
2019-05-28T17:12:19.310Z,1559063539.310 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010328
CHAN A1 (24V): -0.023647
CHAN A2 (12V): -0.005070
CHAN A3 (5V): -0.003046
CHAN B0 (3.3V): -0.001166
CHAN B1 (3.15aV): -0.001016
CHAN B2 (3.15bV): -0.000826
CHAN B3 (GND): -0.000169
OPEN: 0.006963
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-28T17:12:22.427Z,1559063542.427 [NAL9602](INFO): NAL9602 initialized
2019-05-28T17:12:23.281Z,1559063543.281 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:33.838Z,1559063553.838 [DVL_micro](ERROR): No DVL communication! Re-initializing
2019-05-28T17:12:33.838Z,1559063553.838 [DVL_micro] Communications Fault, FailCount= 1
2019-05-28T17:12:33.839Z,1559063553.839 [DVL_micro](ERROR): Communications Fault
2019-05-28T17:12:33.918Z,1559063553.918 [CBIT](ERROR): Communications Fault in component: DVL_micro
2019-05-28T17:12:34.305Z,1559063554.305 [DVL_micro](INFO): uninitialize:Powering down
2019-05-28T17:12:35.154Z,1559063555.154 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-28T17:12:35.154Z,1559063555.154 [DVL_micro] No Fault, FailCount= 1
2019-05-28T17:12:35.456Z,1559063555.456 [DVL_micro](INFO): Initializing
2019-05-28T17:12:35.467Z,1559063555.467 [NAL9602](INFO): SBD MO Status=0, MOMSN=26136, MT Status=0, MTMSN=0
2019-05-28T17:12:35.467Z,1559063555.467 [NAL9602](INFO): No messages in MT queue
2019-05-28T17:12:36.277Z,1559063556.277 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:39.097Z,1559063559.097 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:42.337Z,1559063562.337 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:45.173Z,1559063565.173 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:48.429Z,1559063568.429 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:51.305Z,1559063571.305 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:51.703Z,1559063571.703 [DVL_micro](ERROR): only read 40 of 46 data items
2019-05-28T17:12:51.704Z,1559063571.704 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0663 -111 60 4 2 3 2 2 2139.4 -153.5 435.7 2 354.2 2115.3 435.7 153 435 2 354 2115 435 2 -3.70 1.71 84.6 -30.005 35.0 1489 115
2019-05-28T17:12:54.141Z,1559063574.141 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:12:57.377Z,1559063577.377 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:13:00.201Z,1559063580.201 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:13:02.260Z,1559063582.260 [SBIT](IMPORTANT): SBIT PASSED
2019-05-28T17:13:02.354Z,1559063582.354 [CommandLine](IMPORTANT): got command configSet list
2019-05-28T17:13:02.354Z,1559063582.354 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-28T17:13:02.356Z,1559063582.356 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=1 bool;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup=0 bool;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): BR_Ping1D.verbosity=1 count;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): CBIT.abortDepth=300 meter;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): CBIT.stopDepth=295 meter;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle=1 bool;
2019-05-28T17:13:02.357Z,1559063582.357 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=1 bool;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=1 bool;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): Express linearApproximation DAT.range 20.000000 meter;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): PAR_Licor.adcCal=8.765e-06 microampere_per_count;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): PAR_Licor.darkCount=0 count;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): PAR_Licor.multiplier=190.3 micromole_per_second_per_square_meter_per_microampere;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup=0 bool;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;
2019-05-28T17:13:02.358Z,1559063582.358 [CommandLine](IMPORTANT): VerticalControl.massDefault=-7 millimeter;
2019-05-28T17:13:02.643Z,1559063582.643 [MissionManager](IMPORTANT): Started mission Startup
2019-05-28T17:13:02.643Z,1559063582.643 [Startup] Running Loop=1
2019-05-28T17:13:02.643Z,1559063582.643 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-28T17:13:02.643Z,1559063582.643 [Startup:A.GoToSurface] Running Loop=1
2019-05-28T17:13:02.643Z,1559063582.643 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T17:13:02.644Z,1559063582.644 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T17:13:02.644Z,1559063582.644 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T17:13:02.645Z,1559063582.645 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T17:13:02.645Z,1559063582.645 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T17:13:02.646Z,1559063582.646 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T17:13:02.647Z,1559063582.647 [Startup:StartupSatComms] Running Loop=1
2019-05-28T17:13:02.647Z,1559063582.647 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-28T17:13:02.647Z,1559063582.647 [Startup:StartupSatComms:A] Running Loop=1
2019-05-28T17:13:03.041Z,1559063583.041 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:13:03.066Z,1559063583.066 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-28T17:13:05.461Z,1559063585.461 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:13:05.844Z,1559063585.844 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171301.00,A,3648.16584,N,12147.21662,W,0.019,297.76,280519,,,A*7C
2019-05-28T17:13:05.847Z,1559063585.847 [NAL9602](INFO): GPS fix at 20190528T171301: (36.802764, -121.786944)
2019-05-28T17:13:05.893Z,1559063585.893 [Startup:StartupSatComms:A] Stopped
2019-05-28T17:13:05.894Z,1559063585.894 [Startup:StartupSatComms:B] Running Loop=1
2019-05-28T17:13:06.324Z,1559063586.324 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T17:13:27.002Z,1559063607.002 [NAL9602](INFO): SBD MO Status=1, MOMSN=26137, MT Status=0, MTMSN=0
2019-05-28T17:13:27.053Z,1559063607.053 [NAL9602](INFO): Sent 25 bytes from file Logs/20190528T170323/Courier0007.lzma
2019-05-28T17:13:27.053Z,1559063607.053 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:13:36.158Z,1559063616.158 [NAL9602](INFO): SBD MO Status=1, MOMSN=26138, MT Status=0, MTMSN=0
2019-05-28T17:13:36.217Z,1559063616.217 [NAL9602](INFO): Sent 25 bytes from file Logs/20190528T170323/Courier0010.lzma
2019-05-28T17:13:36.217Z,1559063616.217 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:13:44.967Z,1559063624.967 [NAL9602](INFO): SBD MO Status=1, MOMSN=26139, MT Status=0, MTMSN=0
2019-05-28T17:13:45.017Z,1559063625.017 [NAL9602](INFO): Sent 18 bytes from file Logs/20190528T170323/Courier0013.lzma
2019-05-28T17:13:45.017Z,1559063625.017 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:13:54.845Z,1559063634.845 [NAL9602](INFO): SBD MO Status=1, MOMSN=26140, MT Status=0, MTMSN=0
2019-05-28T17:13:54.893Z,1559063634.893 [NAL9602](INFO): Sent 278 bytes from file Logs/20190528T171132/Courier0000.lzma
2019-05-28T17:13:54.893Z,1559063634.893 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:14:06.017Z,1559063646.017 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-28T17:13:05.9Z
2019-05-28T17:14:06.017Z,1559063646.017 [Startup:StartupSatComms:B] Stopped
2019-05-28T17:14:06.018Z,1559063646.018 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-28T17:14:06.018Z,1559063646.018 [Startup:StartupSatComms] Stopped
2019-05-28T17:14:06.018Z,1559063646.018 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-28T17:14:06.018Z,1559063646.018 [Startup](INFO): Completed Startup
2019-05-28T17:14:06.019Z,1559063646.019 [MissionManager](INFO): Startup is completed.
2019-05-28T17:14:06.019Z,1559063646.019 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-28T17:14:06.019Z,1559063646.019 [Startup] Stopped
2019-05-28T17:14:06.019Z,1559063646.019 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-28T17:14:06.019Z,1559063646.019 [Startup:A.GoToSurface] Stopped
2019-05-28T17:14:06.019Z,1559063646.019 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T17:14:06.480Z,1559063646.480 [MissionManager](IMPORTANT): Started mission Default
2019-05-28T17:14:06.480Z,1559063646.480 [Default] Running Loop=1
2019-05-28T17:14:06.480Z,1559063646.480 [Default](DEBUG): Aggregate::initialize Default
2019-05-28T17:14:06.480Z,1559063646.480 [Default:B.GoToSurface] Running Loop=1
2019-05-28T17:14:06.480Z,1559063646.480 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T17:14:06.526Z,1559063646.526 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T17:14:06.526Z,1559063646.526 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T17:14:06.527Z,1559063646.527 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T17:14:06.528Z,1559063646.528 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T17:14:06.529Z,1559063646.529 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T17:14:06.530Z,1559063646.530 [Default:A.Wait] Running Loop=1
2019-05-28T17:14:06.530Z,1559063646.530 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-28T17:14:11.138Z,1559063651.138 [NAL9602](INFO): SBD MO Status=1, MOMSN=26141, MT Status=0, MTMSN=0
2019-05-28T17:14:11.185Z,1559063651.185 [NAL9602](INFO): Sent 61 bytes from file Logs/20190528T045030/Express0239.lzma
2019-05-28T17:14:11.185Z,1559063651.185 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:14:19.667Z,1559063659.667 [Default:A.Wait](INFO): Done Waiting.
2019-05-28T17:14:19.668Z,1559063659.668 [Default:A.Wait] Stopped
2019-05-28T17:14:19.668Z,1559063659.668 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T17:14:20.190Z,1559063660.190 [Default:CheckIn] Running Loop=1
2019-05-28T17:14:20.190Z,1559063660.190 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T17:14:20.191Z,1559063660.191 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T17:14:20.555Z,1559063660.555 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-28T17:14:21.657Z,1559063661.657 [NAL9602](DEBUG): Fix Requested
2019-05-28T17:14:22.050Z,1559063662.050 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171417.00,A,3648.16405,N,12147.21546,W,0.019,297.76,280519,,,A*71
2019-05-28T17:14:22.052Z,1559063662.052 [NAL9602](INFO): GPS fix at 20190528T171417: (36.802734, -121.786924)
2019-05-28T17:14:22.088Z,1559063662.088 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T17:14:22.088Z,1559063662.088 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T17:14:22.513Z,1559063662.513 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T17:14:45.610Z,1559063685.610 [NAL9602](INFO): SBD MO Status=1, MOMSN=26142, MT Status=0, MTMSN=0
2019-05-28T17:14:45.657Z,1559063685.657 [NAL9602](INFO): Sent 62 bytes from file Logs/20190528T171132/Courier0004.lzma
2019-05-28T17:14:45.657Z,1559063685.657 [NAL9602](INFO): Packets left to send: 0
2019-05-28T17:14:49.245Z,1559063689.245 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-28T17:14:49.245Z,1559063689.245 [DVL_micro] Data Fault, FailCount= 1
2019-05-28T17:14:49.245Z,1559063689.245 [DVL_micro](ERROR): Data Fault
2019-05-28T17:14:49.298Z,1559063689.298 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-28T17:14:49.665Z,1559063689.665 [DVL_micro](INFO): uninitialize:Powering down
2019-05-28T17:14:52.250Z,1559063692.250 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-28T17:14:52.250Z,1559063692.250 [DVL_micro] No Fault, FailCount= 1
2019-05-28T17:14:52.581Z,1559063692.581 [DVL_micro](INFO): Initializing
2019-05-28T17:14:56.622Z,1559063696.622 [NAL9602](INFO): SBD MO Status=1, MOMSN=26143, MT Status=0, MTMSN=0
2019-05-28T17:14:56.669Z,1559063696.669 [NAL9602](INFO): Sent 332 bytes from file Logs/20190528T170323/Express0001.lzma
2019-05-28T17:14:56.669Z,1559063696.669 [NAL9602](INFO): Packets left to send: 3
2019-05-28T17:15:08.642Z,1559063708.642 [NAL9602](INFO): SBD MO Status=1, MOMSN=26144, MT Status=0, MTMSN=0
2019-05-28T17:15:08.693Z,1559063708.693 [NAL9602](INFO): Sent 332 bytes from file Logs/20190528T170323/Express0001.lzma
2019-05-28T17:15:08.693Z,1559063708.693 [NAL9602](INFO): Packets left to send: 2
2019-05-28T17:15:31.838Z,1559063731.838 [NAL9602](INFO): SBD MO Status=2, MOMSN=26145, MT Status=2, MTMSN=0
2019-05-28T17:15:31.838Z,1559063731.838 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-05-28T17:15:41.219Z,1559063741.219 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004835
2019-05-28T17:15:44.761Z,1559063744.761 [DVL_micro](ERROR): only read 37 of 46 data items
2019-05-28T17:15:44.762Z,1559063744.762 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 2160 31 2 3 2 2 2522.558.2 2 -2.2 758.2 2 2528 2 -96 2 -3.74 1 -3.0 24.3 0. 1489 87
2019-05-28T17:15:49.818Z,1559063749.818 [DataOverHttps](INFO): Sending 1139 bytes from file Logs/20190528T170323/Express0001.lzma
2019-05-28T17:15:50.622Z,1559063750.622 [DataOverHttps](INFO): Moved sent file to Logs/20190528T170323/Express0001.lzma.bak
2019-05-28T17:15:50.622Z,1559063750.622 [DataOverHttps](INFO): SBD MOMSN=11205901
2019-05-28T17:15:56.448Z,1559063756.448 [NAL9602](INFO): SBD MO Status=1, MOMSN=26145, MT Status=0, MTMSN=0
2019-05-28T17:15:56.497Z,1559063756.497 [NAL9602](INFO): Sent 332 bytes from file Logs/20190528T170323/Express0001.lzma
2019-05-28T17:15:56.497Z,1559063756.497 [NAL9602](INFO): Packets left to send: 1
2019-05-28T17:15:56.572Z,1559063756.572 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T17:15:56.572Z,1559063756.572 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T17:15:56.572Z,1559063756.572 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T17:16:11.042Z,1559063771.042 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190528T170323/Express0005.lzma
2019-05-28T17:16:11.846Z,1559063771.846 [DataOverHttps](INFO): Moved sent file to Logs/20190528T170323/Express0005.lzma.bak
2019-05-28T17:16:11.847Z,1559063771.847 [DataOverHttps](INFO): SBD MOMSN=11205937
2019-05-28T17:16:19.082Z,1559063779.082 [CommandLine](IMPORTANT): got command show stack
2019-05-28T17:16:19.082Z,1559063779.082 [CommandLine](IMPORTANT): Behavior Stack:
2019-05-28T17:16:19.083Z,1559063779.083 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-05-28T17:16:19.083Z,1559063779.083 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-05-28T17:16:27.231Z,1559063787.231 [NAL9602](INFO): Powering down
2019-05-28T17:17:56.912Z,1559063876.912 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout.
2019-05-28T17:17:56.912Z,1559063876.912 [DVL_micro] Data Fault, FailCount= 1
2019-05-28T17:17:56.912Z,1559063876.912 [DVL_micro](ERROR): Data Fault
2019-05-28T17:17:56.957Z,1559063876.957 [CBIT](ERROR): Data Fault in component: DVL_micro
2019-05-28T17:17:57.397Z,1559063877.397 [DVL_micro](INFO): uninitialize:Powering down
2019-05-28T17:17:58.163Z,1559063878.163 [CBIT](INFO): Clearing failed state for component DVL_micro
2019-05-28T17:17:58.163Z,1559063878.163 [DVL_micro] No Fault, FailCount= 1
2019-05-28T17:17:58.550Z,1559063878.550 [DVL_micro](INFO): Initializing
2019-05-28T17:20:07.440Z,1559064007.440 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-05-28T17:20:07.445Z,1559064007.445 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0.
2019-05-28T17:20:07.446Z,1559064007.446 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2019-05-28T17:20:07.453Z,1559064007.453 [BPC1](INFO): Received data from all battery sticks.
2019-05-28T17:20:08.718Z,1559064008.718 [DataOverHttps](IMPORTANT): SBD MTMSN=20190528T172004
2019-05-28T17:20:15.049Z,1559064015.049 [DataOverHttps](INFO): Received command:restart sys
2019-05-28T17:20:15.085Z,1559064015.085 [CommandLine](IMPORTANT): got command restart system
2019-05-28T17:20:17.155Z,1559064017.155 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.155Z,1559064017.155 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.297Z,1559064017.297 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2019-05-28T17:20:17.297Z,1559064017.297 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.298Z,1559064017.298 [CommandLine](INFO): Join timeout helper Thread ID is 968
2019-05-28T17:20:17.298Z,1559064017.298 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-28T17:20:17.298Z,1559064017.298 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.299Z,1559064017.299 [NavChartDb](INFO): Join timeout helper Thread ID is 969
2019-05-28T17:20:17.329Z,1559064017.329 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.329Z,1559064017.329 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.337Z,1559064017.337 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-28T17:20:17.337Z,1559064017.337 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.337Z,1559064017.337 [Radio_Surface](INFO): Join timeout helper Thread ID is 970
2019-05-28T17:20:17.397Z,1559064017.397 [Radio_Surface](INFO): Powering down
2019-05-28T17:20:17.398Z,1559064017.398 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.398Z,1559064017.398 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.401Z,1559064017.401 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-28T17:20:17.401Z,1559064017.401 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.401Z,1559064017.401 [DataOverHttps](INFO): Join timeout helper Thread ID is 971
2019-05-28T17:20:17.469Z,1559064017.469 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.469Z,1559064017.469 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.501Z,1559064017.501 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-28T17:20:17.502Z,1559064017.502 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.503Z,1559064017.503 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 972
2019-05-28T17:20:17.541Z,1559064017.541 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.541Z,1559064017.541 [WetLabsBB2FL](INFO): Powering down
2019-05-28T17:20:17.542Z,1559064017.542 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.554Z,1559064017.554 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2019-05-28T17:20:17.554Z,1559064017.554 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.554Z,1559064017.554 [CTD_Seabird](INFO): Join timeout helper Thread ID is 973
2019-05-28T17:20:17.881Z,1559064017.881 [CTD_Seabird](INFO): Powering down
2019-05-28T17:20:17.901Z,1559064017.901 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.903Z,1559064017.903 [CTD_Seabird](INFO): Powering down
2019-05-28T17:20:17.917Z,1559064017.917 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.922Z,1559064017.922 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-28T17:20:17.922Z,1559064017.922 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.922Z,1559064017.922 [logger](INFO): Join timeout helper Thread ID is 974
2019-05-28T17:20:17.945Z,1559064017.945 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.947Z,1559064017.947 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.958Z,1559064017.958 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-28T17:20:17.958Z,1559064017.958 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.958Z,1559064017.958 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-28T17:20:17.958Z,1559064017.958 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:17.959Z,1559064017.959 [controlThread](INFO): Join timeout helper Thread ID is 975
2019-05-28T17:20:17.979Z,1559064017.979 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T17:20:17.980Z,1559064017.980 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-28T17:20:17.980Z,1559064017.980 [Aanderaa_O2](INFO): Powering down
2019-05-28T17:20:18.003Z,1559064018.003 [AHRS_M2](INFO): Powering down
2019-05-28T17:20:18.145Z,1559064018.145 [DVL_micro](INFO): uninitialize:Powering down
2019-05-28T17:20:18.146Z,1559064018.146 [NAL9602](INFO): Powering down
2019-05-28T17:20:18.147Z,1559064018.147 [DAT](INFO): Powering down
2019-05-28T17:20:18.266Z,1559064018.266 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-28T17:20:18.267Z,1559064018.267 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-28T17:20:18.267Z,1559064018.267 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-28T17:20:18.267Z,1559064018.267 [MissionManager](INFO): Uninitializing Mission Default
2019-05-28T17:20:18.268Z,1559064018.268 [Default] Stopped
2019-05-28T17:20:18.268Z,1559064018.268 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-28T17:20:18.268Z,1559064018.268 [Default:B.GoToSurface] Stopped
2019-05-28T17:20:18.268Z,1559064018.268 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T17:20:18.268Z,1559064018.268 [Default:CheckIn] Stopped
2019-05-28T17:20:18.268Z,1559064018.268 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T17:20:18.268Z,1559064018.268 [Default:CheckIn:C.Wait] Stopped
2019-05-28T17:20:18.268Z,1559064018.268 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T17:20:18.271Z,1559064018.271 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-28T17:20:18.271Z,1559064018.271 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-28T17:20:18.271Z,1559064018.271 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-28T17:20:18.272Z,1559064018.272 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-28T17:20:18.272Z,1559064018.272 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-28T17:20:18.272Z,1559064018.272 [BuoyancyServo](INFO): Powering down
2019-05-28T17:20:18.285Z,1559064018.285 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-28T17:20:18.285Z,1559064018.285 [ElevatorServo](INFO): Powering down
2019-05-28T17:20:18.286Z,1559064018.286 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-28T17:20:18.286Z,1559064018.286 [MassServo](INFO): Powering down
2019-05-28T17:20:18.287Z,1559064018.287 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-28T17:20:18.287Z,1559064018.287 [RudderServo](INFO): Powering down
2019-05-28T17:20:18.288Z,1559064018.288 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-28T17:20:18.288Z,1559064018.288 [ThrusterServo](INFO): Powering down
2019-05-28T17:20:18.289Z,1559064018.289 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-28T17:20:18.289Z,1559064018.289 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-28T17:20:18.289Z,1559064018.289 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-28T17:20:18.290Z,1559064018.290 [CBIT](DEBUG): Powering off loads.
2019-05-28T17:20:18.301Z,1559064018.301 [CBIT](DEBUG): Disabling WDT.
2019-05-28T17:20:18.313Z,1559064018.313 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-28T17:20:18.314Z,1559064018.314 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.345Z,1559064018.345 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.350Z,1559064018.350 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.416Z,1559064018.416 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.424Z,1559064018.424 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.474Z,1559064018.474 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T17:20:18.543Z,1559064018.543 [logger ThreadHandler](INFO): Thread cancelled.