2018-12-18T16:48:50.507Z,1545151730.507 [Supervisor](DEBUG): Initializing supervisor.
2018-12-18T16:48:50.510Z,1545151730.510 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-12-18T16:48:50.511Z,1545151730.511 [SyncHandler](INFO): Protected caller Thread ID is 7921
2018-12-18T16:48:50.511Z,1545151730.511 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-12-18T16:48:50.512Z,1545151730.512 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-12-18T16:48:50.512Z,1545151730.512 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7922
2018-12-18T16:48:50.516Z,1545151730.516 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-12-18T16:48:50.529Z,1545151730.529 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-12-18T16:48:50.530Z,1545151730.530 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-12-18T16:48:50.530Z,1545151730.530 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7923
2018-12-18T16:48:50.531Z,1545151730.531 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-12-18T16:48:50.532Z,1545151730.532 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-12-18T16:48:50.532Z,1545151730.532 [logger ThreadHandler](INFO): Protected caller Thread ID is 7924
2018-12-18T16:48:50.534Z,1545151730.534 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-12-18T16:48:50.534Z,1545151730.534 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-12-18T16:48:50.536Z,1545151730.536 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-12-18T16:48:50.843Z,1545151730.843 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-12-18T16:48:50.843Z,1545151730.843 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-12-18T16:48:51.029Z,1545151731.029 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-12-18T16:48:51.030Z,1545151731.030 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-12-18T16:48:51.311Z,1545151731.311 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-12-18T16:48:51.312Z,1545151731.312 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-12-18T16:48:51.451Z,1545151731.451 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-12-18T16:48:51.452Z,1545151731.452 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-12-18T16:48:51.549Z,1545151731.549 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-12-18T16:48:51.549Z,1545151731.549 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-12-18T16:48:52.006Z,1545151732.006 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-12-18T16:48:52.007Z,1545151732.007 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-12-18T16:48:52.448Z,1545151732.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-12-18T16:48:52.449Z,1545151732.449 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-12-18T16:48:52.892Z,1545151732.892 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-12-18T16:48:52.893Z,1545151732.893 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-12-18T16:48:52.993Z,1545151732.993 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-12-18T16:48:52.994Z,1545151732.994 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-12-18T16:48:53.087Z,1545151733.087 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-12-18T16:48:53.087Z,1545151733.087 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-12-18T16:48:53.295Z,1545151733.295 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-12-18T16:48:53.295Z,1545151733.295 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-12-18T16:48:53.491Z,1545151733.491 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-12-18T16:48:53.492Z,1545151733.492 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-12-18T16:48:53.873Z,1545151733.873 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-12-18T16:48:53.874Z,1545151733.874 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-12-18T16:48:54.014Z,1545151734.014 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-12-18T16:48:54.015Z,1545151734.015 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-12-18T16:48:54.096Z,1545151734.096 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-12-18T16:48:54.097Z,1545151734.097 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-12-18T16:48:54.198Z,1545151734.198 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-12-18T16:48:54.313Z,1545151734.313 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-12-18T16:48:54.484Z,1545151734.484 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-12-18T16:48:54.678Z,1545151734.678 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-12-18T16:48:54.846Z,1545151734.846 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-12-18T16:48:55.143Z,1545151735.143 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-12-18T16:48:55.218Z,1545151735.218 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-12-18T16:48:55.439Z,1545151735.439 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-12-18T16:48:55.440Z,1545151735.440 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-12-18T16:48:55.521Z,1545151735.521 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-12-18T16:48:55.609Z,1545151735.609 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-12-18T16:48:55.706Z,1545151735.706 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-12-18T16:48:55.830Z,1545151735.830 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-12-18T16:48:55.844Z,1545151735.844 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-12-18T16:48:56.080Z,1545151736.080 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-12-18T16:48:56.080Z,1545151736.080 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-12-18T16:48:56.123Z,1545151736.123 [DepthRateCalculator] Loaded
2018-12-18T16:48:56.124Z,1545151736.124 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-12-18T16:48:56.129Z,1545151736.129 [PitchRateCalculator] Loaded
2018-12-18T16:48:56.130Z,1545151736.130 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-12-18T16:48:56.145Z,1545151736.145 [SpeedCalculator] Loaded
2018-12-18T16:48:56.145Z,1545151736.145 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-12-18T16:48:56.165Z,1545151736.165 [TempGradientCalculator] Loaded
2018-12-18T16:48:56.166Z,1545151736.166 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-12-18T16:48:56.171Z,1545151736.171 [YawRateCalculator] Loaded
2018-12-18T16:48:56.171Z,1545151736.171 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-12-18T16:48:56.210Z,1545151736.210 [ElevatorOffsetCalculator] Loaded
2018-12-18T16:48:56.211Z,1545151736.211 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-12-18T16:48:56.211Z,1545151736.211 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-12-18T16:48:56.211Z,1545151736.211 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-12-18T16:48:56.278Z,1545151736.278 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-12-18T16:48:56.278Z,1545151736.278 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-12-18T16:48:56.379Z,1545151736.379 [BuoyancyServo] Loaded
2018-12-18T16:48:56.379Z,1545151736.379 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-12-18T16:48:56.394Z,1545151736.394 [ElevatorServo] Loaded
2018-12-18T16:48:56.394Z,1545151736.394 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-12-18T16:48:56.408Z,1545151736.408 [MassServo] Loaded
2018-12-18T16:48:56.408Z,1545151736.408 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-12-18T16:48:56.422Z,1545151736.422 [RudderServo] Loaded
2018-12-18T16:48:56.423Z,1545151736.423 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-12-18T16:48:56.436Z,1545151736.436 [ThrusterServo] Loaded
2018-12-18T16:48:56.436Z,1545151736.436 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-12-18T16:48:56.437Z,1545151736.437 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-12-18T16:48:56.437Z,1545151736.437 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-12-18T16:48:56.451Z,1545151736.451 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-12-18T16:48:56.451Z,1545151736.451 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-12-18T16:48:56.551Z,1545151736.551 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-12-18T16:48:56.552Z,1545151736.552 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-12-18T16:48:56.980Z,1545151736.980 [DataOverHttps] Loaded
2018-12-18T16:48:56.980Z,1545151736.980 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-12-18T16:48:56.993Z,1545151736.993 [Depth_Keller] Loaded
2018-12-18T16:48:56.993Z,1545151736.993 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-12-18T16:48:56.998Z,1545151736.998 [DropWeight] Loaded
2018-12-18T16:48:56.998Z,1545151736.998 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-12-18T16:48:57.094Z,1545151737.094 [NAL9602] Loaded
2018-12-18T16:48:57.094Z,1545151737.094 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-12-18T16:48:57.109Z,1545151737.109 [Onboard] Loaded
2018-12-18T16:48:57.110Z,1545151737.110 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-12-18T16:48:57.119Z,1545151737.119 [Radio_Surface] Loaded
2018-12-18T16:48:57.120Z,1545151737.120 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-12-18T16:48:57.121Z,1545151737.121 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-12-18T16:48:57.121Z,1545151737.121 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 8008
2018-12-18T16:48:57.299Z,1545151737.299 [PNI_TCM] Loaded
2018-12-18T16:48:57.300Z,1545151737.300 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-12-18T16:48:57.300Z,1545151737.300 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-12-18T16:48:57.301Z,1545151737.301 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-12-18T16:48:57.435Z,1545151737.435 [SBIT](DEBUG): Construct Startup Built In Test.
2018-12-18T16:48:57.456Z,1545151737.456 [SBIT] Loaded
2018-12-18T16:48:57.456Z,1545151737.456 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-12-18T16:48:57.457Z,1545151737.457 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-12-18T16:48:57.468Z,1545151737.468 [IBIT] Loaded
2018-12-18T16:48:57.469Z,1545151737.469 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-12-18T16:48:57.472Z,1545151737.472 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-12-18T16:48:57.842Z,1545151737.842 [CBIT] Loaded
2018-12-18T16:48:57.842Z,1545151737.842 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-12-18T16:48:57.842Z,1545151737.842 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-12-18T16:48:57.843Z,1545151737.843 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-12-18T16:48:58.085Z,1545151738.085 [CTD_NeilBrown] Loaded
2018-12-18T16:48:58.085Z,1545151738.085 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-12-18T16:48:58.086Z,1545151738.086 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4096F4E0
2018-12-18T16:48:58.087Z,1545151738.087 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 8009
2018-12-18T16:48:58.166Z,1545151738.166 [CTD_Seabird] Loaded
2018-12-18T16:48:58.166Z,1545151738.166 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-12-18T16:48:58.167Z,1545151738.167 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4099F4E0
2018-12-18T16:48:58.167Z,1545151738.167 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 8010
2018-12-18T16:48:58.181Z,1545151738.181 [PAR_Licor] Loaded
2018-12-18T16:48:58.182Z,1545151738.182 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-12-18T16:48:58.229Z,1545151738.229 [WetLabsBB2FL] Loaded
2018-12-18T16:48:58.229Z,1545151738.229 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-12-18T16:48:58.230Z,1545151738.230 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409CF4E0
2018-12-18T16:48:58.230Z,1545151738.230 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 8011
2018-12-18T16:48:58.231Z,1545151738.231 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-12-18T16:48:58.232Z,1545151738.232 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-12-18T16:48:58.299Z,1545151738.299 [VerticalControl](DEBUG): Construct VerticalControl.
2018-12-18T16:48:58.379Z,1545151738.379 [VerticalControl] Loaded
2018-12-18T16:48:58.379Z,1545151738.379 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-12-18T16:48:58.380Z,1545151738.380 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-12-18T16:48:58.434Z,1545151738.434 [HorizontalControl] Loaded
2018-12-18T16:48:58.435Z,1545151738.435 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-12-18T16:48:58.435Z,1545151738.435 [SpeedControl](DEBUG): Construct SpeedControl.
2018-12-18T16:48:58.437Z,1545151738.437 [SpeedControl] Loaded
2018-12-18T16:48:58.437Z,1545151738.437 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-12-18T16:48:58.438Z,1545151738.438 [LoopControl](DEBUG): Construct LoopControl.
2018-12-18T16:48:58.438Z,1545151738.438 [LoopControl] Loaded
2018-12-18T16:48:58.439Z,1545151738.439 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-12-18T16:48:58.439Z,1545151738.439 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-12-18T16:48:58.440Z,1545151738.440 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-12-18T16:48:58.467Z,1545151738.467 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-12-18T16:48:58.467Z,1545151738.467 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-12-18T16:48:58.562Z,1545151738.562 [DeadReckonUsingSpeedCalculator] Loaded
2018-12-18T16:48:58.563Z,1545151738.563 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-12-18T16:48:58.579Z,1545151738.579 [NavChart] Loaded
2018-12-18T16:48:58.579Z,1545151738.579 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-12-18T16:48:58.583Z,1545151738.583 [UniversalFixResidualReporter] Loaded
2018-12-18T16:48:58.583Z,1545151738.583 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-12-18T16:48:58.584Z,1545151738.584 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-12-18T16:48:58.587Z,1545151738.587 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-12-18T16:48:58.588Z,1545151738.588 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-12-18T16:48:58.595Z,1545151738.595 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-12-18T16:48:58.596Z,1545151738.596 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A684E0
2018-12-18T16:48:58.596Z,1545151738.596 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 8012
2018-12-18T16:48:58.601Z,1545151738.601 [Supervisor](INFO): Main Thread ID is 7920
2018-12-18T16:48:58.601Z,1545151738.601 [Supervisor](DEBUG): Running supervisor.
2018-12-18T16:48:58.602Z,1545151738.602 [CommandLine ThreadHandler](INFO): Handler Thread ID is 8013
2018-12-18T16:48:58.604Z,1545151738.604 [controlThread ThreadHandler](INFO): Handler Thread ID is 8014
2018-12-18T16:48:58.605Z,1545151738.605 [controlThread](DEBUG): Initializing ControlThread
2018-12-18T16:48:58.606Z,1545151738.606 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-12-18T16:48:58.606Z,1545151738.606 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-12-18T16:48:58.606Z,1545151738.606 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-12-18T16:48:58.607Z,1545151738.607 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-12-18T16:48:58.607Z,1545151738.607 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-12-18T16:48:58.608Z,1545151738.608 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-12-18T16:48:58.615Z,1545151738.615 [SBIT](INFO): Initialize SBIT Component.
2018-12-18T16:48:58.615Z,1545151738.615 [SBIT](IMPORTANT): git: 2018-12-13
2018-12-18T16:48:58.615Z,1545151738.615 [SBIT](INFO): git hash: 8200dc43e6ef01082c531ff0fab84136a371dc2d
2018-12-18T16:48:58.616Z,1545151738.616 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-12-18T16:48:58.616Z,1545151738.616 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-12-18T16:48:58.617Z,1545151738.617 [SBIT](INFO): Beginning SBIT in 36.000000 seconds.
2018-12-18T16:48:58.618Z,1545151738.618 [IBIT](INFO): Initialize IBIT Component.
2018-12-18T16:48:58.618Z,1545151738.618 [CBIT](DEBUG): Initialize CBIT Component.
2018-12-18T16:48:58.619Z,1545151738.619 [logger ThreadHandler](INFO): Handler Thread ID is 8015
2018-12-18T16:48:58.633Z,1545151738.633 [CBIT](DEBUG): Initialized mux pins.
2018-12-18T16:48:58.633Z,1545151738.633 [CBIT](DEBUG): Initializing the watchdog timer.
2018-12-18T16:48:58.637Z,1545151738.637 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 8016
2018-12-18T16:48:58.643Z,1545151738.643 [Radio_Surface](INFO): Powering up
2018-12-18T16:48:58.653Z,1545151738.653 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 8017
2018-12-18T16:48:58.654Z,1545151738.654 [CTD_NeilBrown](INFO): Powering down
2018-12-18T16:48:58.661Z,1545151738.661 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-12-18T16:48:58.661Z,1545151738.661 [CBIT](DEBUG): Initializing heartbeat.
2018-12-18T16:48:58.681Z,1545151738.681 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 8018
2018-12-18T16:48:58.682Z,1545151738.682 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2018-12-18T16:48:58.689Z,1545151738.689 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 8020
2018-12-18T16:48:58.690Z,1545151738.690 [WetLabsBB2FL](INFO): Powering down
2018-12-18T16:48:58.709Z,1545151738.709 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2018-12-18T16:48:58.717Z,1545151738.717 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 8021
2018-12-18T16:48:58.733Z,1545151738.733 [CBIT](DEBUG): Deactivating GF circuits.
2018-12-18T16:48:58.733Z,1545151738.733 [CBIT](DEBUG): Deactivating emergency mode.
2018-12-18T16:48:58.739Z,1545151738.739 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-12-18T16:48:58.739Z,1545151738.739 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-12-18T16:48:58.739Z,1545151738.740 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-12-18T16:48:58.740Z,1545151738.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-12-18T16:48:58.740Z,1545151738.740 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-12-18T16:48:58.740Z,1545151738.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-12-18T16:48:58.740Z,1545151738.740 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-12-18T16:48:58.740Z,1545151738.740 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-12-18T16:48:58.741Z,1545151738.741 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-12-18T16:48:58.741Z,1545151738.741 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-12-18T16:48:58.741Z,1545151738.741 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-12-18T16:48:58.741Z,1545151738.741 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-12-18T16:48:58.741Z,1545151738.741 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-12-18T16:48:58.742Z,1545151738.742 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-12-18T16:48:58.742Z,1545151738.742 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-12-18T16:48:58.742Z,1545151738.742 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-12-18T16:48:58.773Z,1545151738.773 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-12-18T16:48:58.775Z,1545151738.775 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-12-18T16:48:58.776Z,1545151738.776 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-12-18T16:48:58.776Z,1545151738.776 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-12-18T16:48:58.777Z,1545151738.777 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-12-18T16:48:58.777Z,1545151738.777 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-12-18T16:48:58.778Z,1545151738.778 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-12-18T16:48:58.778Z,1545151738.778 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-12-18T16:48:58.779Z,1545151738.779 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-12-18T16:48:58.780Z,1545151738.780 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-12-18T16:48:58.811Z,1545151738.811 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-12-18T16:48:58.847Z,1545151738.847 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2018-12-18T16:48:58.848Z,1545151738.848 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-12-18T16:48:58.993Z,1545151738.993 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-12-18T16:48:58.994Z,1545151738.994 [Default:A.Wait](DEBUG): Construct Wait.
2018-12-18T16:48:58.996Z,1545151738.996 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-12-18T16:48:59.043Z,1545151739.043 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-12-18T16:48:59.074Z,1545151739.074 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-12-18T16:48:59.079Z,1545151739.079 [Default:E.Execute](DEBUG): Construct Execute.
2018-12-18T16:48:59.103Z,1545151739.103 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2018-12-18T16:48:59.108Z,1545151739.108 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-12-18T16:48:59.145Z,1545151739.145 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-12-18T16:48:59.177Z,1545151739.177 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-12-18T16:48:59.461Z,1545151739.461 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-12-18T16:48:59.917Z,1545151739.917 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-12-18T16:48:59.933Z,1545151739.933 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-12-18T16:48:59.959Z,1545151739.959 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-12-18T16:48:59.977Z,1545151739.977 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-12-18T16:48:59.995Z,1545151739.995 [MassServo](DEBUG): Initializing EZServoServo.
2018-12-18T16:49:00.001Z,1545151740.001 [MassServo](DEBUG): Initializing MassServo.
2018-12-18T16:49:00.039Z,1545151740.039 [RudderServo](DEBUG): Initializing EZServoServo.
2018-12-18T16:49:00.049Z,1545151740.049 [RudderServo](DEBUG): Initializing RudderServo.
2018-12-18T16:49:00.058Z,1545151740.058 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-12-18T16:49:00.069Z,1545151740.069 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-12-18T16:49:05.757Z,1545151745.757 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2018-12-18T16:49:12.043Z,1545151752.043 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.048857
2018-12-18T16:49:27.280Z,1545151767.280 [NAL9602](INFO): Powering up NAL9602
2018-12-18T16:49:35.375Z,1545151775.375 [SBIT](IMPORTANT): Beginning Startup BIT
2018-12-18T16:49:35.388Z,1545151775.388 [CBIT](IMPORTANT): Beginning ground fault scan
2018-12-18T16:49:38.615Z,1545151778.615 [NAL9602](INFO): NAL9602 initialized
2018-12-18T16:49:46.307Z,1545151786.307 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.002938
CHAN A1 (24V): -0.007559
CHAN A2 (12V): 4.697929
CHAN A3 (5V): -0.001236
CHAN B0 (3.3V): 0.000290
CHAN B1 (3.15aV): -0.000010
CHAN B2 (3.15bV): -0.000623
CHAN B3 (GND): 0.000447
OPEN: -0.000277
Full Scale Calc: 4.765 mA, -1.589 mA
2018-12-18T16:50:18.239Z,1545151818.239 [CommandLine](IMPORTANT): got command burn 5.000000
2018-12-18T16:50:23.257Z,1545151823.257 [CommandLine](IMPORTANT): Deactivating dropweight wire
2018-12-18T16:50:29.528Z,1545151829.528 [SBIT](IMPORTANT): SBIT PASSED
2018-12-18T16:50:29.576Z,1545151829.576 [CommandLine](IMPORTANT): got command configSet list
2018-12-18T16:50:29.577Z,1545151829.577 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): BPC1.batteryMuxCycleTime=10 minute;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_salinity;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_temperature 0.150000 kelvin;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): Express linearApproximation CTD_NeilBrown.bin_median_sea_water_salinity 0.020000 practical_salinity_unit;

2018-12-18T16:50:29.578Z,1545151829.578 [CommandLine](IMPORTANT): Express lin