2019-01-24T01:41:39.632Z,1548294099.632 [Supervisor](DEBUG): Initializing supervisor.
2019-01-24T01:41:39.635Z,1548294099.635 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-01-24T01:41:39.636Z,1548294099.636 [SyncHandler](INFO): Protected caller Thread ID is 800
2019-01-24T01:41:39.636Z,1548294099.636 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-01-24T01:41:39.637Z,1548294099.637 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-01-24T01:41:39.637Z,1548294099.637 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 801
2019-01-24T01:41:39.640Z,1548294099.640 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-01-24T01:41:39.651Z,1548294099.651 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-01-24T01:41:39.652Z,1548294099.652 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-01-24T01:41:39.653Z,1548294099.653 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 802
2019-01-24T01:41:39.654Z,1548294099.654 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-01-24T01:41:39.654Z,1548294099.654 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-01-24T01:41:39.655Z,1548294099.655 [logger ThreadHandler](INFO): Protected caller Thread ID is 803
2019-01-24T01:41:39.657Z,1548294099.657 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-01-24T01:41:39.657Z,1548294099.657 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-01-24T01:41:39.662Z,1548294099.662 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-01-24T01:41:40.009Z,1548294100.009 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-01-24T01:41:40.010Z,1548294100.010 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-01-24T01:41:40.450Z,1548294100.450 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-01-24T01:41:40.450Z,1548294100.450 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-01-24T01:41:40.774Z,1548294100.774 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-01-24T01:41:40.775Z,1548294100.775 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-01-24T01:41:40.966Z,1548294100.966 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-01-24T01:41:40.968Z,1548294100.968 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-01-24T01:41:41.424Z,1548294101.424 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-01-24T01:41:41.424Z,1548294101.424 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-01-24T01:41:41.894Z,1548294101.894 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-01-24T01:41:41.894Z,1548294101.894 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-01-24T01:41:41.998Z,1548294101.998 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-01-24T01:41:41.999Z,1548294101.999 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-01-24T01:41:42.192Z,1548294102.192 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-01-24T01:41:42.193Z,1548294102.193 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-01-24T01:41:42.337Z,1548294102.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-01-24T01:41:42.337Z,1548294102.337 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-01-24T01:41:42.418Z,1548294102.418 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-01-24T01:41:42.626Z,1548294102.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-01-24T01:41:42.626Z,1548294102.626 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-01-24T01:41:42.728Z,1548294102.728 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-01-24T01:41:42.729Z,1548294102.729 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-01-24T01:41:42.825Z,1548294102.825 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-01-24T01:41:42.826Z,1548294102.826 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-01-24T01:41:42.972Z,1548294102.972 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-01-24T01:41:42.972Z,1548294102.972 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-01-24T01:41:43.374Z,1548294103.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-01-24T01:41:43.376Z,1548294103.376 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-01-24T01:41:44.004Z,1548294104.004 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-01-24T01:41:44.137Z,1548294104.137 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-01-24T01:41:44.360Z,1548294104.360 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-01-24T01:41:44.361Z,1548294104.361 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-01-24T01:41:44.529Z,1548294104.529 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-01-24T01:41:44.630Z,1548294104.630 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-01-24T01:41:44.729Z,1548294104.729 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-01-24T01:41:44.920Z,1548294104.920 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-01-24T01:41:45.006Z,1548294105.006 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-01-24T01:41:45.103Z,1548294105.103 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-01-24T01:41:45.197Z,1548294105.197 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-01-24T01:41:45.279Z,1548294105.279 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-01-24T01:41:45.387Z,1548294105.387 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-01-24T01:41:45.394Z,1548294105.394 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-01-24T01:41:45.550Z,1548294105.550 [SBIT](DEBUG): Construct Startup Built In Test.
2019-01-24T01:41:45.579Z,1548294105.579 [SBIT] Loaded
2019-01-24T01:41:45.579Z,1548294105.579 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-01-24T01:41:45.580Z,1548294105.580 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-01-24T01:41:45.606Z,1548294105.606 [IBIT] Loaded
2019-01-24T01:41:45.607Z,1548294105.607 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-01-24T01:41:45.610Z,1548294105.610 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-01-24T01:41:45.984Z,1548294105.984 [CBIT] Loaded
2019-01-24T01:41:45.984Z,1548294105.984 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-01-24T01:41:45.985Z,1548294105.985 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-01-24T01:41:45.986Z,1548294105.986 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-01-24T01:41:46.130Z,1548294106.130 [BuoyancyServo] Loaded
2019-01-24T01:41:46.130Z,1548294106.130 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-01-24T01:41:46.144Z,1548294106.144 [ElevatorServo] Loaded
2019-01-24T01:41:46.145Z,1548294106.145 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-01-24T01:41:46.158Z,1548294106.158 [MassServo] Loaded
2019-01-24T01:41:46.159Z,1548294106.159 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-01-24T01:41:46.173Z,1548294106.173 [RudderServo] Loaded
2019-01-24T01:41:46.173Z,1548294106.173 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-01-24T01:41:46.187Z,1548294106.187 [ThrusterServo] Loaded
2019-01-24T01:41:46.187Z,1548294106.187 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-01-24T01:41:46.188Z,1548294106.188 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-01-24T01:41:46.188Z,1548294106.188 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-01-24T01:41:46.305Z,1548294106.305 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-01-24T01:41:46.306Z,1548294106.306 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-01-24T01:41:46.361Z,1548294106.361 [DeadReckonUsingSpeedCalculator] Loaded
2019-01-24T01:41:46.362Z,1548294106.362 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-01-24T01:41:46.377Z,1548294106.377 [NavChart] Loaded
2019-01-24T01:41:46.378Z,1548294106.378 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-01-24T01:41:46.381Z,1548294106.381 [UniversalFixResidualReporter] Loaded
2019-01-24T01:41:46.382Z,1548294106.382 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-01-24T01:41:46.382Z,1548294106.382 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-01-24T01:41:46.383Z,1548294106.383 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-01-24T01:41:46.406Z,1548294106.406 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-01-24T01:41:46.407Z,1548294106.407 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-01-24T01:41:46.676Z,1548294106.676 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-01-24T01:41:46.677Z,1548294106.677 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-01-24T01:41:47.299Z,1548294107.299 [AHRS_M2] Loaded
2019-01-24T01:41:47.300Z,1548294107.300 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-01-24T01:41:47.437Z,1548294107.437 [DataOverHttps] Loaded
2019-01-24T01:41:47.437Z,1548294107.437 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2019-01-24T01:41:47.450Z,1548294107.450 [Depth_Keller] Loaded
2019-01-24T01:41:47.450Z,1548294107.450 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-01-24T01:41:47.455Z,1548294107.455 [DropWeight] Loaded
2019-01-24T01:41:47.455Z,1548294107.455 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-01-24T01:41:47.541Z,1548294107.541 [NAL9602] Loaded
2019-01-24T01:41:47.541Z,1548294107.541 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-01-24T01:41:47.546Z,1548294107.546 [Onboard] Loaded
2019-01-24T01:41:47.547Z,1548294107.547 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-01-24T01:41:47.553Z,1548294107.553 [Radio_Surface] Loaded
2019-01-24T01:41:47.553Z,1548294107.553 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-01-24T01:41:47.555Z,1548294107.555 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408484E0
2019-01-24T01:41:47.555Z,1548294107.555 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 882
2019-01-24T01:41:47.581Z,1548294107.581 [RDI_Pathfinder] Loaded
2019-01-24T01:41:47.582Z,1548294107.582 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-01-24T01:41:47.602Z,1548294107.602 [RDI_PathfinderUp] Loaded
2019-01-24T01:41:47.603Z,1548294107.603 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-01-24T01:41:49.381Z,1548294109.381 [BPC1] Loaded
2019-01-24T01:41:49.381Z,1548294109.381 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-01-24T01:41:49.381Z,1548294109.381 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-01-24T01:41:49.382Z,1548294109.382 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-01-24T01:41:49.467Z,1548294109.467 [VerticalControl](DEBUG): Construct VerticalControl.
2019-01-24T01:41:49.551Z,1548294109.551 [VerticalControl] Loaded
2019-01-24T01:41:49.551Z,1548294109.551 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-01-24T01:41:49.552Z,1548294109.552 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-01-24T01:41:49.607Z,1548294109.607 [HorizontalControl] Loaded
2019-01-24T01:41:49.608Z,1548294109.608 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-01-24T01:41:49.608Z,1548294109.608 [SpeedControl](DEBUG): Construct SpeedControl.
2019-01-24T01:41:49.610Z,1548294109.610 [SpeedControl] Loaded
2019-01-24T01:41:49.611Z,1548294109.611 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-01-24T01:41:49.611Z,1548294109.611 [LoopControl](DEBUG): Construct LoopControl.
2019-01-24T01:41:49.612Z,1548294109.612 [LoopControl] Loaded
2019-01-24T01:41:49.612Z,1548294109.612 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-01-24T01:41:49.612Z,1548294109.612 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-01-24T01:41:49.613Z,1548294109.613 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-01-24T01:41:49.735Z,1548294109.735 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-01-24T01:41:49.735Z,1548294109.735 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-01-24T01:41:49.960Z,1548294109.960 [Aanderaa_O2] Loaded
2019-01-24T01:41:49.960Z,1548294109.960 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-01-24T01:41:50.043Z,1548294110.043 [CTD_NeilBrown] Loaded
2019-01-24T01:41:50.043Z,1548294110.043 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-01-24T01:41:50.044Z,1548294110.044 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409544E0
2019-01-24T01:41:50.045Z,1548294110.045 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 883
2019-01-24T01:41:50.088Z,1548294110.088 [WetLabsSeaOWL_UV_A] Loaded
2019-01-24T01:41:50.089Z,1548294110.089 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-01-24T01:41:50.090Z,1548294110.090 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409844E0
2019-01-24T01:41:50.090Z,1548294110.090 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 884
2019-01-24T01:41:50.091Z,1548294110.091 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-01-24T01:41:50.091Z,1548294110.091 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-01-24T01:41:50.192Z,1548294110.192 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-01-24T01:41:50.193Z,1548294110.193 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-01-24T01:41:50.247Z,1548294110.247 [DepthRateCalculator] Loaded
2019-01-24T01:41:50.248Z,1548294110.248 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-01-24T01:41:50.253Z,1548294110.253 [PitchRateCalculator] Loaded
2019-01-24T01:41:50.253Z,1548294110.253 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-01-24T01:41:50.265Z,1548294110.265 [SpeedCalculator] Loaded
2019-01-24T01:41:50.265Z,1548294110.265 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-01-24T01:41:50.286Z,1548294110.286 [TempGradientCalculator] Loaded
2019-01-24T01:41:50.286Z,1548294110.286 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-01-24T01:41:50.291Z,1548294110.291 [YawRateCalculator] Loaded
2019-01-24T01:41:50.291Z,1548294110.291 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-01-24T01:41:50.320Z,1548294110.320 [ElevatorOffsetCalculator] Loaded
2019-01-24T01:41:50.320Z,1548294110.320 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-01-24T01:41:50.320Z,1548294110.320 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-01-24T01:41:50.321Z,1548294110.321 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-01-24T01:41:50.361Z,1548294110.361 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-01-24T01:41:50.364Z,1548294110.364 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-01-24T01:41:50.365Z,1548294110.365 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-01-24T01:41:50.372Z,1548294110.372 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-01-24T01:41:50.373Z,1548294110.373 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A404E0
2019-01-24T01:41:50.373Z,1548294110.373 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 885
2019-01-24T01:41:50.378Z,1548294110.378 [Supervisor](INFO): Main Thread ID is 796
2019-01-24T01:41:50.378Z,1548294110.378 [Supervisor](DEBUG): Running supervisor.
2019-01-24T01:41:50.378Z,1548294110.378 [CommandLine ThreadHandler](INFO): Handler Thread ID is 886
2019-01-24T01:41:50.381Z,1548294110.381 [controlThread ThreadHandler](INFO): Handler Thread ID is 887
2019-01-24T01:41:50.381Z,1548294110.381 [controlThread](DEBUG): Initializing ControlThread
2019-01-24T01:41:50.382Z,1548294110.382 [SBIT](INFO): Initialize SBIT Component.
2019-01-24T01:41:50.382Z,1548294110.382 [SBIT](IMPORTANT): git: 2019-01-14A-1-gbf16392
2019-01-24T01:41:50.383Z,1548294110.383 [SBIT](INFO): git hash: bf16392e469ce9bf3416e817fec750860d5875a3
2019-01-24T01:41:50.383Z,1548294110.383 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-01-24T01:41:50.383Z,1548294110.383 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-01-24T01:41:50.384Z,1548294110.384 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-01-24T01:41:50.385Z,1548294110.385 [IBIT](INFO): Initialize IBIT Component.
2019-01-24T01:41:50.386Z,1548294110.386 [CBIT](DEBUG): Initialize CBIT Component.
2019-01-24T01:41:50.387Z,1548294110.387 [logger ThreadHandler](INFO): Handler Thread ID is 888
2019-01-24T01:41:50.397Z,1548294110.397 [CBIT](DEBUG): Initialized mux pins.
2019-01-24T01:41:50.397Z,1548294110.397 [CBIT](DEBUG): Initializing the watchdog timer.
2019-01-24T01:41:50.405Z,1548294110.405 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 889
2019-01-24T01:41:50.411Z,1548294110.411 [Radio_Surface](INFO): Powering up
2019-01-24T01:41:50.417Z,1548294110.417 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 890
2019-01-24T01:41:50.418Z,1548294110.418 [CTD_NeilBrown](INFO): Powering down
2019-01-24T01:41:50.421Z,1548294110.421 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-01-24T01:41:50.421Z,1548294110.421 [CBIT](DEBUG): Initializing heartbeat.
2019-01-24T01:41:50.449Z,1548294110.449 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 891
2019-01-24T01:41:50.450Z,1548294110.450 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-01-24T01:41:50.475Z,1548294110.475 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 892
2019-01-24T01:41:50.487Z,1548294110.487 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-01-24T01:41:50.487Z,1548294110.487 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-01-24T01:41:50.487Z,1548294110.487 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-01-24T01:41:50.487Z,1548294110.487 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-01-24T01:41:50.488Z,1548294110.488 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-01-24T01:41:50.488Z,1548294110.488 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-01-24T01:41:50.488Z,1548294110.488 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-01-24T01:41:50.488Z,1548294110.488 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-01-24T01:41:50.488Z,1548294110.488 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-01-24T01:41:50.489Z,1548294110.489 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-01-24T01:41:50.489Z,1548294110.489 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-01-24T01:41:50.489Z,1548294110.489 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-01-24T01:41:50.489Z,1548294110.489 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-01-24T01:41:50.489Z,1548294110.490 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-01-24T01:41:50.490Z,1548294110.490 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-01-24T01:41:50.490Z,1548294110.490 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-01-24T01:41:50.493Z,1548294110.493 [CBIT](DEBUG): Deactivating GF circuits.
2019-01-24T01:41:50.493Z,1548294110.493 [CBIT](DEBUG): Deactivating emergency mode.
2019-01-24T01:41:50.530Z,1548294110.530 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2019-01-24T01:41:50.531Z,1548294110.531 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T01:41:50.531Z,1548294110.531 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T01:41:50.531Z,1548294110.531 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-01-24T01:41:50.532Z,1548294110.532 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T01:41:50.532Z,1548294110.532 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T01:41:50.533Z,1548294110.533 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-01-24T01:41:50.533Z,1548294110.533 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-01-24T01:41:50.540Z,1548294110.540 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-01-24T01:41:50.542Z,1548294110.542 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-01-24T01:41:50.542Z,1548294110.542 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-01-24T01:41:50.543Z,1548294110.543 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-01-24T01:41:50.543Z,1548294110.543 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-01-24T01:41:50.544Z,1548294110.544 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-01-24T01:41:50.544Z,1548294110.544 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-01-24T01:41:50.553Z,1548294110.553 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-01-24T01:41:50.553Z,1548294110.553 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-01-24T01:41:50.554Z,1548294110.554 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-01-24T01:41:50.555Z,1548294110.555 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-01-24T01:41:50.587Z,1548294110.587 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-01-24T01:41:50.610Z,1548294110.610 [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-01-24T01:41:50.610Z,1548294110.610 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-01-24T01:41:50.690Z,1548294110.690 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-01-24T01:41:50.691Z,1548294110.691 [Default:A.Wait](DEBUG): Construct Wait.
2019-01-24T01:41:50.692Z,1548294110.692 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-01-24T01:41:50.740Z,1548294110.740 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-01-24T01:41:50.742Z,1548294110.742 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-01-24T01:41:50.756Z,1548294110.756 [Default:E.Execute](DEBUG): Construct Execute.
2019-01-24T01:41:50.759Z,1548294110.759 [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-01-24T01:41:50.769Z,1548294110.769 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,RDI_PathfinderUp,BPC1,Aanderaa_O2,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-01-24T01:41:50.793Z,1548294110.793 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-01-24T01:41:50.897Z,1548294110.897 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-01-24T01:41:51.413Z,1548294111.413 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:51.421Z,1548294111.421 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-01-24T01:41:51.435Z,1548294111.435 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:51.441Z,1548294111.441 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-01-24T01:41:51.463Z,1548294111.463 [MassServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:51.469Z,1548294111.469 [MassServo](DEBUG): Initializing MassServo.
2019-01-24T01:41:51.481Z,1548294111.481 [RudderServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:51.489Z,1548294111.489 [RudderServo](DEBUG): Initializing RudderServo.
2019-01-24T01:41:51.503Z,1548294111.503 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:51.509Z,1548294111.509 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-01-24T01:41:51.729Z,1548294111.729 [RDI_PathfinderUp](INFO): Powering down
2019-01-24T01:41:52.349Z,1548294112.349 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2019-01-24T01:41:52.349Z,1548294112.349 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2019-01-24T01:41:52.349Z,1548294112.349 [BuoyancyServo] Communications Fault, FailCount= 1
2019-01-24T01:41:52.349Z,1548294112.349 [BuoyancyServo](ERROR): Communications Fault
2019-01-24T01:41:52.557Z,1548294112.557 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-01-24T01:41:54.737Z,1548294114.737 [Aanderaa_O2](INFO): Powering down
2019-01-24T01:41:54.866Z,1548294114.866 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-01-24T01:41:54.866Z,1548294114.866 [BuoyancyServo] No Fault, FailCount= 1
2019-01-24T01:41:55.015Z,1548294115.015 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-01-24T01:41:55.134Z,1548294115.134 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-01-24T01:42:04.640Z,1548294124.640 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-01-24T01:42:17.794Z,1548294137.794 [NAL9602](INFO): Powering up NAL9602
2019-01-24T01:42:19.041Z,1548294139.041 [SBIT](IMPORTANT): Beginning Startup BIT
2019-01-24T01:42:19.046Z,1548294139.046 [CBIT](IMPORTANT): Beginning ground fault scan
2019-01-24T01:42:28.731Z,1548294148.731 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:42:29.549Z,1548294149.549 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:42:30.046Z,1548294150.046 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.021216
CHAN A1 (24V): -0.196481
CHAN A2 (12V): -0.007403
CHAN A3 (5V): -0.001978
CHAN B0 (3.3V): 0.000104
CHAN B1 (3.15aV): 0.000302
CHAN B2 (3.15bV): 0.000148
CHAN B3 (GND): 0.002310
OPEN: 0.006583
Full Scale Calc: 4.765 mA, -1.589 mA
2019-01-24T01:42:53.368Z,1548294173.368 [NAL9602](INFO): SBD MO Status=2, MOMSN=2049, MT Status=2, MTMSN=0
2019-01-24T01:42:53.368Z,1548294173.368 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:43:13.126Z,1548294193.126 [SBIT](IMPORTANT): SBIT PASSED
2019-01-24T01:43:13.222Z,1548294193.222 [CommandLine](IMPORTANT): got command configSet list
2019-01-24T01:43:13.222Z,1548294193.222 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-01-24T01:43:13.223Z,1548294193.223 [CommandLine](IMPORTANT): AHRS_M2.readMagnetics=1 bool;

2019-01-24T01:43:13.223Z,1548294193.223 [CommandLine](IMPORTANT): NAL9602.requestGGA=1 bool;

2019-01-24T01:43:13.517Z,1548294193.517 [MissionManager](IMPORTANT): Started mission Startup
2019-01-24T01:43:13.517Z,1548294193.517 [Startup] Running Loop=1
2019-01-24T01:43:13.517Z,1548294193.517 [Startup](DEBUG): Aggregate::initialize Startup
2019-01-24T01:43:13.517Z,1548294193.517 [Startup:A.GoToSurface] Running Loop=1
2019-01-24T01:43:13.517Z,1548294193.517 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-01-24T01:43:13.518Z,1548294193.518 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-01-24T01:43:13.518Z,1548294193.518 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-01-24T01:43:13.519Z,1548294193.519 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-01-24T01:43:13.519Z,1548294193.519 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-01-24T01:43:13.519Z,1548294193.519 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-01-24T01:43:13.525Z,1548294193.525 [Startup:StartupSatComms] Running Loop=1
2019-01-24T01:43:13.525Z,1548294193.525 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-01-24T01:43:13.525Z,1548294193.525 [Startup:StartupSatComms:A] Running Loop=1
2019-01-24T01:43:13.936Z,1548294193.936 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-01-24T01:44:13.536Z,1548294253.536 [Startup:StartupSatComms:A](INFO): Timed out from 2019-01-24T01:43:13.5Z
2019-01-24T01:44:13.536Z,1548294253.536 [Startup:StartupSatComms:A] Stopped
2019-01-24T01:44:13.536Z,1548294253.536 [Startup:StartupSatComms:B] Running Loop=1
2019-01-24T01:44:13.929Z,1548294253.929 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-01-24T01:44:50.718Z,1548294290.718 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = 1000039.346812
2019-01-24T01:44:50.718Z,1548294290.718 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-01-24T01:44:50.718Z,1548294290.718 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-01-24T01:44:50.722Z,1548294290.722 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = 1000174.878046
2019-01-24T01:44:50.722Z,1548294290.722 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-01-24T01:44:50.722Z,1548294290.722 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-01-24T01:44:50.743Z,1548294290.743 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-01-24T01:44:50.744Z,1548294290.744 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-01-24T01:44:51.137Z,1548294291.137 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-01-24T01:44:51.137Z,1548294291.137 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-01-24T01:44:51.137Z,1548294291.137 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-01-24T01:44:51.138Z,1548294291.138 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-01-24T01:44:51.519Z,1548294291.519 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2019-01-24T01:44:51.520Z,1548294291.520 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T01:44:51.520Z,1548294291.520 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T01:44:51.520Z,1548294291.520 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-01-24T01:44:51.522Z,1548294291.522 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T01:44:51.522Z,1548294291.522 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T01:45:16.487Z,1548294316.487 [Startup:StartupSatComms:B](INFO): Timed out from 2019-01-24T01:44:13.5Z
2019-01-24T01:45:16.487Z,1548294316.487 [Startup:StartupSatComms:B] Stopped
2019-01-24T01:45:16.487Z,1548294316.487 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-01-24T01:45:16.488Z,1548294316.488 [Startup:StartupSatComms] Stopped
2019-01-24T01:45:16.488Z,1548294316.488 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-01-24T01:45:16.488Z,1548294316.488 [Startup](INFO): Completed Startup
2019-01-24T01:45:16.489Z,1548294316.489 [MissionManager](INFO): Startup is completed.
2019-01-24T01:45:16.489Z,1548294316.489 [MissionManager](INFO): Uninitializing Mission Startup
2019-01-24T01:45:16.489Z,1548294316.489 [Startup] Stopped
2019-01-24T01:45:16.489Z,1548294316.489 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-01-24T01:45:16.489Z,1548294316.489 [Startup:A.GoToSurface] Stopped
2019-01-24T01:45:16.489Z,1548294316.489 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-01-24T01:45:16.628Z,1548294316.628 [MissionManager](IMPORTANT): Started mission Default
2019-01-24T01:45:16.628Z,1548294316.628 [Default] Running Loop=1
2019-01-24T01:45:16.628Z,1548294316.628 [Default](DEBUG): Aggregate::initialize Default
2019-01-24T01:45:16.628Z,1548294316.628 [Default:B.GoToSurface] Running Loop=1
2019-01-24T01:45:16.628Z,1548294316.628 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-01-24T01:45:16.633Z,1548294316.633 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-01-24T01:45:16.633Z,1548294316.633 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-01-24T01:45:16.633Z,1548294316.633 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-01-24T01:45:16.634Z,1548294316.634 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-01-24T01:45:16.634Z,1548294316.634 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-01-24T01:45:16.634Z,1548294316.634 [Default:A.Wait] Running Loop=1
2019-01-24T01:45:16.634Z,1548294316.634 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:45:17.330Z,1548294317.330 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.007683
2019-01-24T01:45:31.268Z,1548294331.268 [Default:A.Wait](INFO): Done Waiting.
2019-01-24T01:45:31.268Z,1548294331.268 [Default:A.Wait] Stopped
2019-01-24T01:45:31.268Z,1548294331.268 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:45:31.467Z,1548294331.467 [Default:CheckIn] Running Loop=1
2019-01-24T01:45:31.467Z,1548294331.467 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:45:31.467Z,1548294331.467 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:45:31.792Z,1548294331.792 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-01-24T01:47:08.930Z,1548294428.930 [CommandLine](IMPORTANT): got command failComponent
2019-01-24T01:47:08.931Z,1548294428.931 [CommandLine](IMPORTANT): Failed components:
2019-01-24T01:47:08.931Z,1548294428.931 [CommandLine](IMPORTANT): No failed Components.
2019-01-24T01:47:32.170Z,1548294452.170 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T01:47:32.989Z,1548294452.989 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:47:33.372Z,1548294453.372 [NAL9602](DEBUG): Parsing GGA sentence: $GPGGA,014732.00,3648.16392,N,12147.27960,W,1,5,1.68,-20.6,M,-30.7,M,,*4A
2019-01-24T01:47:33.392Z,1548294453.392 [NAL9602](INFO): GPS fix at 20190124T014732: (36.802732, -121.787993)
2019-01-24T01:47:33.472Z,1548294453.472 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:47:33.472Z,1548294453.472 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:47:33.855Z,1548294453.855 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-01-24T01:47:43.777Z,1548294463.777 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T013347/Courier0007.lzma
2019-01-24T01:47:44.548Z,1548294464.548 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Courier0007.lzma.bak
2019-01-24T01:47:44.548Z,1548294464.548 [DataOverHttps](INFO): SBD MOMSN=9599257
2019-01-24T01:47:55.751Z,1548294475.751 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T013347/Courier0010.lzma
2019-01-24T01:47:56.525Z,1548294476.525 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Courier0010.lzma.bak
2019-01-24T01:47:56.525Z,1548294476.525 [DataOverHttps](INFO): SBD MOMSN=9599259
2019-01-24T01:48:06.385Z,1548294486.385 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20190124T014139/Courier0004.lzma
2019-01-24T01:48:06.388Z,1548294486.388 [NAL9602](INFO): Powering down
2019-01-24T01:48:07.164Z,1548294487.164 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Courier0004.lzma.bak
2019-01-24T01:48:07.164Z,1548294487.164 [DataOverHttps](INFO): SBD MOMSN=9599261
2019-01-24T01:48:18.160Z,1548294498.160 [DataOverHttps](INFO): Sending 763 bytes from file Logs/20190124T013347/Express0001.lzma
2019-01-24T01:48:18.936Z,1548294498.936 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Express0001.lzma.bak
2019-01-24T01:48:18.936Z,1548294498.936 [DataOverHttps](INFO): SBD MOMSN=9599268
2019-01-24T01:48:30.192Z,1548294510.192 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20190124T013347/Express0005.lzma
2019-01-24T01:48:30.956Z,1548294510.956 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Express0005.lzma.bak
2019-01-24T01:48:30.956Z,1548294510.956 [DataOverHttps](INFO): SBD MOMSN=9599290
2019-01-24T01:48:41.714Z,1548294521.714 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20190124T013347/Express0008.lzma
2019-01-24T01:48:42.488Z,1548294522.488 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Express0008.lzma.bak
2019-01-24T01:48:42.488Z,1548294522.488 [DataOverHttps](INFO): SBD MOMSN=9599294
2019-01-24T01:48:49.928Z,1548294529.928 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-01-24T01:48:53.953Z,1548294533.953 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190124T013347/Express0011.lzma
2019-01-24T01:48:54.748Z,1548294534.748 [DataOverHttps](INFO): Moved sent file to Logs/20190124T013347/Express0011.lzma.bak
2019-01-24T01:48:54.748Z,1548294534.748 [DataOverHttps](INFO): SBD MOMSN=9599298
2019-01-24T01:49:06.331Z,1548294546.331 [DataOverHttps](INFO): Sending 708 bytes from file Logs/20190124T014139/Express0001.lzma
2019-01-24T01:49:07.104Z,1548294547.104 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0001.lzma.bak
2019-01-24T01:49:07.104Z,1548294547.104 [DataOverHttps](INFO): SBD MOMSN=9599300
2019-01-24T01:49:17.715Z,1548294557.715 [DataOverHttps](INFO): Sending 347 bytes from file Logs/20190124T014139/Express0005.lzma
2019-01-24T01:49:18.441Z,1548294558.441 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0005.lzma.bak
2019-01-24T01:49:18.441Z,1548294558.441 [DataOverHttps](INFO): SBD MOMSN=9599316
2019-01-24T01:49:20.772Z,1548294560.772 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:49:20.772Z,1548294560.772 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:49:20.772Z,1548294560.772 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:54:20.945Z,1548294860.945 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:54:20.945Z,1548294860.945 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:54:20.945Z,1548294860.945 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:54:20.945Z,1548294860.945 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:54:21.314Z,1548294861.314 [Default:CheckIn:D] Stopped
2019-01-24T01:54:21.315Z,1548294861.315 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:54:21.742Z,1548294861.742 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.078070 min 
2019-01-24T01:54:21.743Z,1548294861.743 [Default:CheckIn:E] Stopped
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn] Stopped
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn](INFO): Running loop #2
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn] Running Loop=2
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:54:21.744Z,1548294861.744 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:54:22.486Z,1548294862.486 [NAL9602](INFO): Powering up
2019-01-24T01:54:33.291Z,1548294873.291 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:54:34.101Z,1548294874.101 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:59:22.609Z,1548295162.609 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T01:54:21.7Z
2019-01-24T01:59:22.610Z,1548295162.610 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:59:22.610Z,1548295162.610 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:59:28.598Z,1548295168.598 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190124T014139/Courier0007.lzma
2019-01-24T01:59:29.392Z,1548295169.392 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Courier0007.lzma.bak
2019-01-24T01:59:29.392Z,1548295169.392 [DataOverHttps](INFO): SBD MOMSN=9599345
2019-01-24T01:59:36.886Z,1548295176.886 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T01:59:41.069Z,1548295181.069 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20190124T014139/Express0008.lzma
2019-01-24T01:59:42.707Z,1548295182.707 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0008.lzma.bak
2019-01-24T01:59:42.707Z,1548295182.707 [DataOverHttps](INFO): SBD MOMSN=9599347
2019-01-24T01:59:44.803Z,1548295184.803 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:59:44.803Z,1548295184.803 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:59:44.803Z,1548295184.803 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T02:00:07.326Z,1548295207.326 [NAL9602](INFO): Powering down
2019-01-24T02:02:10.606Z,1548295330.606 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-01-24T02:04:44.983Z,1548295484.983 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T02:04:44.983Z,1548295484.983 [Default:CheckIn:C.Wait] Stopped
2019-01-24T02:04:44.983Z,1548295484.983 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T02:04:44.983Z,1548295484.983 [Default:CheckIn:D] Running Loop=1
2019-01-24T02:04:45.394Z,1548295485.394 [Default:CheckIn:D] Stopped
2019-01-24T02:04:45.395Z,1548295485.395 [Default:CheckIn:E] Running Loop=1
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.479437 min 
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn:E] Stopped
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn] Stopped
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn](INFO): Running loop #3
2019-01-24T02:04:45.775Z,1548295485.775 [Default:CheckIn] Running Loop=3
2019-01-24T02:04:45.776Z,1548295485.776 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T02:04:45.776Z,1548295485.776 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T02:04:46.542Z,1548295486.542 [NAL9602](INFO): Powering up
2019-01-24T02:04:57.743Z,1548295497.743 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:04:58.543Z,1548295498.543 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T02:04:58.543Z,1548295498.543 [NAL9602] Data Fault, FailCount= 1
2019-01-24T02:04:58.543Z,1548295498.543 [NAL9602](ERROR): Data Fault
2019-01-24T02:04:58.614Z,1548295498.614 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T02:04:58.934Z,1548295498.934 [NAL9602](INFO): Powering down
2019-01-24T02:04:59.788Z,1548295499.788 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T02:04:59.788Z,1548295499.788 [NAL9602] No Fault, FailCount= 1
2019-01-24T02:05:29.086Z,1548295529.086 [NAL9602](INFO): Powering up NAL9602
2019-01-24T02:05:41.625Z,1548295541.625 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:05:42.437Z,1548295542.437 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:09:49.225Z,1548295789.225 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T02:04:45.8Z
2019-01-24T02:09:49.225Z,1548295789.225 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T02:09:49.225Z,1548295789.225 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T02:09:56.484Z,1548295796.484 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T014139/Courier0010.lzma
2019-01-24T02:09:57.255Z,1548295797.255 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Courier0010.lzma.bak
2019-01-24T02:09:57.255Z,1548295797.255 [DataOverHttps](INFO): SBD MOMSN=9599363
2019-01-24T02:10:08.006Z,1548295808.006 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20190124T014139/Express0011.lzma
2019-01-24T02:10:08.764Z,1548295808.764 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0011.lzma.bak
2019-01-24T02:10:08.764Z,1548295808.764 [DataOverHttps](INFO): SBD MOMSN=9599365
2019-01-24T02:10:11.102Z,1548295811.102 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T02:10:11.102Z,1548295811.102 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T02:10:11.102Z,1548295811.102 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T02:10:44.538Z,1548295844.538 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T02:11:15.038Z,1548295875.038 [NAL9602](INFO): Powering down
2019-01-24T02:15:11.319Z,1548296111.319 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T02:15:11.319Z,1548296111.319 [Default:CheckIn:C.Wait] Stopped
2019-01-24T02:15:11.319Z,1548296111.319 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T02:15:11.319Z,1548296111.319 [Default:CheckIn:D] Running Loop=1
2019-01-24T02:15:11.716Z,1548296111.716 [Default:CheckIn:D] Stopped
2019-01-24T02:15:11.716Z,1548296111.716 [Default:CheckIn:E] Running Loop=1
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.918123 min 
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn:E] Stopped
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn] Stopped
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn](INFO): Running loop #4
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn] Running Loop=4
2019-01-24T02:15:12.111Z,1548296112.111 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T02:15:12.112Z,1548296112.112 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T02:15:12.870Z,1548296112.870 [NAL9602](INFO): Powering up
2019-01-24T02:15:24.070Z,1548296124.070 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:15:24.881Z,1548296124.881 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:15:55.826Z,1548296155.826 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-01-24T02:15:55.902Z,1548296155.902 [NAL9602](FAULT): received: 
+CSQ:0

OK49, 2, 0, 0, 0

OK
2019-01-24T02:15:55.902Z,1548296155.902 [NAL9602] Data Fault, FailCount= 2
2019-01-24T02:15:55.902Z,1548296155.902 [NAL9602](ERROR): Data Fault
2019-01-24T02:15:55.966Z,1548296155.966 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T02:15:56.222Z,1548296156.222 [NAL9602](INFO): Powering down
2019-01-24T02:15:57.076Z,1548296157.076 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T02:15:57.076Z,1548296157.076 [NAL9602] No Fault, FailCount= 2
2019-01-24T02:16:26.490Z,1548296186.490 [NAL9602](INFO): Powering up NAL9602
2019-01-24T02:16:37.699Z,1548296197.699 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:16:38.503Z,1548296198.503 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T02:16:38.503Z,1548296198.503 [NAL9602] Data Fault, FailCount= 3
2019-01-24T02:16:38.504Z,1548296198.504 [NAL9602](ERROR): Data Fault
2019-01-24T02:16:38.572Z,1548296198.572 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T02:16:38.890Z,1548296198.890 [NAL9602](INFO): Powering down
2019-01-24T02:16:42.588Z,1548296202.588 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T02:16:42.588Z,1548296202.588 [NAL9602] No Fault, FailCount= 3
2019-01-24T02:17:09.010Z,1548296229.010 [NAL9602](INFO): Powering up NAL9602
2019-01-24T02:17:19.974Z,1548296239.974 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:17:20.791Z,1548296240.791 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:20:14.127Z,1548296414.127 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T02:15:12.1Z
2019-01-24T02:20:14.127Z,1548296414.127 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T02:20:14.127Z,1548296414.127 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T02:20:20.114Z,1548296420.114 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T014139/Courier0013.lzma
2019-01-24T02:20:20.903Z,1548296420.903 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Courier0013.lzma.bak
2019-01-24T02:20:20.903Z,1548296420.903 [DataOverHttps](INFO): SBD MOMSN=9599392
2019-01-24T02:20:27.130Z,1548296427.130 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T02:20:32.152Z,1548296432.152 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20190124T014139/Express0014.lzma
2019-01-24T02:20:32.920Z,1548296432.920 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0014.lzma.bak
2019-01-24T02:20:32.920Z,1548296432.920 [DataOverHttps](INFO): SBD MOMSN=9599394
2019-01-24T02:20:35.233Z,1548296435.233 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T02:20:35.233Z,1548296435.233 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T02:20:35.234Z,1548296435.234 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T02:20:57.819Z,1548296457.819 [NAL9602](INFO): Powering down
2019-01-24T02:23:00.732Z,1548296580.732 [RDI_Pathfinder](ERROR): only read 3 of 5 data items
2019-01-24T02:23:00.732Z,1548296580.732 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-3268,V
2019-01-24T02:25:35.690Z,1548296735.690 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T02:25:35.691Z,1548296735.691 [Default:CheckIn:C.Wait] Stopped
2019-01-24T02:25:35.691Z,1548296735.691 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T02:25:35.691Z,1548296735.691 [Default:CheckIn:D] Running Loop=1
2019-01-24T02:25:36.115Z,1548296736.115 [Default:CheckIn:D] Stopped
2019-01-24T02:25:36.115Z,1548296736.115 [Default:CheckIn:E] Running Loop=1
2019-01-24T02:25:36.547Z,1548296736.547 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.324780 min 
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn:E] Stopped
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn] Stopped
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn](INFO): Running loop #5
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn] Running Loop=5
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T02:25:36.548Z,1548296736.548 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T02:25:37.280Z,1548296737.280 [NAL9602](INFO): Powering up
2019-01-24T02:25:48.450Z,1548296748.450 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:25:49.281Z,1548296749.281 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:26:20.226Z,1548296780.226 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-01-24T02:26:20.305Z,1548296780.305 [NAL9602](FAULT): received: 
+CSQ:0

OK49, 2, 0, 0, 0

OK
2019-01-24T02:26:20.305Z,1548296780.305 [NAL9602] Data Fault, FailCount= 4
2019-01-24T02:26:20.305Z,1548296780.305 [NAL9602](ERROR): Data Fault
2019-01-24T02:26:20.395Z,1548296780.395 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T02:26:20.626Z,1548296780.626 [NAL9602](INFO): Powering down
2019-01-24T02:26:21.524Z,1548296781.524 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T02:26:21.524Z,1548296781.524 [NAL9602] No Fault, FailCount= 4
2019-01-24T02:26:50.810Z,1548296810.810 [NAL9602](INFO): Powering up NAL9602
2019-01-24T02:27:02.014Z,1548296822.014 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:27:02.825Z,1548296822.825 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:27:56.643Z,1548296876.643 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-01-24T02:27:56.643Z,1548296876.643 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,190123193530440.1,   0.0,1448.9,  0
2019-01-24T02:29:12.643Z,1548296952.643 [RDI_Pathfinder](ERROR): Unknown system health message
2019-01-24T02:29:12.644Z,1548296952.644 [RDI_Pathfinder] Hardware Fault, FailCount= 1
2019-01-24T02:29:12.644Z,1548296952.644 [RDI_Pathfinder](ERROR): Hardware Fault
2019-01-24T02:29:12.701Z,1548296952.701 [CBIT](ERROR): Hardware Fault in component: RDI_Pathfinder
2019-01-24T02:29:13.097Z,1548296953.097 [RDI_Pathfinder](INFO): Powering down
2019-01-24T02:29:13.861Z,1548296953.861 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-01-24T02:29:13.862Z,1548296953.862 [RDI_Pathfinder] No Fault, FailCount= 0
2019-01-24T02:29:27.160Z,1548296967.160 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-01-24T02:29:29.134Z,1548296969.134 [RDI_Pathfinder](ERROR): Failed to parse:
:HM,G,D,0e8c,0ffe,  0.000, 0.000, 0.000
2019-01-24T02:30:37.711Z,1548297037.711 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T02:25:36.5Z
2019-01-24T02:30:37.711Z,1548297037.711 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T02:30:37.711Z,1548297037.711 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T02:30:43.300Z,1548297043.300 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T014139/Courier0016.lzma
2019-01-24T02:30:44.064Z,1548297044.064 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Courier0016.lzma.bak
2019-01-24T02:30:44.064Z,1548297044.064 [DataOverHttps](INFO): SBD MOMSN=9599421
2019-01-24T02:30:51.393Z,1548297051.393 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T02:30:55.094Z,1548297055.094 [DataOverHttps](INFO): Sending 236 bytes from file Logs/20190124T014139/Express0017.lzma
2019-01-24T02:30:55.876Z,1548297055.876 [DataOverHttps](INFO): Moved sent file to Logs/20190124T014139/Express0017.lzma.bak
2019-01-24T02:30:55.876Z,1548297055.876 [DataOverHttps](INFO): SBD MOMSN=9599423
2019-01-24T02:30:58.185Z,1548297058.185 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T02:30:58.185Z,1548297058.185 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T02:30:58.185Z,1548297058.185 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T02:31:22.151Z,1548297082.151 [NAL9602](INFO): Powering down
2019-01-24T02:35:58.352Z,1548297358.352 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T02:35:58.352Z,1548297358.352 [Default:CheckIn:C.Wait] Stopped
2019-01-24T02:35:58.352Z,1548297358.352 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T02:35:58.352Z,1548297358.352 [Default:CheckIn:D] Running Loop=1
2019-01-24T02:35:58.714Z,1548297358.714 [Default:CheckIn:D] Stopped
2019-01-24T02:35:58.714Z,1548297358.714 [Default:CheckIn:E] Running Loop=1
2019-01-24T02:35:59.161Z,1548297359.161 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.701428 min 
2019-01-24T02:35:59.161Z,1548297359.161 [Default:CheckIn:E] Stopped
2019-01-24T02:35:59.161Z,1548297359.161 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T02:35:59.161Z,1548297359.161 [Default:CheckIn] Stopped
2019-01-24T02:35:59.161Z,1548297359.161 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T02:35:59.162Z,1548297359.162 [Default:CheckIn](INFO): Running loop #6
2019-01-24T02:35:59.162Z,1548297359.162 [Default:CheckIn] Running Loop=6
2019-01-24T02:35:59.162Z,1548297359.162 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T02:35:59.162Z,1548297359.162 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T02:35:59.878Z,1548297359.878 [NAL9602](INFO): Powering up
2019-01-24T02:36:10.686Z,1548297370.686 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:36:11.487Z,1548297371.487 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T02:36:11.488Z,1548297371.488 [NAL9602] Data Fault, FailCount= 5
2019-01-24T02:36:11.488Z,1548297371.488 [NAL9602](ERROR): Data Fault
2019-01-24T02:36:11.538Z,1548297371.538 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T02:36:11.538Z,1548297371.538 [CBIT](CRITICAL): Data Fault in component: NAL9602
2019-01-24T02:36:11.878Z,1548297371.878 [NAL9602](INFO): Powering down
2019-01-24T02:36:11.936Z,1548297371.936 [CommandLine](FAULT): Scheduling is paused
2019-01-24T02:36:11.949Z,1548297371.949 [CBIT](INFO): Critical error at 20190124T023611
2019-01-24T02:36:11.949Z,1548297371.949 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-01-24T02:38:11.635Z,1548297491.635 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T02:38:11.635Z,1548297491.635 [NAL9602] No Fault, FailCount= 5
2019-01-24T02:38:11.987Z,1548297491.987 [NAL9602](INFO): Powering up NAL9602
2019-01-24T02:38:23.187Z,1548297503.187 [NAL9602](INFO): NAL9602 initialized
2019-01-24T02:38:23.993Z,1548297503.993 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:39:57.604Z,1548297597.604 [NAL9602](IMPORTANT): SBD MO Status=0, MOMSN=2049, MT Status=1, MTMSN=106
2019-01-24T02:39:57.604Z,1548297597.604 [NAL9602](INFO): Data available in MT queue
2019-01-24T02:39:58.094Z,1548297598.094 [NAL9602](INFO): Received command:restart app
2019-01-24T02:39:58.161Z,1548297598.161 [CommandLine](IMPORTANT): got command restart application
2019-01-24T02:39:58.813Z,1548297598.813 [NAL9602](DEBUG): Fix Requested
2019-01-24T02:39:59.168Z,1548297599.168 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:39:59.168Z,1548297599.168 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.253Z,1548297599.253 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-01-24T02:39:59.253Z,1548297599.253 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.254Z,1548297599.254 [CommandLine](INFO): Join timeout helper Thread ID is 1073
2019-01-24T02:39:59.254Z,1548297599.254 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-01-24T02:39:59.254Z,1548297599.254 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.255Z,1548297599.255 [NavChartDb](INFO): Join timeout helper Thread ID is 1074
2019-01-24T02:39:59.473Z,1548297599.473 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:39:59.473Z,1548297599.473 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.489Z,1548297599.489 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-01-24T02:39:59.489Z,1548297599.489 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.489Z,1548297599.489 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 1075
2019-01-24T02:39:59.649Z,1548297599.649 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:39:59.649Z,1548297599.649 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-01-24T02:39:59.650Z,1548297599.650 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.665Z,1548297599.665 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-01-24T02:39:59.665Z,1548297599.665 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.665Z,1548297599.665 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 1076
2019-01-24T02:39:59.829Z,1548297599.829 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:39:59.829Z,1548297599.829 [CTD_NeilBrown](INFO): Powering down
2019-01-24T02:39:59.845Z,1548297599.845 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.865Z,1548297599.865 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-01-24T02:39:59.865Z,1548297599.865 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:39:59.865Z,1548297599.865 [Radio_Surface](INFO): Join timeout helper Thread ID is 1077
2019-01-24T02:40:00.129Z,1548297600.129 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:40:00.129Z,1548297600.129 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.150Z,1548297600.150 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-01-24T02:40:00.150Z,1548297600.150 [logger ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.150Z,1548297600.150 [logger](INFO): Join timeout helper Thread ID is 1078
2019-01-24T02:40:00.151Z,1548297600.151 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:40:00.151Z,1548297600.151 [logger ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.152Z,1548297600.152 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-01-24T02:40:00.152Z,1548297600.152 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.152Z,1548297600.152 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-01-24T02:40:00.152Z,1548297600.152 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.153Z,1548297600.153 [controlThread](INFO): Join timeout helper Thread ID is 1079
2019-01-24T02:40:00.385Z,1548297600.385 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-01-24T02:40:00.385Z,1548297600.385 [controlThread](DEBUG): Uninitializing ControlThread
2019-01-24T02:40:00.386Z,1548297600.386 [AHRS_M2](INFO): Powering down
2019-01-24T02:40:00.458Z,1548297600.458 [NAL9602](INFO): Powering down
2019-01-24T02:40:00.529Z,1548297600.529 [RDI_Pathfinder](INFO): Powering down
2019-01-24T02:40:00.530Z,1548297600.530 [RDI_PathfinderUp](INFO): Powering down
2019-01-24T02:40:00.531Z,1548297600.531 [Aanderaa_O2](INFO): Powering down
2019-01-24T02:40:00.532Z,1548297600.532 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-01-24T02:40:00.533Z,1548297600.533 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-01-24T02:40:00.533Z,1548297600.533 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-01-24T02:40:00.534Z,1548297600.534 [MissionManager](INFO): Uninitializing Mission Default
2019-01-24T02:40:00.534Z,1548297600.534 [Default] Stopped
2019-01-24T02:40:00.534Z,1548297600.534 [Default](DEBUG): Aggregate::uninitialize Default
2019-01-24T02:40:00.534Z,1548297600.534 [Default:B.GoToSurface] Stopped
2019-01-24T02:40:00.534Z,1548297600.534 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-01-24T02:40:00.534Z,1548297600.534 [Default:CheckIn] Stopped
2019-01-24T02:40:00.534Z,1548297600.534 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T02:40:00.534Z,1548297600.534 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T02:40:00.537Z,1548297600.537 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-01-24T02:40:00.538Z,1548297600.538 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-01-24T02:40:00.538Z,1548297600.538 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-01-24T02:40:00.538Z,1548297600.538 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-01-24T02:40:00.539Z,1548297600.539 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-01-24T02:40:00.539Z,1548297600.539 [BuoyancyServo](INFO): Powering down
2019-01-24T02:40:00.553Z,1548297600.553 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-01-24T02:40:00.553Z,1548297600.553 [ElevatorServo](INFO): Powering down
2019-01-24T02:40:00.554Z,1548297600.554 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-01-24T02:40:00.554Z,1548297600.554 [MassServo](INFO): Powering down
2019-01-24T02:40:00.555Z,1548297600.555 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-01-24T02:40:00.555Z,1548297600.555 [RudderServo](INFO): Powering down
2019-01-24T02:40:00.556Z,1548297600.556 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-01-24T02:40:00.556Z,1548297600.556 [ThrusterServo](INFO): Powering down
2019-01-24T02:40:00.556Z,1548297600.556 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-01-24T02:40:00.557Z,1548297600.557 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-01-24T02:40:00.557Z,1548297600.557 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-01-24T02:40:00.557Z,1548297600.557 [CBIT](DEBUG): Powering off loads.
2019-01-24T02:40:00.569Z,1548297600.569 [CBIT](DEBUG): Disabling WDT.
2019-01-24T02:40:00.581Z,1548297600.581 [CBIT](DEBUG): Opening all GF detection circuits.
2019-01-24T02:40:00.582Z,1548297600.582 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.679Z,1548297600.679 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.720Z,1548297600.720 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.722Z,1548297600.722 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.744Z,1548297600.744 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-01-24T02:40:00.810Z,1548297600.810 [logger ThreadHandler](INFO): Thread cancelled.