2019-11-25T16:35:06.644Z,1574699706.644 [Supervisor](DEBUG): Initializing supervisor.
2019-11-25T16:35:06.647Z,1574699706.647 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-11-25T16:35:06.647Z,1574699706.647 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-11-25T16:35:06.648Z,1574699706.648 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-11-25T16:35:06.649Z,1574699706.649 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-11-25T16:35:06.649Z,1574699706.649 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-11-25T16:35:06.652Z,1574699706.652 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-11-25T16:35:06.663Z,1574699706.663 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-11-25T16:35:06.664Z,1574699706.664 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-11-25T16:35:06.664Z,1574699706.664 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-11-25T16:35:06.665Z,1574699706.665 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-11-25T16:35:06.666Z,1574699706.666 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-11-25T16:35:06.666Z,1574699706.666 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-11-25T16:35:06.668Z,1574699706.668 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-11-25T16:35:06.668Z,1574699706.668 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-11-25T16:35:06.673Z,1574699706.673 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-11-25T16:35:07.085Z,1574699707.085 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-11-25T16:35:07.087Z,1574699707.087 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-11-25T16:35:07.183Z,1574699707.183 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-11-25T16:35:07.185Z,1574699707.185 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-11-25T16:35:07.488Z,1574699707.488 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-11-25T16:35:07.489Z,1574699707.489 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-11-25T16:35:07.628Z,1574699707.628 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-11-25T16:35:07.629Z,1574699707.629 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-11-25T16:35:07.812Z,1574699707.812 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-11-25T16:35:07.814Z,1574699707.814 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-11-25T16:35:08.259Z,1574699708.259 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-11-25T16:35:08.261Z,1574699708.261 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-11-25T16:35:08.462Z,1574699708.462 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-11-25T16:35:08.462Z,1574699708.462 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-11-25T16:35:08.603Z,1574699708.603 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-11-25T16:35:08.605Z,1574699708.605 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-11-25T16:35:08.788Z,1574699708.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-11-25T16:35:08.789Z,1574699708.789 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-11-25T16:35:08.884Z,1574699708.884 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-11-25T16:35:08.885Z,1574699708.885 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-11-25T16:35:09.175Z,1574699709.175 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-11-25T16:35:09.177Z,1574699709.177 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-11-25T16:35:09.257Z,1574699709.257 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-11-25T16:35:09.358Z,1574699709.358 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-11-25T16:35:09.359Z,1574699709.359 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-11-25T16:35:09.992Z,1574699709.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-11-25T16:35:09.992Z,1574699709.992 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-11-25T16:35:11.161Z,1574699711.161 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-11-25T16:35:11.163Z,1574699711.163 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-11-25T16:35:11.165Z,1574699711.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-11-25T16:35:11.365Z,1574699711.365 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-11-25T16:35:11.462Z,1574699711.462 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-11-25T16:35:11.559Z,1574699711.559 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-11-25T16:35:11.783Z,1574699711.783 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-11-25T16:35:11.785Z,1574699711.785 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-11-25T16:35:11.869Z,1574699711.869 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-11-25T16:35:11.960Z,1574699711.960 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-11-25T16:35:12.056Z,1574699712.056 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-11-25T16:35:12.140Z,1574699712.140 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-11-25T16:35:12.246Z,1574699712.246 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-11-25T16:35:12.422Z,1574699712.422 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-11-25T16:35:12.548Z,1574699712.548 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-11-25T16:35:12.568Z,1574699712.568 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-11-25T16:35:13.090Z,1574699713.090 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-11-25T16:35:13.095Z,1574699713.095 [AHRS_M2](INFO): created writer for : platform_orientation
2019-11-25T16:35:13.097Z,1574699713.097 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-11-25T16:35:13.102Z,1574699713.102 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-11-25T16:35:13.103Z,1574699713.103 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-11-25T16:35:13.108Z,1574699713.108 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-11-25T16:35:13.109Z,1574699713.109 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-11-25T16:35:13.114Z,1574699713.114 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-11-25T16:35:13.288Z,1574699713.288 [AHRS_M2] Loaded
2019-11-25T16:35:13.289Z,1574699713.289 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-11-25T16:35:13.434Z,1574699713.434 [DataOverHttps] Loaded
2019-11-25T16:35:13.434Z,1574699713.434 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-11-25T16:35:13.435Z,1574699713.435 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4076A4E0
2019-11-25T16:35:13.436Z,1574699713.436 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 888
2019-11-25T16:35:13.459Z,1574699713.459 [DDM] Loaded
2019-11-25T16:35:13.460Z,1574699713.460 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread.
2019-11-25T16:35:13.472Z,1574699713.472 [Depth_Keller] Loaded
2019-11-25T16:35:13.472Z,1574699713.472 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-11-25T16:35:13.477Z,1574699713.477 [DropWeight] Loaded
2019-11-25T16:35:13.477Z,1574699713.477 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-11-25T16:35:13.538Z,1574699713.538 [DUSBL_Hydroid] Loaded
2019-11-25T16:35:13.538Z,1574699713.538 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-11-25T16:35:13.584Z,1574699713.584 [Micromodem] Loaded
2019-11-25T16:35:13.584Z,1574699713.584 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-11-25T16:35:13.679Z,1574699713.679 [NAL9602] Loaded
2019-11-25T16:35:13.679Z,1574699713.679 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-11-25T16:35:13.695Z,1574699713.695 [Onboard] Loaded
2019-11-25T16:35:13.695Z,1574699713.695 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-11-25T16:35:13.701Z,1574699713.701 [PowerOnly] Loaded
2019-11-25T16:35:13.701Z,1574699713.701 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-11-25T16:35:13.707Z,1574699713.707 [Radio_Surface] Loaded
2019-11-25T16:35:13.707Z,1574699713.707 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-11-25T16:35:13.708Z,1574699713.708 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4079A4E0
2019-11-25T16:35:13.709Z,1574699713.709 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 889
2019-11-25T16:35:13.751Z,1574699713.751 [RDI_Pathfinder] Loaded
2019-11-25T16:35:13.751Z,1574699713.751 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-11-25T16:35:15.209Z,1574699715.209 [BPC1] Loaded
2019-11-25T16:35:15.209Z,1574699715.209 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-11-25T16:35:15.209Z,1574699715.209 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-11-25T16:35:15.210Z,1574699715.210 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-11-25T16:35:15.238Z,1574699715.238 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-11-25T16:35:15.693Z,1574699715.693 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-11-25T16:35:15.813Z,1574699715.813 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-11-25T16:35:15.813Z,1574699715.813 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-11-25T16:35:15.852Z,1574699715.852 [NavChart] Loaded
2019-11-25T16:35:15.852Z,1574699715.852 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-11-25T16:35:15.896Z,1574699715.896 [UniversalFixResidualReporter] Loaded
2019-11-25T16:35:15.896Z,1574699715.896 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-11-25T16:35:15.896Z,1574699715.896 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-11-25T16:35:15.897Z,1574699715.897 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-11-25T16:35:16.025Z,1574699716.025 [BuoyancyServo] Loaded
2019-11-25T16:35:16.025Z,1574699716.025 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-11-25T16:35:16.040Z,1574699716.040 [ElevatorServo] Loaded
2019-11-25T16:35:16.041Z,1574699716.041 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-11-25T16:35:16.055Z,1574699716.055 [MassServo] Loaded
2019-11-25T16:35:16.055Z,1574699716.055 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-11-25T16:35:16.070Z,1574699716.070 [RudderServo] Loaded
2019-11-25T16:35:16.070Z,1574699716.070 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-11-25T16:35:16.084Z,1574699716.084 [ThrusterServo] Loaded
2019-11-25T16:35:16.084Z,1574699716.084 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-11-25T16:35:16.085Z,1574699716.085 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-11-25T16:35:16.086Z,1574699716.086 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-11-25T16:35:16.416Z,1574699716.416 [CTD_NeilBrown] Loaded
2019-11-25T16:35:16.416Z,1574699716.416 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-11-25T16:35:16.417Z,1574699716.417 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408E54E0
2019-11-25T16:35:16.417Z,1574699716.417 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 890
2019-11-25T16:35:16.432Z,1574699716.432 [PAR_Licor] Loaded
2019-11-25T16:35:16.432Z,1574699716.432 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-11-25T16:35:16.474Z,1574699716.474 [WetLabsSeaOWL_UV_A] Loaded
2019-11-25T16:35:16.474Z,1574699716.474 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-11-25T16:35:16.475Z,1574699716.475 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409154E0
2019-11-25T16:35:16.476Z,1574699716.476 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 891
2019-11-25T16:35:16.476Z,1574699716.476 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-11-25T16:35:16.478Z,1574699716.478 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-11-25T16:35:16.834Z,1574699716.834 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-11-25T16:35:16.834Z,1574699716.834 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-11-25T16:35:16.888Z,1574699716.888 [DepthRateCalculator] Loaded
2019-11-25T16:35:16.888Z,1574699716.888 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-11-25T16:35:16.894Z,1574699716.894 [PitchRateCalculator] Loaded
2019-11-25T16:35:16.894Z,1574699716.894 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-11-25T16:35:16.906Z,1574699716.906 [SpeedCalculator] Loaded
2019-11-25T16:35:16.906Z,1574699716.906 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-11-25T16:35:16.926Z,1574699716.926 [TempGradientCalculator] Loaded
2019-11-25T16:35:16.927Z,1574699716.927 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-11-25T16:35:16.932Z,1574699716.932 [YawRateCalculator] Loaded
2019-11-25T16:35:16.932Z,1574699716.932 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-11-25T16:35:16.971Z,1574699716.971 [ElevatorOffsetCalculator] Loaded
2019-11-25T16:35:16.971Z,1574699716.971 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-11-25T16:35:16.972Z,1574699716.972 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-11-25T16:35:16.972Z,1574699716.972 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-11-25T16:35:17.132Z,1574699717.132 [SBIT](DEBUG): Construct Startup Built In Test.
2019-11-25T16:35:17.153Z,1574699717.153 [SBIT] Loaded
2019-11-25T16:35:17.154Z,1574699717.154 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-11-25T16:35:17.154Z,1574699717.154 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-11-25T16:35:17.166Z,1574699717.166 [IBIT] Loaded
2019-11-25T16:35:17.167Z,1574699717.167 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-11-25T16:35:17.170Z,1574699717.170 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-11-25T16:35:17.303Z,1574699717.303 [CBIT] Loaded
2019-11-25T16:35:17.303Z,1574699717.303 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-11-25T16:35:17.304Z,1574699717.304 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-11-25T16:35:17.306Z,1574699717.306 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-11-25T16:35:17.428Z,1574699717.428 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-11-25T16:35:17.429Z,1574699717.429 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-11-25T16:35:17.552Z,1574699717.552 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-11-25T16:35:17.553Z,1574699717.553 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-11-25T16:35:17.615Z,1574699717.615 [VerticalControl](DEBUG): Construct VerticalControl.
2019-11-25T16:35:17.696Z,1574699717.696 [VerticalControl] Loaded
2019-11-25T16:35:17.696Z,1574699717.696 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-11-25T16:35:17.697Z,1574699717.697 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-11-25T16:35:17.764Z,1574699717.764 [HorizontalControl] Loaded
2019-11-25T16:35:17.765Z,1574699717.765 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-11-25T16:35:17.765Z,1574699717.765 [SpeedControl](DEBUG): Construct SpeedControl.
2019-11-25T16:35:17.767Z,1574699717.767 [SpeedControl] Loaded
2019-11-25T16:35:17.767Z,1574699717.767 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-11-25T16:35:17.768Z,1574699717.768 [LoopControl](DEBUG): Construct LoopControl.
2019-11-25T16:35:17.768Z,1574699717.768 [LoopControl] Loaded
2019-11-25T16:35:17.769Z,1574699717.769 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-11-25T16:35:17.769Z,1574699717.769 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-11-25T16:35:17.770Z,1574699717.770 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-11-25T16:35:17.818Z,1574699717.818 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-11-25T16:35:17.821Z,1574699717.821 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-11-25T16:35:17.822Z,1574699717.822 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-11-25T16:35:17.828Z,1574699717.828 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-11-25T16:35:17.829Z,1574699717.829 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF44E0
2019-11-25T16:35:17.830Z,1574699717.830 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 892
2019-11-25T16:35:17.834Z,1574699717.834 [Supervisor](INFO): Main Thread ID is 802
2019-11-25T16:35:17.834Z,1574699717.834 [Supervisor](DEBUG): Running supervisor.
2019-11-25T16:35:17.835Z,1574699717.835 [CommandLine ThreadHandler](INFO): Handler Thread ID is 893
2019-11-25T16:35:17.837Z,1574699717.837 [controlThread ThreadHandler](INFO): Handler Thread ID is 894
2019-11-25T16:35:17.838Z,1574699717.838 [controlThread](DEBUG): Initializing ControlThread
2019-11-25T16:35:17.847Z,1574699717.847 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-11-25T16:35:17.847Z,1574699717.847 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-11-25T16:35:17.851Z,1574699717.851 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-11-25T16:35:17.851Z,1574699717.851 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-11-25T16:35:17.852Z,1574699717.852 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-11-25T16:35:17.852Z,1574699717.852 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-11-25T16:35:17.853Z,1574699717.853 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-11-25T16:35:17.853Z,1574699717.853 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-11-25T16:35:17.853Z,1574699717.853 [SBIT](INFO): Initialize SBIT Component.
2019-11-25T16:35:17.854Z,1574699717.854 [SBIT](IMPORTANT): git: 2019-11-25
2019-11-25T16:35:17.854Z,1574699717.854 [SBIT](INFO): git hash: 613c3b988797d140e74aeade4f971920e69097b8
2019-11-25T16:35:17.854Z,1574699717.854 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-11-25T16:35:17.856Z,1574699717.856 [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-11-25T16:35:17.857Z,1574699717.857 [SBIT](INFO): Beginning SBIT in 34.000000 seconds.
2019-11-25T16:35:17.857Z,1574699717.857 [IBIT](INFO): Initialize IBIT Component.
2019-11-25T16:35:17.858Z,1574699717.858 [CBIT](DEBUG): Initialize CBIT Component.
2019-11-25T16:35:17.859Z,1574699717.859 [logger ThreadHandler](INFO): Handler Thread ID is 895
2019-11-25T16:35:17.871Z,1574699717.871 [CBIT](DEBUG): Initialized mux pins.
2019-11-25T16:35:17.871Z,1574699717.871 [CBIT](DEBUG): Initializing the watchdog timer.
2019-11-25T16:35:17.879Z,1574699717.879 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 896
2019-11-25T16:35:17.880Z,1574699717.880 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-11-25T16:35:17.891Z,1574699717.891 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 897
2019-11-25T16:35:17.895Z,1574699717.895 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-11-25T16:35:17.895Z,1574699717.895 [CBIT](DEBUG): Initializing heartbeat.
2019-11-25T16:35:17.904Z,1574699717.904 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 898
2019-11-25T16:35:17.905Z,1574699717.905 [CTD_NeilBrown](INFO): Powering down
2019-11-25T16:35:17.920Z,1574699717.920 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 899
2019-11-25T16:35:17.920Z,1574699717.920 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-11-25T16:35:17.955Z,1574699717.955 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 900
2019-11-25T16:35:17.967Z,1574699717.967 [CBIT](DEBUG): Deactivating GF circuits.
2019-11-25T16:35:17.967Z,1574699717.967 [CBIT](DEBUG): Deactivating emergency mode.
2019-11-25T16:35:17.967Z,1574699717.967 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-11-25T16:35:17.967Z,1574699717.967 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-11-25T16:35:17.968Z,1574699717.968 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-11-25T16:35:17.968Z,1574699717.968 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-11-25T16:35:17.968Z,1574699717.968 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-11-25T16:35:17.968Z,1574699717.968 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-11-25T16:35:17.968Z,1574699717.968 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-11-25T16:35:17.969Z,1574699717.969 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-11-25T16:35:17.969Z,1574699717.969 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-11-25T16:35:17.969Z,1574699717.969 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-11-25T16:35:17.969Z,1574699717.969 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-11-25T16:35:17.969Z,1574699717.969 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-11-25T16:35:17.970Z,1574699717.970 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-11-25T16:35:17.970Z,1574699717.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-11-25T16:35:17.970Z,1574699717.970 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-11-25T16:35:17.970Z,1574699717.970 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-11-25T16:35:18.003Z,1574699718.003 [CBIT](DEBUG): Backplane powered.
2019-11-25T16:35:18.003Z,1574699718.003 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-11-25T16:35:18.005Z,1574699718.005 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-11-25T16:35:18.006Z,1574699718.006 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-11-25T16:35:18.006Z,1574699718.006 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-11-25T16:35:18.007Z,1574699718.007 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-11-25T16:35:18.040Z,1574699718.040 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-25T16:35:18.059Z,1574699718.059 [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-11-25T16:35:18.060Z,1574699718.060 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-11-25T16:35:18.118Z,1574699718.118 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-11-25T16:35:18.119Z,1574699718.119 [Default:A.Wait](DEBUG): Construct Wait.
2019-11-25T16:35:18.121Z,1574699718.121 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-25T16:35:18.148Z,1574699718.148 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-11-25T16:35:18.150Z,1574699718.150 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-11-25T16:35:18.179Z,1574699718.179 [Default:E.Execute](DEBUG): Construct Execute.
2019-11-25T16:35:18.199Z,1574699718.199 [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-11-25T16:35:18.219Z,1574699718.219 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,DDM,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-11-25T16:35:18.224Z,1574699718.224 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-11-25T16:35:18.295Z,1574699718.295 [Radio_Surface](INFO): Powering up
2019-11-25T16:35:18.303Z,1574699718.303 [DDM](INFO): Powering up
2019-11-25T16:35:18.303Z,1574699718.303 [DDM](DEBUG): Initializing DDM.
2019-11-25T16:35:18.363Z,1574699718.363 [DUSBL_Hydroid](INFO): Powering up
2019-11-25T16:35:18.364Z,1574699718.364 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-11-25T16:35:18.568Z,1574699718.568 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:18.575Z,1574699718.575 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-11-25T16:35:18.576Z,1574699718.576 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:18.583Z,1574699718.583 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-11-25T16:35:18.584Z,1574699718.584 [MassServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:18.591Z,1574699718.591 [MassServo](DEBUG): Initializing MassServo.
2019-11-25T16:35:18.592Z,1574699718.592 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:18.599Z,1574699718.599 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-25T16:35:18.600Z,1574699718.600 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:18.607Z,1574699718.607 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-11-25T16:35:18.662Z,1574699718.662 [Micromodem](INFO): Powering up
2019-11-25T16:35:18.662Z,1574699718.662 [Micromodem](DEBUG): Initializing Micromodem.
2019-11-25T16:35:19.415Z,1574699719.415 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-11-25T16:35:19.415Z,1574699719.415 [RudderServo](FAULT): Rudder failed to initialize
2019-11-25T16:35:19.415Z,1574699719.415 [RudderServo] Communications Fault, FailCount= 1
2019-11-25T16:35:19.415Z,1574699719.415 [RudderServo](ERROR): Communications Fault
2019-11-25T16:35:19.610Z,1574699719.610 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-11-25T16:35:19.812Z,1574699719.812 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-11-25T16:35:19.812Z,1574699719.812 [RudderServo](INFO): Powering down
2019-11-25T16:35:20.482Z,1574699720.482 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-25T16:35:20.600Z,1574699720.600 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-25T16:35:20.604Z,1574699720.604 [CBIT](INFO): Clearing failed state for component RudderServo
2019-11-25T16:35:20.604Z,1574699720.604 [RudderServo] No Fault, FailCount= 1
2019-11-25T16:35:23.699Z,1574699723.699 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-11-25T16:35:24.102Z,1574699724.102 [Micromodem](INFO): Nmea in: $CATMG,2019-11-25T16:36:28.475091Z,RTC,RTC*5B

2019-11-25T16:35:24.102Z,1574699724.102 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-11-25T16:36:28.475091Z,RTC,RTC*5B

2019-11-25T16:35:24.509Z,1574699724.509 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-11-25T16:35:24.510Z,1574699724.510 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-11-25T16:35:24.910Z,1574699724.910 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-11-25T16:35:24.910Z,1574699724.910 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-11-25T16:35:25.313Z,1574699725.313 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-11-25T16:35:25.314Z,1574699725.314 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-11-25T16:35:25.717Z,1574699725.717 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-11-25T16:35:25.718Z,1574699725.718 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-11-25T16:35:26.121Z,1574699726.121 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-11-25T16:35:26.121Z,1574699726.121 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-11-25T16:35:26.513Z,1574699726.513 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-11-25T16:35:26.513Z,1574699726.513 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-11-25T16:35:27.365Z,1574699727.365 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-11-25T16:35:27.365Z,1574699727.365 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-11-25T16:35:27.584Z,1574699727.584 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-11-25T16:35:27.585Z,1574699727.585 [Micromodem](INFO): Nmea out: $CCCLK,2019,11,25,16,35,28*42

2019-11-25T16:35:27.953Z,1574699727.953 [Micromodem](INFO): Nmea in: $CACLK,2019,11,25,16,35,28*40

2019-11-25T16:35:28.366Z,1574699728.366 [Micromodem](INFO): Nmea in: $CATMS,0,2019-11-25T16:35:29Z*71

2019-11-25T16:35:28.367Z,1574699728.367 [Micromodem](INFO): Nmea in: $CATMG,2019-11-25T16:35:29.026163Z,USER_CMD,RTC*16

2019-11-25T16:35:28.767Z,1574699728.767 [DDM](INFO): Dynamic Docking Module:
2019-11-25T16:35:31.617Z,1574699731.617 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-25T16:35:36.445Z,1574699736.445 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-11-25T16:35:43.705Z,1574699743.705 [NAL9602](INFO): Powering up NAL9602
2019-11-25T16:35:52.692Z,1574699752.692 [SBIT](IMPORTANT): Beginning Startup BIT
2019-11-25T16:35:52.704Z,1574699752.704 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-25T16:35:54.621Z,1574699754.621 [NAL9602](INFO): NAL9602 initialized
2019-11-25T16:36:03.796Z,1574699763.796 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.000729
CHAN A1 (24V): -0.028746
CHAN A2 (12V): -0.007506
CHAN A3 (5V): -0.002225
CHAN B0 (3.3V): 0.000334
CHAN B1 (3.15aV): 0.000308
CHAN B2 (3.15bV): 0.000002
CHAN B3 (GND): 0.002248
OPEN: 0.005003
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-25T16:36:10.299Z,1574699770.299 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:36:10.299Z,1574699770.299 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19112509481700,35.0, -0.,1448.9,  0
2019-11-25T16:36:35.902Z,1574699795.902 [RDI_Pathfinder](ERROR): Failed to parse:     +0.00,        +0.00,+0.00,   0.00, 63.00
2019-11-25T16:36:46.044Z,1574699806.044 [SBIT](IMPORTANT): SBIT PASSED
2019-11-25T16:36:46.139Z,1574699806.139 [CommandLine](IMPORTANT): got command configSet list
2019-11-25T16:36:46.140Z,1574699806.140 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): DDM.loadAtStartup=1 bool;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): DDM.verbosity=3 count;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=75 count;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout=40 millisecond;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.acoustic_contact_range 1.000000 meter;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 degree;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): Express linearApproximation platform_orientation 5.000000 degree;

2019-11-25T16:36:46.141Z,1574699806.141 [CommandLine](IMPORTANT): Express linearApproximation platform_x_velocity_wrt_ground 0.100000 meter_per_second;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): Express linearApproximation platform_y_velocity_wrt_ground 0.100000 meter_per_second;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): HorizontalControl.kiHeading=0.002 reciprocal_second;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): HorizontalControl.kpHeading=0.8 none;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband=0.05 degree;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): PowerOnly.sampleTime=90 second;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup=1 bool;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=350 cubic_centimeter;

2019-11-25T16:36:46.142Z,1574699806.142 [CommandLine](IMPORTANT): VerticalControl.massDefault=3.6 millimeter;

2019-11-25T16:36:46.437Z,1574699806.437 [MissionManager](IMPORTANT): Started mission Startup
2019-11-25T16:36:46.437Z,1574699806.437 [Startup] Running Loop=1
2019-11-25T16:36:46.437Z,1574699806.437 [Startup](DEBUG): Aggregate::initialize Startup
2019-11-25T16:36:46.437Z,1574699806.437 [Startup:A.GoToSurface] Running Loop=1
2019-11-25T16:36:46.437Z,1574699806.437 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-25T16:36:46.438Z,1574699806.438 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-25T16:36:46.438Z,1574699806.438 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-25T16:36:46.439Z,1574699806.439 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-25T16:36:46.439Z,1574699806.439 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-25T16:36:46.440Z,1574699806.440 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-25T16:36:46.441Z,1574699806.441 [Startup:StartupSatComms] Running Loop=1
2019-11-25T16:36:46.441Z,1574699806.441 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-11-25T16:36:46.441Z,1574699806.441 [Startup:StartupSatComms:A] Running Loop=1
2019-11-25T16:36:46.806Z,1574699806.806 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-11-25T16:37:02.943Z,1574699822.943 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:37:02.943Z,1574699822.943 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19112509491000,.1,   0.0,1448.9,  0
2019-11-25T16:37:46.602Z,1574699866.602 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-11-25T16:37:46.602Z,1574699866.602 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,32768,V
2019-11-25T16:37:46.617Z,1574699866.617 [Startup:StartupSatComms:A](INFO): Timed out from 2019-11-25T16:36:46.4Z
2019-11-25T16:37:46.617Z,1574699866.617 [Startup:StartupSatComms:A] Stopped
2019-11-25T16:37:46.617Z,1574699866.617 [Startup:StartupSatComms:B] Running Loop=1
2019-11-25T16:37:46.981Z,1574699866.981 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-25T16:37:47.070Z,1574699867.070 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005436
2019-11-25T16:37:55.003Z,1574699875.003 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191125T163159/Courier0004.lzma
2019-11-25T16:37:57.008Z,1574699877.008 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163159/Courier0004.lzma.bak
2019-11-25T16:37:57.009Z,1574699877.009 [DataOverHttps](INFO): SBD MOMSN=12103208
2019-11-25T16:38:18.090Z,1574699898.090 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-11-25T16:38:18.090Z,1574699898.090 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-25T16:38:18.120Z,1574699898.120 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-25T16:38:18.577Z,1574699898.577 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-25T16:38:18.577Z,1574699898.577 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-11-25T16:38:39.930Z,1574699919.930 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T16:38:39.930Z,1574699919.930 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T16:38:44.766Z,1574699924.766 [RDI_Pathfinder](ERROR): Failed to parse:
:B  +0.00,        +0.00,        +0.00,   0.00,192.00
2019-11-25T16:38:46.795Z,1574699926.795 [Startup:StartupSatComms:B](INFO): Timed out from 2019-11-25T16:37:46.6Z
2019-11-25T16:38:46.795Z,1574699926.795 [Startup:StartupSatComms:B] Stopped
2019-11-25T16:38:46.795Z,1574699926.795 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-11-25T16:38:46.795Z,1574699926.795 [Startup:StartupSatComms] Stopped
2019-11-25T16:38:46.795Z,1574699926.795 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-11-25T16:38:46.796Z,1574699926.796 [Startup](INFO): Completed Startup
2019-11-25T16:38:46.796Z,1574699926.796 [MissionManager](INFO): Startup is completed.
2019-11-25T16:38:46.796Z,1574699926.796 [MissionManager](INFO): Uninitializing Mission Startup
2019-11-25T16:38:46.797Z,1574699926.797 [Startup] Stopped
2019-11-25T16:38:46.797Z,1574699926.797 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-11-25T16:38:46.797Z,1574699926.797 [Startup:A.GoToSurface] Stopped
2019-11-25T16:38:46.797Z,1574699926.797 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-25T16:38:47.204Z,1574699927.204 [MissionManager](IMPORTANT): Started mission Default
2019-11-25T16:38:47.204Z,1574699927.204 [Default] Running Loop=1
2019-11-25T16:38:47.204Z,1574699927.204 [Default](DEBUG): Aggregate::initialize Default
2019-11-25T16:38:47.204Z,1574699927.204 [Default:B.GoToSurface] Running Loop=1
2019-11-25T16:38:47.204Z,1574699927.204 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-25T16:38:47.205Z,1574699927.205 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-25T16:38:47.205Z,1574699927.205 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-25T16:38:47.205Z,1574699927.205 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-25T16:38:47.205Z,1574699927.205 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-25T16:38:47.206Z,1574699927.206 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-25T16:38:47.206Z,1574699927.206 [Default:A.Wait] Running Loop=1
2019-11-25T16:38:47.206Z,1574699927.206 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-11-25T16:38:56.056Z,1574699936.056 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2019-11-25T16:38:56.778Z,1574699936.778 [DataOverHttps](INFO): Sending 1347 bytes from file Logs/20191125T163159/Express0001.lzma
2019-11-25T16:39:00.520Z,1574699940.520 [Default:A.Wait](INFO): Done Waiting.
2019-11-25T16:39:00.520Z,1574699940.520 [Default:A.Wait] Stopped
2019-11-25T16:39:00.520Z,1574699940.520 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T16:39:00.948Z,1574699940.948 [Default:CheckIn] Running Loop=1
2019-11-25T16:39:00.948Z,1574699940.948 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T16:39:00.948Z,1574699940.948 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T16:39:01.323Z,1574699941.323 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-11-25T16:39:02.797Z,1574699942.797 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163159/Express0001.lzma.bak
2019-11-25T16:39:02.797Z,1574699942.797 [DataOverHttps](INFO): SBD MOMSN=12103211
2019-11-25T16:39:28.392Z,1574699968.392 [CommandLine](IMPORTANT): got command burn on
2019-11-25T16:39:28.392Z,1574699968.392 [CommandLine](IMPORTANT): Activating dropweight wire
2019-11-25T16:39:31.916Z,1574699971.916 [CommandLine](IMPORTANT): got command burn off
2019-11-25T16:39:31.916Z,1574699971.916 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-11-25T16:39:46.600Z,1574699986.600 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-11-25T16:39:46.600Z,1574699986.600 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,              +0.00,  5.00
2019-11-25T16:40:03.946Z,1574700003.946 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T16:40:03.946Z,1574700003.946 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,

2019-11-25T16:40:58.065Z,1574700058.065 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-11-25T16:41:19.169Z,1574700079.169 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-11-25T16:41:19.169Z,1574700079.169 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-25T16:41:19.179Z,1574700079.179 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-25T16:41:19.525Z,1574700079.525 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-25T16:41:19.525Z,1574700079.525 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-11-25T16:41:53.141Z,1574700113.141 [CommandLine](IMPORTANT): got command failComponent
2019-11-25T16:41:53.141Z,1574700113.141 [CommandLine](IMPORTANT): Failed components:
2019-11-25T16:41:53.142Z,1574700113.142 [CommandLine](IMPORTANT): No failed Components.
2019-11-25T16:42:05.627Z,1574700125.627 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-11-25T16:42:05.627Z,1574700125.627 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-11-25T16:42:05.627Z,1574700125.627 [RDI_Pathfinder](ERROR): Communications Fault
2019-11-25T16:42:05.627Z,1574700125.627 [RDI_Pathfinder](ERROR): Failed to parse:
2019-11-25T16:42:05.653Z,1574700125.653 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-11-25T16:42:06.027Z,1574700126.027 [RDI_Pathfinder](INFO): Powering down
2019-11-25T16:42:06.791Z,1574700126.791 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-11-25T16:42:06.791Z,1574700126.791 [RDI_Pathfinder] No Fault, FailCount= 1
2019-11-25T16:42:20.106Z,1574700140.106 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-25T16:43:26.755Z,1574700206.755 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-11-25T16:43:26.758Z,1574700206.758 [BPC1](INFO): Received data from all battery sticks.
2019-11-25T16:44:01.152Z,1574700241.152 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-25T16:39:00.9Z
2019-11-25T16:44:01.152Z,1574700241.152 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T16:44:01.152Z,1574700241.152 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T16:44:01.510Z,1574700241.510 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-25T16:44:08.823Z,1574700248.823 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20191125T163506/Courier0004.lzma
2019-11-25T16:44:10.828Z,1574700250.828 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0004.lzma.bak
2019-11-25T16:44:10.828Z,1574700250.828 [DataOverHttps](INFO): SBD MOMSN=12103275
2019-11-25T16:44:20.104Z,1574700260.104 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-11-25T16:44:20.104Z,1574700260.104 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-25T16:44:20.130Z,1574700260.130 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-25T16:44:20.498Z,1574700260.498 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-25T16:44:20.498Z,1574700260.498 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-11-25T16:44:28.582Z,1574700268.582 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20191125T163159/Express0005.lzma
2019-11-25T16:44:30.588Z,1574700270.588 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163159/Express0005.lzma.bak
2019-11-25T16:44:30.588Z,1574700270.588 [DataOverHttps](INFO): SBD MOMSN=12103278
2019-11-25T16:44:47.632Z,1574700287.632 [DataOverHttps](INFO): Sending 1099 bytes from file Logs/20191125T163506/Express0001.lzma
2019-11-25T16:44:49.636Z,1574700289.636 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0001.lzma.bak
2019-11-25T16:44:49.637Z,1574700289.637 [DataOverHttps](INFO): SBD MOMSN=12103280
2019-11-25T16:45:06.679Z,1574700306.679 [DataOverHttps](INFO): Sending 368 bytes from file Logs/20191125T163506/Express0005.lzma
2019-11-25T16:45:08.685Z,1574700308.685 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0005.lzma.bak
2019-11-25T16:45:08.685Z,1574700308.685 [DataOverHttps](INFO): SBD MOMSN=12103310
2019-11-25T16:45:09.786Z,1574700309.786 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T16:45:09.786Z,1574700309.786 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T16:45:10.575Z,1574700310.575 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T16:45:10.575Z,1574700310.575 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T16:45:10.575Z,1574700310.575 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T16:45:57.426Z,1574700357.426 [NAL9602](FAULT): GPS failed to acquire within timeout.
2019-11-25T16:45:57.426Z,1574700357.426 [NAL9602] Data Fault, FailCount= 1
2019-11-25T16:45:57.426Z,1574700357.426 [NAL9602](ERROR): Data Fault
2019-11-25T16:45:57.566Z,1574700357.566 [CBIT](ERROR): Data Fault in component: NAL9602
2019-11-25T16:45:57.821Z,1574700357.821 [NAL9602](INFO): Powering down
2019-11-25T16:45:58.762Z,1574700358.762 [CBIT](INFO): Clearing failed state for component NAL9602
2019-11-25T16:45:58.763Z,1574700358.763 [NAL9602] No Fault, FailCount= 1
2019-11-25T16:46:28.127Z,1574700388.127 [NAL9602](INFO): Powering up NAL9602
2019-11-25T16:46:39.029Z,1574700399.029 [NAL9602](INFO): NAL9602 initialized
2019-11-25T16:47:21.094Z,1574700441.094 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-11-25T16:47:21.094Z,1574700441.094 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-25T16:47:21.122Z,1574700441.122 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-25T16:47:21.505Z,1574700441.505 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-25T16:47:21.505Z,1574700441.505 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-11-25T16:49:31.139Z,1574700571.139 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164930.00,A,3648.17198,N,12147.27866,W,0.039,191.19,251119,,,A*72
2019-11-25T16:49:31.142Z,1574700571.142 [NAL9602](INFO): GPS fix at 20191125T164930: (36.802866, -121.787978)
2019-11-25T16:50:03.517Z,1574700603.517 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T16:50:11.233Z,1574700611.233 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T16:50:11.233Z,1574700611.233 [Default:CheckIn:C.Wait] Stopped
2019-11-25T16:50:11.233Z,1574700611.233 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T16:50:11.233Z,1574700611.233 [Default:CheckIn:D] Running Loop=1
2019-11-25T16:50:11.631Z,1574700611.631 [Default:CheckIn:D] Stopped
2019-11-25T16:50:11.631Z,1574700611.631 [Default:CheckIn:E] Running Loop=1
2019-11-25T16:50:12.058Z,1574700612.058 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.407118 min 
2019-11-25T16:50:12.058Z,1574700612.058 [Default:CheckIn:E] Stopped
2019-11-25T16:50:12.059Z,1574700612.059 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn] Stopped
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn](INFO): Running loop #2
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn] Running Loop=2
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T16:50:12.063Z,1574700612.063 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T16:50:14.048Z,1574700614.048 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165013.00,A,3648.16387,N,12147.25122,W,3.285,141.65,251119,,,A*7D
2019-11-25T16:50:14.050Z,1574700614.050 [NAL9602](INFO): GPS fix at 20191125T165013: (36.802731, -121.787520)
2019-11-25T16:50:14.106Z,1574700614.106 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T16:50:14.106Z,1574700614.106 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T16:50:22.262Z,1574700622.262 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191125T163506/Courier0007.lzma
2019-11-25T16:50:24.268Z,1574700624.268 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0007.lzma.bak
2019-11-25T16:50:24.269Z,1574700624.269 [DataOverHttps](INFO): SBD MOMSN=12103321
2019-11-25T16:50:31.414Z,1574700631.414 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:50:31.414Z,1574700631.414 [RDI_Pathfinder](ERROR): Failed to parse:
:TS2768,-32768,-32768,-32768,V
2019-11-25T16:50:38.667Z,1574700638.667 [NAL9602](INFO): SBD MO Status=2, MOMSN=9955, MT Status=2, MTMSN=0
2019-11-25T16:50:38.667Z,1574700638.667 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T16:50:42.696Z,1574700642.696 [DataOverHttps](INFO): Sending 639 bytes from file Logs/20191125T163506/Express0008.lzma
2019-11-25T16:50:44.700Z,1574700644.700 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0008.lzma.bak
2019-11-25T16:50:44.701Z,1574700644.701 [DataOverHttps](INFO): SBD MOMSN=12103324
2019-11-25T16:50:46.798Z,1574700646.798 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T16:50:46.798Z,1574700646.798 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T16:50:46.798Z,1574700646.798 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T16:50:48.414Z,1574700648.414 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-25T16:50:53.233Z,1574700653.233 [NAL9602](INFO): SBD MO Status=0, MOMSN=9955, MT Status=0, MTMSN=0
2019-11-25T16:50:53.233Z,1574700653.233 [NAL9602](INFO): No messages in MT queue
2019-11-25T16:51:23.912Z,1574700683.912 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T16:51:28.414Z,1574700688.414 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-25T16:51:55.082Z,1574700715.082 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2019-11-25T16:51:55.082Z,1574700715.082 [RDI_Pathfinder](ERROR): Failed to parse:
:BD,        +0.00,        +0.   +0.00,   0.00,574.99
2019-11-25T16:53:13.423Z,1574700793.423 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:53:13.424Z,1574700793.424 [RDI_Pathfinder](ERROR): Failed to parse:
:TS0052049,35.0, -0.1,   0.0,1448.9,  0
2019-11-25T16:53:15.458Z,1574700795.458 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T16:53:15.458Z,1574700795.458 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T16:53:53.415Z,1574700833.415 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T16:53:53.416Z,1574700833.416 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T16:53:58.676Z,1574700838.676 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:53:58.676Z,1574700838.676 [RDI_Pathfinder](ERROR): Failed to parse:
:TS2768,-32768,-32768,-32768,V
2019-11-25T16:54:07.224Z,1574700847.224 [DataOverHttps](IMPORTANT): SBD MTMSN=20191125T165406
2019-11-25T16:54:14.904Z,1574700854.904 [DataOverHttps](INFO): Received command:Ibit
2019-11-25T16:54:14.956Z,1574700854.956 [CommandLine](IMPORTANT): got command ibit
2019-11-25T16:54:15.261Z,1574700855.261 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-11-25T16:54:15.262Z,1574700855.262 [IBIT](IMPORTANT): Beginning control surface checks.
2019-11-25T16:54:15.265Z,1574700855.265 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-25T16:54:16.827Z,1574700856.827 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165416.00,A,3648.11977,N,12147.23304,W,0.156,84.98,251119,,,A*4A
2019-11-25T16:54:16.829Z,1574700856.829 [NAL9602](INFO): GPS fix at 20191125T165416: (36.801996, -121.787217)
2019-11-25T16:54:26.201Z,1574700866.201 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.008068
CHAN A1 (24V): -0.012825
CHAN A2 (12V): 0.000037
CHAN A3 (5V): 0.001100
CHAN B0 (3.3V): 0.001871
CHAN B1 (3.15aV): 0.001864
CHAN B2 (3.15bV): 0.001879
CHAN B3 (GND): 0.001536
OPEN: 0.005615
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-25T16:54:33.411Z,1574700873.411 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T16:54:33.412Z,1574700873.412 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,191125100.0, -0.1,   0.0,1448.9,  0
2019-11-25T16:54:34.198Z,1574700874.198 [NAL9602](INFO): SBD MO Status=0, MOMSN=9956, MT Status=0, MTMSN=0
2019-11-25T16:54:34.198Z,1574700874.198 [NAL9602](INFO): No messages in MT queue
2019-11-25T16:54:35.409Z,1574700875.409 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165434.00,A,3648.12028,N,12147.23078,W,0.194,84.98,251119,,,A*4C
2019-11-25T16:54:35.411Z,1574700875.411 [NAL9602](INFO): GPS fix at 20191125T165434: (36.802005, -121.787180)
2019-11-25T16:54:37.838Z,1574700877.838 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165437.00,A,3648.12031,N,12147.23048,W,0.136,84.98,251119,,,A*4C
2019-11-25T16:54:37.841Z,1574700877.841 [NAL9602](INFO): GPS fix at 20191125T165437: (36.802005, -121.787175)
2019-11-25T16:54:41.070Z,1574700881.070 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165440.00,A,3648.11995,N,12147.23054,W,0.156,84.98,251119,,,A*43
2019-11-25T16:54:41.072Z,1574700881.072 [NAL9602](INFO): GPS fix at 20191125T165440: (36.801999, -121.787176)
2019-11-25T16:54:43.898Z,1574700883.898 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165443.00,A,3648.12014,N,12147.23039,W,0.078,84.98,251119,,,A*45
2019-11-25T16:54:43.901Z,1574700883.901 [NAL9602](INFO): GPS fix at 20191125T165443: (36.802002, -121.787173)
2019-11-25T16:54:47.126Z,1574700887.126 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165446.00,A,3648.12017,N,12147.23047,W,0.078,84.98,251119,,,A*4A
2019-11-25T16:54:47.129Z,1574700887.129 [NAL9602](INFO): GPS fix at 20191125T165446: (36.802003, -121.787175)
2019-11-25T16:54:49.955Z,1574700889.955 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165449.00,A,3648.12014,N,12147.23035,W,0.175,84.98,251119,,,A*4F
2019-11-25T16:54:49.957Z,1574700889.957 [NAL9602](INFO): GPS fix at 20191125T165449: (36.802002, -121.787172)
2019-11-25T16:54:52.787Z,1574700892.787 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165452.00,A,3648.12013,N,12147.23039,W,0.253,84.98,251119,,,A*49
2019-11-25T16:54:52.789Z,1574700892.789 [NAL9602](INFO): GPS fix at 20191125T165452: (36.802002, -121.787173)
2019-11-25T16:54:56.024Z,1574700896.024 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165455.00,A,3648.11988,N,12147.23025,W,0.253,84.98,251119,,,A*4B
2019-11-25T16:54:56.026Z,1574700896.026 [NAL9602](INFO): GPS fix at 20191125T165455: (36.801998, -121.787171)
2019-11-25T16:54:58.843Z,1574700898.843 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165458.00,A,3648.11959,N,12147.22999,W,0.350,84.98,251119,,,A*47
2019-11-25T16:54:58.845Z,1574700898.845 [NAL9602](INFO): GPS fix at 20191125T165458: (36.801993, -121.787166)
2019-11-25T16:55:01.730Z,1574700901.730 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 5
Latitude: 36.801994 Longitude: -121.787163
2019-11-25T16:55:02.079Z,1574700902.079 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165501.00,A,3648.11951,N,12147.22982,W,0.058,84.98,251119,,,A*43
2019-11-25T16:55:02.081Z,1574700902.081 [NAL9602](INFO): GPS fix at 20191125T165501: (36.801992, -121.787164)
2019-11-25T16:55:02.147Z,1574700902.147 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 0.000000
2019-11-25T16:55:02.148Z,1574700902.148 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2019-11-25T16:55:02.148Z,1574700902.148 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2019-11-25T16:55:02.552Z,1574700902.552 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-11-25T16:55:02.552Z,1574700902.552 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-11-25T16:55:02.553Z,1574700902.553 [IBIT](IMPORTANT): Pressure:9.446441 PSI
2019-11-25T16:55:02.553Z,1574700902.553 [IBIT](IMPORTANT): Humidity:10.676353 %
2019-11-25T16:55:02.936Z,1574700902.936 [IBIT](IMPORTANT): Vehicle Pitch:1.590245 degrees
2019-11-25T16:55:02.936Z,1574700902.936 [IBIT](IMPORTANT): Vehicle  Roll:-2.376411 degrees
2019-11-25T16:55:02.937Z,1574700902.937 [IBIT](IMPORTANT): Vehicle  Heading:282.549774 degrees
2019-11-25T16:55:03.376Z,1574700903.376 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-11-25T16:55:03.377Z,1574700903.377 [IBIT](IMPORTANT): buoyancyNeutral: 350.000000 cc
2019-11-25T16:55:03.377Z,1574700903.377 [IBIT](IMPORTANT): massDefault: 0.360000 cm
2019-11-25T16:55:03.377Z,1574700903.377 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2019-11-25T16:55:03.378Z,1574700903.378 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2019-11-25T16:55:03.378Z,1574700903.378 [IBIT](IMPORTANT): IBIT PASSED
2019-11-25T16:55:34.391Z,1574700934.391 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T16:55:47.371Z,1574700947.371 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T16:55:47.372Z,1574700947.372 [Default:CheckIn:C.Wait] Stopped
2019-11-25T16:55:47.372Z,1574700947.372 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T16:55:47.372Z,1574700947.372 [Default:CheckIn:D] Running Loop=1
2019-11-25T16:55:47.759Z,1574700947.759 [Default:CheckIn:D] Stopped
2019-11-25T16:55:47.759Z,1574700947.759 [Default:CheckIn:E] Running Loop=1
2019-11-25T16:55:48.163Z,1574700948.163 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.009247 min 
2019-11-25T16:55:48.163Z,1574700948.163 [Default:CheckIn:E] Stopped
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn] Stopped
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn](INFO): Running loop #3
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn] Running Loop=3
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T16:55:48.164Z,1574700948.164 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T16:55:50.155Z,1574700950.155 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165549.00,A,3648.11852,N,12147.22919,W,0.039,84.98,251119,,,A*48
2019-11-25T16:55:50.157Z,1574700950.157 [NAL9602](INFO): GPS fix at 20191125T165549: (36.801975, -121.787153)
2019-11-25T16:55:50.216Z,1574700950.216 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T16:55:50.216Z,1574700950.216 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T16:55:58.286Z,1574700958.286 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191125T163506/Courier0010.lzma
2019-11-25T16:56:00.293Z,1574700960.293 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0010.lzma.bak
2019-11-25T16:56:00.293Z,1574700960.293 [DataOverHttps](INFO): SBD MOMSN=12103350
2019-11-25T16:56:02.282Z,1574700962.282 [NAL9602](INFO): SBD MO Status=0, MOMSN=9957, MT Status=0, MTMSN=0
2019-11-25T16:56:02.282Z,1574700962.282 [NAL9602](INFO): No messages in MT queue
2019-11-25T16:56:19.648Z,1574700979.648 [DataOverHttps](INFO): Sending 1141 bytes from file Logs/20191125T163506/Express0011.lzma
2019-11-25T16:56:21.652Z,1574700981.652 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0011.lzma.bak
2019-11-25T16:56:21.653Z,1574700981.653 [DataOverHttps](INFO): SBD MOMSN=12103353
2019-11-25T16:56:32.977Z,1574700992.977 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T16:56:39.051Z,1574700999.051 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191125T163506/Express0014.lzma
2019-11-25T16:56:41.056Z,1574701001.056 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0014.lzma.bak
2019-11-25T16:56:41.057Z,1574701001.057 [DataOverHttps](INFO): SBD MOMSN=12103379
2019-11-25T16:56:43.158Z,1574701003.158 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T16:56:43.158Z,1574701003.158 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T16:56:43.158Z,1574701003.158 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T17:01:43.692Z,1574701303.692 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T17:01:43.692Z,1574701303.692 [Default:CheckIn:C.Wait] Stopped
2019-11-25T17:01:43.693Z,1574701303.693 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T17:01:43.693Z,1574701303.693 [Default:CheckIn:D] Running Loop=1
2019-11-25T17:01:44.119Z,1574701304.119 [Default:CheckIn:D] Stopped
2019-11-25T17:01:44.119Z,1574701304.119 [Default:CheckIn:E] Running Loop=1
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.948586 min 
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn:E] Stopped
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn] Stopped
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn](INFO): Running loop #4
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn] Running Loop=4
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T17:01:44.497Z,1574701304.497 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T17:01:46.497Z,1574701306.497 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170146.00,A,3648.24047,N,12147.14352,W,5.559,14.23,251119,,,A*42
2019-11-25T17:01:46.499Z,1574701306.499 [NAL9602](INFO): GPS fix at 20191125T170146: (36.804008, -121.785725)
2019-11-25T17:01:46.524Z,1574701306.524 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T17:01:46.524Z,1574701306.524 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T17:01:54.122Z,1574701314.122 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191125T163506/Courier0016.lzma
2019-11-25T17:01:56.129Z,1574701316.129 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0016.lzma.bak
2019-11-25T17:01:56.129Z,1574701316.129 [DataOverHttps](INFO): SBD MOMSN=12103384
2019-11-25T17:01:56.995Z,1574701316.995 [NAL9602](INFO): SBD MO Status=0, MOMSN=9958, MT Status=0, MTMSN=0
2019-11-25T17:01:56.995Z,1574701316.995 [NAL9602](INFO): No messages in MT queue
2019-11-25T17:02:16.375Z,1574701336.375 [DataOverHttps](INFO): Sending 182 bytes from file Logs/20191125T163506/Express0017.lzma
2019-11-25T17:02:18.379Z,1574701338.379 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0017.lzma.bak
2019-11-25T17:02:18.380Z,1574701338.380 [DataOverHttps](INFO): SBD MOMSN=12103389
2019-11-25T17:02:20.475Z,1574701340.475 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T17:02:20.475Z,1574701340.475 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T17:02:20.475Z,1574701340.475 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T17:02:27.701Z,1574701347.701 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T17:05:40.058Z,1574701540.058 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T17:05:40.058Z,1574701540.058 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19112510174749,35.0, -0.1, 48.9,  0
2019-11-25T17:07:21.075Z,1574701641.075 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T17:07:21.075Z,1574701641.075 [Default:CheckIn:C.Wait] Stopped
2019-11-25T17:07:21.075Z,1574701641.075 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T17:07:21.075Z,1574701641.075 [Default:CheckIn:D] Running Loop=1
2019-11-25T17:07:21.441Z,1574701641.441 [Default:CheckIn:D] Stopped
2019-11-25T17:07:21.441Z,1574701641.441 [Default:CheckIn:E] Running Loop=1
2019-11-25T17:07:21.845Z,1574701641.845 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.570612 min 
2019-11-25T17:07:21.845Z,1574701641.845 [Default:CheckIn:E] Stopped
2019-11-25T17:07:21.845Z,1574701641.845 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn] Stopped
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn](INFO): Running loop #5
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn] Running Loop=5
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T17:07:21.846Z,1574701641.846 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T17:07:23.837Z,1574701643.837 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170724.00,A,3648.33079,N,12147.52567,W,9.428,251.36,251119,,,A*75
2019-11-25T17:07:23.839Z,1574701643.839 [NAL9602](INFO): GPS fix at 20191125T170724: (36.805513, -121.792095)
2019-11-25T17:07:23.887Z,1574701643.887 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T17:07:23.887Z,1574701643.887 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T17:07:31.510Z,1574701651.510 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191125T163506/Courier0019.lzma
2019-11-25T17:07:33.516Z,1574701653.516 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0019.lzma.bak
2019-11-25T17:07:33.517Z,1574701653.517 [DataOverHttps](INFO): SBD MOMSN=12103409
2019-11-25T17:07:52.087Z,1574701672.087 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20191125T163506/Express0020.lzma
2019-11-25T17:07:54.092Z,1574701674.092 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0020.lzma.bak
2019-11-25T17:07:54.093Z,1574701674.093 [DataOverHttps](INFO): SBD MOMSN=12103412
2019-11-25T17:07:56.162Z,1574701676.162 [NAL9602](INFO): SBD MO Status=2, MOMSN=9959, MT Status=2, MTMSN=0
2019-11-25T17:07:56.162Z,1574701676.162 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:07:57.066Z,1574701677.066 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T17:07:57.066Z,1574701677.066 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T17:07:57.067Z,1574701677.067 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T17:08:23.250Z,1574701703.250 [NAL9602](INFO): SBD MO Status=0, MOMSN=9959, MT Status=0, MTMSN=0
2019-11-25T17:08:23.250Z,1574701703.250 [NAL9602](INFO): No messages in MT queue
2019-11-25T17:08:53.953Z,1574701733.953 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T17:09:37.287Z,1574701777.287 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-11-25T17:09:37.287Z,1574701777.287 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-11-25T17:09:37.287Z,1574701777.287 [RDI_Pathfinder](ERROR): Communications Fault
2019-11-25T17:09:37.287Z,1574701777.287 [RDI_Pathfinder](ERROR): Failed to parse:
2019-11-25T17:09:37.314Z,1574701777.314 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-11-25T17:09:37.679Z,1574701777.679 [RDI_Pathfinder](INFO): Powering down
2019-11-25T17:09:38.443Z,1574701778.443 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-11-25T17:09:38.443Z,1574701778.443 [RDI_Pathfinder] No Fault, FailCount= 1
2019-11-25T17:09:51.758Z,1574701791.758 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-25T17:10:04.706Z,1574701804.706 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-11-25T17:10:04.727Z,1574701804.727 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768V
2019-11-25T17:10:47.109Z,1574701847.109 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-11-25T17:10:47.109Z,1574701847.109 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19112510225, -0.1,   0.0,1448.9,  0
2019-11-25T17:11:46.088Z,1574701906.088 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T17:11:46.089Z,1574701906.089 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T17:12:01.445Z,1574701921.445 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-25T17:12:57.619Z,1574701977.619 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T17:12:57.619Z,1574701977.619 [Default:CheckIn:C.Wait] Stopped
2019-11-25T17:12:57.619Z,1574701977.619 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T17:12:57.619Z,1574701977.619 [Default:CheckIn:D] Running Loop=1
2019-11-25T17:12:58.050Z,1574701978.050 [Default:CheckIn:D] Stopped
2019-11-25T17:12:58.050Z,1574701978.050 [Default:CheckIn:E] Running Loop=1
2019-11-25T17:12:58.426Z,1574701978.426 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.180770 min 
2019-11-25T17:12:58.426Z,1574701978.426 [Default:CheckIn:E] Stopped
2019-11-25T17:12:58.427Z,1574701978.427 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T17:12:58.451Z,1574701978.451 [Default:CheckIn] Stopped
2019-11-25T17:12:58.451Z,1574701978.451 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T17:12:58.451Z,1574701978.451 [Default:CheckIn](INFO): Running loop #6
2019-11-25T17:12:58.451Z,1574701978.451 [Default:CheckIn] Running Loop=6
2019-11-25T17:12:58.451Z,1574701978.451 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T17:12:58.452Z,1574701978.452 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T17:13:00.403Z,1574701980.403 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171300.00,A,3648.50434,N,12149.19422,W,14.229,279.58,251119,,,A*46
2019-11-25T17:13:00.405Z,1574701980.405 [NAL9602](INFO): GPS fix at 20191125T171300: (36.808406, -121.819904)
2019-11-25T17:13:00.481Z,1574701980.481 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T17:13:00.481Z,1574701980.481 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T17:13:02.386Z,1574701982.386 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191125T163506/Courier0022.lzma
2019-11-25T17:13:04.393Z,1574701984.393 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0022.lzma.bak
2019-11-25T17:13:04.393Z,1574701984.393 [DataOverHttps](INFO): SBD MOMSN=12103425
2019-11-25T17:13:19.490Z,1574701999.490 [NAL9602](INFO): SBD MO Status=2, MOMSN=9960, MT Status=2, MTMSN=0
2019-11-25T17:13:19.491Z,1574701999.491 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:13:21.947Z,1574702001.947 [DataOverHttps](INFO): Sending 229 bytes from file Logs/20191125T163506/Express0023.lzma
2019-11-25T17:13:23.953Z,1574702003.953 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0023.lzma.bak
2019-11-25T17:13:23.953Z,1574702003.953 [DataOverHttps](INFO): SBD MOMSN=12103428
2019-11-25T17:13:26.035Z,1574702006.035 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T17:13:26.035Z,1574702006.035 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T17:13:26.035Z,1574702006.035 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T17:13:28.782Z,1574702008.782 [NAL9602](INFO): SBD MO Status=0, MOMSN=9960, MT Status=0, MTMSN=0
2019-11-25T17:13:28.782Z,1574702008.782 [NAL9602](INFO): No messages in MT queue
2019-11-25T17:13:36.083Z,1574702016.083 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-25T17:13:36.083Z,1574702016.083 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-25T17:13:59.493Z,1574702039.493 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-25T17:15:36.064Z,1574702136.064 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-11-25T17:17:57.093Z,1574702277.093 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-11-25T17:18:26.579Z,1574702306.579 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-25T17:18:26.579Z,1574702306.579 [Default:CheckIn:C.Wait] Stopped
2019-11-25T17:18:26.579Z,1574702306.579 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-25T17:18:26.579Z,1574702306.579 [Default:CheckIn:D] Running Loop=1
2019-11-25T17:18:26.994Z,1574702306.994 [Default:CheckIn:D] Stopped
2019-11-25T17:18:26.994Z,1574702306.994 [Default:CheckIn:E] Running Loop=1
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.663167 min 
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn:E] Stopped
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn] Stopped
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-25T17:18:27.389Z,1574702307.389 [Default:CheckIn](INFO): Running loop #7
2019-11-25T17:18:27.390Z,1574702307.390 [Default:CheckIn] Running Loop=7
2019-11-25T17:18:27.390Z,1574702307.390 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-25T17:18:27.390Z,1574702307.390 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-25T17:18:29.373Z,1574702309.373 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171829.00,A,3648.50197,N,12149.42001,W,4.257,159.66,251119,,,A*75
2019-11-25T17:18:29.376Z,1574702309.376 [NAL9602](INFO): GPS fix at 20191125T171829: (36.808366, -121.823667)
2019-11-25T17:18:29.416Z,1574702309.416 [Default:CheckIn:Read_GPS] Stopped
2019-11-25T17:18:29.416Z,1574702309.416 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-25T17:18:37.490Z,1574702317.490 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191125T163506/Courier0025.lzma
2019-11-25T17:18:39.497Z,1574702319.497 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Courier0025.lzma.bak
2019-11-25T17:18:39.497Z,1574702319.497 [DataOverHttps](INFO): SBD MOMSN=12103440
2019-11-25T17:18:56.869Z,1574702336.869 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-11-25T17:19:14.619Z,1574702354.619 [NAL9602](INFO): SBD MO Status=2, MOMSN=9961, MT Status=2, MTMSN=0
2019-11-25T17:19:14.619Z,1574702354.619 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:19:19.015Z,1574702359.015 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20191125T163506/Express0026.lzma
2019-11-25T17:19:21.023Z,1574702361.023 [DataOverHttps](INFO): Moved sent file to Logs/20191125T163506/Express0026.lzma.bak
2019-11-25T17:19:21.024Z,1574702361.024 [DataOverHttps](INFO): SBD MOMSN=12103443
2019-11-25T17:19:22.755Z,1574702362.755 [Default:CheckIn:Read_Iridium] Stopped
2019-11-25T17:19:22.755Z,1574702362.755 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-25T17:19:22.755Z,1574702362.755 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-25T17:19:33.627Z,1574702373.627 [NAL9602](INFO): SBD MO Status=2, MOMSN=9961, MT Status=2, MTMSN=0
2019-11-25T17:19:33.632Z,1574702373.632 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:19:56.642Z,1574702396.642 [NAL9602](INFO): SBD MO Status=2, MOMSN=9961, MT Status=2, MTMSN=0
2019-11-25T17:19:56.642Z,1574702396.642 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:20:26.938Z,1574702426.938 [NAL9602](INFO): SBD MO Status=2, MOMSN=9961, MT Status=2, MTMSN=0
2019-11-25T17:20:26.938Z,1574702426.938 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-25T17:20:41.996Z,1574702441.996 [DataOverHttps](IMPORTANT): SBD MTMSN=20191125T172041
2019-11-25T17:20:49.727Z,1574702449.727 [DataOverHttps](INFO): Received command:restart logs