2019-06-02T16:53:17.672Z,1559494397.672 [Supervisor](DEBUG): Initializing supervisor.
2019-06-02T16:53:17.675Z,1559494397.675 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-06-02T16:53:17.675Z,1559494397.675 [SyncHandler](INFO): Protected caller Thread ID is 5490
2019-06-02T16:53:17.676Z,1559494397.676 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-06-02T16:53:17.677Z,1559494397.677 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-06-02T16:53:17.677Z,1559494397.677 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5491
2019-06-02T16:53:17.679Z,1559494397.679 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-06-02T16:53:17.691Z,1559494397.691 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-06-02T16:53:17.692Z,1559494397.692 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-06-02T16:53:17.692Z,1559494397.692 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5492
2019-06-02T16:53:17.693Z,1559494397.693 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-06-02T16:53:17.694Z,1559494397.694 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-06-02T16:53:17.695Z,1559494397.695 [logger ThreadHandler](INFO): Protected caller Thread ID is 5493
2019-06-02T16:53:17.697Z,1559494397.697 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-06-02T16:53:17.697Z,1559494397.697 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-06-02T16:53:17.702Z,1559494397.702 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-06-02T16:53:18.249Z,1559494398.249 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-06-02T16:53:18.250Z,1559494398.250 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-06-02T16:53:18.352Z,1559494398.352 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-06-02T16:53:18.354Z,1559494398.354 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-06-02T16:53:18.716Z,1559494398.716 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-06-02T16:53:18.717Z,1559494398.717 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-06-02T16:53:18.868Z,1559494398.868 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-06-02T16:53:18.869Z,1559494398.869 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-06-02T16:53:19.078Z,1559494399.078 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-06-02T16:53:19.080Z,1559494399.080 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-06-02T16:53:19.617Z,1559494399.617 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-06-02T16:53:19.800Z,1559494399.800 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-06-02T16:53:20.387Z,1559494400.387 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-06-02T16:53:20.388Z,1559494400.388 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-06-02T16:53:20.543Z,1559494400.543 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-06-02T16:53:20.545Z,1559494400.545 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-06-02T16:53:20.762Z,1559494400.762 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-06-02T16:53:20.764Z,1559494400.764 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-06-02T16:53:20.864Z,1559494400.864 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-06-02T16:53:20.866Z,1559494400.866 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-06-02T16:53:21.222Z,1559494401.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-06-02T16:53:21.223Z,1559494401.223 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-06-02T16:53:21.306Z,1559494401.306 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-06-02T16:53:21.414Z,1559494401.414 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-06-02T16:53:21.415Z,1559494401.415 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-06-02T16:53:22.055Z,1559494402.055 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-06-02T16:53:22.055Z,1559494402.055 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-06-02T16:53:22.478Z,1559494402.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-06-02T16:53:22.480Z,1559494402.480 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-06-02T16:53:22.483Z,1559494402.483 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-06-02T16:53:22.711Z,1559494402.711 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-06-02T16:53:22.817Z,1559494402.817 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-06-02T16:53:22.920Z,1559494402.920 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-06-02T16:53:23.159Z,1559494403.159 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-06-02T16:53:23.160Z,1559494403.160 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-06-02T16:53:23.248Z,1559494403.248 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-06-02T16:53:23.347Z,1559494403.347 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-06-02T16:53:23.449Z,1559494403.449 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-06-02T16:53:23.535Z,1559494403.535 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-06-02T16:53:23.650Z,1559494403.650 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-06-02T16:53:23.837Z,1559494403.837 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-06-02T16:53:23.978Z,1559494403.978 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-06-02T16:53:23.995Z,1559494403.995 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-06-02T16:53:24.491Z,1559494404.491 [AHRS_M2] Loaded
2019-06-02T16:53:24.492Z,1559494404.492 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-06-02T16:53:24.564Z,1559494404.564 [DataOverHttps] Loaded
2019-06-02T16:53:24.564Z,1559494404.564 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-06-02T16:53:24.566Z,1559494404.566 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-06-02T16:53:24.566Z,1559494404.566 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5572
2019-06-02T16:53:24.580Z,1559494404.580 [Depth_Keller] Loaded
2019-06-02T16:53:24.580Z,1559494404.580 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-06-02T16:53:24.585Z,1559494404.585 [DropWeight] Loaded
2019-06-02T16:53:24.585Z,1559494404.585 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-06-02T16:53:24.645Z,1559494404.645 [DUSBL_Hydroid] Loaded
2019-06-02T16:53:24.646Z,1559494404.646 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-06-02T16:53:24.688Z,1559494404.688 [Micromodem] Loaded
2019-06-02T16:53:24.688Z,1559494404.688 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-06-02T16:53:24.793Z,1559494404.793 [NAL9602] Loaded
2019-06-02T16:53:24.794Z,1559494404.794 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-06-02T16:53:24.810Z,1559494404.810 [Onboard] Loaded
2019-06-02T16:53:24.810Z,1559494404.810 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-06-02T16:53:24.816Z,1559494404.816 [PowerOnly] Loaded
2019-06-02T16:53:24.817Z,1559494404.817 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-06-02T16:53:24.823Z,1559494404.823 [Radio_Surface] Loaded
2019-06-02T16:53:24.824Z,1559494404.824 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-06-02T16:53:24.825Z,1559494404.825 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-06-02T16:53:24.825Z,1559494404.825 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5573
2019-06-02T16:53:24.872Z,1559494404.872 [RDI_Pathfinder] Loaded
2019-06-02T16:53:24.872Z,1559494404.872 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-06-02T16:53:26.997Z,1559494406.997 [BPC1] Loaded
2019-06-02T16:53:26.997Z,1559494406.997 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-06-02T16:53:26.997Z,1559494406.997 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-06-02T16:53:26.998Z,1559494406.998 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-06-02T16:53:27.019Z,1559494407.019 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-06-02T16:53:27.019Z,1559494407.019 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-06-02T16:53:27.142Z,1559494407.142 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-06-02T16:53:27.142Z,1559494407.142 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-06-02T16:53:27.163Z,1559494407.163 [NavChart] Loaded
2019-06-02T16:53:27.164Z,1559494407.164 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-06-02T16:53:27.168Z,1559494407.168 [UniversalFixResidualReporter] Loaded
2019-06-02T16:53:27.168Z,1559494407.168 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-06-02T16:53:27.168Z,1559494407.168 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-06-02T16:53:27.169Z,1559494407.169 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-06-02T16:53:27.304Z,1559494407.304 [BuoyancyServo] Loaded
2019-06-02T16:53:27.304Z,1559494407.304 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-06-02T16:53:27.320Z,1559494407.320 [ElevatorServo] Loaded
2019-06-02T16:53:27.320Z,1559494407.320 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-06-02T16:53:27.336Z,1559494407.336 [MassServo] Loaded
2019-06-02T16:53:27.336Z,1559494407.336 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-06-02T16:53:27.352Z,1559494407.352 [RudderServo] Loaded
2019-06-02T16:53:27.352Z,1559494407.352 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-06-02T16:53:27.367Z,1559494407.367 [ThrusterServo] Loaded
2019-06-02T16:53:27.368Z,1559494407.368 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-06-02T16:53:27.368Z,1559494407.368 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-06-02T16:53:27.369Z,1559494407.369 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-06-02T16:53:27.683Z,1559494407.683 [CTD_NeilBrown] Loaded
2019-06-02T16:53:27.683Z,1559494407.683 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-06-02T16:53:27.684Z,1559494407.684 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-06-02T16:53:27.684Z,1559494407.684 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 5574
2019-06-02T16:53:27.732Z,1559494407.732 [WetLabsSeaOWL_UV_A] Loaded
2019-06-02T16:53:27.732Z,1559494407.732 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-06-02T16:53:27.733Z,1559494407.733 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-06-02T16:53:27.733Z,1559494407.733 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 5575
2019-06-02T16:53:27.734Z,1559494407.734 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-06-02T16:53:27.734Z,1559494407.734 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-06-02T16:53:28.086Z,1559494408.086 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-06-02T16:53:28.086Z,1559494408.086 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-06-02T16:53:28.140Z,1559494408.140 [DepthRateCalculator] Loaded
2019-06-02T16:53:28.141Z,1559494408.141 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-06-02T16:53:28.147Z,1559494408.147 [PitchRateCalculator] Loaded
2019-06-02T16:53:28.147Z,1559494408.147 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-06-02T16:53:28.160Z,1559494408.160 [SpeedCalculator] Loaded
2019-06-02T16:53:28.160Z,1559494408.160 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-06-02T16:53:28.182Z,1559494408.182 [TempGradientCalculator] Loaded
2019-06-02T16:53:28.183Z,1559494408.183 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-06-02T16:53:28.188Z,1559494408.188 [YawRateCalculator] Loaded
2019-06-02T16:53:28.189Z,1559494408.189 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-06-02T16:53:28.231Z,1559494408.231 [ElevatorOffsetCalculator] Loaded
2019-06-02T16:53:28.231Z,1559494408.231 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-06-02T16:53:28.232Z,1559494408.232 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-06-02T16:53:28.232Z,1559494408.232 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-06-02T16:53:28.400Z,1559494408.400 [SBIT](DEBUG): Construct Startup Built In Test.
2019-06-02T16:53:28.422Z,1559494408.422 [SBIT] Loaded
2019-06-02T16:53:28.423Z,1559494408.423 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-06-02T16:53:28.423Z,1559494408.423 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-06-02T16:53:28.435Z,1559494408.435 [IBIT] Loaded
2019-06-02T16:53:28.436Z,1559494408.436 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-06-02T16:53:28.439Z,1559494408.439 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-06-02T16:53:28.583Z,1559494408.583 [CBIT] Loaded
2019-06-02T16:53:28.583Z,1559494408.583 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-06-02T16:53:28.584Z,1559494408.584 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-06-02T16:53:28.584Z,1559494408.584 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-06-02T16:53:28.704Z,1559494408.704 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-06-02T16:53:28.705Z,1559494408.705 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-06-02T16:53:28.834Z,1559494408.834 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-06-02T16:53:28.834Z,1559494408.834 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-06-02T16:53:28.921Z,1559494408.921 [VerticalControl](DEBUG): Construct VerticalControl.
2019-06-02T16:53:29.010Z,1559494409.010 [VerticalControl] Loaded
2019-06-02T16:53:29.010Z,1559494409.010 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-06-02T16:53:29.011Z,1559494409.011 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-06-02T16:53:29.071Z,1559494409.071 [HorizontalControl] Loaded
2019-06-02T16:53:29.072Z,1559494409.072 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-06-02T16:53:29.072Z,1559494409.072 [SpeedControl](DEBUG): Construct SpeedControl.
2019-06-02T16:53:29.074Z,1559494409.074 [SpeedControl] Loaded
2019-06-02T16:53:29.075Z,1559494409.075 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-06-02T16:53:29.075Z,1559494409.075 [LoopControl](DEBUG): Construct LoopControl.
2019-06-02T16:53:29.076Z,1559494409.076 [LoopControl] Loaded
2019-06-02T16:53:29.076Z,1559494409.076 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-06-02T16:53:29.077Z,1559494409.077 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-06-02T16:53:29.077Z,1559494409.077 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-06-02T16:53:29.116Z,1559494409.116 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-06-02T16:53:29.120Z,1559494409.120 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-06-02T16:53:29.120Z,1559494409.120 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-06-02T16:53:29.127Z,1559494409.127 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-06-02T16:53:29.128Z,1559494409.128 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD54E0
2019-06-02T16:53:29.128Z,1559494409.128 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5576
2019-06-02T16:53:29.133Z,1559494409.133 [Supervisor](INFO): Main Thread ID is 802
2019-06-02T16:53:29.133Z,1559494409.133 [Supervisor](DEBUG): Running supervisor.
2019-06-02T16:53:29.134Z,1559494409.134 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5577
2019-06-02T16:53:29.136Z,1559494409.136 [controlThread ThreadHandler](INFO): Handler Thread ID is 5578
2019-06-02T16:53:29.136Z,1559494409.136 [controlThread](DEBUG): Initializing ControlThread
2019-06-02T16:53:29.145Z,1559494409.145 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-06-02T16:53:29.145Z,1559494409.145 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-06-02T16:53:29.146Z,1559494409.146 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-06-02T16:53:29.146Z,1559494409.146 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-06-02T16:53:29.147Z,1559494409.147 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-06-02T16:53:29.147Z,1559494409.147 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-06-02T16:53:29.147Z,1559494409.147 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-06-02T16:53:29.148Z,1559494409.148 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-06-02T16:53:29.148Z,1559494409.148 [SBIT](INFO): Initialize SBIT Component.
2019-06-02T16:53:29.149Z,1559494409.149 [SBIT](IMPORTANT): git: 2019-05-29
2019-06-02T16:53:29.149Z,1559494409.149 [SBIT](INFO): git hash: 3a408d161d85e02f941062c72493668314c507d3
2019-06-02T16:53:29.149Z,1559494409.149 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-06-02T16:53:29.150Z,1559494409.150 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-06-02T16:53:29.151Z,1559494409.151 [SBIT](INFO): Beginning SBIT in 39.000000 seconds.
2019-06-02T16:53:29.152Z,1559494409.152 [IBIT](INFO): Initialize IBIT Component.
2019-06-02T16:53:29.153Z,1559494409.153 [CBIT](DEBUG): Initialize CBIT Component.
2019-06-02T16:53:29.154Z,1559494409.154 [logger ThreadHandler](INFO): Handler Thread ID is 5579
2019-06-02T16:53:29.165Z,1559494409.165 [CBIT](DEBUG): Initialized mux pins.
2019-06-02T16:53:29.165Z,1559494409.165 [CBIT](DEBUG): Initializing the watchdog timer.
2019-06-02T16:53:29.173Z,1559494409.173 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5580
2019-06-02T16:53:29.174Z,1559494409.174 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-06-02T16:53:29.185Z,1559494409.185 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5581
2019-06-02T16:53:29.189Z,1559494409.189 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-06-02T16:53:29.189Z,1559494409.189 [CBIT](DEBUG): Initializing heartbeat.
2019-06-02T16:53:29.205Z,1559494409.205 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 5582
2019-06-02T16:53:29.206Z,1559494409.206 [CTD_NeilBrown](INFO): Powering down
2019-06-02T16:53:29.233Z,1559494409.233 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 5583
2019-06-02T16:53:29.234Z,1559494409.234 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-06-02T16:53:29.261Z,1559494409.261 [CBIT](DEBUG): Deactivating GF circuits.
2019-06-02T16:53:29.261Z,1559494409.261 [CBIT](DEBUG): Deactivating emergency mode.
2019-06-02T16:53:29.262Z,1559494409.262 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5584
2019-06-02T16:53:29.268Z,1559494409.268 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-06-02T16:53:29.269Z,1559494409.269 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-06-02T16:53:29.269Z,1559494409.269 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-06-02T16:53:29.269Z,1559494409.269 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-06-02T16:53:29.269Z,1559494409.269 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-06-02T16:53:29.269Z,1559494409.269 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-06-02T16:53:29.270Z,1559494409.270 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-06-02T16:53:29.270Z,1559494409.270 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-06-02T16:53:29.270Z,1559494409.270 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-06-02T16:53:29.270Z,1559494409.270 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-06-02T16:53:29.270Z,1559494409.270 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-06-02T16:53:29.271Z,1559494409.271 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-06-02T16:53:29.271Z,1559494409.271 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-06-02T16:53:29.271Z,1559494409.271 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-06-02T16:53:29.271Z,1559494409.271 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-06-02T16:53:29.271Z,1559494409.271 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-06-02T16:53:29.297Z,1559494409.297 [CBIT](DEBUG): Backplane powered.
2019-06-02T16:53:29.297Z,1559494409.297 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-06-02T16:53:29.299Z,1559494409.299 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-06-02T16:53:29.299Z,1559494409.299 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-06-02T16:53:29.300Z,1559494409.300 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-06-02T16:53:29.301Z,1559494409.301 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-06-02T16:53:29.321Z,1559494409.321 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-06-02T16:53:29.352Z,1559494409.352 [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>


2019-06-02T16:53:29.353Z,1559494409.353 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-06-02T16:53:29.419Z,1559494409.419 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-06-02T16:53:29.420Z,1559494409.420 [Default:A.Wait](DEBUG): Construct Wait.
2019-06-02T16:53:29.422Z,1559494409.422 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-06-02T16:53:29.465Z,1559494409.465 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-06-02T16:53:29.467Z,1559494409.467 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-06-02T16:53:29.481Z,1559494409.481 [Default:E.Execute](DEBUG): Construct Execute.
2019-06-02T16:53:29.484Z,1559494409.484 [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>


2019-06-02T16:53:29.503Z,1559494409.503 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-06-02T16:53:29.516Z,1559494409.516 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-06-02T16:53:29.578Z,1559494409.578 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-06-02T16:53:29.579Z,1559494409.579 [DUSBL_Hydroid](INFO): Powering up
2019-06-02T16:53:29.579Z,1559494409.579 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-06-02T16:53:29.589Z,1559494409.589 [Radio_Surface](INFO): Powering up
2019-06-02T16:53:29.645Z,1559494409.645 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-06-02T16:53:29.663Z,1559494409.663 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:29.669Z,1559494409.669 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-06-02T16:53:29.670Z,1559494409.670 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:29.677Z,1559494409.677 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-06-02T16:53:29.678Z,1559494409.678 [MassServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:29.685Z,1559494409.685 [MassServo](DEBUG): Initializing MassServo.
2019-06-02T16:53:29.686Z,1559494409.686 [RudderServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:29.693Z,1559494409.693 [RudderServo](DEBUG): Initializing RudderServo.
2019-06-02T16:53:29.694Z,1559494409.694 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:29.701Z,1559494409.701 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-06-02T16:53:29.925Z,1559494409.925 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-06-02T16:53:29.925Z,1559494409.925 [DropWeight] Hardware Fault, FailCount= 1
2019-06-02T16:53:29.926Z,1559494409.926 [DropWeight](ERROR): Hardware Fault
2019-06-02T16:53:29.927Z,1559494409.927 [Micromodem](INFO): Powering up
2019-06-02T16:53:29.927Z,1559494409.927 [Micromodem](DEBUG): Initializing Micromodem.
2019-06-02T16:53:29.961Z,1559494409.961 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-06-02T16:53:29.977Z,1559494409.977 [CommandLine](FAULT): Scheduling is paused
2019-06-02T16:53:29.978Z,1559494409.978 [CBIT](INFO): Critical error at 20190602T165329
2019-06-02T16:53:29.978Z,1559494409.978 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-06-02T16:53:29.989Z,1559494409.989 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-06-02T16:53:29.989Z,1559494409.989 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-06-02T16:53:30.685Z,1559494410.685 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-06-02T16:53:30.685Z,1559494410.685 [RudderServo](FAULT): Rudder failed to initialize
2019-06-02T16:53:30.685Z,1559494410.685 [RudderServo] Communications Fault, FailCount= 1
2019-06-02T16:53:30.685Z,1559494410.685 [RudderServo](ERROR): Communications Fault
2019-06-02T16:53:30.794Z,1559494410.794 [CBIT](INFO): Critical error at 20190602T165329
2019-06-02T16:53:30.797Z,1559494410.797 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-06-02T16:53:30.982Z,1559494410.982 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-06-02T16:53:30.982Z,1559494410.982 [RudderServo](INFO): Powering down
2019-06-02T16:53:31.647Z,1559494411.647 [RudderServo](DEBUG): Initializing EZServoServo.
2019-06-02T16:53:31.766Z,1559494411.766 [RudderServo](DEBUG): Initializing RudderServo.
2019-06-02T16:53:31.770Z,1559494411.770 [CBIT](INFO): Clearing failed state for component RudderServo
2019-06-02T16:53:31.770Z,1559494411.770 [RudderServo] No Fault, FailCount= 1
2019-06-02T16:53:42.959Z,1559494422.959 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-06-02T16:53:46.162Z,1559494426.162 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-06-02T16:53:47.786Z,1559494427.786 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-06-02T16:53:55.050Z,1559494435.050 [NAL9602](INFO): Powering up NAL9602
2019-06-02T16:54:05.962Z,1559494445.962 [NAL9602](INFO): NAL9602 initialized
2019-06-02T16:54:06.781Z,1559494446.781 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:54:08.844Z,1559494448.844 [SBIT](IMPORTANT): Beginning Startup BIT
2019-06-02T16:54:08.860Z,1559494448.860 [CBIT](IMPORTANT): Beginning ground fault scan
2019-06-02T16:54:20.062Z,1559494460.062 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.018806
CHAN A1 (24V): -0.027489
CHAN A2 (12V): -0.007145
CHAN A3 (5V): -0.002115
CHAN B0 (3.3V): 0.000046
CHAN B1 (3.15aV): -0.000216
CHAN B2 (3.15bV): -0.000176
CHAN B3 (GND): 0.002115
OPEN: 0.005264
Full Scale Calc: 4.765 mA, -1.589 mA
2019-06-02T16:55:02.547Z,1559494502.547 [SBIT](IMPORTANT): SBIT PASSED
2019-06-02T16:55:02.613Z,1559494502.613 [CommandLine](IMPORTANT): got command configSet list
2019-06-02T16:55:02.614Z,1559494502.614 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-06-02T16:55:02.614Z,1559494502.614 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-06-02T16:55:02.615Z,1559494502.615 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-06-02T16:55:02.616Z,1559494502.616 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter;

2019-06-02T16:55:02.616Z,1559494502.616 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water;

2019-06-02T16:55:02.616Z,1559494502.616 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-06-02T16:55:02.616Z,1559494502.616 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-06-02T16:55:02.616Z,1559494502.616 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter;

2019-06-02T16:55:02.959Z,1559494502.959 [MissionManager](IMPORTANT): Started mission Startup
2019-06-02T16:55:02.959Z,1559494502.959 [Startup] Running Loop=1
2019-06-02T16:55:02.960Z,1559494502.960 [Startup](DEBUG): Aggregate::initialize Startup
2019-06-02T16:55:02.960Z,1559494502.960 [Startup:A.GoToSurface] Running Loop=1
2019-06-02T16:55:02.960Z,1559494502.960 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-06-02T16:55:02.960Z,1559494502.960 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-06-02T16:55:02.962Z,1559494502.962 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-06-02T16:55:02.962Z,1559494502.962 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-06-02T16:55:02.962Z,1559494502.962 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-06-02T16:55:02.963Z,1559494502.963 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-06-02T16:55:02.964Z,1559494502.964 [Startup:StartupSatComms] Running Loop=1
2019-06-02T16:55:02.964Z,1559494502.964 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-06-02T16:55:02.964Z,1559494502.964 [Startup:StartupSatComms:A] Running Loop=1
2019-06-02T16:55:03.405Z,1559494503.405 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-06-02T16:56:03.146Z,1559494563.146 [Startup:StartupSatComms:A](INFO): Timed out from 2019-06-02T16:55:02.0Z
2019-06-02T16:56:03.147Z,1559494563.147 [Startup:StartupSatComms:A] Stopped
2019-06-02T16:56:03.147Z,1559494563.147 [Startup:StartupSatComms:B] Running Loop=1
2019-06-02T16:56:03.551Z,1559494563.551 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-06-02T16:56:29.401Z,1559494589.401 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-06-02T16:56:29.401Z,1559494589.401 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-06-02T16:56:29.411Z,1559494589.411 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-06-02T16:56:29.830Z,1559494589.830 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-06-02T16:56:29.830Z,1559494589.830 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-06-02T16:56:51.520Z,1559494611.520 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005593
2019-06-02T16:57:03.338Z,1559494623.338 [Startup:StartupSatComms:B](INFO): Timed out from 2019-06-02T16:56:03.1Z
2019-06-02T16:57:03.338Z,1559494623.338 [Startup:StartupSatComms:B] Stopped
2019-06-02T16:57:03.338Z,1559494623.338 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-06-02T16:57:03.338Z,1559494623.338 [Startup:StartupSatComms] Stopped
2019-06-02T16:57:03.338Z,1559494623.338 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-06-02T16:57:03.339Z,1559494623.339 [Startup](INFO): Completed Startup
2019-06-02T16:57:03.339Z,1559494623.339 [MissionManager](INFO): Startup is completed.
2019-06-02T16:57:03.339Z,1559494623.339 [MissionManager](INFO): Uninitializing Mission Startup
2019-06-02T16:57:03.340Z,1559494623.340 [Startup] Stopped
2019-06-02T16:57:03.340Z,1559494623.340 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-06-02T16:57:03.340Z,1559494623.340 [Startup:A.GoToSurface] Stopped
2019-06-02T16:57:03.340Z,1559494623.340 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-06-02T16:57:03.768Z,1559494623.768 [MissionManager](IMPORTANT): Started mission Default
2019-06-02T16:57:03.768Z,1559494623.768 [Default] Running Loop=1
2019-06-02T16:57:03.768Z,1559494623.768 [Default](DEBUG): Aggregate::initialize Default
2019-06-02T16:57:03.768Z,1559494623.768 [Default:B.GoToSurface] Running Loop=1
2019-06-02T16:57:03.769Z,1559494623.769 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-06-02T16:57:03.769Z,1559494623.769 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-06-02T16:57:03.770Z,1559494623.770 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-06-02T16:57:03.770Z,1559494623.770 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-06-02T16:57:03.770Z,1559494623.770 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-06-02T16:57:03.771Z,1559494623.771 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-06-02T16:57:03.771Z,1559494623.771 [Default:A.Wait] Running Loop=1
2019-06-02T16:57:03.771Z,1559494623.771 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-06-02T16:57:17.100Z,1559494637.100 [Default:A.Wait](INFO): Done Waiting.
2019-06-02T16:57:17.100Z,1559494637.100 [Default:A.Wait] Stopped
2019-06-02T16:57:17.100Z,1559494637.100 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-06-02T16:57:17.502Z,1559494637.502 [Default:CheckIn] Running Loop=1
2019-06-02T16:57:17.502Z,1559494637.502 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-06-02T16:57:17.502Z,1559494637.502 [Default:CheckIn:Read_GPS] Running Loop=1
2019-06-02T16:57:17.911Z,1559494637.911 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-06-02T16:59:09.359Z,1559494749.359 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-06-02T16:59:10.181Z,1559494750.181 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:12.609Z,1559494752.609 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:15.841Z,1559494755.841 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:18.673Z,1559494758.673 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:21.501Z,1559494761.501 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:24.325Z,1559494764.325 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:27.553Z,1559494767.553 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:29.825Z,1559494769.825 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20190531T180759/Courier0393.lzma
2019-06-02T16:59:30.389Z,1559494770.389 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:30.413Z,1559494770.413 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-06-02T16:59:30.413Z,1559494770.413 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-06-02T16:59:30.428Z,1559494770.428 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-06-02T16:59:30.631Z,1559494770.631 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Courier0393.lzma.bak
2019-06-02T16:59:30.631Z,1559494770.631 [DataOverHttps](INFO): SBD MOMSN=11307966
2019-06-02T16:59:30.826Z,1559494770.826 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-06-02T16:59:30.827Z,1559494770.827 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-06-02T16:59:33.613Z,1559494773.613 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:36.441Z,1559494776.441 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:39.673Z,1559494779.673 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:42.509Z,1559494782.509 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:45.753Z,1559494785.753 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:48.565Z,1559494788.565 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:51.793Z,1559494791.793 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:54.621Z,1559494794.621 [NAL9602](DEBUG): Fix Requested
2019-06-02T16:59:57.857Z,1559494797.857 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:00.681Z,1559494800.681 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:03.509Z,1559494803.509 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:06.337Z,1559494806.337 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:09.573Z,1559494809.573 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:12.401Z,1559494812.401 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:15.641Z,1559494815.641 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:18.461Z,1559494818.461 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:21.693Z,1559494821.693 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:24.521Z,1559494824.521 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:27.749Z,1559494827.749 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:30.577Z,1559494830.577 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:33.405Z,1559494833.405 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:36.637Z,1559494836.637 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:39.465Z,1559494839.465 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:42.297Z,1559494842.297 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:45.143Z,1559494845.143 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-06-02T17:00:45.529Z,1559494845.529 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:48.357Z,1559494848.357 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:51.589Z,1559494851.589 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:53.219Z,1559494853.219 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-06-02T17:00:53.222Z,1559494853.222 [BPC1](INFO): Received data from all battery sticks.
2019-06-02T17:00:54.413Z,1559494854.413 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:00:57.645Z,1559494857.645 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:00.473Z,1559494860.473 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:03.301Z,1559494863.301 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:06.537Z,1559494866.537 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:09.369Z,1559494869.369 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:12.597Z,1559494872.597 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:15.421Z,1559494875.421 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:18.657Z,1559494878.657 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:21.481Z,1559494881.481 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:24.309Z,1559494884.309 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:27.541Z,1559494887.541 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:30.369Z,1559494890.369 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:33.601Z,1559494893.601 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:36.437Z,1559494896.437 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:39.265Z,1559494899.265 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:42.493Z,1559494902.493 [NAL9602](DEBUG): Fix Requested
2019-06-02T17:01:42.885Z,1559494902.885 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170134.00,A,3646.64550,N,12146.46570,W,48.421,135.78,020619,,,A*46
2019-06-02T17:01:42.888Z,1559494902.888 [NAL9602](INFO): GPS fix at 20190602T170134: (36.777425, -121.774428)
2019-06-02T17:01:42.938Z,1559494902.938 [Default:CheckIn:Read_GPS] Stopped
2019-06-02T17:01:42.938Z,1559494902.938 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-06-02T17:01:43.339Z,1559494903.339 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-06-02T17:02:15.427Z,1559494935.427 [NAL9602](INFO): Not Powering down - fast GPS
2019-06-02T17:05:44.752Z,1559495144.752 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-06-02T17:05:44.757Z,1559495144.757 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19060210150906,35.0, -0.1,   0.0,10
2019-06-02T17:06:37.328Z,1559495197.328 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190531T180759/Courier0396.lzma
2019-06-02T17:06:38.135Z,1559495198.135 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Courier0396.lzma.bak
2019-06-02T17:06:38.135Z,1559495198.135 [DataOverHttps](INFO): SBD MOMSN=11308032
2019-06-02T17:08:08.154Z,1559495288.154 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-06-02T17:08:08.154Z,1559495288.154 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19060210173206,35.0, -0.1,   0.,  0
2019-06-02T17:08:27.129Z,1559495307.129 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-06-02T17:08:27.129Z,1559495307.129 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-06-02T17:08:30.054Z,1559495310.054 [CBIT](INFO): Clearing failed state for component DropWeight
2019-06-02T17:08:30.054Z,1559495310.054 [DropWeight] No Fault, FailCount= 1
2019-06-02T17:09:07.933Z,1559495347.933 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-06-02T17:09:07.934Z,1559495347.934 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19060210183106,35.0, -0.1,   0.0,1448.96
2019-06-02T17:13:02.956Z,1559495582.956 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190602T165317/Courier0000.lzma
2019-06-02T17:13:03.762Z,1559495583.762 [DataOverHttps](INFO): Moved sent file to Logs/20190602T165317/Courier0000.lzma.bak
2019-06-02T17:13:03.762Z,1559495583.762 [DataOverHttps](INFO): SBD MOMSN=11308086
2019-06-02T17:13:16.598Z,1559495596.598 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20190602T165317/Courier0004.lzma
2019-06-02T17:13:17.402Z,1559495597.402 [DataOverHttps](INFO): Moved sent file to Logs/20190602T165317/Courier0004.lzma.bak
2019-06-02T17:13:17.402Z,1559495597.402 [DataOverHttps](INFO): SBD MOMSN=11308093
2019-06-02T17:13:29.937Z,1559495609.937 [DataOverHttps](INFO): Sending 8348 bytes from file Logs/20190531T180759/Express0388.lzma
2019-06-02T17:13:31.115Z,1559495611.115 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Express0388.lzma.bak
2019-06-02T17:13:31.115Z,1559495611.115 [DataOverHttps](INFO): SBD MOMSN=11308098
2019-06-02T17:17:12.841Z,1559495832.841 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-06-02T17:17:12.841Z,1559495832.841 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-06-02T17:17:12.841Z,1559495832.841 [RDI_Pathfinder](ERROR): Communications Fault
2019-06-02T17:17:12.841Z,1559495832.841 [RDI_Pathfinder](ERROR): Failed to parse:
2019-06-02T17:17:12.868Z,1559495832.868 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-06-02T17:17:13.221Z,1559495833.221 [RDI_Pathfinder](INFO): Powering down
2019-06-02T17:17:13.989Z,1559495833.989 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-06-02T17:17:13.989Z,1559495833.989 [RDI_Pathfinder] No Fault, FailCount= 1
2019-06-02T17:17:27.307Z,1559495847.307 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-06-02T17:17:36.611Z,1559495856.611 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-06-02T17:17:36.611Z,1559495856.611 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-06-02T17:17:40.617Z,1559495860.617 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-06-02T17:17:40.618Z,1559495860.618 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-06-02T17:19:21.264Z,1559495961.264 [RDI_Pathfinder](ERROR): only read 0 of 4 data items
2019-06-02T17:19:21.264Z,1559495961.264 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,,-32768,V
2019-06-02T17:20:44.237Z,1559496044.237 [DataOverHttps](INFO): Sending 8915 bytes from file Logs/20190531T180759/Express0391.lzma
2019-06-02T17:20:45.431Z,1559496045.431 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Express0391.lzma.bak
2019-06-02T17:20:45.431Z,1559496045.431 [DataOverHttps](INFO): SBD MOMSN=11308189
2019-06-02T17:21:36.957Z,1559496096.957 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-06-02T17:26:07.636Z,1559496367.636 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-06-02T17:26:07.636Z,1559496367.636 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19060210353156,35.0, 0.0,1448.9,  0
2019-06-02T17:28:44.146Z,1559496524.146 [DataOverHttps](INFO): Sending 5287 bytes from file Logs/20190531T180759/Express0394.lzma
2019-06-02T17:28:44.943Z,1559496524.943 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Express0394.lzma.bak
2019-06-02T17:28:44.943Z,1559496524.943 [DataOverHttps](INFO): SBD MOMSN=11308218
2019-06-02T17:34:27.393Z,1559496867.393 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-06-02T17:37:20.064Z,1559497040.064 [DataOverHttps](INFO): Sending 80 bytes from file Logs/20190531T180759/Express0397.lzma
2019-06-02T17:37:20.871Z,1559497040.871 [DataOverHttps](INFO): Moved sent file to Logs/20190531T180759/Express0397.lzma.bak
2019-06-02T17:37:20.871Z,1559497040.871 [DataOverHttps](INFO): SBD MOMSN=11308226
2019-06-02T17:37:47.386Z,1559497067.386 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-06-02T17:37:47.387Z,1559497067.387 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32
2019-06-02T17:38:31.382Z,1559497111.382 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2019-06-02T17:38:31.382Z,1559497111.382 [DropWeight] Hardware Fault, FailCount= 1
2019-06-02T17:38:31.382Z,1559497111.382 [DropWeight](ERROR): Hardware Fault
2019-06-02T17:38:31.422Z,1559497111.422 [CBIT](INFO): Critical error at 20190602T173831
2019-06-02T17:38:31.425Z,1559497111.425 [CBIT](ERROR): Hardware Fault in component: DropWeight
2019-06-02T17:38:31.426Z,1559497111.426 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2019-06-02T17:38:31.836Z,1559497111.836 [CBIT](INFO): Critical error at 20190602T173831
2019-06-02T17:38:32.613Z,1559497112.613 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-06-02T17:38:32.614Z,1559497112.614 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19060210475656,35.0, -0.1,   0.0,1448.9,,  0.00,   0.00,   0.00,   0.00
2019-06-02T17:42:15.898Z,1559497335.898 [DataOverHttps](IMPORTANT): SBD MTMSN=20190602T174207