2019-10-24T17:47:28.438Z,1571939248.438 [Supervisor](DEBUG): Initializing supervisor.
2019-10-24T17:47:28.440Z,1571939248.440 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-10-24T17:47:28.441Z,1571939248.441 [SyncHandler](INFO): Protected caller Thread ID is 3531
2019-10-24T17:47:28.441Z,1571939248.441 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-10-24T17:47:28.442Z,1571939248.442 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-10-24T17:47:28.443Z,1571939248.443 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3532
2019-10-24T17:47:28.445Z,1571939248.445 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-10-24T17:47:28.456Z,1571939248.456 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-10-24T17:47:28.457Z,1571939248.457 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-10-24T17:47:28.457Z,1571939248.457 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3533
2019-10-24T17:47:28.458Z,1571939248.458 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-10-24T17:47:28.459Z,1571939248.459 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-10-24T17:47:28.460Z,1571939248.460 [logger ThreadHandler](INFO): Protected caller Thread ID is 3534
2019-10-24T17:47:28.462Z,1571939248.462 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-10-24T17:47:28.462Z,1571939248.462 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-10-24T17:47:28.467Z,1571939248.467 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-10-24T17:47:29.001Z,1571939249.001 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-10-24T17:47:29.003Z,1571939249.003 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-10-24T17:47:29.101Z,1571939249.101 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-10-24T17:47:29.103Z,1571939249.103 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-10-24T17:47:29.412Z,1571939249.412 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-10-24T17:47:29.413Z,1571939249.413 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-10-24T17:47:29.551Z,1571939249.551 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-10-24T17:47:29.553Z,1571939249.553 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-10-24T17:47:29.742Z,1571939249.742 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-10-24T17:47:29.743Z,1571939249.743 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-10-24T17:47:30.181Z,1571939250.181 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-10-24T17:47:30.182Z,1571939250.182 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-10-24T17:47:30.386Z,1571939250.386 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-10-24T17:47:30.387Z,1571939250.387 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-10-24T17:47:30.530Z,1571939250.530 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-10-24T17:47:30.531Z,1571939250.531 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-10-24T17:47:30.721Z,1571939250.721 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-10-24T17:47:30.723Z,1571939250.723 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-10-24T17:47:30.818Z,1571939250.818 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-10-24T17:47:30.819Z,1571939250.819 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-10-24T17:47:31.113Z,1571939251.113 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-10-24T17:47:31.115Z,1571939251.115 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-10-24T17:47:31.197Z,1571939251.197 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-10-24T17:47:31.300Z,1571939251.300 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-10-24T17:47:31.301Z,1571939251.301 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-10-24T17:47:31.905Z,1571939251.905 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-10-24T17:47:31.907Z,1571939251.907 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-10-24T17:47:32.290Z,1571939252.290 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-10-24T17:47:32.292Z,1571939252.292 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-10-24T17:47:32.295Z,1571939252.295 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-10-24T17:47:32.497Z,1571939252.497 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-10-24T17:47:32.597Z,1571939252.597 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-10-24T17:47:32.694Z,1571939252.694 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-10-24T17:47:32.918Z,1571939252.918 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-10-24T17:47:32.918Z,1571939252.918 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-10-24T17:47:33.006Z,1571939253.006 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-10-24T17:47:33.100Z,1571939253.100 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-10-24T17:47:33.197Z,1571939253.197 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-10-24T17:47:33.281Z,1571939253.281 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-10-24T17:47:33.390Z,1571939253.390 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-10-24T17:47:33.575Z,1571939253.575 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-10-24T17:47:33.707Z,1571939253.707 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-10-24T17:47:33.713Z,1571939253.713 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-10-24T17:47:34.232Z,1571939254.232 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-10-24T17:47:34.238Z,1571939254.238 [AHRS_M2](INFO): created writer for : platform_orientation
2019-10-24T17:47:34.240Z,1571939254.240 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-10-24T17:47:34.257Z,1571939254.257 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-10-24T17:47:34.257Z,1571939254.257 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-10-24T17:47:34.263Z,1571939254.263 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-10-24T17:47:34.263Z,1571939254.263 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-10-24T17:47:34.283Z,1571939254.283 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-10-24T17:47:34.633Z,1571939254.633 [AHRS_M2] Loaded
2019-10-24T17:47:34.633Z,1571939254.633 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-10-24T17:47:34.728Z,1571939254.728 [DataOverHttps] Loaded
2019-10-24T17:47:34.729Z,1571939254.729 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-10-24T17:47:34.730Z,1571939254.730 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075C4E0
2019-10-24T17:47:34.730Z,1571939254.730 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3613
2019-10-24T17:47:34.743Z,1571939254.743 [Depth_Keller] Loaded
2019-10-24T17:47:34.743Z,1571939254.743 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-10-24T17:47:34.748Z,1571939254.748 [DropWeight] Loaded
2019-10-24T17:47:34.748Z,1571939254.748 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-10-24T17:47:34.805Z,1571939254.805 [DUSBL_Hydroid] Loaded
2019-10-24T17:47:34.806Z,1571939254.806 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-10-24T17:47:34.853Z,1571939254.853 [Micromodem] Loaded
2019-10-24T17:47:34.853Z,1571939254.853 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-10-24T17:47:34.949Z,1571939254.949 [NAL9602] Loaded
2019-10-24T17:47:34.949Z,1571939254.949 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-10-24T17:47:34.965Z,1571939254.965 [Onboard] Loaded
2019-10-24T17:47:34.965Z,1571939254.965 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-10-24T17:47:34.971Z,1571939254.971 [PowerOnly] Loaded
2019-10-24T17:47:34.971Z,1571939254.971 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-10-24T17:47:34.978Z,1571939254.978 [Radio_Surface] Loaded
2019-10-24T17:47:34.978Z,1571939254.978 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-10-24T17:47:34.979Z,1571939254.979 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078C4E0
2019-10-24T17:47:34.979Z,1571939254.979 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3614
2019-10-24T17:47:35.023Z,1571939255.023 [RDI_Pathfinder] Loaded
2019-10-24T17:47:35.023Z,1571939255.023 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-10-24T17:47:36.495Z,1571939256.495 [BPC1] Loaded
2019-10-24T17:47:36.496Z,1571939256.496 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-10-24T17:47:36.496Z,1571939256.496 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-10-24T17:47:36.497Z,1571939256.497 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-10-24T17:47:36.517Z,1571939256.517 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-10-24T17:47:36.518Z,1571939256.518 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-10-24T17:47:36.632Z,1571939256.632 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-10-24T17:47:36.633Z,1571939256.633 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-10-24T17:47:36.653Z,1571939256.653 [NavChart] Loaded
2019-10-24T17:47:36.653Z,1571939256.653 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-10-24T17:47:36.657Z,1571939256.657 [UniversalFixResidualReporter] Loaded
2019-10-24T17:47:36.657Z,1571939256.657 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-10-24T17:47:36.657Z,1571939256.657 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-10-24T17:47:36.658Z,1571939256.658 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-10-24T17:47:36.781Z,1571939256.781 [BuoyancyServo] Loaded
2019-10-24T17:47:36.782Z,1571939256.782 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-10-24T17:47:36.797Z,1571939256.797 [ElevatorServo] Loaded
2019-10-24T17:47:36.797Z,1571939256.797 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-10-24T17:47:36.812Z,1571939256.812 [MassServo] Loaded
2019-10-24T17:47:36.812Z,1571939256.812 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-10-24T17:47:36.827Z,1571939256.827 [RudderServo] Loaded
2019-10-24T17:47:36.827Z,1571939256.827 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-10-24T17:47:36.842Z,1571939256.842 [ThrusterServo] Loaded
2019-10-24T17:47:36.842Z,1571939256.842 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-10-24T17:47:36.842Z,1571939256.842 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-10-24T17:47:36.843Z,1571939256.843 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-10-24T17:47:37.139Z,1571939257.139 [CTD_NeilBrown] Loaded
2019-10-24T17:47:37.139Z,1571939257.139 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-10-24T17:47:37.140Z,1571939257.140 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D74E0
2019-10-24T17:47:37.141Z,1571939257.141 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3615
2019-10-24T17:47:37.155Z,1571939257.155 [PAR_Licor] Loaded
2019-10-24T17:47:37.155Z,1571939257.155 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-10-24T17:47:37.199Z,1571939257.199 [WetLabsSeaOWL_UV_A] Loaded
2019-10-24T17:47:37.199Z,1571939257.199 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-10-24T17:47:37.200Z,1571939257.200 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409074E0
2019-10-24T17:47:37.201Z,1571939257.201 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 3616
2019-10-24T17:47:37.201Z,1571939257.201 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-10-24T17:47:37.202Z,1571939257.202 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-10-24T17:47:37.523Z,1571939257.523 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-10-24T17:47:37.523Z,1571939257.523 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-10-24T17:47:37.576Z,1571939257.576 [DepthRateCalculator] Loaded
2019-10-24T17:47:37.576Z,1571939257.576 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-10-24T17:47:37.582Z,1571939257.582 [PitchRateCalculator] Loaded
2019-10-24T17:47:37.582Z,1571939257.582 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-10-24T17:47:37.594Z,1571939257.594 [SpeedCalculator] Loaded
2019-10-24T17:47:37.595Z,1571939257.595 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-10-24T17:47:37.616Z,1571939257.616 [TempGradientCalculator] Loaded
2019-10-24T17:47:37.616Z,1571939257.616 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-10-24T17:47:37.622Z,1571939257.622 [YawRateCalculator] Loaded
2019-10-24T17:47:37.622Z,1571939257.622 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-10-24T17:47:37.661Z,1571939257.661 [ElevatorOffsetCalculator] Loaded
2019-10-24T17:47:37.662Z,1571939257.662 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-10-24T17:47:37.662Z,1571939257.662 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-10-24T17:47:37.663Z,1571939257.663 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-10-24T17:47:37.815Z,1571939257.815 [SBIT](DEBUG): Construct Startup Built In Test.
2019-10-24T17:47:37.837Z,1571939257.837 [SBIT] Loaded
2019-10-24T17:47:37.837Z,1571939257.837 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-10-24T17:47:37.838Z,1571939257.838 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-10-24T17:47:37.850Z,1571939257.850 [IBIT] Loaded
2019-10-24T17:47:37.850Z,1571939257.850 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-10-24T17:47:37.853Z,1571939257.853 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-10-24T17:47:37.990Z,1571939257.990 [CBIT] Loaded
2019-10-24T17:47:37.990Z,1571939257.990 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-10-24T17:47:37.990Z,1571939257.990 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-10-24T17:47:37.991Z,1571939257.991 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-10-24T17:47:38.106Z,1571939258.106 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-10-24T17:47:38.106Z,1571939258.106 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-10-24T17:47:38.225Z,1571939258.225 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-10-24T17:47:38.226Z,1571939258.226 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-10-24T17:47:38.310Z,1571939258.310 [VerticalControl](DEBUG): Construct VerticalControl.
2019-10-24T17:47:38.393Z,1571939258.393 [VerticalControl] Loaded
2019-10-24T17:47:38.393Z,1571939258.393 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-10-24T17:47:38.394Z,1571939258.394 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-10-24T17:47:38.450Z,1571939258.450 [HorizontalControl] Loaded
2019-10-24T17:47:38.451Z,1571939258.451 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-10-24T17:47:38.451Z,1571939258.451 [SpeedControl](DEBUG): Construct SpeedControl.
2019-10-24T17:47:38.453Z,1571939258.453 [SpeedControl] Loaded
2019-10-24T17:47:38.453Z,1571939258.453 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-10-24T17:47:38.454Z,1571939258.454 [LoopControl](DEBUG): Construct LoopControl.
2019-10-24T17:47:38.455Z,1571939258.455 [LoopControl] Loaded
2019-10-24T17:47:38.455Z,1571939258.455 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-10-24T17:47:38.455Z,1571939258.455 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-10-24T17:47:38.456Z,1571939258.456 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-10-24T17:47:38.499Z,1571939258.499 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-10-24T17:47:38.502Z,1571939258.502 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-10-24T17:47:38.503Z,1571939258.503 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-10-24T17:47:38.510Z,1571939258.510 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-10-24T17:47:38.511Z,1571939258.511 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AE44E0
2019-10-24T17:47:38.511Z,1571939258.511 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3617
2019-10-24T17:47:38.516Z,1571939258.516 [Supervisor](INFO): Main Thread ID is 802
2019-10-24T17:47:38.516Z,1571939258.516 [Supervisor](DEBUG): Running supervisor.
2019-10-24T17:47:38.516Z,1571939258.516 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3618
2019-10-24T17:47:38.519Z,1571939258.519 [controlThread ThreadHandler](INFO): Handler Thread ID is 3619
2019-10-24T17:47:38.519Z,1571939258.519 [controlThread](DEBUG): Initializing ControlThread
2019-10-24T17:47:38.524Z,1571939258.524 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-10-24T17:47:38.524Z,1571939258.524 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-10-24T17:47:38.529Z,1571939258.529 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-10-24T17:47:38.529Z,1571939258.529 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-10-24T17:47:38.530Z,1571939258.530 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-10-24T17:47:38.530Z,1571939258.530 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-10-24T17:47:38.530Z,1571939258.530 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-10-24T17:47:38.531Z,1571939258.531 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-10-24T17:47:38.531Z,1571939258.531 [SBIT](INFO): Initialize SBIT Component.
2019-10-24T17:47:38.532Z,1571939258.532 [SBIT](IMPORTANT): git: 2019-10-15
2019-10-24T17:47:38.532Z,1571939258.532 [SBIT](INFO): git hash: 5afd4984613942c073d284d94e598e25fc5569fb
2019-10-24T17:47:38.532Z,1571939258.532 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-10-24T17:47:38.533Z,1571939258.533 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #2 PREEMPT Wed May 15 08:34:03 PDT 2019
2019-10-24T17:47:38.535Z,1571939258.535 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-10-24T17:47:38.535Z,1571939258.535 [IBIT](INFO): Initialize IBIT Component.
2019-10-24T17:47:38.536Z,1571939258.536 [CBIT](DEBUG): Initialize CBIT Component.
2019-10-24T17:47:38.537Z,1571939258.537 [logger ThreadHandler](INFO): Handler Thread ID is 3620
2019-10-24T17:47:38.549Z,1571939258.549 [CBIT](DEBUG): Initialized mux pins.
2019-10-24T17:47:38.549Z,1571939258.549 [CBIT](DEBUG): Initializing the watchdog timer.
2019-10-24T17:47:38.557Z,1571939258.557 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3621
2019-10-24T17:47:38.558Z,1571939258.558 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-10-24T17:47:38.569Z,1571939258.569 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3622
2019-10-24T17:47:38.573Z,1571939258.573 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2019-10-24T17:47:38.573Z,1571939258.573 [CBIT](DEBUG): Initializing heartbeat.
2019-10-24T17:47:38.581Z,1571939258.581 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3623
2019-10-24T17:47:38.582Z,1571939258.582 [CTD_NeilBrown](INFO): Powering down
2019-10-24T17:47:38.613Z,1571939258.613 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 3624
2019-10-24T17:47:38.615Z,1571939258.615 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-10-24T17:47:38.645Z,1571939258.645 [CBIT](DEBUG): Deactivating GF circuits.
2019-10-24T17:47:38.645Z,1571939258.645 [CBIT](DEBUG): Deactivating emergency mode.
2019-10-24T17:47:38.652Z,1571939258.652 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3625
2019-10-24T17:47:38.681Z,1571939258.681 [CBIT](DEBUG): Backplane powered.
2019-10-24T17:47:38.681Z,1571939258.681 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-10-24T17:47:38.683Z,1571939258.683 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-10-24T17:47:38.683Z,1571939258.683 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-10-24T17:47:38.684Z,1571939258.684 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-10-24T17:47:38.685Z,1571939258.685 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-10-24T17:47:38.973Z,1571939258.973 [Radio_Surface](INFO): Powering up
2019-10-24T17:47:39.035Z,1571939259.035 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-10-24T17:47:39.035Z,1571939259.035 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-10-24T17:47:39.035Z,1571939259.035 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-10-24T17:47:39.036Z,1571939259.036 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-10-24T17:47:39.036Z,1571939259.036 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-10-24T17:47:39.036Z,1571939259.036 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-10-24T17:47:39.036Z,1571939259.036 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-10-24T17:47:39.036Z,1571939259.036 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-10-24T17:47:39.037Z,1571939259.037 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-10-24T17:47:39.037Z,1571939259.037 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-10-24T17:47:39.037Z,1571939259.037 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-10-24T17:47:39.037Z,1571939259.037 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-10-24T17:47:39.037Z,1571939259.037 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-10-24T17:47:39.038Z,1571939259.038 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-10-24T17:47:39.038Z,1571939259.038 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-10-24T17:47:39.038Z,1571939259.038 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-10-24T17:47:39.220Z,1571939259.220 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-24T17:47:39.238Z,1571939259.238 [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-10-24T17:47:39.239Z,1571939259.239 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-10-24T17:47:39.322Z,1571939259.322 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-10-24T17:47:39.323Z,1571939259.323 [Default:A.Wait](DEBUG): Construct Wait.
2019-10-24T17:47:39.325Z,1571939259.325 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-24T17:47:39.360Z,1571939259.360 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-10-24T17:47:39.379Z,1571939259.379 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-10-24T17:47:39.393Z,1571939259.393 [Default:E.Execute](DEBUG): Construct Execute.
2019-10-24T17:47:39.396Z,1571939259.396 [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-10-24T17:47:39.417Z,1571939259.417 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-10-24T17:47:39.434Z,1571939259.434 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-10-24T17:47:39.472Z,1571939259.472 [DUSBL_Hydroid](INFO): Powering up
2019-10-24T17:47:39.472Z,1571939259.472 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-10-24T17:47:39.711Z,1571939259.711 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:39.717Z,1571939259.717 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-10-24T17:47:39.719Z,1571939259.719 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:39.729Z,1571939259.729 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-10-24T17:47:39.730Z,1571939259.730 [MassServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:39.737Z,1571939259.737 [MassServo](DEBUG): Initializing MassServo.
2019-10-24T17:47:39.738Z,1571939259.738 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:39.745Z,1571939259.745 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-24T17:47:39.746Z,1571939259.746 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:39.753Z,1571939259.753 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-10-24T17:47:39.755Z,1571939259.755 [CommandLine](FAULT): Scheduling is paused
2019-10-24T17:47:39.755Z,1571939259.755 [CBIT](INFO): Critical error at 20191024T174738
2019-10-24T17:47:39.756Z,1571939259.756 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-10-24T17:47:39.843Z,1571939259.843 [Micromodem](INFO): Powering up
2019-10-24T17:47:39.844Z,1571939259.844 [Micromodem](DEBUG): Initializing Micromodem.
2019-10-24T17:47:40.633Z,1571939260.633 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-10-24T17:47:40.633Z,1571939260.633 [RudderServo](FAULT): Rudder failed to initialize
2019-10-24T17:47:40.633Z,1571939260.633 [RudderServo] Communications Fault, FailCount= 1
2019-10-24T17:47:40.633Z,1571939260.633 [RudderServo](ERROR): Communications Fault
2019-10-24T17:47:40.744Z,1571939260.744 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-10-24T17:47:40.922Z,1571939260.922 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-24T17:47:40.922Z,1571939260.922 [RudderServo](INFO): Powering down
2019-10-24T17:47:41.610Z,1571939261.610 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-24T17:47:41.730Z,1571939261.730 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-24T17:47:41.734Z,1571939261.734 [CBIT](INFO): Clearing failed state for component RudderServo
2019-10-24T17:47:41.734Z,1571939261.734 [RudderServo] No Fault, FailCount= 1
2019-10-24T17:47:44.831Z,1571939264.831 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-10-24T17:47:47.711Z,1571939267.711 [Micromodem](INFO): Nmea in: $CATMG,2019-10-24T17:47:47.377556Z,RTC,RTC*5E

2019-10-24T17:47:47.712Z,1571939267.712 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-10-24T17:47:47.377556Z,RTC,RTC*5E

2019-10-24T17:47:52.969Z,1571939272.969 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-10-24T17:47:56.175Z,1571939276.175 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-10-24T17:47:56.983Z,1571939276.983 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-10-24T17:47:56.983Z,1571939276.983 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-10-24T17:47:57.009Z,1571939277.009 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-24T17:47:57.009Z,1571939277.009 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19102410584504,35.0, -0.1,   0.0,10
2019-10-24T17:47:57.386Z,1571939277.386 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-10-24T17:47:57.397Z,1571939277.397 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-10-24T17:47:57.398Z,1571939277.398 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-10-24T17:47:57.791Z,1571939277.791 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-10-24T17:47:57.791Z,1571939277.791 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-10-24T17:47:58.195Z,1571939278.195 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-10-24T17:47:58.195Z,1571939278.195 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-10-24T17:47:58.598Z,1571939278.598 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-10-24T17:47:58.599Z,1571939278.599 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-10-24T17:47:58.999Z,1571939278.999 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-10-24T17:47:58.999Z,1571939278.999 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-10-24T17:47:59.403Z,1571939279.403 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-10-24T17:47:59.403Z,1571939279.403 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-10-24T17:47:59.814Z,1571939279.814 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-10-24T17:47:59.815Z,1571939279.815 [Micromodem](INFO): Nmea out: $CCCLK,2019,10,24,17,48,00*43

2019-10-24T17:48:00.215Z,1571939280.215 [Micromodem](INFO): Nmea in: $CACLK,2019,10,24,17,48,0*71

2019-10-24T17:48:00.619Z,1571939280.619 [Micromodem](INFO): Nmea in: $CATMS,0,2019-10-24T17:48:01Z*70

2019-10-24T17:48:00.620Z,1571939280.620 [Micromodem](INFO): Nmea in: $CATMG,2019-10-24T17:48:01.028038Z,USER_CMD,RTC*16

2019-10-24T17:48:05.065Z,1571939285.065 [NAL9602](INFO): Powering up NAL9602
2019-10-24T17:48:07.153Z,1571939287.153 [SBIT](IMPORTANT): Beginning Startup BIT
2019-10-24T17:48:07.161Z,1571939287.161 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-24T17:48:16.074Z,1571939296.074 [NAL9602](INFO): NAL9602 initialized
2019-10-24T17:48:16.897Z,1571939296.897 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:48:18.207Z,1571939298.207 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011281
CHAN A1 (24V): -0.028956
CHAN A2 (12V): -0.007521
CHAN A3 (5V): -0.004611
CHAN B0 (3.3V): 0.000367
CHAN B1 (3.15aV): 0.000025
CHAN B2 (3.15bV): 0.000192
CHAN B3 (GND): 0.002107
OPEN: 0.005070
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-24T17:49:00.791Z,1571939340.791 [SBIT](IMPORTANT): SBIT PASSED
2019-10-24T17:49:00.817Z,1571939340.817 [CommandLine](IMPORTANT): got command configSet list
2019-10-24T17:49:00.817Z,1571939340.817 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-10-24T17:49:00.818Z,1571939340.818 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=40 millisecond;

2019-10-24T17:49:01.191Z,1571939341.191 [MissionManager](IMPORTANT): Started mission Startup
2019-10-24T17:49:01.191Z,1571939341.191 [Startup] Running Loop=1
2019-10-24T17:49:01.191Z,1571939341.191 [Startup](DEBUG): Aggregate::initialize Startup
2019-10-24T17:49:01.191Z,1571939341.191 [Startup:A.GoToSurface] Running Loop=1
2019-10-24T17:49:01.191Z,1571939341.191 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T17:49:01.192Z,1571939341.192 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T17:49:01.192Z,1571939341.192 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T17:49:01.210Z,1571939341.210 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T17:49:01.212Z,1571939341.212 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T17:49:01.217Z,1571939341.217 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T17:49:01.219Z,1571939341.219 [Startup:StartupSatComms] Running Loop=1
2019-10-24T17:49:01.219Z,1571939341.219 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-10-24T17:49:01.219Z,1571939341.219 [Startup:StartupSatComms:A] Running Loop=1
2019-10-24T17:49:01.579Z,1571939341.579 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-10-24T17:49:05.633Z,1571939345.633 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-10-24T17:50:01.392Z,1571939401.392 [Startup:StartupSatComms:A](INFO): Timed out from 2019-10-24T17:49:01.2Z
2019-10-24T17:50:01.401Z,1571939401.401 [Startup:StartupSatComms:A] Stopped
2019-10-24T17:50:01.401Z,1571939401.401 [Startup:StartupSatComms:B] Running Loop=1
2019-10-24T17:50:01.794Z,1571939401.794 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-24T17:50:08.086Z,1571939408.086 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004546
2019-10-24T17:50:18.480Z,1571939418.480 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20191022T205814/Courier0757.lzma
2019-10-24T17:50:20.487Z,1571939420.487 [DataOverHttps](INFO): Moved sent file to Logs/20191022T205814/Courier0757.lzma.bak
2019-10-24T17:50:20.487Z,1571939420.487 [DataOverHttps](INFO): SBD MOMSN=11951303
2019-10-24T17:50:21.418Z,1571939421.418 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:50:38.761Z,1571939438.761 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-10-24T17:50:38.761Z,1571939438.761 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T17:50:38.798Z,1571939438.798 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T17:50:39.167Z,1571939439.167 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T17:50:39.167Z,1571939439.167 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-10-24T17:50:40.468Z,1571939440.468 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20191024T174728/Courier0000.lzma
2019-10-24T17:50:42.474Z,1571939442.474 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Courier0000.lzma.bak
2019-10-24T17:50:42.474Z,1571939442.474 [DataOverHttps](INFO): SBD MOMSN=11951305
2019-10-24T17:51:01.791Z,1571939461.791 [Startup:StartupSatComms:B](INFO): Timed out from 2019-10-24T17:50:01.4Z
2019-10-24T17:51:01.791Z,1571939461.791 [Startup:StartupSatComms:B] Stopped
2019-10-24T17:51:01.792Z,1571939461.792 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-10-24T17:51:01.792Z,1571939461.792 [Startup:StartupSatComms] Stopped
2019-10-24T17:51:01.792Z,1571939461.792 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-10-24T17:51:01.813Z,1571939461.813 [Startup](INFO): Completed Startup
2019-10-24T17:51:01.813Z,1571939461.813 [MissionManager](INFO): Startup is completed.
2019-10-24T17:51:01.813Z,1571939461.813 [MissionManager](INFO): Uninitializing Mission Startup
2019-10-24T17:51:01.813Z,1571939461.813 [Startup] Stopped
2019-10-24T17:51:01.813Z,1571939461.813 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-10-24T17:51:01.813Z,1571939461.813 [Startup:A.GoToSurface] Stopped
2019-10-24T17:51:01.813Z,1571939461.813 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T17:51:02.276Z,1571939462.276 [MissionManager](IMPORTANT): Started mission Default
2019-10-24T17:51:02.276Z,1571939462.276 [Default] Running Loop=1
2019-10-24T17:51:02.276Z,1571939462.276 [Default](DEBUG): Aggregate::initialize Default
2019-10-24T17:51:02.276Z,1571939462.276 [Default:B.GoToSurface] Running Loop=1
2019-10-24T17:51:02.276Z,1571939462.276 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-24T17:51:02.277Z,1571939462.277 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-24T17:51:02.277Z,1571939462.277 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-24T17:51:02.277Z,1571939462.277 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-24T17:51:02.278Z,1571939462.278 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-24T17:51:02.278Z,1571939462.278 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-24T17:51:02.278Z,1571939462.278 [Default:A.Wait] Running Loop=1
2019-10-24T17:51:02.278Z,1571939462.278 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-24T17:51:07.401Z,1571939467.401 [DataOverHttps](INFO): Sending 346 bytes from file Logs/20191022T205814/Express0758.lzma
2019-10-24T17:51:09.407Z,1571939469.407 [DataOverHttps](INFO): Moved sent file to Logs/20191022T205814/Express0758.lzma.bak
2019-10-24T17:51:09.407Z,1571939469.407 [DataOverHttps](INFO): SBD MOMSN=11951309
2019-10-24T17:51:15.508Z,1571939475.508 [Default:A.Wait](INFO): Done Waiting.
2019-10-24T17:51:15.508Z,1571939475.508 [Default:A.Wait] Stopped
2019-10-24T17:51:15.508Z,1571939475.508 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T17:51:15.983Z,1571939475.983 [Default:CheckIn] Running Loop=1
2019-10-24T17:51:15.983Z,1571939475.983 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T17:51:15.984Z,1571939475.984 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T17:51:16.457Z,1571939476.457 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-10-24T17:51:29.841Z,1571939489.841 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:51:56.042Z,1571939516.042 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:52:09.318Z,1571939529.318 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:52:21.826Z,1571939541.826 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:53:19.095Z,1571939599.095 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-24T17:53:19.925Z,1571939599.925 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:28.413Z,1571939608.413 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:31.641Z,1571939611.641 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:34.469Z,1571939614.469 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:37.297Z,1571939617.297 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:39.317Z,1571939619.317 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:39.746Z,1571939619.746 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-10-24T17:53:39.746Z,1571939619.746 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T17:53:39.756Z,1571939619.756 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T17:53:40.168Z,1571939620.168 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T17:53:40.168Z,1571939620.168 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-10-24T17:53:41.331Z,1571939621.331 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:43.048Z,1571939623.048 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:53:43.349Z,1571939623.349 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:46.597Z,1571939626.597 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:49.409Z,1571939629.409 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:52.661Z,1571939632.661 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:55.473Z,1571939635.473 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:53:58.297Z,1571939638.297 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:00.321Z,1571939640.321 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:02.345Z,1571939642.345 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:05.573Z,1571939645.573 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:08.405Z,1571939648.405 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:08.913Z,1571939648.913 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2019-10-24T17:54:11.637Z,1571939651.637 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:14.465Z,1571939654.465 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:17.285Z,1571939657.285 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:19.313Z,1571939659.313 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:21.329Z,1571939661.329 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:21.760Z,1571939661.760 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-10-24T17:54:21.763Z,1571939661.763 [BPC1](INFO): Received data from all battery sticks.
2019-10-24T17:54:23.347Z,1571939663.347 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:26.581Z,1571939666.581 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:29.409Z,1571939669.409 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:32.657Z,1571939672.657 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:35.469Z,1571939675.469 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:38.297Z,1571939678.297 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:40.313Z,1571939680.313 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:42.337Z,1571939682.337 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:45.573Z,1571939685.573 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:48.405Z,1571939688.405 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:51.625Z,1571939691.625 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:54.469Z,1571939694.469 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:54:57.685Z,1571939697.685 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:00.521Z,1571939700.521 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:03.345Z,1571939703.345 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:06.585Z,1571939706.585 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:08.333Z,1571939708.333 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.689766
2019-10-24T17:55:09.401Z,1571939709.401 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:12.653Z,1571939712.653 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:15.461Z,1571939715.461 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:18.293Z,1571939718.293 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:20.309Z,1571939720.309 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:22.337Z,1571939722.337 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:24.357Z,1571939724.357 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:27.581Z,1571939727.581 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:30.409Z,1571939730.409 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:33.653Z,1571939733.653 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:36.483Z,1571939736.483 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:39.305Z,1571939739.305 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:40.461Z,1571939740.461 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-24T17:55:41.317Z,1571939741.317 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:43.341Z,1571939743.341 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:46.581Z,1571939746.581 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:49.397Z,1571939749.397 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:52.657Z,1571939752.657 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:55.461Z,1571939755.461 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:55:58.289Z,1571939758.289 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:00.313Z,1571939760.313 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:02.342Z,1571939762.342 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:05.561Z,1571939765.561 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:08.393Z,1571939768.393 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:11.617Z,1571939771.617 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:14.453Z,1571939774.453 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:15.602Z,1571939775.602 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-24T17:56:16.075Z,1571939776.075 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-10-24T17:51:15.0Z
2019-10-24T17:56:16.075Z,1571939776.075 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T17:56:16.075Z,1571939776.075 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T17:56:16.479Z,1571939776.479 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-24T17:56:17.681Z,1571939777.681 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:20.509Z,1571939780.509 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:23.335Z,1571939783.335 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:26.585Z,1571939786.585 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:29.397Z,1571939789.397 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:32.653Z,1571939792.653 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:35.461Z,1571939795.461 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:38.705Z,1571939798.705 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:40.717Z,1571939800.717 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-10-24T17:56:40.717Z,1571939800.717 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T17:56:40.726Z,1571939800.726 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T17:56:41.166Z,1571939801.166 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T17:56:41.166Z,1571939801.166 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-10-24T17:56:41.517Z,1571939801.517 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:44.345Z,1571939804.345 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:47.577Z,1571939807.577 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:50.405Z,1571939810.405 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:50.741Z,1571939810.741 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2019-10-24T17:56:53.645Z,1571939813.645 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:56.465Z,1571939816.465 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:56:59.707Z,1571939819.707 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:02.521Z,1571939822.521 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:05.357Z,1571939825.357 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:08.589Z,1571939828.589 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:11.421Z,1571939831.421 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:14.653Z,1571939834.653 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:17.486Z,1571939837.486 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:20.305Z,1571939840.305 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:22.325Z,1571939842.325 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:24.341Z,1571939844.341 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:24.406Z,1571939844.406 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003771
2019-10-24T17:57:27.569Z,1571939847.569 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:30.403Z,1571939850.403 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:33.645Z,1571939853.645 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:34.888Z,1571939854.888 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20191024T174728/Courier0004.lzma
2019-10-24T17:57:36.461Z,1571939856.461 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:36.894Z,1571939856.894 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Courier0004.lzma.bak
2019-10-24T17:57:36.894Z,1571939856.894 [DataOverHttps](INFO): SBD MOMSN=11951347
2019-10-24T17:57:39.693Z,1571939859.693 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:42.521Z,1571939862.521 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:45.349Z,1571939865.349 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:48.591Z,1571939868.591 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:51.413Z,1571939871.413 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:54.643Z,1571939874.643 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:57.481Z,1571939877.481 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:57:59.478Z,1571939879.478 [DataOverHttps](INFO): Sending 679 bytes from file Logs/20191024T174728/Express0001.lzma
2019-10-24T17:58:00.297Z,1571939880.297 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:01.482Z,1571939881.482 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Express0001.lzma.bak
2019-10-24T17:58:01.482Z,1571939881.482 [DataOverHttps](INFO): SBD MOMSN=11951349
2019-10-24T17:58:02.321Z,1571939882.321 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:04.341Z,1571939884.341 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:07.573Z,1571939887.573 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:10.397Z,1571939890.397 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:13.651Z,1571939893.651 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:16.457Z,1571939896.457 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:58:19.675Z,1571939899.675 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-10-24T17:58:19.675Z,1571939899.675 [NAL9602] Data Fault, FailCount= 1
2019-10-24T17:58:19.675Z,1571939899.675 [NAL9602](ERROR): Data Fault
2019-10-24T17:58:19.750Z,1571939899.750 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-24T17:58:20.079Z,1571939900.079 [NAL9602](INFO): Powering down
2019-10-24T17:58:20.989Z,1571939900.989 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-24T17:58:20.989Z,1571939900.989 [NAL9602] No Fault, FailCount= 1
2019-10-24T17:58:25.472Z,1571939905.472 [DataOverHttps](INFO): Sending 176 bytes from file Logs/20191024T174728/Express0005.lzma
2019-10-24T17:58:27.478Z,1571939907.478 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Express0005.lzma.bak
2019-10-24T17:58:27.479Z,1571939907.479 [DataOverHttps](INFO): SBD MOMSN=11951364
2019-10-24T17:58:41.187Z,1571939921.187 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T17:58:41.187Z,1571939921.187 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-24T17:58:41.187Z,1571939921.187 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-24T17:58:50.388Z,1571939930.388 [NAL9602](INFO): Powering up NAL9602
2019-10-24T17:59:01.298Z,1571939941.298 [NAL9602](INFO): NAL9602 initialized
2019-10-24T17:59:02.109Z,1571939942.109 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:04.943Z,1571939944.943 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:07.773Z,1571939947.773 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:10.601Z,1571939950.601 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:12.626Z,1571939952.626 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:14.645Z,1571939954.645 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:16.657Z,1571939956.657 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:19.889Z,1571939959.889 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:22.713Z,1571939962.713 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:25.953Z,1571939965.953 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:28.781Z,1571939968.781 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:31.601Z,1571939971.601 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:34.041Z,1571939974.041 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:36.861Z,1571939976.861 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:39.681Z,1571939979.681 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:41.719Z,1571939981.719 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-10-24T17:59:41.719Z,1571939981.719 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T17:59:41.729Z,1571939981.729 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T17:59:42.109Z,1571939982.109 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:42.147Z,1571939982.147 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T17:59:42.147Z,1571939982.147 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-10-24T17:59:44.941Z,1571939984.941 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:48.169Z,1571939988.169 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:51.005Z,1571939991.005 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:54.229Z,1571939994.229 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:57.053Z,1571939997.053 [NAL9602](DEBUG): Fix Requested
2019-10-24T17:59:59.889Z,1571939999.889 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:02.309Z,1571940002.309 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:05.133Z,1571940005.133 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:08.381Z,1571940008.381 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:11.197Z,1571940011.197 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:14.433Z,1571940014.433 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:17.257Z,1571940017.257 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:20.125Z,1571940020.125 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:22.941Z,1571940022.941 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:26.181Z,1571940026.181 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:29.013Z,1571940029.013 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:32.239Z,1571940032.239 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:35.073Z,1571940035.073 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:38.293Z,1571940038.293 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:41.125Z,1571940041.125 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:44.353Z,1571940044.353 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:47.181Z,1571940047.181 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:50.013Z,1571940050.013 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:53.245Z,1571940053.245 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:56.069Z,1571940056.069 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:00:58.903Z,1571940058.903 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:02.129Z,1571940062.129 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:04.957Z,1571940064.957 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:08.189Z,1571940068.189 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:11.017Z,1571940071.017 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:14.245Z,1571940074.245 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:17.077Z,1571940077.077 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:20.309Z,1571940080.309 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:23.137Z,1571940083.137 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:26.369Z,1571940086.369 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:29.197Z,1571940089.197 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:32.025Z,1571940092.025 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:35.253Z,1571940095.253 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:38.085Z,1571940098.085 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:40.913Z,1571940100.913 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:44.149Z,1571940104.149 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:46.989Z,1571940106.989 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:50.209Z,1571940110.209 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:53.029Z,1571940113.029 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:56.265Z,1571940116.265 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:01:59.089Z,1571940119.089 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:02.338Z,1571940122.338 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:05.153Z,1571940125.153 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:08.385Z,1571940128.385 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:11.213Z,1571940131.213 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:14.041Z,1571940134.041 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:16.873Z,1571940136.873 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:18.889Z,1571940138.889 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:22.121Z,1571940142.121 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:24.949Z,1571940144.949 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:28.177Z,1571940148.177 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:31.017Z,1571940151.017 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:34.241Z,1571940154.241 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:37.065Z,1571940157.065 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:39.909Z,1571940159.909 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:42.746Z,1571940162.746 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2019-10-24T18:02:42.746Z,1571940162.746 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T18:02:42.760Z,1571940162.760 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T18:02:43.129Z,1571940163.129 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:43.186Z,1571940163.186 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T18:02:43.186Z,1571940163.186 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2019-10-24T18:02:45.957Z,1571940165.957 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:49.185Z,1571940169.185 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:52.019Z,1571940172.019 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:55.247Z,1571940175.247 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:02:58.077Z,1571940178.077 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:00.901Z,1571940180.901 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:04.133Z,1571940184.133 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:06.972Z,1571940186.972 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:10.201Z,1571940190.201 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:13.029Z,1571940193.029 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:16.265Z,1571940196.265 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:19.081Z,1571940199.081 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:21.909Z,1571940201.909 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:25.141Z,1571940205.141 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:27.973Z,1571940207.973 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:31.204Z,1571940211.204 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:34.037Z,1571940214.037 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:37.265Z,1571940217.265 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:40.097Z,1571940220.097 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:41.739Z,1571940221.739 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-24T18:03:41.739Z,1571940221.739 [Default:CheckIn:C.Wait] Stopped
2019-10-24T18:03:41.739Z,1571940221.739 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T18:03:41.739Z,1571940221.739 [Default:CheckIn:D] Running Loop=1
2019-10-24T18:03:42.159Z,1571940222.159 [Default:CheckIn:D] Stopped
2019-10-24T18:03:42.160Z,1571940222.160 [Default:CheckIn:E] Running Loop=1
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.664727 min 
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn:E] Stopped
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn] Stopped
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn](INFO): Running loop #2
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn] Running Loop=2
2019-10-24T18:03:42.531Z,1571940222.531 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T18:03:42.532Z,1571940222.532 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T18:03:42.925Z,1571940222.925 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:46.151Z,1571940226.151 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:48.985Z,1571940228.985 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:52.213Z,1571940232.213 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:55.041Z,1571940235.041 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:03:58.273Z,1571940238.273 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:01.097Z,1571940241.097 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:04.329Z,1571940244.329 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:07.165Z,1571940247.165 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:09.989Z,1571940249.989 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:13.225Z,1571940253.225 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:16.049Z,1571940256.049 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:19.298Z,1571940259.298 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:22.105Z,1571940262.105 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:24.937Z,1571940264.937 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:28.165Z,1571940268.165 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:31.001Z,1571940271.001 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:32.648Z,1571940272.648 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-10-24T18:04:32.648Z,1571940272.648 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +0.   +0.00,   0.00,999.96
2019-10-24T18:04:34.228Z,1571940274.228 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:37.057Z,1571940277.057 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:40.289Z,1571940280.289 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:43.113Z,1571940283.113 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:45.945Z,1571940285.945 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:49.177Z,1571940289.177 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:52.009Z,1571940292.009 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:55.245Z,1571940295.245 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:04:58.069Z,1571940298.069 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:01.297Z,1571940301.297 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:04.129Z,1571940304.129 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:06.949Z,1571940306.949 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:10.198Z,1571940310.198 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:13.012Z,1571940313.012 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:16.257Z,1571940316.257 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:19.073Z,1571940319.073 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:22.309Z,1571940322.309 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:25.133Z,1571940325.133 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:27.961Z,1571940327.961 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:31.193Z,1571940331.193 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:34.017Z,1571940334.017 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:37.253Z,1571940337.253 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:40.081Z,1571940340.081 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:43.309Z,1571940343.309 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:43.767Z,1571940343.767 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2019-10-24T18:05:43.767Z,1571940343.767 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-24T18:05:43.785Z,1571940343.785 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-24T18:05:44.162Z,1571940344.162 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-24T18:05:44.162Z,1571940344.162 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2019-10-24T18:05:46.137Z,1571940346.137 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:48.973Z,1571940348.973 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:52.199Z,1571940352.199 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:55.029Z,1571940355.029 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:05:58.261Z,1571940358.261 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:01.093Z,1571940361.093 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:04.317Z,1571940364.317 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:07.154Z,1571940367.154 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:09.977Z,1571940369.977 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:13.213Z,1571940373.213 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:16.033Z,1571940376.033 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:19.269Z,1571940379.269 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:22.097Z,1571940382.097 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:25.329Z,1571940385.329 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:28.156Z,1571940388.156 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:30.993Z,1571940390.993 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:32.647Z,1571940392.647 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-10-24T18:06:32.647Z,1571940392.647 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-10-24T18:06:34.217Z,1571940394.217 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:37.041Z,1571940397.041 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:40.277Z,1571940400.277 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:43.109Z,1571940403.109 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:46.333Z,1571940406.333 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:49.169Z,1571940409.169 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:52.001Z,1571940412.001 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:55.221Z,1571940415.221 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:06:58.053Z,1571940418.053 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:01.285Z,1571940421.285 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:04.113Z,1571940424.113 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:06.941Z,1571940426.941 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:10.173Z,1571940430.173 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:13.001Z,1571940433.001 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:16.237Z,1571940436.237 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:19.061Z,1571940439.061 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:22.301Z,1571940442.301 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:25.120Z,1571940445.120 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:28.353Z,1571940448.353 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:31.181Z,1571940451.181 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:34.005Z,1571940454.005 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:37.237Z,1571940457.237 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:40.469Z,1571940460.469 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:43.300Z,1571940463.300 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:46.133Z,1571940466.133 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:49.361Z,1571940469.361 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:52.189Z,1571940472.189 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:55.421Z,1571940475.421 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:07:58.245Z,1571940478.245 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:01.077Z,1571940481.077 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:04.321Z,1571940484.321 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:07.137Z,1571940487.137 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:10.365Z,1571940490.365 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:13.197Z,1571940493.197 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:16.429Z,1571940496.429 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:19.257Z,1571940499.257 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:22.095Z,1571940502.095 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:25.317Z,1571940505.317 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:28.161Z,1571940508.161 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:31.381Z,1571940511.381 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:08:31.779Z,1571940511.779 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180742.00,A,3648.12072,N,12147.28454,W,0.564,334.24,241019,,,A*7F
2019-10-24T18:08:31.795Z,1571940511.795 [NAL9602](INFO): GPS fix at 20191024T180742: (36.802012, -121.788076)
2019-10-24T18:08:31.819Z,1571940511.819 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T18:08:31.819Z,1571940511.819 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T18:08:44.372Z,1571940524.372 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20191024T174728/Courier0007.lzma
2019-10-24T18:08:46.378Z,1571940526.378 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Courier0007.lzma.bak
2019-10-24T18:08:46.379Z,1571940526.379 [DataOverHttps](INFO): SBD MOMSN=11951401
2019-10-24T18:09:04.110Z,1571940544.110 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-24T18:09:13.197Z,1571940553.197 [DataOverHttps](INFO): Sending 297 bytes from file Logs/20191024T174728/Express0008.lzma
2019-10-24T18:09:15.202Z,1571940555.202 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Express0008.lzma.bak
2019-10-24T18:09:15.202Z,1571940555.202 [DataOverHttps](INFO): SBD MOMSN=11951404
2019-10-24T18:09:22.377Z,1571940562.377 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T18:09:22.377Z,1571940562.377 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-24T18:09:22.377Z,1571940562.377 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-24T18:11:56.661Z,1571940716.661 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-10-24T18:11:56.661Z,1571940716.661 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.   +0.49,        +0.01,   8.23,  0.00
2019-10-24T18:14:22.938Z,1571940862.938 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-24T18:14:22.938Z,1571940862.938 [Default:CheckIn:C.Wait] Stopped
2019-10-24T18:14:22.939Z,1571940862.939 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T18:14:22.939Z,1571940862.939 [Default:CheckIn:D] Running Loop=1
2019-10-24T18:14:23.303Z,1571940863.303 [Default:CheckIn:D] Stopped
2019-10-24T18:14:23.304Z,1571940863.304 [Default:CheckIn:E] Running Loop=1
2019-10-24T18:14:23.742Z,1571940863.742 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.350460 min 
2019-10-24T18:14:23.742Z,1571940863.742 [Default:CheckIn:E] Stopped
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn] Stopped
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn](INFO): Running loop #3
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn] Running Loop=3
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-24T18:14:23.743Z,1571940863.743 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-24T18:14:25.301Z,1571940865.301 [NAL9602](DEBUG): Fix Requested
2019-10-24T18:14:25.697Z,1571940865.697 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181336.00,A,3648.15981,N,12147.28395,W,0.875,167.87,241019,,,A*71
2019-10-24T18:14:25.700Z,1571940865.700 [NAL9602](INFO): GPS fix at 20191024T181336: (36.802664, -121.788066)
2019-10-24T18:14:25.789Z,1571940865.789 [Default:CheckIn:Read_GPS] Stopped
2019-10-24T18:14:25.789Z,1571940865.789 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-24T18:14:34.389Z,1571940874.389 [CommandLine](IMPORTANT): got command show variable limitFwd
2019-10-24T18:14:34.414Z,1571940874.414 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd (millimeter)
2019-10-24T18:14:34.804Z,1571940874.804 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191024T174728/Courier0010.lzma
2019-10-24T18:14:36.810Z,1571940876.810 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Courier0010.lzma.bak
2019-10-24T18:14:36.810Z,1571940876.810 [DataOverHttps](INFO): SBD MOMSN=11951420
2019-10-24T18:14:42.280Z,1571940882.280 [CommandLine](IMPORTANT): got command get VerticalControl.massPositionLimitFwd
2019-10-24T18:14:42.285Z,1571940882.285 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd 33.000000 mm
2019-10-24T18:14:50.870Z,1571940890.870 [CommandLine](IMPORTANT): got command maintain control VerticalControl.massPositionAction 3.000000 centimeter
2019-10-24T18:14:50.871Z,1571940890.871 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread.
2019-10-24T18:14:50.933Z,1571940890.933 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-10-24T18:14:58.213Z,1571940898.213 [CommandLine](IMPORTANT): got command show variable range
2019-10-24T18:14:58.218Z,1571940898.218 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-10-24T18:14:58.396Z,1571940898.396 [CommandLine](IMPORTANT): BR_Ping1D.minRange (meter)
2019-10-24T18:14:58.401Z,1571940898.401 [CommandLine](IMPORTANT): BR_Ping1D.maxRange (meter)
2019-10-24T18:14:58.462Z,1571940898.462 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-10-24T18:14:58.463Z,1571940898.463 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-10-24T18:14:58.464Z,1571940898.464 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-10-24T18:14:58.471Z,1571940898.471 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-10-24T18:14:58.471Z,1571940898.471 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-10-24T18:14:58.472Z,1571940898.472 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-10-24T18:14:58.472Z,1571940898.472 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-10-24T18:15:03.368Z,1571940903.368 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191024T174728/Express0011.lzma
2019-10-24T18:15:05.374Z,1571940905.374 [DataOverHttps](INFO): Moved sent file to Logs/20191024T174728/Express0011.lzma.bak
2019-10-24T18:15:05.374Z,1571940905.374 [DataOverHttps](INFO): SBD MOMSN=11951423
2019-10-24T18:15:09.655Z,1571940909.655 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.acoustic_contact_range
2019-10-24T18:15:16.352Z,1571940916.352 [Default:CheckIn:Read_Iridium] Stopped
2019-10-24T18:15:16.352Z,1571940916.352 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-24T18:15:16.352Z,1571940916.352 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-24T18:16:16.246Z,1571940976.246 [DataOverHttps](IMPORTANT): SBD MTMSN=20191024T181525
2019-10-24T18:16:25.547Z,1571940985.547 [DataOverHttps](INFO): Received command:restart sys
2019-10-24T18:16:25.577Z,1571940985.577 [CommandLine](IMPORTANT): got command restart system
2019-10-24T18:16:27.785Z,1571940987.785 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:27.786Z,1571940987.786 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:27.945Z,1571940987.945 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-10-24T18:16:27.945Z,1571940987.945 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:27.945Z,1571940987.945 [CommandLine](INFO): Join timeout helper Thread ID is 3718
2019-10-24T18:16:27.946Z,1571940987.946 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-10-24T18:16:27.946Z,1571940987.946 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:27.947Z,1571940987.947 [NavChartDb](INFO): Join timeout helper Thread ID is 3719
2019-10-24T18:16:28.173Z,1571940988.173 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:28.173Z,1571940988.173 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.185Z,1571940988.185 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-10-24T18:16:28.185Z,1571940988.185 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.185Z,1571940988.185 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 3720
2019-10-24T18:16:28.361Z,1571940988.361 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:28.361Z,1571940988.361 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-10-24T18:16:28.362Z,1571940988.362 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.369Z,1571940988.369 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-10-24T18:16:28.369Z,1571940988.369 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.370Z,1571940988.370 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3721
2019-10-24T18:16:28.505Z,1571940988.505 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:28.505Z,1571940988.505 [CTD_NeilBrown](INFO): Powering down
2019-10-24T18:16:28.517Z,1571940988.517 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.529Z,1571940988.529 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-10-24T18:16:28.529Z,1571940988.529 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.529Z,1571940988.529 [Radio_Surface](INFO): Join timeout helper Thread ID is 3722
2019-10-24T18:16:28.773Z,1571940988.773 [Radio_Surface](INFO): Powering down
2019-10-24T18:16:28.774Z,1571940988.774 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:28.774Z,1571940988.774 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.794Z,1571940988.794 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-10-24T18:16:28.794Z,1571940988.794 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:28.794Z,1571940988.794 [DataOverHttps](INFO): Join timeout helper Thread ID is 3723
2019-10-24T18:16:29.557Z,1571940989.557 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:29.557Z,1571940989.557 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:29.577Z,1571940989.577 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-10-24T18:16:29.577Z,1571940989.577 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:29.578Z,1571940989.578 [logger](INFO): Join timeout helper Thread ID is 3724
2019-10-24T18:16:29.621Z,1571940989.621 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:29.622Z,1571940989.622 [logger ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:29.639Z,1571940989.639 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-10-24T18:16:29.640Z,1571940989.640 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:29.640Z,1571940989.640 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-10-24T18:16:29.641Z,1571940989.641 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:29.642Z,1571940989.642 [controlThread](INFO): Join timeout helper Thread ID is 3725
2019-10-24T18:16:29.833Z,1571940989.833 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-10-24T18:16:29.833Z,1571940989.833 [controlThread](DEBUG): Uninitializing ControlThread
2019-10-24T18:16:29.834Z,1571940989.834 [AHRS_M2](INFO): Powering down
2019-10-24T18:16:29.905Z,1571940989.905 [DUSBL_Hydroid](INFO): Powering down
2019-10-24T18:16:29.997Z,1571940989.997 [Micromodem](INFO): Powering down
2019-10-24T18:16:30.093Z,1571940990.093 [NAL9602](INFO): Powering down
2019-10-24T18:16:30.165Z,1571940990.165 [RDI_Pathfinder](INFO): Powering down
2019-10-24T18:16:30.166Z,1571940990.166 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-10-24T18:16:30.167Z,1571940990.167 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-10-24T18:16:30.168Z,1571940990.168 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-10-24T18:16:30.168Z,1571940990.168 [MissionManager](INFO): Uninitializing Mission Default
2019-10-24T18:16:30.168Z,1571940990.168 [Default] Stopped
2019-10-24T18:16:30.169Z,1571940990.169 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-24T18:16:30.169Z,1571940990.169 [Default:B.GoToSurface] Stopped
2019-10-24T18:16:30.169Z,1571940990.169 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-24T18:16:30.169Z,1571940990.169 [Default:CheckIn] Stopped
2019-10-24T18:16:30.169Z,1571940990.169 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-24T18:16:30.169Z,1571940990.169 [Default:CheckIn:C.Wait] Stopped
2019-10-24T18:16:30.169Z,1571940990.169 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-24T18:16:30.171Z,1571940990.171 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-10-24T18:16:30.172Z,1571940990.172 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-10-24T18:16:30.172Z,1571940990.172 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-10-24T18:16:30.173Z,1571940990.173 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-10-24T18:16:30.173Z,1571940990.173 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-10-24T18:16:30.173Z,1571940990.173 [BuoyancyServo](INFO): Powering down
2019-10-24T18:16:30.185Z,1571940990.185 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-10-24T18:16:30.185Z,1571940990.185 [ElevatorServo](INFO): Powering down
2019-10-24T18:16:30.186Z,1571940990.186 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-10-24T18:16:30.186Z,1571940990.186 [MassServo](INFO): Powering down
2019-10-24T18:16:30.187Z,1571940990.187 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-24T18:16:30.187Z,1571940990.187 [RudderServo](INFO): Powering down
2019-10-24T18:16:30.188Z,1571940990.188 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-10-24T18:16:30.188Z,1571940990.188 [ThrusterServo](INFO): Powering down
2019-10-24T18:16:30.189Z,1571940990.189 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-10-24T18:16:30.189Z,1571940990.189 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-10-24T18:16:30.189Z,1571940990.189 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-10-24T18:16:30.189Z,1571940990.189 [CBIT](DEBUG): Powering off loads.
2019-10-24T18:16:30.201Z,1571940990.201 [CBIT](DEBUG): Disabling WDT.
2019-10-24T18:16:30.212Z,1571940990.212 [CBIT](DEBUG): Opening all GF detection circuits.
2019-10-24T18:16:30.213Z,1571940990.213 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.261Z,1571940990.261 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.271Z,1571940990.271 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.314Z,1571940990.314 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.317Z,1571940990.317 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.386Z,1571940990.386 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-10-24T18:16:30.449Z,1571940990.449 [logger ThreadHandler](INFO): Thread cancelled.