2018-05-29T16:13:03.797Z,1527610383.797 [Supervisor](DEBUG): Initializing supervisor. 2018-05-29T16:13:03.801Z,1527610383.801 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2018-05-29T16:13:03.802Z,1527610383.802 [SyncHandler](INFO): Protected caller Thread ID is 805 2018-05-29T16:13:03.803Z,1527610383.803 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2018-05-29T16:13:03.804Z,1527610383.804 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2018-05-29T16:13:03.804Z,1527610383.804 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 806 2018-05-29T16:13:03.811Z,1527610383.811 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2018-05-29T16:13:03.826Z,1527610383.826 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2018-05-29T16:13:03.827Z,1527610383.827 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2018-05-29T16:13:03.828Z,1527610383.828 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 807 2018-05-29T16:13:03.830Z,1527610383.830 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2018-05-29T16:13:03.831Z,1527610383.831 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2018-05-29T16:13:03.832Z,1527610383.832 [logger ThreadHandler](INFO): Protected caller Thread ID is 808 2018-05-29T16:13:03.835Z,1527610383.835 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2018-05-29T16:13:03.835Z,1527610383.835 [Supervisor](INFO): Looking for Config files in directory: Config/ 2018-05-29T16:13:03.840Z,1527610383.840 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2018-05-29T16:13:03.964Z,1527610383.964 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2018-05-29T16:13:03.965Z,1527610383.965 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2018-05-29T16:13:04.093Z,1527610384.093 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2018-05-29T16:13:04.095Z,1527610384.095 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2018-05-29T16:13:04.334Z,1527610384.334 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2018-05-29T16:13:04.336Z,1527610384.336 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2018-05-29T16:13:04.682Z,1527610384.682 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2018-05-29T16:13:04.684Z,1527610384.684 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2018-05-29T16:13:05.063Z,1527610385.063 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2018-05-29T16:13:05.063Z,1527610385.063 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2018-05-29T16:13:05.564Z,1527610385.564 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2018-05-29T16:13:05.566Z,1527610385.566 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2018-05-29T16:13:06.047Z,1527610386.047 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2018-05-29T16:13:06.048Z,1527610386.048 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2018-05-29T16:13:06.557Z,1527610386.557 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2018-05-29T16:13:06.558Z,1527610386.558 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2018-05-29T16:13:06.665Z,1527610386.665 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2018-05-29T16:13:07.023Z,1527610387.023 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2018-05-29T16:13:07.025Z,1527610387.025 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2018-05-29T16:13:07.184Z,1527610387.184 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2018-05-29T16:13:07.185Z,1527610387.185 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2018-05-29T16:13:07.432Z,1527610387.432 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2018-05-29T16:13:07.434Z,1527610387.434 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2018-05-29T16:13:07.682Z,1527610387.682 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2018-05-29T16:13:07.683Z,1527610387.683 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2018-05-29T16:13:07.815Z,1527610387.815 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2018-05-29T16:13:07.816Z,1527610387.816 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2018-05-29T16:13:07.976Z,1527610387.976 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2018-05-29T16:13:07.978Z,1527610387.978 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-INSERTREALNAME/ 2018-05-29T16:13:07.978Z,1527610387.978 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2018-05-29T16:13:07.981Z,1527610387.981 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2018-05-29T16:13:08.196Z,1527610388.196 [InternalSim] Loaded 2018-05-29T16:13:08.197Z,1527610388.197 [ComponentRegistry](DEBUG): SyncComponent "InternalSim" handled in the control thread. 2018-05-29T16:13:08.197Z,1527610388.197 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2018-05-29T16:13:08.199Z,1527610388.199 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2018-05-29T16:13:08.223Z,1527610388.223 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2018-05-29T16:13:08.224Z,1527610388.224 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2018-05-29T16:13:08.283Z,1527610388.283 [DepthRateCalculator] Loaded 2018-05-29T16:13:08.283Z,1527610388.283 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2018-05-29T16:13:08.289Z,1527610388.289 [PitchRateCalculator] Loaded 2018-05-29T16:13:08.289Z,1527610388.289 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2018-05-29T16:13:08.304Z,1527610388.304 [SpeedCalculator] Loaded 2018-05-29T16:13:08.304Z,1527610388.304 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2018-05-29T16:13:08.327Z,1527610388.327 [TempGradientCalculator] Loaded 2018-05-29T16:13:08.327Z,1527610388.327 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2018-05-29T16:13:08.342Z,1527610388.342 [VerticalTemperatureHomogeneityIndexCalculator] Loaded 2018-05-29T16:13:08.343Z,1527610388.343 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread. 2018-05-29T16:13:08.348Z,1527610388.348 [YawRateCalculator] Loaded 2018-05-29T16:13:08.348Z,1527610388.348 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2018-05-29T16:13:08.391Z,1527610388.391 [ElevatorOffsetCalculator] Loaded 2018-05-29T16:13:08.391Z,1527610388.391 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2018-05-29T16:13:08.392Z,1527610388.392 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2018-05-29T16:13:08.392Z,1527610388.392 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2018-05-29T16:13:08.431Z,1527610388.431 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2018-05-29T16:13:08.432Z,1527610388.432 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2018-05-29T16:13:09.037Z,1527610389.037 [AHRS_sp3003D] Loaded 2018-05-29T16:13:09.038Z,1527610389.038 [ComponentRegistry](DEBUG): SyncComponent "AHRS_sp3003D" handled in the control thread. 2018-05-29T16:13:09.039Z,1527610389.039 [AHRS_M2](CRITICAL): Could not find element AHRS_M2.loadControl 2018-05-29T16:13:09.040Z,1527610389.040 [AHRS_M2](CRITICAL): Could not find element AHRS_M2.uart 2018-05-29T16:13:09.040Z,1527610389.040 [AHRS_M2](CRITICAL): Could not find element AHRS_M2.baud 2018-05-29T16:13:09.124Z,1527610389.124 [AHRS_M2] Loaded 2018-05-29T16:13:09.124Z,1527610389.124 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2018-05-29T16:13:09.287Z,1527610389.287 [DataOverHttps] Loaded 2018-05-29T16:13:09.287Z,1527610389.287 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread. 2018-05-29T16:13:09.300Z,1527610389.300 [Depth_Keller] Loaded 2018-05-29T16:13:09.300Z,1527610389.300 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2018-05-29T16:13:09.304Z,1527610389.304 [DropWeight] Loaded 2018-05-29T16:13:09.305Z,1527610389.305 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2018-05-29T16:13:09.475Z,1527610389.475 [DVL_micro] Loaded 2018-05-29T16:13:09.476Z,1527610389.476 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2018-05-29T16:13:09.476Z,1527610389.476 [Module Loader](CRITICAL): Could not find element GobyModem.loadAtStartup 2018-05-29T16:13:09.636Z,1527610389.636 [NAL9602] Loaded 2018-05-29T16:13:09.636Z,1527610389.636 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2018-05-29T16:13:09.653Z,1527610389.653 [Onboard] Loaded 2018-05-29T16:13:09.654Z,1527610389.654 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2018-05-29T16:13:09.676Z,1527610389.676 [Radio_Surface] Loaded 2018-05-29T16:13:09.677Z,1527610389.677 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2018-05-29T16:13:09.679Z,1527610389.679 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407B74E0 2018-05-29T16:13:09.679Z,1527610389.679 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 854 2018-05-29T16:13:09.680Z,1527610389.680 [Module Loader](CRITICAL): Could not find element RDI_Pathfinder.loadAtStartup 2018-05-29T16:13:09.827Z,1527610389.827 [DAT] Loaded 2018-05-29T16:13:09.827Z,1527610389.827 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2018-05-29T16:13:09.833Z,1527610389.833 [SCPI] Loaded 2018-05-29T16:13:09.833Z,1527610389.833 [ComponentRegistry](DEBUG): SyncComponent "SCPI" handled in the control thread. 2018-05-29T16:13:09.834Z,1527610389.834 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2018-05-29T16:13:09.835Z,1527610389.835 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2018-05-29T16:13:09.992Z,1527610389.992 [SBIT](DEBUG): Construct Startup Built In Test. 2018-05-29T16:13:10.026Z,1527610390.026 [SBIT] Loaded 2018-05-29T16:13:10.027Z,1527610390.027 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2018-05-29T16:13:10.027Z,1527610390.027 [IBIT](DEBUG): Construct Initiated Built In Test. 2018-05-29T16:13:10.042Z,1527610390.042 [IBIT] Loaded 2018-05-29T16:13:10.042Z,1527610390.042 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2018-05-29T16:13:10.045Z,1527610390.045 [CBIT](DEBUG): Construct Continuous Built In Test. 2018-05-29T16:13:10.203Z,1527610390.203 [CBIT] Loaded 2018-05-29T16:13:10.204Z,1527610390.204 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2018-05-29T16:13:10.205Z,1527610390.205 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2018-05-29T16:13:10.206Z,1527610390.206 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2018-05-29T16:13:10.472Z,1527610390.472 [CTD_NeilBrown] Loaded 2018-05-29T16:13:10.472Z,1527610390.472 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2018-05-29T16:13:10.473Z,1527610390.473 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408774E0 2018-05-29T16:13:10.474Z,1527610390.474 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 855 2018-05-29T16:13:10.500Z,1527610390.500 [PAR_Licor] Loaded 2018-05-29T16:13:10.501Z,1527610390.501 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2018-05-29T16:13:10.550Z,1527610390.550 [WetLabsBB2FL] Loaded 2018-05-29T16:13:10.550Z,1527610390.550 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2018-05-29T16:13:10.552Z,1527610390.552 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408A74E0 2018-05-29T16:13:10.553Z,1527610390.553 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 856 2018-05-29T16:13:10.554Z,1527610390.554 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2018-05-29T16:13:10.557Z,1527610390.557 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2018-05-29T16:13:10.866Z,1527610390.866 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2018-05-29T16:13:10.867Z,1527610390.867 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2018-05-29T16:13:10.958Z,1527610390.958 [VerticalControl](DEBUG): Construct VerticalControl. 2018-05-29T16:13:11.058Z,1527610391.058 [VerticalControl] Loaded 2018-05-29T16:13:11.058Z,1527610391.058 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2018-05-29T16:13:11.059Z,1527610391.059 [HorizontalControl](DEBUG): Construct HorizontalControl. 2018-05-29T16:13:11.128Z,1527610391.128 [HorizontalControl] Loaded 2018-05-29T16:13:11.128Z,1527610391.128 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2018-05-29T16:13:11.129Z,1527610391.129 [SpeedControl](DEBUG): Construct SpeedControl. 2018-05-29T16:13:11.130Z,1527610391.130 [SpeedControl] Loaded 2018-05-29T16:13:11.130Z,1527610391.130 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2018-05-29T16:13:11.131Z,1527610391.131 [BackSeatDriver](DEBUG): Construct BackSeatDriver. 2018-05-29T16:13:11.133Z,1527610391.133 [BackSeatDriver] Loaded 2018-05-29T16:13:11.133Z,1527610391.133 [ComponentRegistry](DEBUG): SyncComponent "BackSeatDriver" handled in the control thread. 2018-05-29T16:13:11.134Z,1527610391.134 [LoopControl](DEBUG): Construct LoopControl. 2018-05-29T16:13:11.135Z,1527610391.135 [LoopControl] Loaded 2018-05-29T16:13:11.135Z,1527610391.135 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2018-05-29T16:13:11.135Z,1527610391.135 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2018-05-29T16:13:11.136Z,1527610391.136 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2018-05-29T16:13:11.259Z,1527610391.259 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC 2018-05-29T16:13:11.259Z,1527610391.259 [StratificationFrontDetector](DEBUG): (re)initializing 2018-05-29T16:13:11.260Z,1527610391.260 [StratificationFrontDetector] Loaded 2018-05-29T16:13:11.260Z,1527610391.260 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread. 2018-05-29T16:13:11.260Z,1527610391.260 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2018-05-29T16:13:11.261Z,1527610391.261 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2018-05-29T16:13:11.385Z,1527610391.385 [BuoyancyServo] Loaded 2018-05-29T16:13:11.386Z,1527610391.386 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2018-05-29T16:13:11.407Z,1527610391.407 [ElevatorServo] Loaded 2018-05-29T16:13:11.407Z,1527610391.407 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2018-05-29T16:13:11.418Z,1527610391.418 [MassServo] Loaded 2018-05-29T16:13:11.418Z,1527610391.418 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2018-05-29T16:13:11.431Z,1527610391.431 [RudderServo] Loaded 2018-05-29T16:13:11.432Z,1527610391.432 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2018-05-29T16:13:11.442Z,1527610391.442 [ThrusterServo] Loaded 2018-05-29T16:13:11.442Z,1527610391.442 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2018-05-29T16:13:11.442Z,1527610391.442 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2018-05-29T16:13:11.443Z,1527610391.443 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2018-05-29T16:13:11.561Z,1527610391.561 [DeadReckonUsingMultipleVelocitySources] Loaded 2018-05-29T16:13:11.561Z,1527610391.561 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2018-05-29T16:13:11.620Z,1527610391.620 [DeadReckonUsingSpeedCalculator] Loaded 2018-05-29T16:13:11.620Z,1527610391.620 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread. 2018-05-29T16:13:11.638Z,1527610391.638 [NavChart] Loaded 2018-05-29T16:13:11.639Z,1527610391.639 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2018-05-29T16:13:11.643Z,1527610391.643 [UniversalFixResidualReporter] Loaded 2018-05-29T16:13:11.643Z,1527610391.643 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2018-05-29T16:13:11.643Z,1527610391.643 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2018-05-29T16:13:11.662Z,1527610391.662 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2018-05-29T16:13:11.663Z,1527610391.663 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2018-05-29T16:13:11.670Z,1527610391.670 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2018-05-29T16:13:11.671Z,1527610391.671 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A004E0 2018-05-29T16:13:11.671Z,1527610391.671 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 857 2018-05-29T16:13:11.676Z,1527610391.676 [Supervisor](INFO): Main Thread ID is 800 2018-05-29T16:13:11.676Z,1527610391.676 [Supervisor](DEBUG): Running supervisor. 2018-05-29T16:13:11.677Z,1527610391.677 [CommandLine ThreadHandler](INFO): Handler Thread ID is 858 2018-05-29T16:13:11.697Z,1527610391.697 [controlThread ThreadHandler](INFO): Handler Thread ID is 859 2018-05-29T16:13:11.698Z,1527610391.698 [controlThread](DEBUG): Initializing ControlThread 2018-05-29T16:13:11.699Z,1527610391.699 [InternalSim](DEBUG): InternalSim initializing... 2018-05-29T16:13:11.705Z,1527610391.705 [InternalSim](DEBUG): oceanModelVarCount=0 2018-05-29T16:13:11.723Z,1527610391.723 [logger ThreadHandler](INFO): Handler Thread ID is 860 2018-05-29T16:13:11.747Z,1527610391.747 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 861 2018-05-29T16:13:11.767Z,1527610391.767 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 862 2018-05-29T16:13:11.768Z,1527610391.768 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 863 2018-05-29T16:13:11.783Z,1527610391.783 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 864 2018-05-29T16:13:11.880Z,1527610391.880 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-05-29T16:13:11.881Z,1527610391.881 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2018-05-29T16:13:11.881Z,1527610391.881 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2018-05-29T16:13:11.882Z,1527610391.882 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2018-05-29T16:13:11.882Z,1527610391.882 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing 2018-05-29T16:13:11.883Z,1527610391.883 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2018-05-29T16:13:11.884Z,1527610391.884 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2018-05-29T16:13:11.894Z,1527610391.894 [SBIT](INFO): Initialize SBIT Component. 2018-05-29T16:13:11.898Z,1527610391.898 [SBIT](IMPORTANT): git: 2018-03-26-67-g62fca4c 2018-05-29T16:13:11.898Z,1527610391.898 [SBIT](INFO): git hash: 62fca4cdfc31339340ec3e9fddabc998ec27ce75 2018-05-29T16:13:11.900Z,1527610391.900 [SBIT](INFO): Kernel Reporting Different Release From Configuration. Kernel Expected: 2.6.32-45-generic-pae Kernel Reported: 2.6.27.8 2018-05-29T16:13:11.900Z,1527610391.900 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #102-Ubuntu SMP Wed Jan 2 22:10:16 UTC 2013 Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 2018-05-29T16:13:11.901Z,1527610391.901 [SBIT](INFO): Beginning SBIT in 20.000000 seconds. 2018-05-29T16:13:11.902Z,1527610391.902 [IBIT](INFO): Initialize IBIT Component. 2018-05-29T16:13:11.907Z,1527610391.907 [CBIT](DEBUG): Initialize CBIT Component. 2018-05-29T16:13:11.907Z,1527610391.907 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2018-05-29T16:13:11.907Z,1527610391.907 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2018-05-29T16:13:11.908Z,1527610391.908 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2018-05-29T16:13:11.916Z,1527610391.916 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2018-05-29T16:13:11.916Z,1527610391.916 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2018-05-29T16:13:11.918Z,1527610391.918 [BackSeatDriver](DEBUG): Initialize BackSeatDriver Component. 2018-05-29T16:13:12.141Z,1527610392.141 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2018-05-29T16:13:12.142Z,1527610392.142 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2018-05-29T16:13:12.142Z,1527610392.142 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2018-05-29T16:13:12.142Z,1527610392.142 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2018-05-29T16:13:12.142Z,1527610392.142 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2018-05-29T16:13:12.142Z,1527610392.142 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2018-05-29T16:13:12.143Z,1527610392.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2018-05-29T16:13:12.143Z,1527610392.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2018-05-29T16:13:12.143Z,1527610392.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2018-05-29T16:13:12.143Z,1527610392.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2018-05-29T16:13:12.143Z,1527610392.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2018-05-29T16:13:12.144Z,1527610392.144 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2018-05-29T16:13:12.144Z,1527610392.144 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2018-05-29T16:13:12.144Z,1527610392.144 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2018-05-29T16:13:12.144Z,1527610392.144 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2018-05-29T16:13:12.144Z,1527610392.144 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2018-05-29T16:13:12.564Z,1527610392.564 [LoopControl](DEBUG): Initialize LoopControlComponent. 2018-05-29T16:13:12.565Z,1527610392.565 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component. 2018-05-29T16:13:12.566Z,1527610392.566 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s. 2018-05-29T16:13:12.566Z,1527610392.566 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s. 2018-05-29T16:13:12.575Z,1527610392.575 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component. 2018-05-29T16:13:12.575Z,1527610392.575 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s. 2018-05-29T16:13:12.575Z,1527610392.575 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s. 2018-05-29T16:13:12.576Z,1527610392.576 [NavChart](DEBUG): Initialize NavChart Navigation. 2018-05-29T16:13:12.576Z,1527610392.576 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2018-05-29T16:13:12.577Z,1527610392.577 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2018-05-29T16:13:12.604Z,1527610392.604 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2018-05-29T16:13:12.635Z,1527610392.635 [MissionManager](DEBUG): 2018-05-29T16:13:12.635Z,1527610392.635 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2018-05-29T16:13:12.719Z,1527610392.719 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2018-05-29T16:13:12.720Z,1527610392.720 [Default:A.Wait](DEBUG): Construct Wait. 2018-05-29T16:13:12.722Z,1527610392.722 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2018-05-29T16:13:12.745Z,1527610392.745 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2018-05-29T16:13:12.771Z,1527610392.771 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2018-05-29T16:13:12.777Z,1527610392.777 [Default:E.Execute](DEBUG): Construct Execute. 2018-05-29T16:13:12.793Z,1527610392.793 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn 300 Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2018-05-29T16:13:12.798Z,1527610392.798 [controlThread](DEBUG): Component order: CycleStarter,InternalSim,AHRS_sp3003D,AHRS_M2,DataOverHttps,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,SCPI,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,BackSeatDriver,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-05-29T16:13:12.898Z,1527610392.898 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2018-05-29T16:13:12.958Z,1527610392.958 [DVL_micro](INFO): Initializing 2018-05-29T16:13:13.147Z,1527610393.147 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:13.154Z,1527610393.154 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:13.287Z,1527610393.287 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2018-05-29T16:13:13.298Z,1527610393.298 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2018-05-29T16:13:13.311Z,1527610393.311 [MassServo](DEBUG): Initializing MassServo. 2018-05-29T16:13:13.322Z,1527610393.322 [RudderServo](DEBUG): Initializing RudderServo. 2018-05-29T16:13:13.335Z,1527610393.335 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2018-05-29T16:13:13.375Z,1527610393.375 [CommandLine](FAULT): Scheduling is paused 2018-05-29T16:13:13.376Z,1527610393.376 [CBIT](INFO): Critical error at 20180529T161309 2018-05-29T16:13:13.376Z,1527610393.376 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2018-05-29T16:13:13.520Z,1527610393.520 [AHRS_M2](DEBUG): orientation 1 set drop 2018-05-29T16:13:13.600Z,1527610393.600 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:13.601Z,1527610393.601 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.216Z,1527610402.216 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:22.223Z,1527610402.223 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.224Z,1527610402.224 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.482Z,1527610402.482 [AHRS_M2](DEBUG): chan0Format 2 set drop 2018-05-29T16:13:22.483Z,1527610402.483 [AHRS_M2](FAULT): Failed to initialize 2018-05-29T16:13:22.483Z,1527610402.483 [AHRS_M2] Communications Fault, FailCount= 1 2018-05-29T16:13:22.483Z,1527610402.483 [AHRS_M2](ERROR): Communications Fault 2018-05-29T16:13:22.509Z,1527610402.509 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:22.532Z,1527610402.532 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.533Z,1527610402.533 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.569Z,1527610402.569 [CBIT](ERROR): Communications Fault in component: AHRS_M2 2018-05-29T16:13:22.570Z,1527610402.570 [CBIT](CRITICAL): Communications Fault in component: AHRS_M2 2018-05-29T16:13:22.678Z,1527610402.678 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:22.685Z,1527610402.685 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.686Z,1527610402.686 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet. 2018-05-29T16:13:22.741Z,1527610402.741 [CBIT](INFO): Critical error at 20180529T161322 2018-05-29T16:13:23.080Z,1527610403.080 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003978 2018-05-29T16:13:23.083Z,1527610403.083 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:23.478Z,1527610403.478 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:23.880Z,1527610403.880 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:24.278Z,1527610404.278 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:24.679Z,1527610404.679 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:25.078Z,1527610405.078 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:25.478Z,1527610405.478 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:25.887Z,1527610405.887 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:26.278Z,1527610406.278 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:26.678Z,1527610406.678 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:27.078Z,1527610407.078 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:27.478Z,1527610407.478 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:27.877Z,1527610407.877 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:28.278Z,1527610408.278 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:28.491Z,1527610408.491 [CommandLine](IMPORTANT): got command quit 2018-05-29T16:13:28.678Z,1527610408.678 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:29.078Z,1527610409.078 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:29.478Z,1527610409.478 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:29.497Z,1527610409.497 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:29.497Z,1527610409.497 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:29.542Z,1527610409.542 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-05-29T16:13:29.543Z,1527610409.543 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:29.543Z,1527610409.543 [CommandLine](INFO): Join timeout helper Thread ID is 867 2018-05-29T16:13:29.559Z,1527610409.559 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-05-29T16:13:29.559Z,1527610409.559 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:29.559Z,1527610409.559 [NavChartDb](INFO): Join timeout helper Thread ID is 868 2018-05-29T16:13:29.878Z,1527610409.878 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:30.206Z,1527610410.206 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:30.218Z,1527610410.218 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.222Z,1527610410.222 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-05-29T16:13:30.223Z,1527610410.223 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.223Z,1527610410.223 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 869 2018-05-29T16:13:30.277Z,1527610410.277 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:30.423Z,1527610410.423 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:30.423Z,1527610410.423 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.426Z,1527610410.426 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2018-05-29T16:13:30.426Z,1527610410.426 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.427Z,1527610410.427 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 870 2018-05-29T16:13:30.579Z,1527610410.579 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:30.579Z,1527610410.579 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.586Z,1527610410.586 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-05-29T16:13:30.586Z,1527610410.586 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.587Z,1527610410.587 [Radio_Surface](INFO): Join timeout helper Thread ID is 871 2018-05-29T16:13:30.677Z,1527610410.677 [DAT](ERROR): Could not read simulated DAT measurements from SimSlate. 2018-05-29T16:13:30.775Z,1527610410.775 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:30.775Z,1527610410.775 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.779Z,1527610410.779 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-05-29T16:13:30.779Z,1527610410.779 [logger ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.780Z,1527610410.780 [logger](INFO): Join timeout helper Thread ID is 872 2018-05-29T16:13:30.803Z,1527610410.803 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:30.803Z,1527610410.803 [logger ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.819Z,1527610410.819 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-05-29T16:13:30.819Z,1527610410.819 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.819Z,1527610410.819 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-05-29T16:13:30.819Z,1527610410.819 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:30.820Z,1527610410.820 [controlThread](INFO): Join timeout helper Thread ID is 873 2018-05-29T16:13:31.063Z,1527610411.063 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-05-29T16:13:31.063Z,1527610411.063 [controlThread](DEBUG): Uninitializing ControlThread 2018-05-29T16:13:31.064Z,1527610411.064 [DVL_micro](INFO): uninitialize:Powering down 2018-05-29T16:13:31.065Z,1527610411.065 [NAL9602](INFO): Powering down 2018-05-29T16:13:31.066Z,1527610411.066 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-05-29T16:13:31.067Z,1527610411.067 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-05-29T16:13:31.068Z,1527610411.068 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-05-29T16:13:31.068Z,1527610411.068 [MissionManager](INFO): Uninitializing Mission Default 2018-05-29T16:13:31.071Z,1527610411.071 [MissionManager](INFO): Uninitializing Mission Startup 2018-05-29T16:13:31.072Z,1527610411.072 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-05-29T16:13:31.072Z,1527610411.072 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-05-29T16:13:31.072Z,1527610411.072 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-05-29T16:13:31.073Z,1527610411.073 [BackSeatDriver](DEBUG): Uninitialize BackSeatDriver Component. 2018-05-29T16:13:31.073Z,1527610411.073 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-05-29T16:13:31.073Z,1527610411.073 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-05-29T16:13:31.074Z,1527610411.074 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-05-29T16:13:31.074Z,1527610411.074 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-05-29T16:13:31.074Z,1527610411.074 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-05-29T16:13:31.074Z,1527610411.074 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-05-29T16:13:31.075Z,1527610411.075 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-05-29T16:13:31.075Z,1527610411.075 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-05-29T16:13:31.075Z,1527610411.075 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-05-29T16:13:31.076Z,1527610411.076 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:31.109Z,1527610411.109 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:31.148Z,1527610411.148 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:31.150Z,1527610411.150 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:31.191Z,1527610411.191 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-05-29T16:13:31.227Z,1527610411.227 [logger ThreadHandler](INFO): Thread cancelled.