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.