2019-01-24T00:31:47.355Z,1548289907.355 [Supervisor](DEBUG): Initializing supervisor.
2019-01-24T00:31:47.358Z,1548289907.358 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-01-24T00:31:47.358Z,1548289907.358 [SyncHandler](INFO): Protected caller Thread ID is 3311
2019-01-24T00:31:47.359Z,1548289907.359 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-01-24T00:31:47.360Z,1548289907.360 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-01-24T00:31:47.360Z,1548289907.360 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3312
2019-01-24T00:31:47.363Z,1548289907.363 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-01-24T00:31:47.374Z,1548289907.374 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-01-24T00:31:47.375Z,1548289907.375 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-01-24T00:31:47.375Z,1548289907.375 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3313
2019-01-24T00:31:47.376Z,1548289907.376 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-01-24T00:31:47.377Z,1548289907.377 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-01-24T00:31:47.378Z,1548289907.378 [logger ThreadHandler](INFO): Protected caller Thread ID is 3314
2019-01-24T00:31:47.379Z,1548289907.379 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-01-24T00:31:47.380Z,1548289907.380 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-01-24T00:31:47.381Z,1548289907.381 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-01-24T00:31:47.793Z,1548289907.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-01-24T00:31:47.793Z,1548289907.793 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-01-24T00:31:48.237Z,1548289908.237 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-01-24T00:31:48.238Z,1548289908.238 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-01-24T00:31:48.562Z,1548289908.562 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-01-24T00:31:48.563Z,1548289908.563 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-01-24T00:31:48.755Z,1548289908.755 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-01-24T00:31:48.756Z,1548289908.756 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-01-24T00:31:49.199Z,1548289909.199 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-01-24T00:31:49.199Z,1548289909.199 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-01-24T00:31:49.672Z,1548289909.672 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-01-24T00:31:49.672Z,1548289909.672 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-01-24T00:31:49.777Z,1548289909.777 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-01-24T00:31:49.777Z,1548289909.777 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-01-24T00:31:49.973Z,1548289909.973 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-01-24T00:31:49.974Z,1548289909.974 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-01-24T00:31:50.118Z,1548289910.118 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-01-24T00:31:50.119Z,1548289910.119 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-01-24T00:31:50.200Z,1548289910.200 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-01-24T00:31:50.409Z,1548289910.409 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-01-24T00:31:50.410Z,1548289910.410 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-01-24T00:31:50.512Z,1548289910.512 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-01-24T00:31:50.513Z,1548289910.513 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-01-24T00:31:50.610Z,1548289910.610 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-01-24T00:31:50.610Z,1548289910.610 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-01-24T00:31:50.758Z,1548289910.758 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-01-24T00:31:50.759Z,1548289910.759 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-01-24T00:31:51.076Z,1548289911.076 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-01-24T00:31:51.078Z,1548289911.078 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-01-24T00:31:51.079Z,1548289911.079 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-01-24T00:31:51.212Z,1548289911.212 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-01-24T00:31:51.444Z,1548289911.444 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-01-24T00:31:51.444Z,1548289911.444 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-01-24T00:31:51.976Z,1548289911.976 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-01-24T00:31:52.410Z,1548289912.410 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-01-24T00:31:52.723Z,1548289912.723 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-01-24T00:31:52.916Z,1548289912.916 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-01-24T00:31:53.002Z,1548289913.002 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-01-24T00:31:53.101Z,1548289913.101 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-01-24T00:31:53.196Z,1548289913.196 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-01-24T00:31:53.279Z,1548289913.279 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-01-24T00:31:53.388Z,1548289913.388 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-01-24T00:31:53.393Z,1548289913.393 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-01-24T00:31:53.523Z,1548289913.523 [SBIT](DEBUG): Construct Startup Built In Test.
2019-01-24T00:31:53.552Z,1548289913.552 [SBIT] Loaded
2019-01-24T00:31:53.553Z,1548289913.553 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-01-24T00:31:53.553Z,1548289913.553 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-01-24T00:31:53.580Z,1548289913.580 [IBIT] Loaded
2019-01-24T00:31:53.581Z,1548289913.581 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-01-24T00:31:53.584Z,1548289913.584 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-01-24T00:31:53.963Z,1548289913.963 [CBIT] Loaded
2019-01-24T00:31:53.963Z,1548289913.963 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-01-24T00:31:53.963Z,1548289913.963 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-01-24T00:31:53.964Z,1548289913.964 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-01-24T00:31:54.086Z,1548289914.086 [BuoyancyServo] Loaded
2019-01-24T00:31:54.086Z,1548289914.086 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-01-24T00:31:54.101Z,1548289914.101 [ElevatorServo] Loaded
2019-01-24T00:31:54.101Z,1548289914.101 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-01-24T00:31:54.114Z,1548289914.114 [MassServo] Loaded
2019-01-24T00:31:54.115Z,1548289914.115 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-01-24T00:31:54.129Z,1548289914.129 [RudderServo] Loaded
2019-01-24T00:31:54.130Z,1548289914.130 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-01-24T00:31:54.144Z,1548289914.144 [ThrusterServo] Loaded
2019-01-24T00:31:54.144Z,1548289914.144 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-01-24T00:31:54.145Z,1548289914.145 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-01-24T00:31:54.145Z,1548289914.145 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-01-24T00:31:54.246Z,1548289914.246 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-01-24T00:31:54.246Z,1548289914.246 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-01-24T00:31:54.303Z,1548289914.303 [DeadReckonUsingSpeedCalculator] Loaded
2019-01-24T00:31:54.303Z,1548289914.303 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2019-01-24T00:31:54.319Z,1548289914.319 [NavChart] Loaded
2019-01-24T00:31:54.319Z,1548289914.319 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-01-24T00:31:54.323Z,1548289914.323 [UniversalFixResidualReporter] Loaded
2019-01-24T00:31:54.323Z,1548289914.323 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-01-24T00:31:54.324Z,1548289914.324 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-01-24T00:31:54.324Z,1548289914.324 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-01-24T00:31:54.337Z,1548289914.337 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-01-24T00:31:54.337Z,1548289914.337 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-01-24T00:31:54.567Z,1548289914.567 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-01-24T00:31:54.567Z,1548289914.567 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-01-24T00:31:54.878Z,1548289914.878 [AHRS_M2] Loaded
2019-01-24T00:31:54.878Z,1548289914.878 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-01-24T00:31:54.948Z,1548289914.948 [DataOverHttps] Loaded
2019-01-24T00:31:54.949Z,1548289914.949 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2019-01-24T00:31:54.961Z,1548289914.961 [Depth_Keller] Loaded
2019-01-24T00:31:54.962Z,1548289914.962 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-01-24T00:31:54.966Z,1548289914.966 [DropWeight] Loaded
2019-01-24T00:31:54.967Z,1548289914.967 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-01-24T00:31:55.054Z,1548289915.054 [NAL9602] Loaded
2019-01-24T00:31:55.054Z,1548289915.054 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-01-24T00:31:55.060Z,1548289915.060 [Onboard] Loaded
2019-01-24T00:31:55.060Z,1548289915.060 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-01-24T00:31:55.067Z,1548289915.067 [Radio_Surface] Loaded
2019-01-24T00:31:55.067Z,1548289915.067 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-01-24T00:31:55.068Z,1548289915.068 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408474E0
2019-01-24T00:31:55.068Z,1548289915.068 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3393
2019-01-24T00:31:55.095Z,1548289915.095 [RDI_Pathfinder] Loaded
2019-01-24T00:31:55.095Z,1548289915.095 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-01-24T00:31:55.116Z,1548289915.116 [RDI_PathfinderUp] Loaded
2019-01-24T00:31:55.117Z,1548289915.117 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2019-01-24T00:31:56.616Z,1548289916.616 [BPC1] Loaded
2019-01-24T00:31:56.616Z,1548289916.616 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-01-24T00:31:56.617Z,1548289916.617 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-01-24T00:31:56.617Z,1548289916.617 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-01-24T00:31:56.845Z,1548289916.845 [VerticalControl](DEBUG): Construct VerticalControl.
2019-01-24T00:31:57.029Z,1548289917.029 [VerticalControl] Loaded
2019-01-24T00:31:57.029Z,1548289917.029 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-01-24T00:31:57.030Z,1548289917.030 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-01-24T00:31:57.086Z,1548289917.086 [HorizontalControl] Loaded
2019-01-24T00:31:57.086Z,1548289917.086 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-01-24T00:31:57.087Z,1548289917.087 [SpeedControl](DEBUG): Construct SpeedControl.
2019-01-24T00:31:57.089Z,1548289917.089 [SpeedControl] Loaded
2019-01-24T00:31:57.089Z,1548289917.089 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-01-24T00:31:57.090Z,1548289917.090 [LoopControl](DEBUG): Construct LoopControl.
2019-01-24T00:31:57.091Z,1548289917.091 [LoopControl] Loaded
2019-01-24T00:31:57.091Z,1548289917.091 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-01-24T00:31:57.091Z,1548289917.091 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-01-24T00:31:57.092Z,1548289917.092 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-01-24T00:31:57.187Z,1548289917.187 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-01-24T00:31:57.187Z,1548289917.187 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-01-24T00:31:57.358Z,1548289917.358 [Aanderaa_O2] Loaded
2019-01-24T00:31:57.358Z,1548289917.358 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2019-01-24T00:31:57.439Z,1548289917.439 [CTD_NeilBrown] Loaded
2019-01-24T00:31:57.440Z,1548289917.440 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-01-24T00:31:57.441Z,1548289917.441 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409534E0
2019-01-24T00:31:57.441Z,1548289917.441 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3394
2019-01-24T00:31:57.485Z,1548289917.485 [WetLabsSeaOWL_UV_A] Loaded
2019-01-24T00:31:57.485Z,1548289917.485 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-01-24T00:31:57.486Z,1548289917.486 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409834E0
2019-01-24T00:31:57.486Z,1548289917.486 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3395
2019-01-24T00:31:57.487Z,1548289917.487 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-01-24T00:31:57.488Z,1548289917.488 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-01-24T00:31:57.549Z,1548289917.549 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-01-24T00:31:57.550Z,1548289917.550 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-01-24T00:31:57.590Z,1548289917.590 [DepthRateCalculator] Loaded
2019-01-24T00:31:57.590Z,1548289917.590 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-01-24T00:31:57.595Z,1548289917.595 [PitchRateCalculator] Loaded
2019-01-24T00:31:57.595Z,1548289917.595 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-01-24T00:31:57.607Z,1548289917.607 [SpeedCalculator] Loaded
2019-01-24T00:31:57.608Z,1548289917.608 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-01-24T00:31:57.629Z,1548289917.629 [TempGradientCalculator] Loaded
2019-01-24T00:31:57.629Z,1548289917.629 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-01-24T00:31:57.634Z,1548289917.634 [YawRateCalculator] Loaded
2019-01-24T00:31:57.634Z,1548289917.634 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-01-24T00:31:57.663Z,1548289917.663 [ElevatorOffsetCalculator] Loaded
2019-01-24T00:31:57.663Z,1548289917.663 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-01-24T00:31:57.664Z,1548289917.664 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-01-24T00:31:57.664Z,1548289917.664 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-01-24T00:31:57.690Z,1548289917.690 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-01-24T00:31:57.693Z,1548289917.693 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-01-24T00:31:57.694Z,1548289917.694 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-01-24T00:31:57.701Z,1548289917.701 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-01-24T00:31:57.702Z,1548289917.702 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A3F4E0
2019-01-24T00:31:57.702Z,1548289917.702 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3396
2019-01-24T00:31:57.707Z,1548289917.707 [Supervisor](INFO): Main Thread ID is 795
2019-01-24T00:31:57.707Z,1548289917.707 [Supervisor](DEBUG): Running supervisor.
2019-01-24T00:31:57.708Z,1548289917.708 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3397
2019-01-24T00:31:57.710Z,1548289917.710 [controlThread ThreadHandler](INFO): Handler Thread ID is 3398
2019-01-24T00:31:57.710Z,1548289917.710 [controlThread](DEBUG): Initializing ControlThread
2019-01-24T00:31:57.711Z,1548289917.711 [SBIT](INFO): Initialize SBIT Component.
2019-01-24T00:31:57.712Z,1548289917.712 [SBIT](IMPORTANT): git: 2019-01-14A-1-gbf16392
2019-01-24T00:31:57.712Z,1548289917.712 [SBIT](INFO): git hash: bf16392e469ce9bf3416e817fec750860d5875a3
2019-01-24T00:31:57.712Z,1548289917.712 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-01-24T00:31:57.712Z,1548289917.712 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2019-01-24T00:31:57.714Z,1548289917.714 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-01-24T00:31:57.714Z,1548289917.714 [IBIT](INFO): Initialize IBIT Component.
2019-01-24T00:31:57.715Z,1548289917.715 [CBIT](DEBUG): Initialize CBIT Component.
2019-01-24T00:31:57.716Z,1548289917.716 [logger ThreadHandler](INFO): Handler Thread ID is 3399
2019-01-24T00:31:57.729Z,1548289917.729 [CBIT](DEBUG): Initialized mux pins.
2019-01-24T00:31:57.729Z,1548289917.729 [CBIT](DEBUG): Initializing the watchdog timer.
2019-01-24T00:31:57.741Z,1548289917.741 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3400
2019-01-24T00:31:57.747Z,1548289917.747 [Radio_Surface](INFO): Powering up
2019-01-24T00:31:57.753Z,1548289917.753 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-01-24T00:31:57.753Z,1548289917.753 [CBIT](DEBUG): Initializing heartbeat.
2019-01-24T00:31:57.754Z,1548289917.754 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3401
2019-01-24T00:31:57.754Z,1548289917.754 [CTD_NeilBrown](INFO): Powering down
2019-01-24T00:31:57.781Z,1548289917.781 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3402
2019-01-24T00:31:57.782Z,1548289917.782 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-01-24T00:31:57.813Z,1548289917.813 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3403
2019-01-24T00:31:57.819Z,1548289917.819 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-01-24T00:31:57.819Z,1548289917.819 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-01-24T00:31:57.819Z,1548289917.819 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-01-24T00:31:57.819Z,1548289917.819 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-01-24T00:31:57.819Z,1548289917.819 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-01-24T00:31:57.820Z,1548289917.820 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-01-24T00:31:57.820Z,1548289917.820 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-01-24T00:31:57.820Z,1548289917.820 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-01-24T00:31:57.820Z,1548289917.820 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-01-24T00:31:57.820Z,1548289917.820 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-01-24T00:31:57.821Z,1548289917.821 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-01-24T00:31:57.821Z,1548289917.821 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-01-24T00:31:57.821Z,1548289917.821 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-01-24T00:31:57.821Z,1548289917.821 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-01-24T00:31:57.821Z,1548289917.821 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-01-24T00:31:57.822Z,1548289917.822 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-01-24T00:31:57.825Z,1548289917.825 [CBIT](DEBUG): Deactivating GF circuits.
2019-01-24T00:31:57.825Z,1548289917.825 [CBIT](DEBUG): Deactivating emergency mode.
2019-01-24T00:31:57.862Z,1548289917.862 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2019-01-24T00:31:57.863Z,1548289917.863 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T00:31:57.863Z,1548289917.863 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T00:31:57.863Z,1548289917.863 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-01-24T00:31:57.864Z,1548289917.864 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T00:31:57.864Z,1548289917.864 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T00:31:57.865Z,1548289917.865 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-01-24T00:31:57.865Z,1548289917.865 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-01-24T00:31:57.871Z,1548289917.871 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-01-24T00:31:57.873Z,1548289917.873 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-01-24T00:31:57.874Z,1548289917.874 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-01-24T00:31:57.875Z,1548289917.875 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-01-24T00:31:57.875Z,1548289917.875 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-01-24T00:31:57.876Z,1548289917.876 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-01-24T00:31:57.876Z,1548289917.876 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-01-24T00:31:57.876Z,1548289917.876 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-01-24T00:31:57.877Z,1548289917.877 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-01-24T00:31:57.877Z,1548289917.877 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-01-24T00:31:57.879Z,1548289917.879 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-01-24T00:31:57.907Z,1548289917.907 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-01-24T00:31:57.942Z,1548289917.942 [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-24T00:31:57.942Z,1548289917.942 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-01-24T00:31:58.035Z,1548289918.035 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-01-24T00:31:58.036Z,1548289918.036 [Default:A.Wait](DEBUG): Construct Wait.
2019-01-24T00:31:58.045Z,1548289918.045 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-01-24T00:31:58.072Z,1548289918.072 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-01-24T00:31:58.074Z,1548289918.074 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-01-24T00:31:58.090Z,1548289918.090 [Default:E.Execute](DEBUG): Construct Execute.
2019-01-24T00:31:58.117Z,1548289918.117 [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-24T00:31:58.137Z,1548289918.137 [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-24T00:31:58.157Z,1548289918.157 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-01-24T00:31:58.226Z,1548289918.226 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-01-24T00:31:58.242Z,1548289918.242 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-01-24T00:31:58.421Z,1548289918.421 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-01-24T00:31:58.610Z,1548289918.610 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:31:58.617Z,1548289918.617 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-01-24T00:31:58.636Z,1548289918.636 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:31:58.641Z,1548289918.641 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-01-24T00:31:58.673Z,1548289918.673 [MassServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:31:58.677Z,1548289918.677 [MassServo](DEBUG): Initializing MassServo.
2019-01-24T00:31:58.683Z,1548289918.683 [RudderServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:31:58.689Z,1548289918.689 [RudderServo](DEBUG): Initializing RudderServo.
2019-01-24T00:31:58.710Z,1548289918.710 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:31:58.717Z,1548289918.717 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-01-24T00:31:58.941Z,1548289918.941 [RDI_PathfinderUp](INFO): Powering down
2019-01-24T00:31:59.013Z,1548289919.013 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-01-24T00:31:59.209Z,1548289919.209 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-01-24T00:31:59.557Z,1548289919.557 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2019-01-24T00:31:59.557Z,1548289919.557 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2019-01-24T00:31:59.557Z,1548289919.557 [BuoyancyServo] Communications Fault, FailCount= 1
2019-01-24T00:31:59.557Z,1548289919.557 [BuoyancyServo](ERROR): Communications Fault
2019-01-24T00:31:59.769Z,1548289919.769 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2019-01-24T00:32:01.553Z,1548289921.553 [Aanderaa_O2](INFO): Powering down
2019-01-24T00:32:01.910Z,1548289921.910 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2019-01-24T00:32:01.910Z,1548289921.910 [BuoyancyServo] No Fault, FailCount= 1
2019-01-24T00:32:02.259Z,1548289922.259 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-01-24T00:32:02.378Z,1548289922.378 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-01-24T00:32:11.846Z,1548289931.846 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-01-24T00:32:25.422Z,1548289945.422 [NAL9602](INFO): Powering up NAL9602
2019-01-24T00:32:26.273Z,1548289946.273 [SBIT](IMPORTANT): Beginning Startup BIT
2019-01-24T00:32:26.278Z,1548289946.278 [CBIT](IMPORTANT): Beginning ground fault scan
2019-01-24T00:32:36.346Z,1548289956.346 [NAL9602](INFO): NAL9602 initialized
2019-01-24T00:32:37.161Z,1548289957.161 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:32:37.262Z,1548289957.262 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.021996
CHAN A1 (24V): -0.196589
CHAN A2 (12V): -0.007347
CHAN A3 (5V): -0.001780
CHAN B0 (3.3V): 0.000147
CHAN B1 (3.15aV): 0.000064
CHAN B2 (3.15bV): 0.000140
CHAN B3 (GND): 0.002442
OPEN: 0.005102
Full Scale Calc: 4.765 mA, -1.589 mA
2019-01-24T00:33:20.402Z,1548290000.402 [SBIT](IMPORTANT): SBIT PASSED
2019-01-24T00:33:20.462Z,1548290000.462 [CommandLine](IMPORTANT): got command configSet list
2019-01-24T00:33:20.462Z,1548290000.462 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-01-24T00:33:20.463Z,1548290000.463 [CommandLine](IMPORTANT): AHRS_M2.readMagnetics=1 bool;

2019-01-24T00:33:20.463Z,1548290000.463 [CommandLine](IMPORTANT): NAL9602.requestGGA=1 bool;

2019-01-24T00:33:20.790Z,1548290000.790 [MissionManager](IMPORTANT): Started mission Startup
2019-01-24T00:33:20.790Z,1548290000.790 [Startup] Running Loop=1
2019-01-24T00:33:20.791Z,1548290000.791 [Startup](DEBUG): Aggregate::initialize Startup
2019-01-24T00:33:20.791Z,1548290000.791 [Startup:A.GoToSurface] Running Loop=1
2019-01-24T00:33:20.791Z,1548290000.791 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-01-24T00:33:20.791Z,1548290000.791 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-01-24T00:33:20.792Z,1548290000.792 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-01-24T00:33:20.792Z,1548290000.792 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-01-24T00:33:20.793Z,1548290000.793 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-01-24T00:33:20.794Z,1548290000.794 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-01-24T00:33:20.800Z,1548290000.800 [Startup:StartupSatComms] Running Loop=1
2019-01-24T00:33:20.800Z,1548290000.800 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-01-24T00:33:20.800Z,1548290000.800 [Startup:StartupSatComms:A] Running Loop=1
2019-01-24T00:33:21.186Z,1548290001.186 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-01-24T00:34:21.196Z,1548290061.196 [Startup:StartupSatComms:A](INFO): Timed out from 2019-01-24T00:33:20.8Z
2019-01-24T00:34:21.196Z,1548290061.196 [Startup:StartupSatComms:A] Stopped
2019-01-24T00:34:21.196Z,1548290061.196 [Startup:StartupSatComms:B] Running Loop=1
2019-01-24T00:34:21.592Z,1548290061.592 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-01-24T00:34:57.995Z,1548290097.995 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = 1000039.362365
2019-01-24T00:34:57.995Z,1548290097.995 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-01-24T00:34:57.995Z,1548290097.995 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-01-24T00:34:58.001Z,1548290098.001 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = 1000174.945111
2019-01-24T00:34:58.002Z,1548290098.002 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2019-01-24T00:34:58.002Z,1548290098.002 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2019-01-24T00:34:58.053Z,1548290098.053 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-01-24T00:34:58.053Z,1548290098.053 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2019-01-24T00:34:58.413Z,1548290098.413 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-01-24T00:34:58.413Z,1548290098.413 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-01-24T00:34:58.413Z,1548290098.413 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2019-01-24T00:34:58.414Z,1548290098.414 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2019-01-24T00:34:58.797Z,1548290098.797 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2019-01-24T00:34:58.798Z,1548290098.798 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T00:34:58.798Z,1548290098.798 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T00:34:58.799Z,1548290098.799 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2019-01-24T00:34:58.799Z,1548290098.799 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2019-01-24T00:34:58.799Z,1548290098.799 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2019-01-24T00:35:20.087Z,1548290120.087 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004877
2019-01-24T00:35:21.523Z,1548290121.523 [Startup:StartupSatComms:B](INFO): Timed out from 2019-01-24T00:34:21.2Z
2019-01-24T00:35:21.523Z,1548290121.523 [Startup:StartupSatComms:B] Stopped
2019-01-24T00:35:21.524Z,1548290121.524 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-01-24T00:35:21.524Z,1548290121.524 [Startup:StartupSatComms] Stopped
2019-01-24T00:35:21.524Z,1548290121.524 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-01-24T00:35:21.525Z,1548290121.525 [Startup](INFO): Completed Startup
2019-01-24T00:35:21.525Z,1548290121.525 [MissionManager](INFO): Startup is completed.
2019-01-24T00:35:21.525Z,1548290121.525 [MissionManager](INFO): Uninitializing Mission Startup
2019-01-24T00:35:21.525Z,1548290121.525 [Startup] Stopped
2019-01-24T00:35:21.525Z,1548290121.525 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-01-24T00:35:21.525Z,1548290121.525 [Startup:A.GoToSurface] Stopped
2019-01-24T00:35:21.525Z,1548290121.525 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-01-24T00:35:21.676Z,1548290121.676 [MissionManager](IMPORTANT): Started mission Default
2019-01-24T00:35:21.676Z,1548290121.676 [Default] Running Loop=1
2019-01-24T00:35:21.676Z,1548290121.676 [Default](DEBUG): Aggregate::initialize Default
2019-01-24T00:35:21.676Z,1548290121.676 [Default:B.GoToSurface] Running Loop=1
2019-01-24T00:35:21.676Z,1548290121.676 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-01-24T00:35:21.681Z,1548290121.681 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-01-24T00:35:21.681Z,1548290121.681 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-01-24T00:35:21.681Z,1548290121.681 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-01-24T00:35:21.682Z,1548290121.682 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-01-24T00:35:21.682Z,1548290121.682 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-01-24T00:35:21.682Z,1548290121.682 [Default:A.Wait] Running Loop=1
2019-01-24T00:35:21.683Z,1548290121.683 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-01-24T00:35:24.920Z,1548290124.920 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190123T172911/Courier0127.lzma
2019-01-24T00:35:25.703Z,1548290125.703 [DataOverHttps](INFO): Moved sent file to Logs/20190123T172911/Courier0127.lzma.bak
2019-01-24T00:35:25.703Z,1548290125.703 [DataOverHttps](INFO): SBD MOMSN=9598883
2019-01-24T00:35:34.948Z,1548290134.948 [Default:A.Wait](INFO): Done Waiting.
2019-01-24T00:35:34.948Z,1548290134.948 [Default:A.Wait] Stopped
2019-01-24T00:35:34.948Z,1548290134.948 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T00:35:35.344Z,1548290135.344 [Default:CheckIn] Running Loop=1
2019-01-24T00:35:35.344Z,1548290135.344 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T00:35:35.344Z,1548290135.344 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T00:35:35.762Z,1548290135.762 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-01-24T00:36:10.228Z,1548290170.228 [RDI_Pathfinder](ERROR): Failed to parse:
:HM,G,D,0e8c,0ffe,*14.201,*-0.110,*0.000
2019-01-24T00:36:36.753Z,1548290196.753 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-01-24T00:37:39.942Z,1548290259.942 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T00:37:40.757Z,1548290260.757 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:37:48.056Z,1548290268.056 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:37:48.432Z,1548290268.432 [NAL9602](DEBUG): Parsing GGA sentence: $GPGGA,002224.00,,,,,1,3,5.45,,,,,,*66
2019-01-24T00:37:48.432Z,1548290268.432 [NAL9602](ERROR): Invalid hemisphere value reported: 44
2019-01-24T00:37:48.433Z,1548290268.433 [NAL9602](ERROR): Invalid hemisphere value reported: 44
2019-01-24T00:37:48.435Z,1548290268.435 [NAL9602](INFO): GPS fix at 20190124T002224: (0.000000, 0.000000)
2019-01-24T00:37:48.484Z,1548290268.484 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T00:37:48.489Z,1548290268.489 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T00:37:48.903Z,1548290268.903 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-01-24T00:37:53.924Z,1548290273.924 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20190124T003147/Courier0004.lzma
2019-01-24T00:37:54.692Z,1548290274.692 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0004.lzma.bak
2019-01-24T00:37:54.692Z,1548290274.692 [DataOverHttps](INFO): SBD MOMSN=9598896
2019-01-24T00:38:06.273Z,1548290286.273 [DataOverHttps](INFO): Sending 335 bytes from file Logs/20190123T172911/Express0128.lzma
2019-01-24T00:38:07.040Z,1548290287.040 [DataOverHttps](INFO): Moved sent file to Logs/20190123T172911/Express0128.lzma.bak
2019-01-24T00:38:07.040Z,1548290287.040 [DataOverHttps](INFO): SBD MOMSN=9598950
2019-01-24T00:38:17.934Z,1548290297.934 [DataOverHttps](INFO): Sending 708 bytes from file Logs/20190124T003147/Express0001.lzma
2019-01-24T00:38:18.728Z,1548290298.728 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0001.lzma.bak
2019-01-24T00:38:18.728Z,1548290298.728 [DataOverHttps](INFO): SBD MOMSN=9598958
2019-01-24T00:38:24.206Z,1548290304.206 [NAL9602](INFO): Powering down
2019-01-24T00:38:29.351Z,1548290309.351 [DataOverHttps](INFO): Sending 291 bytes from file Logs/20190124T003147/Express0005.lzma
2019-01-24T00:38:30.087Z,1548290310.087 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0005.lzma.bak
2019-01-24T00:38:30.088Z,1548290310.088 [DataOverHttps](INFO): SBD MOMSN=9598974
2019-01-24T00:38:32.277Z,1548290312.277 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T00:38:32.277Z,1548290312.277 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T00:38:32.277Z,1548290312.277 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T00:39:24.377Z,1548290364.377 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-01-24T00:43:32.408Z,1548290612.408 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T00:43:32.408Z,1548290612.408 [Default:CheckIn:C.Wait] Stopped
2019-01-24T00:43:32.408Z,1548290612.408 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T00:43:32.408Z,1548290612.408 [Default:CheckIn:D] Running Loop=1
2019-01-24T00:43:32.832Z,1548290612.832 [Default:CheckIn:D] Stopped
2019-01-24T00:43:32.832Z,1548290612.832 [Default:CheckIn:E] Running Loop=1
2019-01-24T00:43:33.230Z,1548290613.230 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.185898 min 
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn:E] Stopped
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn] Stopped
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn](INFO): Running loop #2
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn] Running Loop=2
2019-01-24T00:43:33.232Z,1548290613.232 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T00:43:33.233Z,1548290613.233 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T00:43:33.982Z,1548290613.982 [NAL9602](INFO): Powering up
2019-01-24T00:43:44.787Z,1548290624.787 [NAL9602](INFO): NAL9602 initialized
2019-01-24T00:43:45.601Z,1548290625.601 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:44:16.498Z,1548290656.498 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-01-24T00:44:16.581Z,1548290656.581 [NAL9602](FAULT): received: 
+CSQ:0

OK
2019-01-24T00:44:16.581Z,1548290656.581 [NAL9602] Data Fault, FailCount= 1
2019-01-24T00:44:16.581Z,1548290656.581 [NAL9602](ERROR): Data Fault
2019-01-24T00:44:16.664Z,1548290656.664 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T00:44:16.878Z,1548290656.878 [NAL9602](INFO): Powering down
2019-01-24T00:44:17.766Z,1548290657.766 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T00:44:17.766Z,1548290657.766 [NAL9602] No Fault, FailCount= 1
2019-01-24T00:44:46.972Z,1548290686.972 [NAL9602](INFO): Powering up NAL9602
2019-01-24T00:44:58.170Z,1548290698.170 [NAL9602](INFO): NAL9602 initialized
2019-01-24T00:44:58.981Z,1548290698.981 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:48:35.458Z,1548290915.458 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T00:43:33.2Z
2019-01-24T00:48:35.459Z,1548290915.459 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T00:48:35.459Z,1548290915.459 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T00:48:36.887Z,1548290916.887 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190124T003147/Courier0007.lzma
2019-01-24T00:48:36.921Z,1548290916.921 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32768,V
2019-01-24T00:48:37.796Z,1548290917.796 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0007.lzma.bak
2019-01-24T00:48:37.796Z,1548290917.796 [DataOverHttps](INFO): SBD MOMSN=9598998
2019-01-24T00:48:48.158Z,1548290928.158 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T00:48:48.299Z,1548290928.299 [DataOverHttps](INFO): Sending 172 bytes from file Logs/20190124T003147/Express0008.lzma
2019-01-24T00:48:49.047Z,1548290929.047 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0008.lzma.bak
2019-01-24T00:48:49.047Z,1548290929.047 [DataOverHttps](INFO): SBD MOMSN=9599000
2019-01-24T00:48:51.263Z,1548290931.263 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T00:48:51.263Z,1548290931.263 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T00:48:51.263Z,1548290931.263 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T00:49:18.450Z,1548290958.450 [NAL9602](INFO): Powering down
2019-01-24T00:51:18.807Z,1548291078.807 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-01-24T00:53:51.646Z,1548291231.646 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T00:53:51.646Z,1548291231.646 [Default:CheckIn:C.Wait] Stopped
2019-01-24T00:53:51.647Z,1548291231.647 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T00:53:51.647Z,1548291231.647 [Default:CheckIn:D] Running Loop=1
2019-01-24T00:53:52.030Z,1548291232.030 [Default:CheckIn:D] Stopped
2019-01-24T00:53:52.030Z,1548291232.030 [Default:CheckIn:E] Running Loop=1
2019-01-24T00:53:52.449Z,1548291232.449 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.505900 min 
2019-01-24T00:53:52.450Z,1548291232.450 [Default:CheckIn:E] Stopped
2019-01-24T00:53:52.450Z,1548291232.450 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T00:53:52.450Z,1548291232.450 [Default:CheckIn] Stopped
2019-01-24T00:53:52.450Z,1548291232.450 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T00:53:52.451Z,1548291232.451 [Default:CheckIn](INFO): Running loop #3
2019-01-24T00:53:52.451Z,1548291232.451 [Default:CheckIn] Running Loop=3
2019-01-24T00:53:52.451Z,1548291232.451 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T00:53:52.451Z,1548291232.451 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T00:53:53.186Z,1548291233.186 [NAL9602](INFO): Powering up
2019-01-24T00:54:03.988Z,1548291243.988 [NAL9602](INFO): NAL9602 initialized
2019-01-24T00:54:04.803Z,1548291244.803 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T00:54:04.803Z,1548291244.803 [NAL9602] Data Fault, FailCount= 2
2019-01-24T00:54:04.803Z,1548291244.803 [NAL9602](ERROR): Data Fault
2019-01-24T00:54:04.886Z,1548291244.886 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T00:54:05.202Z,1548291245.202 [NAL9602](INFO): Powering down
2019-01-24T00:54:06.029Z,1548291246.029 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T00:54:06.029Z,1548291246.029 [NAL9602] No Fault, FailCount= 2
2019-01-24T00:54:13.746Z,1548291253.746 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,-32768,V
2019-01-24T00:54:35.319Z,1548291275.319 [NAL9602](INFO): Powering up NAL9602
2019-01-24T00:54:48.218Z,1548291288.218 [NAL9602](INFO): NAL9602 initialized
2019-01-24T00:54:49.029Z,1548291289.029 [NAL9602](DEBUG): Fix Requested
2019-01-24T00:55:10.222Z,1548291310.222 [NAL9602](INFO): SBD MO Status=2, MOMSN=2047, MT Status=2, MTMSN=0
2019-01-24T00:55:10.222Z,1548291310.222 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T00:55:36.720Z,1548291336.720 [NAL9602](INFO): SBD MO Status=2, MOMSN=2047, MT Status=2, MTMSN=0
2019-01-24T00:55:36.720Z,1548291336.720 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T00:56:10.391Z,1548291370.391 [NAL9602](INFO): SBD MO Status=2, MOMSN=2047, MT Status=2, MTMSN=0
2019-01-24T00:56:10.392Z,1548291370.392 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T00:57:02.924Z,1548291422.924 [NAL9602](INFO): SBD MO Status=2, MOMSN=2047, MT Status=2, MTMSN=0
2019-01-24T00:57:02.925Z,1548291422.925 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T00:58:40.837Z,1548291520.837 [RDI_Pathfinder](ERROR): Unknown system health message
2019-01-24T00:58:40.838Z,1548291520.838 [RDI_Pathfinder] Hardware Fault, FailCount= 1
2019-01-24T00:58:40.838Z,1548291520.838 [RDI_Pathfinder](ERROR): Hardware Fault
2019-01-24T00:58:40.877Z,1548291520.877 [CBIT](ERROR): Hardware Fault in component: RDI_Pathfinder
2019-01-24T00:58:41.301Z,1548291521.301 [RDI_Pathfinder](INFO): Powering down
2019-01-24T00:58:42.044Z,1548291522.044 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-01-24T00:58:42.044Z,1548291522.044 [RDI_Pathfinder] No Fault, FailCount= 0
2019-01-24T00:58:55.408Z,1548291535.408 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T00:53:52.5Z
2019-01-24T00:58:55.408Z,1548291535.408 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T00:58:55.408Z,1548291535.408 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T00:58:55.617Z,1548291535.617 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-01-24T00:58:57.565Z,1548291537.565 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T003147/Courier0010.lzma
2019-01-24T00:58:58.056Z,1548291538.056 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0010.lzma.bak
2019-01-24T00:58:58.056Z,1548291538.056 [DataOverHttps](INFO): SBD MOMSN=9599023
2019-01-24T00:59:10.954Z,1548291550.954 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20190124T003147/Express0011.lzma
2019-01-24T00:59:11.749Z,1548291551.749 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0011.lzma.bak
2019-01-24T00:59:11.749Z,1548291551.749 [DataOverHttps](INFO): SBD MOMSN=9599025
2019-01-24T00:59:13.942Z,1548291553.942 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T00:59:13.942Z,1548291553.942 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T00:59:13.942Z,1548291553.942 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T00:59:46.884Z,1548291586.884 [NAL9602](INFO): SBD MO Status=2, MOMSN=2047, MT Status=2, MTMSN=0
2019-01-24T00:59:46.884Z,1548291586.884 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T00:59:52.886Z,1548291592.886 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T01:00:23.423Z,1548291623.423 [NAL9602](INFO): Powering down
2019-01-24T01:04:14.195Z,1548291854.195 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:04:14.195Z,1548291854.195 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:04:14.195Z,1548291854.195 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:04:14.195Z,1548291854.195 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:04:14.593Z,1548291854.593 [Default:CheckIn:D] Stopped
2019-01-24T01:04:14.594Z,1548291854.594 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.881956 min 
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn:E] Stopped
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn] Stopped
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T01:04:15.010Z,1548291855.010 [Default:CheckIn](INFO): Running loop #4
2019-01-24T01:04:15.011Z,1548291855.011 [Default:CheckIn] Running Loop=4
2019-01-24T01:04:15.011Z,1548291855.011 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:04:15.011Z,1548291855.011 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:04:15.758Z,1548291855.758 [NAL9602](INFO): Powering up
2019-01-24T01:04:26.958Z,1548291866.958 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:04:27.769Z,1548291867.769 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:04:37.507Z,1548291877.507 [RDI_Pathfinder](ERROR): Failed to parse:
:e8c,0ffe, 14.187, -0.118, 0.000
2019-01-24T01:04:58.662Z,1548291898.662 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-01-24T01:04:58.741Z,1548291898.741 [NAL9602](FAULT): received: 
+SBDI: 2, 2047, 2, 0, 0, 0

OK
2019-01-24T01:04:58.741Z,1548291898.741 [NAL9602] Data Fault, FailCount= 3
2019-01-24T01:04:58.741Z,1548291898.741 [NAL9602](ERROR): Data Fault
2019-01-24T01:04:58.834Z,1548291898.834 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T01:04:59.066Z,1548291899.066 [NAL9602](INFO): Powering down
2019-01-24T01:04:59.952Z,1548291899.952 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T01:04:59.952Z,1548291899.952 [NAL9602] No Fault, FailCount= 3
2019-01-24T01:05:29.186Z,1548291929.186 [NAL9602](INFO): Powering up NAL9602
2019-01-24T01:05:40.390Z,1548291940.390 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:05:41.190Z,1548291941.190 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T01:05:41.190Z,1548291941.190 [NAL9602] Data Fault, FailCount= 4
2019-01-24T01:05:41.190Z,1548291941.190 [NAL9602](ERROR): Data Fault
2019-01-24T01:05:41.227Z,1548291941.227 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T01:05:41.590Z,1548291941.590 [NAL9602](INFO): Powering down
2019-01-24T01:05:42.448Z,1548291942.448 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T01:05:42.448Z,1548291942.448 [NAL9602] No Fault, FailCount= 4
2019-01-24T01:06:11.662Z,1548291971.662 [NAL9602](INFO): Powering up NAL9602
2019-01-24T01:06:22.550Z,1548291982.550 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:06:23.353Z,1548291983.353 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:09:17.878Z,1548292157.878 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T01:04:15.0Z
2019-01-24T01:09:17.878Z,1548292157.878 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:09:17.878Z,1548292157.878 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:09:23.363Z,1548292163.363 [NAL9602](INFO): SBD MO Status=0, MOMSN=2047, MT Status=0, MTMSN=0
2019-01-24T01:09:23.364Z,1548292163.364 [NAL9602](INFO): No messages in MT queue
2019-01-24T01:09:23.506Z,1548292163.506 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T003147/Courier0013.lzma
2019-01-24T01:09:24.276Z,1548292164.276 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0013.lzma.bak
2019-01-24T01:09:24.276Z,1548292164.276 [DataOverHttps](INFO): SBD MOMSN=9599054
2019-01-24T01:09:35.135Z,1548292175.135 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20190124T003147/Express0014.lzma
2019-01-24T01:09:36.014Z,1548292176.014 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0014.lzma.bak
2019-01-24T01:09:36.014Z,1548292176.014 [DataOverHttps](INFO): SBD MOMSN=9599056
2019-01-24T01:09:38.091Z,1548292178.091 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:09:38.091Z,1548292178.091 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:09:38.091Z,1548292178.091 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:09:53.530Z,1548292193.530 [NAL9602](INFO): Powering down
2019-01-24T01:11:21.389Z,1548292281.389 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-01-24T01:11:21.389Z,1548292281.389 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +0.0  +0.00,   0.00,745.98
2019-01-24T01:14:38.399Z,1548292478.399 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:14:38.399Z,1548292478.399 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:14:38.400Z,1548292478.400 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:14:38.400Z,1548292478.400 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:14:38.806Z,1548292478.806 [Default:CheckIn:D] Stopped
2019-01-24T01:14:38.806Z,1548292478.806 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:14:39.201Z,1548292479.201 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.285502 min 
2019-01-24T01:14:39.201Z,1548292479.201 [Default:CheckIn:E] Stopped
2019-01-24T01:14:39.201Z,1548292479.201 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:14:39.201Z,1548292479.201 [Default:CheckIn] Stopped
2019-01-24T01:14:39.201Z,1548292479.201 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T01:14:39.202Z,1548292479.202 [Default:CheckIn](INFO): Running loop #5
2019-01-24T01:14:39.202Z,1548292479.202 [Default:CheckIn] Running Loop=5
2019-01-24T01:14:39.202Z,1548292479.202 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:14:39.202Z,1548292479.202 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:14:39.966Z,1548292479.966 [NAL9602](INFO): Powering up
2019-01-24T01:14:50.770Z,1548292490.770 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:14:51.573Z,1548292491.573 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:15:02.682Z,1548292502.682 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-01-24T01:17:55.465Z,1548292675.465 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:17:55.465Z,1548292675.465 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:19:41.529Z,1548292781.529 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T01:14:39.2Z
2019-01-24T01:19:41.529Z,1548292781.529 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:19:41.529Z,1548292781.529 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:19:42.834Z,1548292782.834 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T003147/Courier0016.lzma
2019-01-24T01:19:43.715Z,1548292783.715 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0016.lzma.bak
2019-01-24T01:19:43.715Z,1548292783.715 [DataOverHttps](INFO): SBD MOMSN=9599085
2019-01-24T01:19:54.512Z,1548292794.512 [DataOverHttps](INFO): Sending 110 bytes from file Logs/20190124T003147/Express0017.lzma
2019-01-24T01:19:55.318Z,1548292795.318 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0017.lzma.bak
2019-01-24T01:19:55.318Z,1548292795.318 [DataOverHttps](INFO): SBD MOMSN=9599087
2019-01-24T01:19:57.566Z,1548292797.566 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:19:57.566Z,1548292797.566 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:19:57.566Z,1548292797.566 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:20:08.511Z,1548292808.511 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:20:08.511Z,1548292808.511 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:20:08.914Z,1548292808.914 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T01:20:39.438Z,1548292839.438 [NAL9602](INFO): Powering down
2019-01-24T01:24:57.810Z,1548293097.810 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:24:57.810Z,1548293097.810 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:24:57.810Z,1548293097.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:24:57.810Z,1548293097.810 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:24:58.219Z,1548293098.219 [Default:CheckIn:D] Stopped
2019-01-24T01:24:58.219Z,1548293098.219 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:24:58.660Z,1548293098.660 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.609041 min 
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn:E] Stopped
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn] Stopped
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn](INFO): Running loop #6
2019-01-24T01:24:58.665Z,1548293098.665 [Default:CheckIn] Running Loop=6
2019-01-24T01:24:58.666Z,1548293098.666 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:24:58.666Z,1548293098.666 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:24:59.382Z,1548293099.382 [NAL9602](INFO): Powering up
2019-01-24T01:25:10.583Z,1548293110.583 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:25:11.386Z,1548293111.386 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T01:25:11.386Z,1548293111.386 [NAL9602] Data Fault, FailCount= 1
2019-01-24T01:25:11.386Z,1548293111.386 [NAL9602](ERROR): Data Fault
2019-01-24T01:25:11.486Z,1548293111.486 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T01:25:11.782Z,1548293111.782 [NAL9602](INFO): Powering down
2019-01-24T01:25:12.673Z,1548293112.673 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T01:25:12.673Z,1548293112.673 [NAL9602] No Fault, FailCount= 1
2019-01-24T01:25:41.870Z,1548293141.870 [NAL9602](INFO): Powering up NAL9602
2019-01-24T01:25:54.387Z,1548293154.387 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:25:55.189Z,1548293155.189 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:27:19.371Z,1548293239.371 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:27:19.371Z,1548293239.371 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:27:45.480Z,1548293265.480 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:27:45.480Z,1548293265.480 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:28:03.879Z,1548293283.879 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:28:03.879Z,1548293283.879 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:28:54.099Z,1548293334.099 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:28:54.099Z,1548293334.099 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:29:20.103Z,1548293360.103 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:29:20.103Z,1548293360.103 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:29:46.207Z,1548293386.207 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:29:46.208Z,1548293386.208 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:30:01.072Z,1548293401.072 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T01:24:58.7Z
2019-01-24T01:30:01.072Z,1548293401.072 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:30:01.072Z,1548293401.072 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:30:06.599Z,1548293406.599 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T003147/Courier0019.lzma
2019-01-24T01:30:07.376Z,1548293407.376 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0019.lzma.bak
2019-01-24T01:30:07.376Z,1548293407.376 [DataOverHttps](INFO): SBD MOMSN=9599112
2019-01-24T01:30:17.893Z,1548293417.893 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20190124T003147/Express0020.lzma
2019-01-24T01:30:18.660Z,1548293418.660 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0020.lzma.bak
2019-01-24T01:30:18.660Z,1548293418.660 [DataOverHttps](INFO): SBD MOMSN=9599114
2019-01-24T01:30:20.849Z,1548293420.849 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:30:20.849Z,1548293420.849 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:30:20.849Z,1548293420.849 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:30:56.416Z,1548293456.416 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:30:56.416Z,1548293456.416 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:30:59.902Z,1548293459.902 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-01-24T01:31:30.418Z,1548293490.418 [NAL9602](INFO): Powering down
2019-01-24T01:35:21.094Z,1548293721.094 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:35:21.094Z,1548293721.094 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:35:21.094Z,1548293721.094 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:35:21.094Z,1548293721.094 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:35:21.498Z,1548293721.498 [Default:CheckIn:D] Stopped
2019-01-24T01:35:21.498Z,1548293721.498 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:35:21.898Z,1548293721.898 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.997038 min 
2019-01-24T01:35:21.898Z,1548293721.898 [Default:CheckIn:E] Stopped
2019-01-24T01:35:21.898Z,1548293721.898 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:35:21.898Z,1548293721.898 [Default:CheckIn] Stopped
2019-01-24T01:35:21.898Z,1548293721.898 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-01-24T01:35:21.899Z,1548293721.899 [Default:CheckIn](INFO): Running loop #7
2019-01-24T01:35:21.899Z,1548293721.899 [Default:CheckIn] Running Loop=7
2019-01-24T01:35:21.899Z,1548293721.899 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-01-24T01:35:21.899Z,1548293721.899 [Default:CheckIn:Read_GPS] Running Loop=1
2019-01-24T01:35:22.654Z,1548293722.654 [NAL9602](INFO): Powering up
2019-01-24T01:35:33.458Z,1548293733.458 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:35:34.265Z,1548293734.265 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:37:06.896Z,1548293826.896 [NAL9602](INFO): SBD MO Status=2, MOMSN=2048, MT Status=2, MTMSN=0
2019-01-24T01:37:06.896Z,1548293826.896 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-01-24T01:38:34.291Z,1548293914.291 [NAL9602](INFO): SBD MO Status=0, MOMSN=2048, MT Status=0, MTMSN=0
2019-01-24T01:38:34.292Z,1548293914.292 [NAL9602](INFO): No messages in MT queue
2019-01-24T01:38:35.096Z,1548293915.096 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-01-24T01:38:35.096Z,1548293915.096 [NAL9602] Data Fault, FailCount= 1
2019-01-24T01:38:35.096Z,1548293915.096 [NAL9602](ERROR): Data Fault
2019-01-24T01:38:35.157Z,1548293915.157 [CBIT](ERROR): Data Fault in component: NAL9602
2019-01-24T01:38:38.278Z,1548293918.278 [NAL9602](INFO): Powering down
2019-01-24T01:38:38.857Z,1548293918.857 [CBIT](INFO): Clearing failed state for component NAL9602
2019-01-24T01:38:38.857Z,1548293918.857 [NAL9602] No Fault, FailCount= 1
2019-01-24T01:39:08.394Z,1548293948.394 [NAL9602](INFO): Powering up NAL9602
2019-01-24T01:39:14.920Z,1548293954.920 [RDI_Pathfinder](ERROR): Failed to parse:
:HM,G,D,0e8c,0ffe,*14.174,*-0.117,*0.000
2019-01-24T01:39:19.298Z,1548293959.298 [NAL9602](INFO): NAL9602 initialized
2019-01-24T01:39:20.121Z,1548293960.121 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:22.920Z,1548293962.920 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:26.109Z,1548293966.109 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:28.913Z,1548293968.913 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:32.109Z,1548293972.109 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:34.913Z,1548293974.913 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:38.109Z,1548293978.109 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:40.909Z,1548293980.909 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:44.125Z,1548293984.125 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:49.401Z,1548293989.401 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:51.793Z,1548293991.793 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:54.989Z,1548293994.989 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:39:57.809Z,1548293997.809 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:01.005Z,1548294001.005 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:04.189Z,1548294004.189 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:07.001Z,1548294007.001 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:10.213Z,1548294010.213 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:12.989Z,1548294012.989 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:16.209Z,1548294016.209 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:19.013Z,1548294019.013 [NAL9602](DEBUG): Fix Requested
2019-01-24T01:40:24.227Z,1548294024.227 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-01-24T01:35:21.9Z
2019-01-24T01:40:24.227Z,1548294024.227 [Default:CheckIn:Read_GPS] Stopped
2019-01-24T01:40:24.227Z,1548294024.227 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-01-24T01:40:29.915Z,1548294029.915 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190124T003147/Courier0022.lzma
2019-01-24T01:40:30.560Z,1548294030.560 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Courier0022.lzma.bak
2019-01-24T01:40:30.560Z,1548294030.560 [DataOverHttps](INFO): SBD MOMSN=9599136
2019-01-24T01:40:41.090Z,1548294041.090 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20190124T003147/Express0023.lzma
2019-01-24T01:40:41.867Z,1548294041.867 [DataOverHttps](INFO): Moved sent file to Logs/20190124T003147/Express0023.lzma.bak
2019-01-24T01:40:41.868Z,1548294041.868 [DataOverHttps](INFO): SBD MOMSN=9599138
2019-01-24T01:40:44.030Z,1548294044.030 [Default:CheckIn:Read_Iridium] Stopped
2019-01-24T01:40:44.030Z,1548294044.030 [Default:CheckIn:C.Wait] Running Loop=1
2019-01-24T01:40:44.030Z,1548294044.030 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-01-24T01:40:54.670Z,1548294054.670 [NAL9602](INFO): Powering down
2019-01-24T01:45:44.235Z,1548294344.235 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-01-24T01:45:44.235Z,1548294344.235 [Default:CheckIn:C.Wait] Stopped
2019-01-24T01:45:44.235Z,1548294344.235 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-01-24T01:45:44.235Z,1548294344.235 [Default:CheckIn:D] Running Loop=1
2019-01-24T01:45:44.654Z,1548294344.654 [Default:CheckIn:D] Stopped
2019-01-24T01:45:44.654Z,1548294344.654 [Default:CheckIn:E] Running Loop=1
2019-01-24T01:45:45.058Z,1548294345.058 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.382967 min 
2019-01-24T01:45:45.058Z,1548294345.058 [Default:CheckIn:E] Stopped
2019-01-24T01:45:45.059Z,1548294345.059 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-01-24T01:45:45.0