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.