2019-10-09T19:07:59.413Z,1570648079.413 [Supervisor](DEBUG): Initializing supervisor.
2019-10-09T19:07:59.415Z,1570648079.415 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-10-09T19:07:59.416Z,1570648079.416 [SyncHandler](INFO): Protected caller Thread ID is 1084
2019-10-09T19:07:59.417Z,1570648079.417 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-10-09T19:07:59.418Z,1570648079.418 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-10-09T19:07:59.418Z,1570648079.418 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1085
2019-10-09T19:07:59.421Z,1570648079.421 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-10-09T19:07:59.432Z,1570648079.432 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-10-09T19:07:59.433Z,1570648079.433 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-10-09T19:07:59.434Z,1570648079.434 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1086
2019-10-09T19:07:59.435Z,1570648079.435 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-10-09T19:07:59.435Z,1570648079.435 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-10-09T19:07:59.436Z,1570648079.436 [logger ThreadHandler](INFO): Protected caller Thread ID is 1087
2019-10-09T19:07:59.438Z,1570648079.438 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-10-09T19:07:59.438Z,1570648079.438 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-10-09T19:07:59.440Z,1570648079.440 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-10-09T19:07:59.884Z,1570648079.884 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-10-09T19:07:59.885Z,1570648079.885 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-10-09T19:07:59.984Z,1570648079.984 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-10-09T19:07:59.985Z,1570648079.985 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-10-09T19:08:00.608Z,1570648080.608 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-10-09T19:08:00.608Z,1570648080.608 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-10-09T19:08:00.752Z,1570648080.752 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-10-09T19:08:00.753Z,1570648080.753 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-10-09T19:08:00.952Z,1570648080.952 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-10-09T19:08:00.953Z,1570648080.953 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-10-09T19:08:01.424Z,1570648081.424 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-10-09T19:08:01.424Z,1570648081.424 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-10-09T19:08:01.639Z,1570648081.639 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-10-09T19:08:01.639Z,1570648081.639 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-10-09T19:08:01.788Z,1570648081.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-10-09T19:08:01.788Z,1570648081.788 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-10-09T19:08:01.996Z,1570648081.996 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-10-09T19:08:01.997Z,1570648081.997 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-10-09T19:08:02.094Z,1570648082.094 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-10-09T19:08:02.095Z,1570648082.095 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-10-09T19:08:02.410Z,1570648082.410 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-10-09T19:08:02.411Z,1570648082.411 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-10-09T19:08:02.492Z,1570648082.492 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-10-09T19:08:02.597Z,1570648082.597 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-10-09T19:08:02.598Z,1570648082.598 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-10-09T19:08:03.244Z,1570648083.244 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-10-09T19:08:03.244Z,1570648083.244 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-10-09T19:08:03.658Z,1570648083.658 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-10-09T19:08:03.660Z,1570648083.660 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-10-09T19:08:03.661Z,1570648083.661 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-10-09T19:08:03.874Z,1570648083.874 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-10-09T19:08:03.975Z,1570648083.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-10-09T19:08:04.074Z,1570648084.074 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-10-09T19:08:04.306Z,1570648084.306 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-10-09T19:08:04.307Z,1570648084.307 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-10-09T19:08:04.392Z,1570648084.392 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-10-09T19:08:04.488Z,1570648084.488 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-10-09T19:08:04.586Z,1570648084.586 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-10-09T19:08:04.671Z,1570648084.671 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-10-09T19:08:04.782Z,1570648084.782 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-10-09T19:08:04.975Z,1570648084.975 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-10-09T19:08:05.112Z,1570648085.112 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/root/
2019-10-09T19:08:05.113Z,1570648085.113 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-10-09T19:08:05.118Z,1570648085.118 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-10-09T19:08:05.432Z,1570648085.432 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-10-09T19:08:05.438Z,1570648085.438 [AHRS_M2](INFO): created writer for : platform_orientation
2019-10-09T19:08:05.439Z,1570648085.439 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-10-09T19:08:05.445Z,1570648085.445 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-10-09T19:08:05.445Z,1570648085.445 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-10-09T19:08:05.451Z,1570648085.451 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-10-09T19:08:05.451Z,1570648085.451 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-10-09T19:08:05.457Z,1570648085.457 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-10-09T19:08:05.532Z,1570648085.532 [AHRS_M2] Loaded
2019-10-09T19:08:05.532Z,1570648085.532 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-10-09T19:08:05.605Z,1570648085.605 [DataOverHttps] Loaded
2019-10-09T19:08:05.606Z,1570648085.606 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-10-09T19:08:05.607Z,1570648085.607 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075C4E0
2019-10-09T19:08:05.607Z,1570648085.607 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1166
2019-10-09T19:08:05.621Z,1570648085.621 [Depth_Keller] Loaded
2019-10-09T19:08:05.621Z,1570648085.621 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-10-09T19:08:05.681Z,1570648085.681 [DUSBL_Hydroid] Loaded
2019-10-09T19:08:05.682Z,1570648085.682 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-10-09T19:08:05.732Z,1570648085.732 [Micromodem] Loaded
2019-10-09T19:08:05.732Z,1570648085.732 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-10-09T19:08:05.835Z,1570648085.835 [NAL9602] Loaded
2019-10-09T19:08:05.836Z,1570648085.836 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-10-09T19:08:05.852Z,1570648085.852 [Onboard] Loaded
2019-10-09T19:08:05.852Z,1570648085.852 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-10-09T19:08:05.858Z,1570648085.858 [PowerOnly] Loaded
2019-10-09T19:08:05.859Z,1570648085.859 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-10-09T19:08:05.866Z,1570648085.866 [Radio_Surface] Loaded
2019-10-09T19:08:05.866Z,1570648085.866 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-10-09T19:08:05.867Z,1570648085.867 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078C4E0
2019-10-09T19:08:05.867Z,1570648085.867 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1167
2019-10-09T19:08:05.915Z,1570648085.915 [RDI_Pathfinder] Loaded
2019-10-09T19:08:05.915Z,1570648085.915 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-10-09T19:08:07.909Z,1570648087.909 [BPC1] Loaded
2019-10-09T19:08:07.909Z,1570648087.909 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-10-09T19:08:07.909Z,1570648087.909 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-10-09T19:08:07.910Z,1570648087.910 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-10-09T19:08:07.923Z,1570648087.923 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-10-09T19:08:07.924Z,1570648087.924 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-10-09T19:08:08.036Z,1570648088.036 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-10-09T19:08:08.036Z,1570648088.036 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-10-09T19:08:08.057Z,1570648088.057 [NavChart] Loaded
2019-10-09T19:08:08.057Z,1570648088.057 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-10-09T19:08:08.061Z,1570648088.061 [UniversalFixResidualReporter] Loaded
2019-10-09T19:08:08.062Z,1570648088.062 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-10-09T19:08:08.062Z,1570648088.062 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-10-09T19:08:08.063Z,1570648088.063 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-10-09T19:08:08.179Z,1570648088.179 [BuoyancyServo] Loaded
2019-10-09T19:08:08.180Z,1570648088.180 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-10-09T19:08:08.195Z,1570648088.195 [ElevatorServo] Loaded
2019-10-09T19:08:08.195Z,1570648088.195 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-10-09T19:08:08.211Z,1570648088.211 [MassServo] Loaded
2019-10-09T19:08:08.211Z,1570648088.211 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-10-09T19:08:08.227Z,1570648088.227 [RudderServo] Loaded
2019-10-09T19:08:08.227Z,1570648088.227 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-10-09T19:08:08.242Z,1570648088.242 [ThrusterServo] Loaded
2019-10-09T19:08:08.242Z,1570648088.242 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-10-09T19:08:08.243Z,1570648088.243 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-10-09T19:08:08.243Z,1570648088.243 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-10-09T19:08:08.440Z,1570648088.440 [PAR_Licor] Loaded
2019-10-09T19:08:08.441Z,1570648088.441 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-10-09T19:08:08.487Z,1570648088.487 [WetLabsSeaOWL_UV_A] Loaded
2019-10-09T19:08:08.487Z,1570648088.487 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-10-09T19:08:08.488Z,1570648088.488 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408D74E0
2019-10-09T19:08:08.489Z,1570648088.489 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 1168
2019-10-09T19:08:08.489Z,1570648088.489 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-10-09T19:08:08.490Z,1570648088.490 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-10-09T19:08:08.811Z,1570648088.811 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-10-09T19:08:08.812Z,1570648088.812 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-10-09T19:08:08.855Z,1570648088.855 [DepthRateCalculator] Loaded
2019-10-09T19:08:08.855Z,1570648088.855 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-10-09T19:08:08.861Z,1570648088.861 [PitchRateCalculator] Loaded
2019-10-09T19:08:08.862Z,1570648088.862 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-10-09T19:08:08.874Z,1570648088.874 [SpeedCalculator] Loaded
2019-10-09T19:08:08.875Z,1570648088.875 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-10-09T19:08:08.896Z,1570648088.896 [TempGradientCalculator] Loaded
2019-10-09T19:08:08.897Z,1570648088.897 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-10-09T19:08:08.902Z,1570648088.902 [YawRateCalculator] Loaded
2019-10-09T19:08:08.903Z,1570648088.903 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-10-09T19:08:08.944Z,1570648088.944 [ElevatorOffsetCalculator] Loaded
2019-10-09T19:08:08.945Z,1570648088.945 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-10-09T19:08:08.945Z,1570648088.945 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-10-09T19:08:08.946Z,1570648088.946 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-10-09T19:08:09.096Z,1570648089.096 [SBIT](DEBUG): Construct Startup Built In Test.
2019-10-09T19:08:09.119Z,1570648089.119 [SBIT] Loaded
2019-10-09T19:08:09.119Z,1570648089.119 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-10-09T19:08:09.120Z,1570648089.120 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-10-09T19:08:09.131Z,1570648089.131 [IBIT] Loaded
2019-10-09T19:08:09.131Z,1570648089.131 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-10-09T19:08:09.135Z,1570648089.135 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-10-09T19:08:09.277Z,1570648089.277 [CBIT] Loaded
2019-10-09T19:08:09.277Z,1570648089.277 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-10-09T19:08:09.277Z,1570648089.277 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-10-09T19:08:09.278Z,1570648089.278 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-10-09T19:08:09.366Z,1570648089.366 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-10-09T19:08:09.366Z,1570648089.366 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-10-09T19:08:09.475Z,1570648089.475 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-10-09T19:08:09.476Z,1570648089.476 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-10-09T19:08:09.548Z,1570648089.548 [VerticalControl](DEBUG): Construct VerticalControl.
2019-10-09T19:08:09.635Z,1570648089.635 [VerticalControl] Loaded
2019-10-09T19:08:09.635Z,1570648089.635 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-10-09T19:08:09.636Z,1570648089.636 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-10-09T19:08:09.696Z,1570648089.696 [HorizontalControl] Loaded
2019-10-09T19:08:09.696Z,1570648089.696 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-10-09T19:08:09.697Z,1570648089.697 [SpeedControl](DEBUG): Construct SpeedControl.
2019-10-09T19:08:09.699Z,1570648089.699 [SpeedControl] Loaded
2019-10-09T19:08:09.699Z,1570648089.699 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-10-09T19:08:09.700Z,1570648089.700 [LoopControl](DEBUG): Construct LoopControl.
2019-10-09T19:08:09.700Z,1570648089.700 [LoopControl] Loaded
2019-10-09T19:08:09.701Z,1570648089.701 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-10-09T19:08:09.701Z,1570648089.701 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-10-09T19:08:09.702Z,1570648089.702 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-10-09T19:08:09.736Z,1570648089.736 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-10-09T19:08:09.739Z,1570648089.739 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-10-09T19:08:09.740Z,1570648089.740 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-10-09T19:08:09.747Z,1570648089.747 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-10-09T19:08:09.748Z,1570648089.748 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AB44E0
2019-10-09T19:08:09.748Z,1570648089.748 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1169
2019-10-09T19:08:09.753Z,1570648089.753 [Supervisor](INFO): Main Thread ID is 802
2019-10-09T19:08:09.753Z,1570648089.753 [Supervisor](DEBUG): Running supervisor.
2019-10-09T19:08:09.754Z,1570648089.754 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1170
2019-10-09T19:08:09.756Z,1570648089.756 [controlThread ThreadHandler](INFO): Handler Thread ID is 1171
2019-10-09T19:08:09.757Z,1570648089.757 [controlThread](DEBUG): Initializing ControlThread
2019-10-09T19:08:09.763Z,1570648089.763 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-10-09T19:08:09.764Z,1570648089.764 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-10-09T19:08:09.769Z,1570648089.769 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-10-09T19:08:09.769Z,1570648089.769 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-10-09T19:08:09.770Z,1570648089.770 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-10-09T19:08:09.770Z,1570648089.770 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-10-09T19:08:09.770Z,1570648089.770 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-10-09T19:08:09.771Z,1570648089.771 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-10-09T19:08:09.771Z,1570648089.771 [SBIT](INFO): Initialize SBIT Component.
2019-10-09T19:08:09.772Z,1570648089.772 [SBIT](IMPORTANT): git: 2019-09-23_TRN-90-g217e710
2019-10-09T19:08:09.772Z,1570648089.772 [SBIT](INFO): git hash: 217e710eb7ee4d50c735837a6a63058c2a331c1b
2019-10-09T19:08:09.772Z,1570648089.772 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-10-09T19:08:09.774Z,1570648089.774 [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-09T19:08:09.775Z,1570648089.775 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-10-09T19:08:09.775Z,1570648089.775 [IBIT](INFO): Initialize IBIT Component.
2019-10-09T19:08:09.776Z,1570648089.776 [CBIT](DEBUG): Initialize CBIT Component.
2019-10-09T19:08:09.777Z,1570648089.777 [logger ThreadHandler](INFO): Handler Thread ID is 1172
2019-10-09T19:08:09.789Z,1570648089.789 [CBIT](DEBUG): Initialized mux pins.
2019-10-09T19:08:09.789Z,1570648089.789 [CBIT](DEBUG): Initializing the watchdog timer.
2019-10-09T19:08:09.797Z,1570648089.797 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1173
2019-10-09T19:08:09.798Z,1570648089.798 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-10-09T19:08:09.809Z,1570648089.809 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1174
2019-10-09T19:08:09.813Z,1570648089.813 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-10-09T19:08:09.813Z,1570648089.813 [CBIT](DEBUG): Initializing heartbeat.
2019-10-09T19:08:09.821Z,1570648089.821 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 1175
2019-10-09T19:08:09.822Z,1570648089.822 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-10-09T19:08:09.849Z,1570648089.849 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1176
2019-10-09T19:08:09.852Z,1570648089.852 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-10-09T19:08:09.852Z,1570648089.852 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-10-09T19:08:09.853Z,1570648089.853 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-10-09T19:08:09.853Z,1570648089.853 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-10-09T19:08:09.853Z,1570648089.853 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-10-09T19:08:09.854Z,1570648089.854 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-10-09T19:08:09.855Z,1570648089.855 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-10-09T19:08:09.855Z,1570648089.855 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-10-09T19:08:09.855Z,1570648089.855 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-10-09T19:08:09.855Z,1570648089.855 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-10-09T19:08:09.855Z,1570648089.855 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-10-09T19:08:09.885Z,1570648089.885 [CBIT](DEBUG): Deactivating GF circuits.
2019-10-09T19:08:09.885Z,1570648089.885 [CBIT](DEBUG): Deactivating emergency mode.
2019-10-09T19:08:09.921Z,1570648089.921 [CBIT](DEBUG): Backplane powered.
2019-10-09T19:08:09.921Z,1570648089.921 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-10-09T19:08:09.923Z,1570648089.923 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-10-09T19:08:09.923Z,1570648089.923 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-10-09T19:08:09.924Z,1570648089.924 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-10-09T19:08:09.925Z,1570648089.925 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-10-09T19:08:09.935Z,1570648089.935 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-09T19:08:09.962Z,1570648089.962 [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-09T19:08:09.962Z,1570648089.962 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-10-09T19:08:10.031Z,1570648090.031 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-10-09T19:08:10.032Z,1570648090.032 [Default:A.Wait](DEBUG): Construct Wait.
2019-10-09T19:08:10.034Z,1570648090.034 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-10-09T19:08:10.068Z,1570648090.068 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-10-09T19:08:10.088Z,1570648090.088 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-10-09T19:08:10.105Z,1570648090.105 [Default:E.Execute](DEBUG): Construct Execute.
2019-10-09T19:08:10.109Z,1570648090.109 [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-09T19:08:10.121Z,1570648090.121 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,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-09T19:08:10.141Z,1570648090.141 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-10-09T19:08:10.176Z,1570648090.176 [DUSBL_Hydroid](INFO): Powering up
2019-10-09T19:08:10.177Z,1570648090.177 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-10-09T19:08:10.213Z,1570648090.213 [Radio_Surface](INFO): Powering up
2019-10-09T19:08:10.391Z,1570648090.391 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:10.397Z,1570648090.397 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-10-09T19:08:10.398Z,1570648090.398 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:10.405Z,1570648090.405 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-10-09T19:08:10.406Z,1570648090.406 [MassServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:10.413Z,1570648090.413 [MassServo](DEBUG): Initializing MassServo.
2019-10-09T19:08:10.414Z,1570648090.414 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:10.421Z,1570648090.421 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-09T19:08:10.422Z,1570648090.422 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:10.429Z,1570648090.429 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-10-09T19:08:10.547Z,1570648090.547 [Micromodem](INFO): Powering up
2019-10-09T19:08:10.547Z,1570648090.547 [Micromodem](DEBUG): Initializing Micromodem.
2019-10-09T19:08:11.325Z,1570648091.325 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-10-09T19:08:11.325Z,1570648091.325 [RudderServo](FAULT): Rudder failed to initialize
2019-10-09T19:08:11.325Z,1570648091.325 [RudderServo] Communications Fault, FailCount= 1
2019-10-09T19:08:11.325Z,1570648091.325 [RudderServo](ERROR): Communications Fault
2019-10-09T19:08:11.436Z,1570648091.436 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-10-09T19:08:11.650Z,1570648091.650 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-10-09T19:08:11.650Z,1570648091.650 [RudderServo](INFO): Powering down
2019-10-09T19:08:12.312Z,1570648092.312 [RudderServo](DEBUG): Initializing EZServoServo.
2019-10-09T19:08:12.430Z,1570648092.430 [RudderServo](DEBUG): Initializing RudderServo.
2019-10-09T19:08:12.434Z,1570648092.434 [CBIT](INFO): Clearing failed state for component RudderServo
2019-10-09T19:08:12.434Z,1570648092.434 [RudderServo] No Fault, FailCount= 1
2019-10-09T19:08:15.523Z,1570648095.523 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-10-09T19:08:19.644Z,1570648099.644 [Micromodem](INFO): Nmea in: $CATMG,2019-10-09T19:08:17.923723Z,RTC,RTC*5A

2019-10-09T19:08:19.644Z,1570648099.644 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2019-10-09T19:08:17.923723Z,RTC,RTC*5A

2019-10-09T19:08:23.688Z,1570648103.688 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-10-09T19:08:26.898Z,1570648106.898 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-10-09T19:08:27.307Z,1570648107.307 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-10-09T19:08:27.309Z,1570648107.309 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-10-09T19:08:27.703Z,1570648107.703 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-10-09T19:08:27.703Z,1570648107.703 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-10-09T19:08:28.110Z,1570648108.110 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-10-09T19:08:28.559Z,1570648108.559 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-10-09T19:08:28.915Z,1570648108.915 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-10-09T19:08:28.915Z,1570648108.915 [Micromodem](INFO): Nmea out: $CCCFG,pwramp.txlevel,0*2F

2019-10-09T19:08:29.323Z,1570648109.323 [Micromodem](INFO): Nmea in: $CACFG,pwramp.txlevel,0*2D

2019-10-09T19:08:29.323Z,1570648109.323 [Micromodem](INFO): Nmea out: $CCCFG,DTO,30*1E

2019-10-09T19:08:29.727Z,1570648109.727 [Micromodem](INFO): Nmea in: $CACFG,DTO,30*1C

2019-10-09T19:08:29.727Z,1570648109.727 [Micromodem](INFO): Nmea out: $CCCFG,FC0,10000*46

2019-10-09T19:08:30.127Z,1570648110.127 [Micromodem](INFO): Nmea in: $CACFG,FC0,10000*44

2019-10-09T19:08:30.127Z,1570648110.127 [Micromodem](INFO): Nmea out: $CCCFG,BW0,4000*63

2019-10-09T19:08:30.534Z,1570648110.534 [Micromodem](INFO): Nmea in: $CACFG,BW0,4000*61

2019-10-09T19:08:30.535Z,1570648110.535 [Micromodem](INFO): Nmea out: $CCCFG,BND,0*3A

2019-10-09T19:08:30.935Z,1570648110.935 [Micromodem](INFO): Nmea in: $CACFG,BND,0*38

2019-10-09T19:08:30.935Z,1570648110.935 [Micromodem](INFO): Nmea out: $CCCLK,2019,10,09,19,08,31*44

2019-10-09T19:08:31.355Z,1570648111.355 [Micromodem](INFO): Nmea in: $CACLK,2019,10,9,19,8,31*46

2019-10-09T19:08:31.756Z,1570648111.756 [Micromodem](INFO): Nmea in: $CATMS,0,2019-10-09T19:08:32Z*75

2019-10-09T19:08:32.147Z,1570648112.147 [Micromodem](INFO): Nmea in: $CATMG,2019-10-09T19:08:32.027796Z,USER_CMD,RTC*1F

2019-10-09T19:08:36.187Z,1570648116.187 [NAL9602](INFO): Powering up NAL9602
2019-10-09T19:08:38.259Z,1570648118.259 [SBIT](IMPORTANT): Beginning Startup BIT
2019-10-09T19:08:38.266Z,1570648118.266 [CBIT](IMPORTANT): Beginning ground fault scan
2019-10-09T19:08:47.302Z,1570648127.302 [NAL9602](INFO): NAL9602 initialized
2019-10-09T19:08:48.117Z,1570648128.117 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:08:49.041Z,1570648129.041 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005814
CHAN A1 (24V): -0.020995
CHAN A2 (12V): -0.004131
CHAN A3 (5V): -0.001097
CHAN B0 (3.3V): 0.000076
CHAN B1 (3.15aV): 0.000334
CHAN B2 (3.15bV): 0.000470
CHAN B3 (GND): 0.001020
OPEN: 0.006177
Full Scale Calc: 4.765 mA, -1.589 mA
2019-10-09T19:09:07.757Z,1570648147.757 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-10-09T19:09:07.757Z,1570648147.757 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00, 101.41,  94.92,   0.00
2019-10-09T19:09:31.787Z,1570648171.787 [SBIT](IMPORTANT): SBIT PASSED
2019-10-09T19:09:31.861Z,1570648171.861 [CommandLine](IMPORTANT): got command configSet list
2019-10-09T19:09:31.861Z,1570648171.861 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-10-09T19:09:31.862Z,1570648171.862 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2019-10-09T19:09:31.862Z,1570648171.862 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2019-10-09T19:09:31.862Z,1570648171.862 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=15 count;

2019-10-09T19:09:31.862Z,1570648171.862 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-10-09T19:09:32.148Z,1570648172.148 [MissionManager](IMPORTANT): Started mission Startup
2019-10-09T19:09:32.148Z,1570648172.148 [Startup] Running Loop=1
2019-10-09T19:09:32.148Z,1570648172.148 [Startup](DEBUG): Aggregate::initialize Startup
2019-10-09T19:09:32.148Z,1570648172.148 [Startup:A.GoToSurface] Running Loop=1
2019-10-09T19:09:32.148Z,1570648172.148 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-09T19:09:32.150Z,1570648172.150 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-09T19:09:32.150Z,1570648172.150 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-09T19:09:32.150Z,1570648172.150 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-09T19:09:32.151Z,1570648172.151 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-09T19:09:32.151Z,1570648172.151 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-09T19:09:32.153Z,1570648172.153 [Startup:StartupSatComms] Running Loop=1
2019-10-09T19:09:32.153Z,1570648172.153 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-10-09T19:09:32.153Z,1570648172.153 [Startup:StartupSatComms:A] Running Loop=1
2019-10-09T19:09:32.547Z,1570648172.547 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-10-09T19:10:32.290Z,1570648232.290 [Startup:StartupSatComms:A](INFO): Timed out from 2019-10-09T19:09:32.2Z
2019-10-09T19:10:32.290Z,1570648232.290 [Startup:StartupSatComms:A] Stopped
2019-10-09T19:10:32.290Z,1570648232.290 [Startup:StartupSatComms:B] Running Loop=1
2019-10-09T19:10:32.716Z,1570648232.716 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-09T19:10:36.697Z,1570648236.697 [Startup:StartupSatComms:B] Stopped
2019-10-09T19:10:36.697Z,1570648236.697 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-10-09T19:10:36.697Z,1570648236.697 [Startup:StartupSatComms] Stopped
2019-10-09T19:10:36.697Z,1570648236.697 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-10-09T19:10:36.698Z,1570648236.698 [Startup](INFO): Completed Startup
2019-10-09T19:10:36.698Z,1570648236.698 [MissionManager](INFO): Startup is completed.
2019-10-09T19:10:36.698Z,1570648236.698 [MissionManager](INFO): Uninitializing Mission Startup
2019-10-09T19:10:36.698Z,1570648236.698 [Startup] Stopped
2019-10-09T19:10:36.698Z,1570648236.698 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-10-09T19:10:36.699Z,1570648236.699 [Startup:A.GoToSurface] Stopped
2019-10-09T19:10:36.699Z,1570648236.699 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-09T19:10:36.825Z,1570648236.825 [MissionManager](IMPORTANT): Started mission Default
2019-10-09T19:10:36.826Z,1570648236.826 [Default] Running Loop=1
2019-10-09T19:10:36.826Z,1570648236.826 [Default](DEBUG): Aggregate::initialize Default
2019-10-09T19:10:36.826Z,1570648236.826 [Default:B.GoToSurface] Running Loop=1
2019-10-09T19:10:36.826Z,1570648236.826 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-09T19:10:36.826Z,1570648236.826 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-09T19:10:36.826Z,1570648236.826 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-09T19:10:36.827Z,1570648236.827 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-09T19:10:36.827Z,1570648236.827 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-09T19:10:36.827Z,1570648236.827 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-09T19:10:36.828Z,1570648236.828 [Default:A.Wait] Running Loop=1
2019-10-09T19:10:36.828Z,1570648236.828 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:10:40.651Z,1570648240.651 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004837
2019-10-09T19:10:50.097Z,1570648250.097 [Default:A.Wait](INFO): Done Waiting.
2019-10-09T19:10:50.097Z,1570648250.097 [Default:A.Wait] Stopped
2019-10-09T19:10:50.097Z,1570648250.097 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:10:50.495Z,1570648250.495 [Default:CheckIn] Running Loop=1
2019-10-09T19:10:50.496Z,1570648250.496 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:10:50.496Z,1570648250.496 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:10:50.901Z,1570648250.901 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-10-09T19:11:09.913Z,1570648269.913 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-10-09T19:11:09.913Z,1570648269.913 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-10-09T19:11:09.951Z,1570648269.951 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-10-09T19:11:10.383Z,1570648270.383 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-10-09T19:11:10.384Z,1570648270.384 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-10-09T19:12:16.125Z,1570648336.125 [NAL9602](INFO): SBD MO Status=2, MOMSN=9091, MT Status=2, MTMSN=0
2019-10-09T19:12:16.125Z,1570648336.125 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:12:50.074Z,1570648370.074 [NAL9602](INFO): SBD MO Status=0, MOMSN=9091, MT Status=0, MTMSN=0
2019-10-09T19:12:50.074Z,1570648370.074 [NAL9602](INFO): No messages in MT queue
2019-10-09T19:12:50.885Z,1570648370.885 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:12:53.697Z,1570648373.697 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:12:56.529Z,1570648376.529 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:12:59.757Z,1570648379.757 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:02.585Z,1570648382.585 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:05.413Z,1570648385.413 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:08.649Z,1570648388.649 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:11.477Z,1570648391.477 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:14.707Z,1570648394.707 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:17.541Z,1570648397.541 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:20.773Z,1570648400.773 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:23.601Z,1570648403.601 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:26.841Z,1570648406.841 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:29.669Z,1570648409.669 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:13:30.045Z,1570648410.045 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190723.00,A,3648.15642,N,12147.28211,W,0.408,0.00,091019,,,D*7F
2019-10-09T19:13:30.048Z,1570648410.048 [NAL9602](INFO): GPS fix at 20191009T190723: (36.802607, -121.788035)
2019-10-09T19:13:30.073Z,1570648410.073 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:13:30.073Z,1570648410.073 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:13:30.522Z,1570648410.522 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-10-09T19:13:35.763Z,1570648415.763 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567
2019-10-09T19:13:35.764Z,1570648415.764 [Micromodem](INFO): Outgoing frame #2, 64 bytes: 266CC0E6F1A517638CB0C0B8BE362003E8C77AD31073D8E3B830D84642FA50DCC30443F63ABFD6289693675E5363BC207B5C64E49FD33E0EB9BB70C222F0983B
2019-10-09T19:13:35.764Z,1570648415.764 [Micromodem](INFO): Outgoing frame #3, 64 bytes: 70E8F52F3F7A4ABAF73F268CD05998C59CA295F552AAD6B5C8634C336DFDD4D67836652BAAA84650A8AB2A00C3D59CB2F40520395EDFF5F40428BC8AFB1FE8E2
2019-10-09T19:13:35.764Z,1570648415.764 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-10-09T19:13:36.498Z,1570648416.498 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-10-09T19:13:36.859Z,1570648416.859 [Micromodem](INFO): Nmea in: $CADRQ,191336,1,9,0,64,1*41

2019-10-09T19:13:36.859Z,1570648416.859 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D040001005D00000400DB0100000000000000151D80030C5669BF3148E2FA22188B6A3173E6960F887FF8A99E669AC91D474B0DB47F940EC581E0D567*71

2019-10-09T19:13:37.266Z,1570648417.266 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:13:37.662Z,1570648417.662 [Micromodem](INFO): Nmea in: $CADRQ,191337,1,9,0,64,2*43

2019-10-09T19:13:37.663Z,1570648417.663 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,266CC0E6F1A517638CB0C0B8BE362003E8C77AD31073D8E3B830D84642FA50DCC30443F63ABFD6289693675E5363BC207B5C64E49FD33E0EB9BB70C222F0983B*09

2019-10-09T19:13:38.066Z,1570648418.066 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:13:38.470Z,1570648418.470 [Micromodem](INFO): Nmea in: $CADRQ,191338,1,9,0,64,3*4D

2019-10-09T19:13:38.471Z,1570648418.471 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,70E8F52F3F7A4ABAF73F268CD05998C59CA295F552AAD6B5C8634C336DFDD4D67836652BAAA84650A8AB2A00C3D59CB2F40520395EDFF5F40428BC8AFB1FE8E2*04

2019-10-09T19:13:38.874Z,1570648418.874 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:13:39.278Z,1570648419.278 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-10-09T19:13:42.476Z,1570648422.476 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191009T190759/Courier0004.lzma
2019-10-09T19:13:42.916Z,1570648422.916 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-10-09T19:13:43.324Z,1570648423.324 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,191338.899116,3,0,200,4000,10000,1,1,9,1,3,3,3,192*4D

2019-10-09T19:13:44.482Z,1570648424.482 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0004.lzma.bak
2019-10-09T19:13:44.483Z,1570648424.483 [DataOverHttps](INFO): SBD MOMSN=11865410
2019-10-09T19:14:06.765Z,1570648446.765 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:14:08.373Z,1570648448.373 [DataOverHttps](INFO): Sending 368 bytes from file Logs/20191009T183941/Express0014.lzma
2019-10-09T19:14:10.359Z,1570648450.359 [DataOverHttps](INFO): Moved sent file to Logs/20191009T183941/Express0014.lzma.bak
2019-10-09T19:14:10.360Z,1570648450.360 [DataOverHttps](INFO): SBD MOMSN=11865418
2019-10-09T19:14:32.109Z,1570648472.109 [DataOverHttps](INFO): Sending 626 bytes from file Logs/20191009T183941/Express0017.lzma
2019-10-09T19:14:34.114Z,1570648474.114 [DataOverHttps](INFO): Moved sent file to Logs/20191009T183941/Express0017.lzma.bak
2019-10-09T19:14:34.114Z,1570648474.114 [DataOverHttps](INFO): SBD MOMSN=11865485
2019-10-09T19:14:41.094Z,1570648481.094 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:14:43.772Z,1570648483.772 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:14:43.772Z,1570648483.772 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:14:43.772Z,1570648483.772 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:14:58.692Z,1570648498.692 [DataOverHttps](INFO): Sending 720 bytes from file Logs/20191009T190759/Express0001.lzma
2019-10-09T19:15:00.694Z,1570648500.694 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0001.lzma.bak
2019-10-09T19:15:00.694Z,1570648500.694 [DataOverHttps](INFO): SBD MOMSN=11865520
2019-10-09T19:15:35.943Z,1570648535.943 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-10-09T19:15:35.946Z,1570648535.946 [BPC1](INFO): Received data from all battery sticks.
2019-10-09T19:16:13.512Z,1570648573.512 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,-32768,-32768,-32768,-32768,V
2019-10-09T19:19:44.010Z,1570648784.010 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:19:44.010Z,1570648784.010 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:19:44.010Z,1570648784.010 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:19:44.010Z,1570648784.010 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:19:44.424Z,1570648784.424 [Default:CheckIn:D] Stopped
2019-10-09T19:19:44.425Z,1570648784.425 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:19:44.830Z,1570648784.830 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.126645 min 
2019-10-09T19:19:44.830Z,1570648784.830 [Default:CheckIn:E] Stopped
2019-10-09T19:19:44.830Z,1570648784.830 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:19:44.830Z,1570648784.830 [Default:CheckIn] Stopped
2019-10-09T19:19:44.831Z,1570648784.831 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:19:44.831Z,1570648784.831 [Default:CheckIn](INFO): Running loop #2
2019-10-09T19:19:44.831Z,1570648784.831 [Default:CheckIn] Running Loop=2
2019-10-09T19:19:44.831Z,1570648784.831 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:19:44.831Z,1570648784.831 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:19:46.413Z,1570648786.413 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:19:46.809Z,1570648786.809 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191340.00,A,3648.16353,N,12147.28284,W,0.253,66.45,091019,,,D*4C
2019-10-09T19:19:46.811Z,1570648786.811 [NAL9602](INFO): GPS fix at 20191009T191340: (36.802726, -121.788047)
2019-10-09T19:19:46.834Z,1570648786.834 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:19:46.835Z,1570648786.835 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:19:50.979Z,1570648790.979 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D070001005D00000400830100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A
2019-10-09T19:19:50.980Z,1570648790.980 [Micromodem](INFO): Outgoing frame #2, 64 bytes: EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C2FC0AB11464037CC4EAB61E9C3457F1722D9198302795383ECC000D5D49BCDE475E73AE60CB
2019-10-09T19:19:50.980Z,1570648790.980 [Micromodem](INFO): Outgoing frame #3, 64 bytes: AC712252029F4BFC11B6571CD1E620A251BCB9C938054A7C435F920BFE4B1429861C5339231F660D38EF2296887F2FEE3E57A72A53EB7277C5A49EF9D0808BFC
2019-10-09T19:19:50.981Z,1570648790.981 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,3*53

2019-10-09T19:19:51.239Z,1570648791.239 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,3*51

2019-10-09T19:19:51.618Z,1570648791.618 [Micromodem](INFO): Nmea in: $CADRQ,191951,1,9,0,64,1*4A

2019-10-09T19:19:51.619Z,1570648791.619 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D070001005D00000400830100000000000000151D80030C5669BF3148E2FA22188B6A3173E5573572661C0BCBDFFAB423BD32D9A51E8904B0A920CE9A*06

2019-10-09T19:19:52.015Z,1570648792.015 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:19:52.419Z,1570648792.419 [Micromodem](INFO): Nmea in: $CADRQ,191951,1,9,0,64,2*49

2019-10-09T19:19:52.420Z,1570648792.420 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,EF9F66414C9B9FD6761AD008C3E3DC4FCA2E4E25B6359B14B772C2FC0AB11464037CC4EAB61E9C3457F1722D9198302795383ECC000D5D49BCDE475E73AE60CB*04

2019-10-09T19:19:52.823Z,1570648792.823 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:19:53.227Z,1570648793.227 [Micromodem](INFO): Nmea in: $CADRQ,191952,1,9,0,64,3*4B

2019-10-09T19:19:53.227Z,1570648793.227 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,AC712252029F4BFC11B6571CD1E620A251BCB9C938054A7C435F920BFE4B1429861C5339231F660D38EF2296887F2FEE3E57A72A53EB7277C5A49EF9D0808BFC*74

2019-10-09T19:19:53.631Z,1570648793.631 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:19:54.035Z,1570648794.035 [Micromodem](INFO): Nmea in: $CATXP,192*48

2019-10-09T19:19:57.674Z,1570648797.674 [Micromodem](INFO): Nmea in: $CATXF,192*5E

2019-10-09T19:19:58.076Z,1570648798.076 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,191953.650792,3,0,200,4000,10000,1,1,9,1,3,3,3,192*4B

2019-10-09T19:19:58.209Z,1570648798.209 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20191009T190759/Courier0007.lzma
2019-10-09T19:20:00.214Z,1570648800.214 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0007.lzma.bak
2019-10-09T19:20:00.214Z,1570648800.214 [DataOverHttps](INFO): SBD MOMSN=11865564
2019-10-09T19:20:23.872Z,1570648823.872 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20191009T190759/Express0005.lzma
2019-10-09T19:20:25.878Z,1570648825.878 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0005.lzma.bak
2019-10-09T19:20:25.879Z,1570648825.879 [DataOverHttps](INFO): SBD MOMSN=11865575
2019-10-09T19:20:49.312Z,1570648849.312 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20191009T190759/Express0008.lzma
2019-10-09T19:20:51.314Z,1570648851.314 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0008.lzma.bak
2019-10-09T19:20:51.314Z,1570648851.314 [DataOverHttps](INFO): SBD MOMSN=11865579
2019-10-09T19:20:54.240Z,1570648854.240 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:20:54.240Z,1570648854.240 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:20:56.254Z,1570648856.254 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:21:00.436Z,1570648860.436 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:21:00.441Z,1570648860.441 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:21:00.441Z,1570648860.441 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:21:43.702Z,1570648903.702 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:21:43.702Z,1570648903.702 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:21:45.741Z,1570648905.741 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-09T19:21:45.742Z,1570648905.742 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19100912270500,35.0, -0.1,   0.0,1448:RA,  0.00, 101.41,  87.44,  94.92,   0.00
2019-10-09T19:22:20.064Z,1570648940.064 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:22:20.064Z,1570648940.064 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:22:47.136Z,1570648967.136 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:22:47.136Z,1570648967.136 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:24:51.563Z,1570649091.563 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T19:25:22.274Z,1570649122.274 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:25:49.453Z,1570649149.453 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout
2019-10-09T19:25:49.453Z,1570649149.453 [RDI_Pathfinder] Communications Fault, FailCount= 1
2019-10-09T19:25:49.453Z,1570649149.453 [RDI_Pathfinder](ERROR): Communications Fault
2019-10-09T19:25:49.454Z,1570649149.454 [RDI_Pathfinder](ERROR): Failed to parse:
2019-10-09T19:25:49.477Z,1570649149.477 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder
2019-10-09T19:25:49.829Z,1570649149.829 [RDI_Pathfinder](INFO): Powering down
2019-10-09T19:25:50.589Z,1570649150.589 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder
2019-10-09T19:25:50.589Z,1570649150.589 [RDI_Pathfinder] No Fault, FailCount= 1
2019-10-09T19:26:00.692Z,1570649160.692 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:26:00.692Z,1570649160.692 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:26:00.692Z,1570649160.692 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:26:00.692Z,1570649160.692 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:26:01.111Z,1570649161.111 [Default:CheckIn:D] Stopped
2019-10-09T19:26:01.112Z,1570649161.112 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:26:01.485Z,1570649161.485 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.404763 min 
2019-10-09T19:26:01.485Z,1570649161.485 [Default:CheckIn:E] Stopped
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn] Stopped
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn](INFO): Running loop #3
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn] Running Loop=3
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:26:01.486Z,1570649161.486 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:26:03.085Z,1570649163.085 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:26:03.487Z,1570649163.487 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191957.00,A,3648.16168,N,12147.28222,W,0.097,66.45,091019,,,D*4C
2019-10-09T19:26:03.489Z,1570649163.489 [NAL9602](INFO): GPS fix at 20191009T191957: (36.802695, -121.788037)
2019-10-09T19:26:03.513Z,1570649163.513 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:26:03.513Z,1570649163.513 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:26:03.920Z,1570649163.920 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-10-09T19:26:07.649Z,1570649167.649 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D0A0000005D00000400370000000000000000151D80030C5669C010B1F86C42EFB9C4BF4E5B1B839310A8F9CF3BDE9165B780E3114C82A1F93F7D6170
2019-10-09T19:26:07.649Z,1570649167.649 [Micromodem](INFO): Outgoing frame #2, 7 bytes: 895BCBC9638000
2019-10-09T19:26:07.649Z,1570649167.649 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:26:07.954Z,1570649167.954 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:26:08.338Z,1570649168.338 [Micromodem](INFO): Nmea in: $CADRQ,192607,1,9,0,64,1*45

2019-10-09T19:26:08.339Z,1570649168.339 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D0A0000005D00000400370000000000000000151D80030C5669C010B1F86C42EFB9C4BF4E5B1B839310A8F9CF3BDE9165B780E3114C82A1F93F7D6170*79

2019-10-09T19:26:08.738Z,1570649168.738 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:26:09.144Z,1570649169.144 [Micromodem](INFO): Nmea in: $CADRQ,192608,1,9,0,64,2*49

2019-10-09T19:26:09.149Z,1570649169.149 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,895BCBC9638000*71

2019-10-09T19:26:09.542Z,1570649169.542 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,7*44

2019-10-09T19:26:09.947Z,1570649169.947 [Micromodem](INFO): Nmea in: $CATXP,71*74

2019-10-09T19:26:12.370Z,1570649172.370 [Micromodem](INFO): Nmea in: $CATXF,71*62

2019-10-09T19:26:13.587Z,1570649173.587 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,192609.500613,3,0,200,4000,10000,1,1,9,1,2,2,3,71*7A

2019-10-09T19:26:15.089Z,1570649175.089 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191009T190759/Courier0010.lzma
2019-10-09T19:26:17.094Z,1570649177.094 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0010.lzma.bak
2019-10-09T19:26:17.094Z,1570649177.094 [DataOverHttps](INFO): SBD MOMSN=11865680
2019-10-09T19:26:34.195Z,1570649194.195 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-10-09T19:26:34.269Z,1570649194.269 [NAL9602](FAULT): received: 
+CSQ:0

OK92, 2, 0, 0, 0

OK
2019-10-09T19:26:34.269Z,1570649194.269 [NAL9602] Data Fault, FailCount= 1
2019-10-09T19:26:34.269Z,1570649194.269 [NAL9602](ERROR): Data Fault
2019-10-09T19:26:34.311Z,1570649194.311 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-09T19:26:34.603Z,1570649194.603 [NAL9602](INFO): Powering down
2019-10-09T19:26:35.481Z,1570649195.481 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-09T19:26:35.481Z,1570649195.481 [NAL9602] No Fault, FailCount= 1
2019-10-09T19:26:38.261Z,1570649198.261 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-09T19:26:38.261Z,1570649198.261 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19100912315752,35.0, -0.1,   0.0,144

2019-10-09T19:26:39.144Z,1570649199.144 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20191009T190759/Express0011.lzma
2019-10-09T19:26:41.150Z,1570649201.150 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0011.lzma.bak
2019-10-09T19:26:41.150Z,1570649201.150 [DataOverHttps](INFO): SBD MOMSN=11865683
2019-10-09T19:26:46.781Z,1570649206.781 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:26:46.781Z,1570649206.781 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:26:46.781Z,1570649206.781 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:27:04.911Z,1570649224.911 [NAL9602](INFO): Powering up NAL9602
2019-10-09T19:27:15.819Z,1570649235.819 [NAL9602](INFO): NAL9602 initialized
2019-10-09T19:27:46.934Z,1570649266.934 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:31:47.357Z,1570649507.357 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:31:47.357Z,1570649507.357 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:31:47.357Z,1570649507.357 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:31:47.357Z,1570649507.357 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:31:47.764Z,1570649507.764 [Default:CheckIn:D] Stopped
2019-10-09T19:31:47.764Z,1570649507.764 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:31:48.194Z,1570649508.194 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.182308 min 
2019-10-09T19:31:48.194Z,1570649508.194 [Default:CheckIn:E] Stopped
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn] Stopped
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn](INFO): Running loop #4
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn] Running Loop=4
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:31:48.195Z,1570649508.195 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:31:49.737Z,1570649509.737 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:31:50.128Z,1570649510.128 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192544.00,A,3648.16203,N,12147.28312,W,0.175,311.86,091019,,,D*7C
2019-10-09T19:31:50.130Z,1570649510.130 [NAL9602](INFO): GPS fix at 20191009T192544: (36.802701, -121.788052)
2019-10-09T19:31:50.201Z,1570649510.201 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:31:50.201Z,1570649510.201 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:31:50.938Z,1570649510.938 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:31:54.184Z,1570649514.184 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191009T190759/Courier0013.lzma
2019-10-09T19:31:54.623Z,1570649514.623 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D0D0000005D00000400370000000000000000151D80030C5669C010B1F8528DF0101AE3021CB899F3FED69AA0E3E1DFB638826BD18626F4C8CDFCAE94
2019-10-09T19:31:54.623Z,1570649514.623 [Micromodem](INFO): Outgoing frame #2, 5 bytes: 757F652400
2019-10-09T19:31:54.624Z,1570649514.624 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:31:54.812Z,1570649514.812 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T19:31:55.562Z,1570649515.562 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:31:55.966Z,1570649515.966 [Micromodem](INFO): Nmea in: $CADRQ,193154,1,9,0,64,1*45

2019-10-09T19:31:55.967Z,1570649515.967 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D0D0000005D00000400370000000000000000151D80030C5669C010B1F8528DF0101AE3021CB899F3FED69AA0E3E1DFB638826BD18626F4C8CDFCAE94*07

2019-10-09T19:31:56.194Z,1570649516.194 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0013.lzma.bak
2019-10-09T19:31:56.194Z,1570649516.194 [DataOverHttps](INFO): SBD MOMSN=11865742
2019-10-09T19:31:56.370Z,1570649516.370 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:31:56.774Z,1570649516.774 [Micromodem](INFO): Nmea in: $CADRQ,193156,1,9,0,64,2*44

2019-10-09T19:31:56.775Z,1570649516.775 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,757F652400*07

2019-10-09T19:31:57.186Z,1570649517.186 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,5*46

2019-10-09T19:31:57.582Z,1570649517.582 [Micromodem](INFO): Nmea in: $CATXP,69*7D

2019-10-09T19:32:00.006Z,1570649520.006 [Micromodem](INFO): Nmea in: $CATXF,69*6B

2019-10-09T19:32:00.411Z,1570649520.411 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,193157.126668,3,0,200,4000,10000,1,1,9,1,2,2,3,69*72

2019-10-09T19:32:25.459Z,1570649545.459 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:32:29.524Z,1570649549.524 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20191009T190759/Express0014.lzma
2019-10-09T19:32:31.531Z,1570649551.531 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0014.lzma.bak
2019-10-09T19:32:31.531Z,1570649551.531 [DataOverHttps](INFO): SBD MOMSN=11865749
2019-10-09T19:32:36.820Z,1570649556.820 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:32:36.820Z,1570649556.820 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:32:36.820Z,1570649556.820 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:35:07.103Z,1570649707.103 [RDI_Pathfinder](ERROR): Failed to parse:
   +26.87,        +2.64,        +6.94,   9.63,  0.00
2019-10-09T19:37:37.417Z,1570649857.417 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:37:37.417Z,1570649857.417 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:37:37.417Z,1570649857.417 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:37:37.417Z,1570649857.417 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:37:37.841Z,1570649857.841 [Default:CheckIn:D] Stopped
2019-10-09T19:37:37.841Z,1570649857.841 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:37:38.245Z,1570649858.245 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.016840 min 
2019-10-09T19:37:38.245Z,1570649858.245 [Default:CheckIn:E] Stopped
2019-10-09T19:37:38.245Z,1570649858.245 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:37:38.245Z,1570649858.245 [Default:CheckIn] Stopped
2019-10-09T19:37:38.245Z,1570649858.245 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:37:38.246Z,1570649858.246 [Default:CheckIn](INFO): Running loop #5
2019-10-09T19:37:38.246Z,1570649858.246 [Default:CheckIn] Running Loop=5
2019-10-09T19:37:38.246Z,1570649858.246 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:37:38.246Z,1570649858.246 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:37:39.821Z,1570649859.821 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:37:40.220Z,1570649860.220 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193134.00,A,3648.16031,N,12147.27834,W,0.311,311.86,091019,,,D*7D
2019-10-09T19:37:40.223Z,1570649860.223 [NAL9602](INFO): GPS fix at 20191009T193134: (36.802672, -121.787972)
2019-10-09T19:37:40.280Z,1570649860.280 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:37:40.280Z,1570649860.280 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:37:41.149Z,1570649861.149 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:37:44.038Z,1570649864.038 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191009T190759/Courier0016.lzma
2019-10-09T19:37:44.638Z,1570649864.638 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D100000005D00000400370000000000000000151D80030C5669C010B1F86B27C970DEADCBEFB3AA6270F5C8FBF32CFC8A1C4AD5A86F9AF43E92B2BD7C
2019-10-09T19:37:44.638Z,1570649864.638 [Micromodem](INFO): Outgoing frame #2, 6 bytes: B66D881B7440
2019-10-09T19:37:44.638Z,1570649864.638 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:37:44.880Z,1570649864.880 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-10-09T19:37:44.880Z,1570649864.880 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,   +4,    +6,A
2019-10-09T19:37:45.663Z,1570649865.663 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:37:45.989Z,1570649865.989 [Micromodem](INFO): Nmea in: $CADRQ,193744,1,9,0,64,1*42

2019-10-09T19:37:45.989Z,1570649865.989 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D100000005D00000400370000000000000000151D80030C5669C010B1F86B27C970DEADCBEFB3AA6270F5C8FBF32CFC8A1C4AD5A86F9AF43E92B2BD7C*05

2019-10-09T19:37:46.407Z,1570649866.407 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:37:46.800Z,1570649866.800 [Micromodem](INFO): Nmea in: $CADRQ,193746,1,9,0,64,2*43

2019-10-09T19:37:46.806Z,1570649866.806 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,B66D881B7440*03

2019-10-09T19:37:47.211Z,1570649867.211 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,6*45

2019-10-09T19:37:47.414Z,1570649867.414 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0016.lzma.bak
2019-10-09T19:37:47.414Z,1570649867.414 [DataOverHttps](INFO): SBD MOMSN=11865849
2019-10-09T19:37:47.602Z,1570649867.602 [Micromodem](INFO): Nmea in: $CATXP,70*75

2019-10-09T19:37:50.036Z,1570649870.036 [Micromodem](INFO): Nmea in: $CATXF,70*63

2019-10-09T19:37:50.439Z,1570649870.439 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,193747.158528,3,0,200,4000,10000,1,1,9,1,2,2,3,70*73

2019-10-09T19:38:08.672Z,1570649888.672 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20191009T190759/Express0017.lzma
2019-10-09T19:38:10.678Z,1570649890.678 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0017.lzma.bak
2019-10-09T19:38:10.679Z,1570649890.679 [DataOverHttps](INFO): SBD MOMSN=11865852
2019-10-09T19:38:16.348Z,1570649896.348 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:38:16.348Z,1570649896.348 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:38:16.348Z,1570649896.348 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:40:59.110Z,1570650059.110 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:40:59.110Z,1570650059.110 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:42:44.950Z,1570650164.950 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T19:43:11.227Z,1570650191.227 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-10-09T19:43:11.227Z,1570650191.227 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00, 101.41,  88.42,  99.42
2019-10-09T19:43:15.655Z,1570650195.655 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:43:16.916Z,1570650196.916 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:43:16.916Z,1570650196.916 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:43:16.933Z,1570650196.933 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:43:16.933Z,1570650196.933 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:43:17.302Z,1570650197.302 [Default:CheckIn:D] Stopped
2019-10-09T19:43:17.302Z,1570650197.302 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:43:17.718Z,1570650197.718 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.674601 min 
2019-10-09T19:43:17.718Z,1570650197.718 [Default:CheckIn:E] Stopped
2019-10-09T19:43:17.718Z,1570650197.718 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:43:17.718Z,1570650197.718 [Default:CheckIn] Stopped
2019-10-09T19:43:17.719Z,1570650197.719 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:43:17.719Z,1570650197.719 [Default:CheckIn](INFO): Running loop #6
2019-10-09T19:43:17.719Z,1570650197.719 [Default:CheckIn] Running Loop=6
2019-10-09T19:43:17.719Z,1570650197.719 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:43:17.719Z,1570650197.719 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:43:19.301Z,1570650199.301 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:43:19.692Z,1570650199.692 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193713.00,A,3648.16319,N,12147.28550,W,0.097,60.36,091019,,,D*44
2019-10-09T19:43:19.699Z,1570650199.699 [NAL9602](INFO): GPS fix at 20191009T193713: (36.802720, -121.788092)
2019-10-09T19:43:19.769Z,1570650199.769 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:43:19.769Z,1570650199.769 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:43:20.605Z,1570650200.605 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:43:24.691Z,1570650204.691 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D130000005D00000400370000000000000000151D80030C5669C010B1F85E61D9EC087BD4210CCDAF86390D03F33524088D23EAA1283BDF4AAF26AF90
2019-10-09T19:43:24.691Z,1570650204.691 [Micromodem](INFO): Outgoing frame #2, 6 bytes: 2FF1956496C0
2019-10-09T19:43:24.691Z,1570650204.691 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:43:25.468Z,1570650205.468 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191009T190759/Courier0019.lzma
2019-10-09T19:43:25.738Z,1570650205.738 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:43:26.149Z,1570650206.149 [Micromodem](INFO): Nmea in: $CADRQ,194324,1,9,0,64,1*47

2019-10-09T19:43:26.150Z,1570650206.150 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D130000005D00000400370000000000000000151D80030C5669C010B1F85E61D9EC087BD4210CCDAF86390D03F33524088D23EAA1283BDF4AAF26AF90*77

2019-10-09T19:43:26.550Z,1570650206.550 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:43:26.954Z,1570650206.954 [Micromodem](INFO): Nmea in: $CADRQ,194326,1,9,0,64,2*46

2019-10-09T19:43:26.955Z,1570650206.955 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,2FF1956496C0*00

2019-10-09T19:43:27.358Z,1570650207.358 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,6*45

2019-10-09T19:43:27.478Z,1570650207.478 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0019.lzma.bak
2019-10-09T19:43:27.478Z,1570650207.478 [DataOverHttps](INFO): SBD MOMSN=11865943
2019-10-09T19:43:27.762Z,1570650207.762 [Micromodem](INFO): Nmea in: $CATXP,70*75

2019-10-09T19:43:30.182Z,1570650210.182 [Micromodem](INFO): Nmea in: $CATXF,70*63

2019-10-09T19:43:30.599Z,1570650210.599 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,194327.308544,3,0,200,4000,10000,1,1,9,1,2,2,3,70*7B

2019-10-09T19:43:48.484Z,1570650228.484 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20191009T190759/Express0020.lzma
2019-10-09T19:43:50.490Z,1570650230.490 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0020.lzma.bak
2019-10-09T19:43:50.490Z,1570650230.490 [DataOverHttps](INFO): SBD MOMSN=11865948
2019-10-09T19:43:56.500Z,1570650236.500 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:43:56.500Z,1570650236.500 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:43:56.500Z,1570650236.500 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:47:15.241Z,1570650435.241 [RDI_Pathfinder](ERROR): Failed to parse:
:BI,   +68,   +69,   +19,-32768,A
2019-10-09T19:48:25.112Z,1570650505.112 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T19:48:37.243Z,1570650517.243 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-09T19:48:37.244Z,1570650517.244 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19100912535652,35.0, -0.1,  8.9,  0
2019-10-09T19:48:55.821Z,1570650535.821 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:48:57.118Z,1570650537.118 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:48:57.118Z,1570650537.118 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:48:57.118Z,1570650537.118 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:48:57.118Z,1570650537.118 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:48:57.469Z,1570650537.469 [Default:CheckIn:D] Stopped
2019-10-09T19:48:57.469Z,1570650537.469 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:48:57.924Z,1570650537.924 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.344055 min 
2019-10-09T19:48:57.924Z,1570650537.924 [Default:CheckIn:E] Stopped
2019-10-09T19:48:57.924Z,1570650537.924 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:48:57.924Z,1570650537.924 [Default:CheckIn] Stopped
2019-10-09T19:48:57.929Z,1570650537.929 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:48:57.929Z,1570650537.929 [Default:CheckIn](INFO): Running loop #7
2019-10-09T19:48:57.929Z,1570650537.929 [Default:CheckIn] Running Loop=7
2019-10-09T19:48:57.929Z,1570650537.929 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:48:57.929Z,1570650537.929 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:48:59.466Z,1570650539.466 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:48:59.885Z,1570650539.885 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194254.00,A,3648.15854,N,12147.28180,W,0.097,86.50,091019,,,D*45
2019-10-09T19:48:59.887Z,1570650539.887 [NAL9602](INFO): GPS fix at 20191009T194254: (36.802642, -121.788030)
2019-10-09T19:48:59.964Z,1570650539.964 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:48:59.964Z,1570650539.964 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:49:00.751Z,1570650540.751 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:49:03.783Z,1570650543.783 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191009T190759/Courier0022.lzma
2019-10-09T19:49:04.299Z,1570650544.299 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D160000005D00000400370000000000000000151D80030C5669C010B1F84AA908BED6B58CAEDDA96B99A461BCFA3A5D15AF2F14C43FDD0C5308DA0F0B
2019-10-09T19:49:04.299Z,1570650544.299 [Micromodem](INFO): Outgoing frame #2, 6 bytes: CB0F01852000
2019-10-09T19:49:04.300Z,1570650544.300 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:49:05.246Z,1570650545.246 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:49:05.657Z,1570650545.657 [Micromodem](INFO): Nmea in: $CADRQ,194904,1,9,0,64,1*4F

2019-10-09T19:49:05.657Z,1570650545.657 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D160000005D00000400370000000000000000151D80030C5669C010B1F84AA908BED6B58CAEDDA96B99A461BCFA3A5D15AF2F14C43FDD0C5308DA0F0B*0A

2019-10-09T19:49:05.790Z,1570650545.790 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0022.lzma.bak
2019-10-09T19:49:05.790Z,1570650545.790 [DataOverHttps](INFO): SBD MOMSN=11866001
2019-10-09T19:49:06.050Z,1570650546.050 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:49:06.454Z,1570650546.454 [Micromodem](INFO): Nmea in: $CADRQ,194906,1,9,0,64,2*4E

2019-10-09T19:49:06.455Z,1570650546.455 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,CB0F01852000*08

2019-10-09T19:49:06.889Z,1570650546.889 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,6*45

2019-10-09T19:49:07.262Z,1570650547.262 [Micromodem](INFO): Nmea in: $CATXP,70*75

2019-10-09T19:49:09.686Z,1570650549.686 [Micromodem](INFO): Nmea in: $CATXF,70*63

2019-10-09T19:49:10.091Z,1570650550.091 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,194906.804595,3,0,200,4000,10000,1,1,9,1,2,2,3,70*79

2019-10-09T19:49:27.536Z,1570650567.536 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20191009T190759/Express0023.lzma
2019-10-09T19:49:29.542Z,1570650569.542 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0023.lzma.bak
2019-10-09T19:49:29.542Z,1570650569.542 [DataOverHttps](INFO): SBD MOMSN=11866004
2019-10-09T19:49:35.203Z,1570650575.203 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:49:35.203Z,1570650575.203 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:49:35.203Z,1570650575.203 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:51:07.656Z,1570650667.656 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:51:07.656Z,1570650667.656 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:51:33.516Z,1570650693.516 [NAL9602](INFO): SBD MO Status=2, MOMSN=9092, MT Status=2, MTMSN=0
2019-10-09T19:51:33.516Z,1570650693.516 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-10-09T19:53:05.252Z,1570650785.252 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-09T19:53:05.252Z,1570650785.252 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19100912582452,35.0, -0.1,   0.0,10
2019-10-09T19:54:04.610Z,1570650844.610 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T19:54:35.315Z,1570650875.315 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:54:35.753Z,1570650875.753 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T19:54:35.753Z,1570650875.753 [Default:CheckIn:C.Wait] Stopped
2019-10-09T19:54:35.753Z,1570650875.753 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T19:54:35.753Z,1570650875.753 [Default:CheckIn:D] Running Loop=1
2019-10-09T19:54:36.168Z,1570650876.168 [Default:CheckIn:D] Stopped
2019-10-09T19:54:36.168Z,1570650876.168 [Default:CheckIn:E] Running Loop=1
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.989034 min 
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn:E] Stopped
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn] Stopped
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn](INFO): Running loop #8
2019-10-09T19:54:36.602Z,1570650876.602 [Default:CheckIn] Running Loop=8
2019-10-09T19:54:36.603Z,1570650876.603 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T19:54:36.603Z,1570650876.603 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T19:54:38.153Z,1570650878.153 [NAL9602](DEBUG): Fix Requested
2019-10-09T19:54:38.544Z,1570650878.544 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194832.00,A,3648.16096,N,12147.28376,W,0.194,234.15,091019,,,D*79
2019-10-09T19:54:38.546Z,1570650878.546 [NAL9602](INFO): GPS fix at 20191009T194832: (36.802683, -121.788063)
2019-10-09T19:54:38.584Z,1570650878.584 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T19:54:38.584Z,1570650878.584 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T19:54:39.453Z,1570650879.453 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T19:54:43.125Z,1570650883.125 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191009T190759/Courier0025.lzma
2019-10-09T19:54:43.309Z,1570650883.309 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D190000005D00000400370000000000000000151D80030C5669C010B1F835B42E12FA2DDF791974F69D0F59CA2B35494458BF3EA2649353449EEFC8C3
2019-10-09T19:54:43.310Z,1570650883.310 [Micromodem](INFO): Outgoing frame #2, 5 bytes: E32B41B400
2019-10-09T19:54:43.310Z,1570650883.310 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T19:54:44.293Z,1570650884.293 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T19:54:44.679Z,1570650884.679 [Micromodem](INFO): Nmea in: $CADRQ,195443,1,9,0,64,1*40

2019-10-09T19:54:44.679Z,1570650884.679 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D190000005D00000400370000000000000000151D80030C5669C010B1F835B42E12FA2DDF791974F69D0F59CA2B35494458BF3EA2649353449EEFC8C3*00

2019-10-09T19:54:45.098Z,1570650885.098 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T19:54:45.146Z,1570650885.146 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0025.lzma.bak
2019-10-09T19:54:45.146Z,1570650885.146 [DataOverHttps](INFO): SBD MOMSN=11866016
2019-10-09T19:54:45.492Z,1570650885.492 [Micromodem](INFO): Nmea in: $CADRQ,195445,1,9,0,64,2*45

2019-10-09T19:54:45.492Z,1570650885.492 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,E32B41B400*04

2019-10-09T19:54:45.896Z,1570650885.896 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,5*46

2019-10-09T19:54:46.304Z,1570650886.304 [Micromodem](INFO): Nmea in: $CATXP,69*7D

2019-10-09T19:54:48.718Z,1570650888.718 [Micromodem](INFO): Nmea in: $CATXF,69*6B

2019-10-09T19:54:49.123Z,1570650889.123 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,195445.844554,3,0,200,4000,10000,1,1,9,1,2,2,3,69*73

2019-10-09T19:55:06.900Z,1570650906.900 [DataOverHttps](INFO): Sending 193 bytes from file Logs/20191009T190759/Express0026.lzma
2019-10-09T19:55:08.906Z,1570650908.906 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0026.lzma.bak
2019-10-09T19:55:08.907Z,1570650908.907 [DataOverHttps](INFO): SBD MOMSN=11866019
2019-10-09T19:55:09.327Z,1570650909.327 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-10-09T19:55:09.405Z,1570650909.405 [NAL9602](FAULT): received: 
+CSQ:0

OK92, 2, 0, 0, 0

OK
2019-10-09T19:55:09.405Z,1570650909.405 [NAL9602] Data Fault, FailCount= 1
2019-10-09T19:55:09.405Z,1570650909.405 [NAL9602](ERROR): Data Fault
2019-10-09T19:55:09.479Z,1570650909.479 [CBIT](ERROR): Data Fault in component: NAL9602
2019-10-09T19:55:09.726Z,1570650909.726 [NAL9602](INFO): Powering down
2019-10-09T19:55:10.594Z,1570650910.594 [CBIT](INFO): Clearing failed state for component NAL9602
2019-10-09T19:55:10.594Z,1570650910.594 [NAL9602] No Fault, FailCount= 1
2019-10-09T19:55:14.620Z,1570650914.620 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T19:55:14.620Z,1570650914.620 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T19:55:14.620Z,1570650914.620 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T19:55:17.874Z,1570650917.874 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-10-09T19:55:17.875Z,1570650917.875 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,  +84,   +28,A
2019-10-09T19:55:40.030Z,1570650940.030 [NAL9602](INFO): Powering up NAL9602
2019-10-09T19:55:50.935Z,1570650950.935 [NAL9602](INFO): NAL9602 initialized
2019-10-09T19:56:22.046Z,1570650982.046 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T19:57:42.083Z,1570651062.083 [RDI_Pathfinder](ERROR): Failed to parse:    +50.92,       +43.08,       +14.89,   9.41,  0.00
2019-10-09T19:58:22.051Z,1570651102.051 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-10-09T19:58:22.051Z,1570651102.051 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,1

2019-10-09T19:59:28.246Z,1570651168.246 [CommandLine](IMPORTANT): got command burn
2019-10-09T19:59:28.247Z,1570651168.247 [CommandLine](FAULT): Incomplete syntax. Try: help burn
2019-10-09T19:59:32.566Z,1570651172.566 [CommandLine](IMPORTANT): got command burn off
2019-10-09T19:59:32.567Z,1570651172.567 [CommandLine](IMPORTANT): Deactivating dropweight wire
2019-10-09T19:59:34.709Z,1570651174.709 [CommandLine](IMPORTANT): got command show stack
2019-10-09T19:59:34.710Z,1570651174.710 [CommandLine](IMPORTANT): Behavior Stack:

2019-10-09T19:59:34.710Z,1570651174.710 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-10-09T19:59:34.710Z,1570651174.710 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2019-10-09T20:00:15.199Z,1570651215.199 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-10-09T20:00:15.199Z,1570651215.199 [Default:CheckIn:C.Wait] Stopped
2019-10-09T20:00:15.199Z,1570651215.199 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:00:15.200Z,1570651215.200 [Default:CheckIn:D] Running Loop=1
2019-10-09T20:00:15.587Z,1570651215.587 [Default:CheckIn:D] Stopped
2019-10-09T20:00:15.587Z,1570651215.587 [Default:CheckIn:E] Running Loop=1
2019-10-09T20:00:16.001Z,1570651216.001 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.646016 min 
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn:E] Stopped
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn] Stopped
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn](INFO): Running loop #9
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn] Running Loop=9
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T20:00:16.002Z,1570651216.002 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T20:00:17.597Z,1570651217.597 [NAL9602](DEBUG): Fix Requested
2019-10-09T20:00:17.981Z,1570651217.981 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195411.00,A,3648.16211,N,12147.28141,W,0.136,54.43,091019,,,D*41
2019-10-09T20:00:17.983Z,1570651217.983 [NAL9602](INFO): GPS fix at 20191009T195411: (36.802702, -121.788023)
2019-10-09T20:00:18.068Z,1570651218.068 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T20:00:18.068Z,1570651218.068 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T20:00:18.941Z,1570651218.941 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T20:00:22.972Z,1570651222.972 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D1C0000005D00000400370000000000000000151D80030C5669C010B1F8641882D1B8DD28854844244187DB07D2CA5A54C9F8408D62A62FBCD0ADFA45
2019-10-09T20:00:22.973Z,1570651222.973 [Micromodem](INFO): Outgoing frame #2, 6 bytes: 10FAF16D781D
2019-10-09T20:00:22.973Z,1570651222.973 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T20:00:23.309Z,1570651223.309 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T20:00:24.062Z,1570651224.062 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T20:00:24.355Z,1570651224.355 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191009T190759/Courier0028.lzma
2019-10-09T20:00:24.466Z,1570651224.466 [Micromodem](INFO): Nmea in: $CADRQ,200023,1,9,0,64,1*4D

2019-10-09T20:00:24.467Z,1570651224.467 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D1C0000005D00000400370000000000000000151D80030C5669C010B1F8641882D1B8DD28854844244187DB07D2CA5A54C9F8408D62A62FBCD0ADFA45*74

2019-10-09T20:00:24.884Z,1570651224.884 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T20:00:25.278Z,1570651225.278 [Micromodem](INFO): Nmea in: $CADRQ,200024,1,9,0,64,2*49

2019-10-09T20:00:25.279Z,1570651225.279 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,10FAF16D781D*08

2019-10-09T20:00:25.686Z,1570651225.686 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,6*45

2019-10-09T20:00:26.086Z,1570651226.086 [Micromodem](INFO): Nmea in: $CATXP,70*75

2019-10-09T20:00:26.366Z,1570651226.366 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0028.lzma.bak
2019-10-09T20:00:26.366Z,1570651226.366 [DataOverHttps](INFO): SBD MOMSN=11866069
2019-10-09T20:00:28.506Z,1570651228.506 [Micromodem](INFO): Nmea in: $CATXF,70*63

2019-10-09T20:00:28.911Z,1570651228.911 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,200025.628646,3,0,200,4000,10000,1,1,9,1,2,2,3,70*72

2019-10-09T20:00:41.889Z,1570651241.889 [CommandLine](IMPORTANT): got command show variable remote
2019-10-09T20:00:42.049Z,1570651242.049 [CommandLine](IMPORTANT): Micromodem.remote_address (count)
2019-10-09T20:00:47.979Z,1570651247.979 [CommandLine](IMPORTANT): got command get Micromodem.remote_address
2019-10-09T20:00:47.979Z,1570651247.979 [CommandLine](IMPORTANT): Micromodem.remote_address 0 count
2019-10-09T20:00:48.789Z,1570651248.789 [DataOverHttps](INFO): Sending 362 bytes from file Logs/20191009T190759/Express0029.lzma
2019-10-09T20:00:52.689Z,1570651252.689 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0029.lzma.bak
2019-10-09T20:00:52.689Z,1570651252.689 [DataOverHttps](INFO): SBD MOMSN=11866072
2019-10-09T20:00:53.990Z,1570651253.990 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T20:00:57.669Z,1570651257.669 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T20:00:57.669Z,1570651257.669 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T20:00:57.669Z,1570651257.669 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:03:03.679Z,1570651383.679 [CommandLine](IMPORTANT): got command show variable destinationaddress
2019-10-09T20:03:03.809Z,1570651383.809 [CommandLine](IMPORTANT): Micromodem.destinationAddress (enum)
2019-10-09T20:03:08.686Z,1570651388.686 [CommandLine](IMPORTANT): got command get Micromodem.destinationAddress
2019-10-09T20:03:08.687Z,1570651388.687 [CommandLine](IMPORTANT): Micromodem.destinationAddress 9 enum
2019-10-09T20:03:34.002Z,1570651414.002 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-10-09T20:03:36.086Z,1570651416.086 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:03:36.087Z,1570651416.087 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:03:36.161Z,1570651416.161 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-10-09T20:03:36.169Z,1570651416.169 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-10-09T20:03:36.185Z,1570651416.185 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-10-09T20:03:36.188Z,1570651416.188 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-10-09T20:03:36.203Z,1570651416.203 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-10-09T20:03:36.213Z,1570651416.213 [DUSBL:A.Pitch](DEBUG): Construct.
2019-10-09T20:03:36.223Z,1570651416.223 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-10-09T20:03:36.676Z,1570651416.676 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-10-09T20:03:36.697Z,1570651416.697 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         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/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</Value></DefineArg>
    
    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-10-09T20:03:36.699Z,1570651416.699 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:03:36.917Z,1570651416.917 [Default] Stopped
2019-10-09T20:03:36.918Z,1570651416.918 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-09T20:03:36.918Z,1570651416.918 [Default:B.GoToSurface] Stopped
2019-10-09T20:03:36.918Z,1570651416.918 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-09T20:03:36.918Z,1570651416.918 [Default:CheckIn] Stopped
2019-10-09T20:03:36.918Z,1570651416.918 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T20:03:36.918Z,1570651416.918 [Default:CheckIn:C.Wait] Stopped
2019-10-09T20:03:36.918Z,1570651416.918 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:03:36.918Z,1570651416.918 [MissionManager](IMPORTANT): Started mission DUSBL
2019-10-09T20:03:36.918Z,1570651416.918 [DUSBL] Running Loop=1
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:A.Pitch] Running Loop=1
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:C.] Running Loop=1
2019-10-09T20:03:36.919Z,1570651416.919 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-10-09T20:03:36.920Z,1570651416.920 [DUSBL:RequestRepeater] Running Loop=1
2019-10-09T20:03:36.920Z,1570651416.920 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-10-09T20:03:36.920Z,1570651416.920 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-10-09T20:03:36.920Z,1570651416.920 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:03:36.920Z,1570651416.920 [DUSBL:C.] Running Loop=1
2019-10-09T20:03:36.933Z,1570651416.933 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-09T20:03:36.933Z,1570651416.933 [DUSBL:A.Pitch] Running Loop=1
2019-10-09T20:03:40.921Z,1570651420.921 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:03:41.655Z,1570651421.655 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:03:42.068Z,1570651422.068 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:03:42.462Z,1570651422.462 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:03:42.894Z,1570651422.894 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200342.03*5A

2019-10-09T20:03:44.934Z,1570651424.934 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:03:45.699Z,1570651425.699 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:03:46.107Z,1570651426.107 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:03:46.919Z,1570651426.919 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200346.08*55

2019-10-09T20:03:47.373Z,1570651427.373 [CommandLine](IMPORTANT): got command stop
2019-10-09T20:03:47.374Z,1570651427.374 [CommandLine](IMPORTANT): Scheduling is paused
2019-10-09T20:03:47.374Z,1570651427.374 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-10-09T20:03:47.750Z,1570651427.750 [MissionManager](INFO): MissionManager is completed.
2019-10-09T20:03:47.751Z,1570651427.751 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:A.Pitch] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:B.SetSpeed] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:C.] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:RequestRepeater] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-10-09T20:03:47.751Z,1570651427.751 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:03:48.164Z,1570651428.164 [MissionManager](IMPORTANT): Started mission Default
2019-10-09T20:03:48.165Z,1570651428.165 [Default] Running Loop=1
2019-10-09T20:03:48.165Z,1570651428.165 [Default](DEBUG): Aggregate::initialize Default
2019-10-09T20:03:48.165Z,1570651428.165 [Default:B.GoToSurface] Running Loop=1
2019-10-09T20:03:48.165Z,1570651428.165 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-09T20:03:48.165Z,1570651428.165 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-09T20:03:48.165Z,1570651428.165 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-09T20:03:48.166Z,1570651428.166 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-09T20:03:48.166Z,1570651428.166 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-09T20:03:48.166Z,1570651428.166 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-09T20:03:48.167Z,1570651428.167 [Default:A.Wait] Running Loop=1
2019-10-09T20:03:48.167Z,1570651428.167 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:04:01.479Z,1570651441.479 [Default:A.Wait](INFO): Done Waiting.
2019-10-09T20:04:01.479Z,1570651441.479 [Default:A.Wait] Stopped
2019-10-09T20:04:01.479Z,1570651441.479 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:04:01.905Z,1570651441.905 [Default:CheckIn] Running Loop=1
2019-10-09T20:04:01.905Z,1570651441.905 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T20:04:01.906Z,1570651441.906 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T20:04:03.481Z,1570651443.481 [NAL9602](DEBUG): Fix Requested
2019-10-09T20:04:03.876Z,1570651443.876 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195757.00,A,3648.16280,N,12147.28182,W,0.350,9.43,091019,,,D*7D
2019-10-09T20:04:03.878Z,1570651443.878 [NAL9602](INFO): GPS fix at 20191009T195757: (36.802713, -121.788030)
2019-10-09T20:04:03.943Z,1570651443.943 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T20:04:03.943Z,1570651443.943 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T20:04:04.677Z,1570651444.677 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T20:04:08.593Z,1570651448.593 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D1F0000005D00000400370000000000000000151D80030C5669C010B1F84838A53158C5844E276C4B48E88E4DF1C48D141C68E0F58AEBAEFB7F38D059
2019-10-09T20:04:08.593Z,1570651448.593 [Micromodem](INFO): Outgoing frame #2, 7 bytes: 5C9323D1D72000
2019-10-09T20:04:08.594Z,1570651448.594 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T20:04:09.535Z,1570651449.535 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T20:04:09.926Z,1570651449.926 [Micromodem](INFO): Nmea in: $CADRQ,200408,1,9,0,64,1*40

2019-10-09T20:04:09.927Z,1570651449.927 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D1F0000005D00000400370000000000000000151D80030C5669C010B1F84838A53158C5844E276C4B48E88E4DF1C48D141C68E0F58AEBAEFB7F38D059*07

2019-10-09T20:04:10.333Z,1570651450.333 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T20:04:10.738Z,1570651450.738 [Micromodem](INFO): Nmea in: $CADRQ,200410,1,9,0,64,2*4A

2019-10-09T20:04:10.739Z,1570651450.739 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,5C9323D1D72000*08

2019-10-09T20:04:11.140Z,1570651451.140 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,7*44

2019-10-09T20:04:11.546Z,1570651451.546 [Micromodem](INFO): Nmea in: $CATXP,71*74

2019-10-09T20:04:13.971Z,1570651453.971 [Micromodem](INFO): Nmea in: $CATXF,71*62

2019-10-09T20:04:14.371Z,1570651454.371 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,200411.089348,3,0,200,4000,10000,1,1,9,1,2,2,3,71*76

2019-10-09T20:04:14.516Z,1570651454.516 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191009T190759/Courier0031.lzma
2019-10-09T20:04:16.522Z,1570651456.522 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0031.lzma.bak
2019-10-09T20:04:16.522Z,1570651456.522 [DataOverHttps](INFO): SBD MOMSN=11866084
2019-10-09T20:04:38.529Z,1570651478.529 [DataOverHttps](INFO): Sending 405 bytes from file Logs/20191009T190759/Express0032.lzma
2019-10-09T20:04:40.534Z,1570651480.534 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0032.lzma.bak
2019-10-09T20:04:40.535Z,1570651480.535 [DataOverHttps](INFO): SBD MOMSN=11866087
2019-10-09T20:04:45.948Z,1570651485.948 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T20:04:45.948Z,1570651485.948 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T20:04:45.965Z,1570651485.965 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:05:18.247Z,1570651518.247 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,   +50,    -2,    +2,A
2019-10-09T20:06:40.532Z,1570651600.532 [CommandLine](IMPORTANT): got command show variable range
2019-10-09T20:06:40.534Z,1570651600.534 [CommandLine](IMPORTANT): acoustic_contact_range (unknown)
2019-10-09T20:06:40.665Z,1570651600.665 [CommandLine](IMPORTANT): BR_Ping1D.minRange (meter)
2019-10-09T20:06:40.665Z,1570651600.665 [CommandLine](IMPORTANT): BR_Ping1D.maxRange (meter)
2019-10-09T20:06:40.718Z,1570651600.718 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-10-09T20:06:40.719Z,1570651600.719 [CommandLine](IMPORTANT): Micromodem.range_request (count)
2019-10-09T20:06:40.720Z,1570651600.720 [CommandLine](IMPORTANT): Micromodem.range (meter)
2019-10-09T20:06:40.727Z,1570651600.727 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter)
2019-10-09T20:06:40.727Z,1570651600.727 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter)
2019-10-09T20:06:40.727Z,1570651600.727 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter)
2019-10-09T20:06:40.728Z,1570651600.728 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter)
2019-10-09T20:06:48.114Z,1570651608.114 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.acoustic_contact_range
2019-10-09T20:06:57.912Z,1570651617.912 [CommandLine](IMPORTANT): got command report touch acoustic_contact_range
2019-10-09T20:07:03.969Z,1570651623.969 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:07:03.970Z,1570651623.970 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:07:03.994Z,1570651623.994 [MissionManager](INFO): DefineArg DUSBL.MissionTimeout = 10.000000 min
2019-10-09T20:07:03.996Z,1570651623.996 [MissionManager](INFO): DefineArg DUSBL.TransponderCode = 2.000000 count
2019-10-09T20:07:03.999Z,1570651623.999 [MissionManager](INFO): DefineArg DUSBL.TrackingUpdatePeriod = 4.000000 s
2019-10-09T20:07:04.001Z,1570651624.001 [MissionManager](INFO): DefineArg DUSBL.NumberOfPings = 1.000000 count
2019-10-09T20:07:04.003Z,1570651624.003 [MissionManager](INFO): DefineArg DUSBL.EnabledDUSBL = DUSBL_Hydroid.loadAtStartup
2019-10-09T20:07:04.004Z,1570651624.004 [DUSBL:A.Pitch](DEBUG): Construct.
2019-10-09T20:07:04.024Z,1570651624.024 [DUSBL:B.SetSpeed](DEBUG): Construct.
2019-10-09T20:07:04.150Z,1570651624.150 [DUSBL:RequestRepeater:A.Wait](DEBUG): Construct Wait.
2019-10-09T20:07:04.158Z,1570651624.158 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         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/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="DUSBL">

    <Description>
        This mission is requests a DUSBL arming.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Transponder Address.
    </Description><Units:count/><Value>2</Value></DefineArg>
    
    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>4</Value></DefineArg>
    
    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>
    
    <DefineArg Name="EnabledDUSBL"><Description>
        Automatically set to true if the DUSBL is enabled. Set to false to disable
        reading from the DUSBL.
    </Description><Sensor:DUSBL_Hydroid.loadAtStartup/></DefineArg>    

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    
    <Estimation:TrackAcousticContact>
        <Parallel/>
        <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
        <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:TrackAcousticContact>
    
      <Aggregate Id="RequestRepeater">

        <Sequence/>
        
          <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>            
          </Guidance:Wait>
      </Aggregate>

</Mission>


2019-10-09T20:07:04.159Z,1570651624.159 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/DUSBL_Tracking.xml
2019-10-09T20:07:04.489Z,1570651624.489 [Default] Stopped
2019-10-09T20:07:04.489Z,1570651624.489 [Default](DEBUG): Aggregate::uninitialize Default
2019-10-09T20:07:04.489Z,1570651624.489 [Default:B.GoToSurface] Stopped
2019-10-09T20:07:04.489Z,1570651624.489 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-10-09T20:07:04.489Z,1570651624.489 [Default:CheckIn] Stopped
2019-10-09T20:07:04.489Z,1570651624.489 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-10-09T20:07:04.489Z,1570651624.489 [Default:CheckIn:C.Wait] Stopped
2019-10-09T20:07:04.489Z,1570651624.489 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:07:04.490Z,1570651624.490 [MissionManager](IMPORTANT): Started mission DUSBL
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL] Running Loop=1
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL](DEBUG): Aggregate::initialize DUSBL
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL:A.Pitch] Running Loop=1
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL:A.Pitch](DEBUG): Initialize.
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL:B.SetSpeed](DEBUG): Initialize.
2019-10-09T20:07:04.490Z,1570651624.490 [DUSBL:C.] Running Loop=1
2019-10-09T20:07:04.491Z,1570651624.491 [DUSBL:C.](INFO): Initializing TrackAcousticContact.
2019-10-09T20:07:04.491Z,1570651624.491 [DUSBL:RequestRepeater] Running Loop=1
2019-10-09T20:07:04.491Z,1570651624.491 [DUSBL:RequestRepeater](DEBUG): Aggregate::initialize DUSBL:RequestRepeater
2019-10-09T20:07:04.491Z,1570651624.491 [DUSBL:RequestRepeater:A.Wait] Running Loop=1
2019-10-09T20:07:04.491Z,1570651624.491 [DUSBL:RequestRepeater:A.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:07:04.492Z,1570651624.492 [DUSBL:C.] Running Loop=1
2019-10-09T20:07:04.492Z,1570651624.492 [DUSBL:B.SetSpeed] Running Loop=1
2019-10-09T20:07:04.492Z,1570651624.492 [DUSBL:A.Pitch] Running Loop=1
2019-10-09T20:07:08.579Z,1570651628.579 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:09.311Z,1570651629.311 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:09.713Z,1570651629.713 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:10.110Z,1570651630.110 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:10.530Z,1570651630.530 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200709.69*5D

2019-10-09T20:07:12.979Z,1570651632.979 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:13.751Z,1570651633.751 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:14.157Z,1570651634.157 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:14.610Z,1570651634.610 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.199997 m
2019-10-09T20:07:14.611Z,1570651634.611 [Reporter](INFO): acoustic_contact_range 100.199997 m
2019-10-09T20:07:14.978Z,1570651634.978 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200714.13*5C

2019-10-09T20:07:16.314Z,1570651636.314 [CommandLine](IMPORTANT): got command show variable DUSBL
2019-10-09T20:07:16.361Z,1570651636.361 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2019-10-09T20:07:16.361Z,1570651636.361 [CommandLine](IMPORTANT): DUSBL_Hydroid.simulateHardware (bool)
2019-10-09T20:07:16.362Z,1570651636.362 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultTurnAroundTime (second)
2019-10-09T20:07:16.362Z,1570651636.362 [CommandLine](IMPORTANT): DUSBL_Hydroid.defaultSoundSpeed (meter_per_second)
2019-10-09T20:07:16.362Z,1570651636.362 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold (count)
2019-10-09T20:07:16.363Z,1570651636.363 [CommandLine](IMPORTANT): DUSBL_Hydroid.recieveTimeout (millisecond)
2019-10-09T20:07:16.363Z,1570651636.363 [CommandLine](IMPORTANT): DUSBL_Hydroid.transmitLockout (millisecond)
2019-10-09T20:07:16.363Z,1570651636.363 [CommandLine](IMPORTANT): DUSBL_Hydroid.transponderCode (enum)
2019-10-09T20:07:16.364Z,1570651636.364 [CommandLine](IMPORTANT): DUSBL_Hydroid.numberOfPingsRequested (count)
2019-10-09T20:07:16.364Z,1570651636.364 [CommandLine](IMPORTANT): DUSBL_Hydroid.verbosity (enum)
2019-10-09T20:07:16.365Z,1570651636.365 [CommandLine](IMPORTANT): DUSBL_Hydroid.xCenter (angular_degree)
2019-10-09T20:07:16.365Z,1570651636.365 [CommandLine](IMPORTANT): DUSBL_Hydroid.yCenter (angular_degree)
2019-10-09T20:07:16.367Z,1570651636.367 [CommandLine](IMPORTANT): Micromodem.dusblPingCode (none)
2019-10-09T20:07:16.378Z,1570651636.378 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadControl (none)
2019-10-09T20:07:16.378Z,1570651636.378 [CommandLine](IMPORTANT): DUSBL_Hydroid.uart (none)
2019-10-09T20:07:16.378Z,1570651636.378 [CommandLine](IMPORTANT): DUSBL_Hydroid.baud (bit_per_second)
2019-10-09T20:07:16.382Z,1570651636.382 [CommandLine](IMPORTANT): DUSBL_Hydroid.pingRequested (count)
2019-10-09T20:07:16.382Z,1570651636.382 [CommandLine](IMPORTANT): Micromodem.dusblPingCodeRequested (enum)
2019-10-09T20:07:16.382Z,1570651636.382 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-10-09T20:07:16.383Z,1570651636.383 [CommandLine](IMPORTANT): DUSBL_Hydroid.yAngle (angular_degree)
2019-10-09T20:07:16.383Z,1570651636.383 [CommandLine](IMPORTANT): DUSBL_Hydroid.travelTime (microsecond)
2019-10-09T20:07:16.384Z,1570651636.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.latency (microsecond)
2019-10-09T20:07:16.384Z,1570651636.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.gain (ratio)
2019-10-09T20:07:16.384Z,1570651636.384 [CommandLine](IMPORTANT): DUSBL_Hydroid.inBandSignalToNoise (ratio)
2019-10-09T20:07:16.385Z,1570651636.385 [CommandLine](IMPORTANT): DUSBL_Hydroid.outBandSignalToNoise (ratio)
2019-10-09T20:07:16.385Z,1570651636.385 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_range (meter)
2019-10-09T20:07:16.385Z,1570651636.385 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_direction_vehicle_frame (none)
2019-10-09T20:07:16.386Z,1570651636.386 [CommandLine](IMPORTANT): DUSBL_Hydroid.acoustic_contact_address (enum)
2019-10-09T20:07:16.440Z,1570651636.440 [CommandLine](IMPORTANT): DUSBL.MissionTimeout (minute)
2019-10-09T20:07:16.441Z,1570651636.441 [CommandLine](IMPORTANT): DUSBL.TransponderCode (count)
2019-10-09T20:07:16.441Z,1570651636.441 [CommandLine](IMPORTANT): DUSBL.TrackingUpdatePeriod (second)
2019-10-09T20:07:16.441Z,1570651636.441 [CommandLine](IMPORTANT): DUSBL.NumberOfPings (count)
2019-10-09T20:07:16.442Z,1570651636.442 [CommandLine](IMPORTANT): DUSBL.EnabledDUSBL (none)
2019-10-09T20:07:16.443Z,1570651636.443 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_voltage (volt)
2019-10-09T20:07:16.443Z,1570651636.443 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgVoltage (volt)
2019-10-09T20:07:16.443Z,1570651636.443 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_current (milliampere)
2019-10-09T20:07:16.444Z,1570651636.444 [CommandLine](IMPORTANT): DUSBL_Hydroid.component_avgCurrent (milliampere)
2019-10-09T20:07:18.633Z,1570651638.633 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:19.402Z,1570651639.402 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:19.821Z,1570651639.821 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:20.214Z,1570651640.214 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:20.626Z,1570651640.626 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200719.78*5C

2019-10-09T20:07:22.115Z,1570651642.115 [CommandLine](IMPORTANT): got command show variable xangle
2019-10-09T20:07:22.147Z,1570651642.147 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-10-09T20:07:22.700Z,1570651642.700 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:23.443Z,1570651643.443 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:23.872Z,1570651643.872 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:24.250Z,1570651644.250 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:24.670Z,1570651644.670 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200723.82*50

2019-10-09T20:07:26.736Z,1570651646.736 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:27.202Z,1570651647.202 [CommandLine](IMPORTANT): got command show variable headingTo
2019-10-09T20:07:27.487Z,1570651647.487 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:27.893Z,1570651647.893 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:28.298Z,1570651648.298 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:28.710Z,1570651648.710 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200727.87*51

2019-10-09T20:07:30.330Z,1570651650.330 [CommandLine](IMPORTANT): got command show variable heading
2019-10-09T20:07:30.341Z,1570651650.341 [CommandLine](IMPORTANT): HorizontalControl.kdHeading (second)
2019-10-09T20:07:30.342Z,1570651650.342 [CommandLine](IMPORTANT): HorizontalControl.kiHeading (reciprocal_second)
2019-10-09T20:07:30.342Z,1570651650.342 [CommandLine](IMPORTANT): HorizontalControl.kiwpHeading (radian_per_second_per_meter)
2019-10-09T20:07:30.342Z,1570651650.342 [CommandLine](IMPORTANT): HorizontalControl.kpHeading (none)
2019-10-09T20:07:30.343Z,1570651650.343 [CommandLine](IMPORTANT): HorizontalControl.kwpHeading (radian_per_meter)
2019-10-09T20:07:30.449Z,1570651650.449 [CommandLine](IMPORTANT): Rowe_600.headingOffset (degree)
2019-10-09T20:07:30.498Z,1570651650.498 [CommandLine](IMPORTANT): HorizontalControl.headingInternal (radian)
2019-10-09T20:07:30.499Z,1570651650.499 [CommandLine](IMPORTANT): HorizontalControl.smoothHeadingInternal (radian)
2019-10-09T20:07:30.499Z,1570651650.499 [CommandLine](IMPORTANT): HorizontalControl.headingIntegralInternal (radian)
2019-10-09T20:07:30.503Z,1570651650.503 [CommandLine](IMPORTANT): TrackAcousticContact.heading_to_contact (radian)
2019-10-09T20:07:30.777Z,1570651650.777 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:31.527Z,1570651651.527 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:31.933Z,1570651651.933 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:32.383Z,1570651652.383 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.080002 m
2019-10-09T20:07:32.383Z,1570651652.383 [Reporter](INFO): acoustic_contact_range 100.080002 m
2019-10-09T20:07:32.754Z,1570651652.754 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200731.90*50

2019-10-09T20:07:36.417Z,1570651656.417 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:37.183Z,1570651657.183 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:37.585Z,1570651657.585 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:37.990Z,1570651657.990 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:38.406Z,1570651658.406 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200737.56*5C

2019-10-09T20:07:40.470Z,1570651660.470 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:41.219Z,1570651661.219 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:41.629Z,1570651661.629 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:42.117Z,1570651662.117 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.140007 m
2019-10-09T20:07:42.117Z,1570651662.117 [Reporter](INFO): acoustic_contact_range 100.140007 m
2019-10-09T20:07:42.458Z,1570651662.458 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200741.59*52

2019-10-09T20:07:46.121Z,1570651666.121 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:46.875Z,1570651666.875 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:47.281Z,1570651667.281 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:47.682Z,1570651667.682 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:48.106Z,1570651668.106 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200747.25*5F

2019-10-09T20:07:49.361Z,1570651669.361 [CommandLine](IMPORTANT): got command report touch TrackAcousticContact.heading_to_contact
2019-10-09T20:07:50.177Z,1570651670.177 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:50.913Z,1570651670.913 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:51.329Z,1570651671.329 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:51.770Z,1570651671.770 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 32.699997 m
2019-10-09T20:07:51.771Z,1570651671.771 [Reporter](INFO): acoustic_contact_range 32.699997 m
2019-10-09T20:07:51.771Z,1570651671.771 [Reporter](INFO): TrackAcousticContact.heading_to_contact 4.862580 rad
2019-10-09T20:07:52.138Z,1570651672.138 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200751.29*54

2019-10-09T20:07:55.635Z,1570651675.635 [CommandLine](IMPORTANT): got command show variable xangle
2019-10-09T20:07:55.669Z,1570651675.669 [CommandLine](IMPORTANT): DUSBL_Hydroid.xAngle (angular_degree)
2019-10-09T20:07:55.814Z,1570651675.814 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:07:56.569Z,1570651676.569 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:07:56.981Z,1570651676.981 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:07:57.384Z,1570651677.384 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:07:57.806Z,1570651677.806 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200756.95*54

2019-10-09T20:07:59.903Z,1570651679.903 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:00.611Z,1570651680.611 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:01.025Z,1570651681.025 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:01.418Z,1570651681.418 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:08:01.853Z,1570651681.853 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200800.99*54

2019-10-09T20:08:03.919Z,1570651683.919 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:04.655Z,1570651684.655 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:05.061Z,1570651685.061 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:05.458Z,1570651685.458 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:08:05.890Z,1570651685.890 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200805.03*52

2019-10-09T20:08:07.823Z,1570651687.823 [CommandLine](IMPORTANT): got command report touch DUSBL_Hydroid.xAngle
2019-10-09T20:08:07.956Z,1570651687.956 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:08.689Z,1570651688.689 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:09.097Z,1570651689.097 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:09.502Z,1570651689.502 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:08:09.922Z,1570651689.922 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200809.07*5A

2019-10-09T20:08:11.977Z,1570651691.977 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:12.735Z,1570651692.735 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:13.148Z,1570651693.148 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:13.589Z,1570651693.589 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.199997 m
2019-10-09T20:08:13.590Z,1570651693.590 [Reporter](INFO): acoustic_contact_range 100.199997 m
2019-10-09T20:08:13.590Z,1570651693.590 [Reporter](INFO): TrackAcousticContact.heading_to_contact 4.956367 rad
2019-10-09T20:08:13.591Z,1570651693.591 [Reporter](INFO): DUSBL_Hydroid.xAngle 12.050000 arcdeg
2019-10-09T20:08:13.958Z,1570651693.958 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200813.11*56

2019-10-09T20:08:17.607Z,1570651697.607 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:18.403Z,1570651698.403 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:18.792Z,1570651698.792 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:19.280Z,1570651699.280 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.080002 m
2019-10-09T20:08:19.285Z,1570651699.285 [Reporter](INFO): acoustic_contact_range 100.080002 m
2019-10-09T20:08:19.286Z,1570651699.286 [Reporter](INFO): TrackAcousticContact.heading_to_contact 0.121561 rad
2019-10-09T20:08:19.286Z,1570651699.286 [Reporter](INFO): DUSBL_Hydroid.xAngle 5.450000 arcdeg
2019-10-09T20:08:19.624Z,1570651699.624 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200818.78*52

2019-10-09T20:08:23.279Z,1570651703.279 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:24.041Z,1570651704.041 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:24.453Z,1570651704.453 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:24.959Z,1570651704.959 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.080002 m
2019-10-09T20:08:24.960Z,1570651704.960 [Reporter](INFO): acoustic_contact_range 100.080002 m
2019-10-09T20:08:24.960Z,1570651704.960 [Reporter](INFO): TrackAcousticContact.heading_to_contact 0.406650 rad
2019-10-09T20:08:24.965Z,1570651704.965 [Reporter](INFO): DUSBL_Hydroid.xAngle 4.750000 arcdeg
2019-10-09T20:08:25.274Z,1570651705.274 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200824.42*54

2019-10-09T20:08:28.938Z,1570651708.938 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:29.703Z,1570651709.703 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:30.116Z,1570651710.116 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:30.593Z,1570651710.593 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 89.940002 m
2019-10-09T20:08:30.593Z,1570651710.593 [Reporter](INFO): acoustic_contact_range 89.940002 m
2019-10-09T20:08:30.594Z,1570651710.594 [Reporter](INFO): TrackAcousticContact.heading_to_contact 1.412971 rad
2019-10-09T20:08:30.595Z,1570651710.595 [Reporter](INFO): DUSBL_Hydroid.xAngle -24.500000 arcdeg
2019-10-09T20:08:30.926Z,1570651710.926 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200830.08*5F

2019-10-09T20:08:34.580Z,1570651714.580 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:35.355Z,1570651715.355 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:35.761Z,1570651715.761 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:36.286Z,1570651716.286 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 73.019997 m
2019-10-09T20:08:36.287Z,1570651716.287 [Reporter](INFO): acoustic_contact_range 73.019997 m
2019-10-09T20:08:36.287Z,1570651716.287 [Reporter](INFO): TrackAcousticContact.heading_to_contact 4.730999 rad
2019-10-09T20:08:36.288Z,1570651716.288 [Reporter](INFO): DUSBL_Hydroid.xAngle 24.249999 arcdeg
2019-10-09T20:08:36.584Z,1570651716.584 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200835.73*56

2019-10-09T20:08:38.577Z,1570651718.577 [CommandLine](IMPORTANT): got command show variable headingCmd
2019-10-09T20:08:40.244Z,1570651720.244 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:41.011Z,1570651721.011 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:41.417Z,1570651721.417 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:41.822Z,1570651721.822 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:08:42.042Z,1570651722.042 [CommandLine](IMPORTANT): got command show variable heading
2019-10-09T20:08:42.054Z,1570651722.054 [CommandLine](IMPORTANT): HorizontalControl.kdHeading (second)
2019-10-09T20:08:42.054Z,1570651722.054 [CommandLine](IMPORTANT): HorizontalControl.kiHeading (reciprocal_second)
2019-10-09T20:08:42.055Z,1570651722.055 [CommandLine](IMPORTANT): HorizontalControl.kiwpHeading (radian_per_second_per_meter)
2019-10-09T20:08:42.055Z,1570651722.055 [CommandLine](IMPORTANT): HorizontalControl.kpHeading (none)
2019-10-09T20:08:42.055Z,1570651722.055 [CommandLine](IMPORTANT): HorizontalControl.kwpHeading (radian_per_meter)
2019-10-09T20:08:42.150Z,1570651722.150 [CommandLine](IMPORTANT): Rowe_600.headingOffset (degree)
2019-10-09T20:08:42.238Z,1570651722.238 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200841.39*5B

2019-10-09T20:08:42.274Z,1570651722.274 [CommandLine](IMPORTANT): HorizontalControl.headingInternal (radian)
2019-10-09T20:08:42.275Z,1570651722.275 [CommandLine](IMPORTANT): HorizontalControl.smoothHeadingInternal (radian)
2019-10-09T20:08:42.275Z,1570651722.275 [CommandLine](IMPORTANT): HorizontalControl.headingIntegralInternal (radian)
2019-10-09T20:08:42.315Z,1570651722.315 [CommandLine](IMPORTANT): TrackAcousticContact.heading_to_contact (radian)
2019-10-09T20:08:44.302Z,1570651724.302 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:45.051Z,1570651725.051 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:45.461Z,1570651725.461 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:45.867Z,1570651725.867 [DUSBL_Hydroid](ERROR): Range is NaN. Not publishing.
2019-10-09T20:08:46.278Z,1570651726.278 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200845.43*52

2019-10-09T20:08:48.333Z,1570651728.333 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:49.090Z,1570651729.090 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:49.507Z,1570651729.507 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:49.962Z,1570651729.962 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.199997 m
2019-10-09T20:08:49.963Z,1570651729.963 [Reporter](INFO): acoustic_contact_range 100.199997 m
2019-10-09T20:08:49.963Z,1570651729.963 [Reporter](INFO): TrackAcousticContact.heading_to_contact 4.983025 rad
2019-10-09T20:08:49.964Z,1570651729.964 [Reporter](INFO): DUSBL_Hydroid.xAngle 11.550000 arcdeg
2019-10-09T20:08:50.314Z,1570651730.314 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200849.47*5A

2019-10-09T20:08:54.006Z,1570651734.006 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:08:54.753Z,1570651734.753 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:08:55.158Z,1570651735.158 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:08:55.602Z,1570651735.602 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.080002 m
2019-10-09T20:08:55.603Z,1570651735.603 [Reporter](INFO): acoustic_contact_range 100.080002 m
2019-10-09T20:08:55.604Z,1570651735.604 [Reporter](INFO): TrackAcousticContact.heading_to_contact 0.098579 rad
2019-10-09T20:08:55.604Z,1570651735.604 [Reporter](INFO): DUSBL_Hydroid.xAngle 5.500000 arcdeg
2019-10-09T20:08:55.980Z,1570651735.980 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200855.13*56

2019-10-09T20:08:59.625Z,1570651739.625 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:09:00.407Z,1570651740.407 [Micromodem](INFO): Nmea out: $CCPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*77

2019-10-09T20:09:00.811Z,1570651740.811 [Micromodem](INFO): Nmea in: $SNPGT,1,10000,40,0,1000,24000,28,4A1C0370,6C8F7D30,2107E320,37BCD1E0,4000,4000,0*6A

2019-10-09T20:09:01.255Z,1570651741.255 [Reporter](INFO): DUSBL_Hydroid.acoustic_contact_range 100.140007 m
2019-10-09T20:09:01.255Z,1570651741.255 [Reporter](INFO): acoustic_contact_range 100.140007 m
2019-10-09T20:09:01.256Z,1570651741.256 [Reporter](INFO): TrackAcousticContact.heading_to_contact 5.812087 rad
2019-10-09T20:09:01.256Z,1570651741.256 [Reporter](INFO): DUSBL_Hydroid.xAngle 6.800000 arcdeg
2019-10-09T20:09:01.634Z,1570651741.634 [Micromodem](INFO): Nmea in: $SNTTA,,,,,200900.78*5A

2019-10-09T20:09:05.275Z,1570651745.275 [DUSBL:C.](INFO): *** querying acoustic contact ***
2019-10-09T20:09:05.647Z,1570651745.647 [CommandLine](IMPORTANT): got command stop
2019-10-09T20:09:05.647Z,1570651745.647 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-10-09T20:09:05.722Z,1570651745.722 [MissionManager](INFO): MissionManager is completed.
2019-10-09T20:09:05.722Z,1570651745.722 [MissionManager](INFO): Uninitializing Mission DUSBL
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL](DEBUG): Aggregate::uninitialize DUSBL
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:A.Pitch] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:B.SetSpeed] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:B.SetSpeed](DEBUG): Uninitialize.
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:C.] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:RequestRepeater] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:RequestRepeater](DEBUG): Aggregate::uninitialize DUSBL:RequestRepeater
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:RequestRepeater:A.Wait] Stopped
2019-10-09T20:09:05.722Z,1570651745.722 [DUSBL:RequestRepeater:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:09:06.100Z,1570651746.100 [MissionManager](IMPORTANT): Started mission Default
2019-10-09T20:09:06.101Z,1570651746.101 [Default] Running Loop=1
2019-10-09T20:09:06.101Z,1570651746.101 [Default](DEBUG): Aggregate::initialize Default
2019-10-09T20:09:06.101Z,1570651746.101 [Default:B.GoToSurface] Running Loop=1
2019-10-09T20:09:06.101Z,1570651746.101 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-10-09T20:09:06.101Z,1570651746.101 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-10-09T20:09:06.102Z,1570651746.102 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-10-09T20:09:06.102Z,1570651746.102 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-10-09T20:09:06.102Z,1570651746.102 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-10-09T20:09:06.103Z,1570651746.103 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-10-09T20:09:06.103Z,1570651746.103 [Default:A.Wait] Running Loop=1
2019-10-09T20:09:06.103Z,1570651746.103 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:09:08.891Z,1570651748.891 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-10-09T20:09:10.123Z,1570651750.123 [CommandLine](IMPORTANT): got command show variable horizontal
2019-10-09T20:09:10.125Z,1570651750.125 [CommandLine](IMPORTANT): fix_horizontal_path_length_since_last_fix (unknown)
2019-10-09T20:09:10.126Z,1570651750.126 [CommandLine](IMPORTANT): horizontal_path_length_since_last_fix (meter)
2019-10-09T20:09:10.147Z,1570651750.147 [CommandLine](IMPORTANT): HorizontalControl.loadAtStartup (bool)
2019-10-09T20:09:10.147Z,1570651750.147 [CommandLine](IMPORTANT): HorizontalControl.kdHeading (second)
2019-10-09T20:09:10.148Z,1570651750.148 [CommandLine](IMPORTANT): HorizontalControl.kiHeading (reciprocal_second)
2019-10-09T20:09:10.148Z,1570651750.148 [CommandLine](IMPORTANT): HorizontalControl.kiwpHeading (radian_per_second_per_meter)
2019-10-09T20:09:10.149Z,1570651750.149 [CommandLine](IMPORTANT): HorizontalControl.kpHeading (none)
2019-10-09T20:09:10.149Z,1570651750.149 [CommandLine](IMPORTANT): HorizontalControl.kwpHeading (radian_per_meter)
2019-10-09T20:09:10.149Z,1570651750.149 [CommandLine](IMPORTANT): HorizontalControl.maxHdgAccel (angular_degree_per_second_squared)
2019-10-09T20:09:10.150Z,1570651750.150 [CommandLine](IMPORTANT): HorizontalControl.maxHdgInt (radian)
2019-10-09T20:09:10.150Z,1570651750.150 [CommandLine](IMPORTANT): HorizontalControl.maxHdgRate (angular_degree_per_second)
2019-10-09T20:09:10.151Z,1570651750.151 [CommandLine](IMPORTANT): HorizontalControl.maxKxte (angular_degree)
2019-10-09T20:09:10.151Z,1570651750.151 [CommandLine](IMPORTANT): HorizontalControl.rudDeadband (angular_degree)
2019-10-09T20:09:10.151Z,1570651750.151 [CommandLine](IMPORTANT): HorizontalControl.rudLimit (angular_degree)
2019-10-09T20:09:10.380Z,1570651750.380 [CommandLine](IMPORTANT): DeadReckonUsingMultipleVelocitySources.horizontal_path_length_since_last_fix (meter)
2019-10-09T20:09:10.389Z,1570651750.389 [CommandLine](IMPORTANT): DeadReckonUsingMultipleVelocitySources.fix_horizontal_path_length_since_last_fix (meter)
2019-10-09T20:09:10.390Z,1570651750.390 [CommandLine](IMPORTANT): HorizontalControl.rudderAngleAction (radian)
2019-10-09T20:09:10.392Z,1570651750.392 [CommandLine](IMPORTANT): HorizontalControl.horizontalMode (enum)
2019-10-09T20:09:10.401Z,1570651750.401 [CommandLine](IMPORTANT): HorizontalControl.rudderAngleCmd (radian)
2019-10-09T20:09:10.404Z,1570651750.404 [CommandLine](IMPORTANT): HorizontalControl.headingInternal (radian)
2019-10-09T20:09:10.404Z,1570651750.404 [CommandLine](IMPORTANT): HorizontalControl.smoothHeadingInternal (radian)
2019-10-09T20:09:10.417Z,1570651750.417 [CommandLine](IMPORTANT): HorizontalControl.headingIntegralInternal (radian)
2019-10-09T20:09:10.417Z,1570651750.417 [CommandLine](IMPORTANT): HorizontalControl.xteIntegralInternal (radian)
2019-10-09T20:09:10.418Z,1570651750.418 [CommandLine](IMPORTANT): HorizontalControl.xteInternal (meter)
2019-10-09T20:09:10.418Z,1570651750.418 [CommandLine](IMPORTANT): HorizontalControl.kxteInternal (radian)
2019-10-09T20:09:10.418Z,1570651750.418 [CommandLine](IMPORTANT): HorizontalControl.bearingInternal (radian)
2019-10-09T20:09:19.425Z,1570651759.425 [Default:A.Wait](INFO): Done Waiting.
2019-10-09T20:09:19.425Z,1570651759.425 [Default:A.Wait] Stopped
2019-10-09T20:09:19.426Z,1570651759.426 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-10-09T20:09:19.861Z,1570651759.861 [Default:CheckIn] Running Loop=1
2019-10-09T20:09:19.861Z,1570651759.861 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-10-09T20:09:19.861Z,1570651759.861 [Default:CheckIn:Read_GPS] Running Loop=1
2019-10-09T20:09:21.421Z,1570651761.421 [NAL9602](DEBUG): Fix Requested
2019-10-09T20:09:21.830Z,1570651761.830 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200315.00,A,3648.16167,N,12147.28883,W,0.350,9.43,091019,,,D*72
2019-10-09T20:09:21.838Z,1570651761.838 [NAL9602](INFO): GPS fix at 20191009T200315: (36.802695, -121.788147)
2019-10-09T20:09:21.899Z,1570651761.899 [Default:CheckIn:Read_GPS] Stopped
2019-10-09T20:09:21.899Z,1570651761.899 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-10-09T20:09:22.620Z,1570651762.620 [Micromodem](ERROR): Buffer fill timout failure.
2019-10-09T20:09:26.521Z,1570651766.521 [Micromodem](INFO): Outgoing frame #1, 64 bytes: 0F309E5D220000005D00000400370000000000000000151D80030C5669C010B1F83C398C757BC66F72E4365B3E0B01A5B8A07F42C65ACF1BB5E46249EC42A4A1
2019-10-09T20:09:26.522Z,1570651766.522 [Micromodem](INFO): Outgoing frame #2, 6 bytes: 47E7AEE66600
2019-10-09T20:09:26.522Z,1570651766.522 [Micromodem](INFO): Nmea out: $CCCYC,0,1,9,1,0,2*52

2019-10-09T20:09:26.710Z,1570651766.710 [Micromodem](INFO): Nmea in: $CACYC,0,1,9,1,0,2*50

2019-10-09T20:09:27.093Z,1570651767.093 [Micromodem](INFO): Nmea in: $CADRQ,200926,1,9,0,64,1*41

2019-10-09T20:09:27.094Z,1570651767.094 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,0F309E5D220000005D00000400370000000000000000151D80030C5669C010B1F83C398C757BC66F72E4365B3E0B01A5B8A07F42C65ACF1BB5E46249EC42A4A1*07

2019-10-09T20:09:27.508Z,1570651767.508 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,64*71

2019-10-09T20:09:27.910Z,1570651767.910 [Micromodem](INFO): Nmea in: $CADRQ,200927,1,9,0,64,2*43

2019-10-09T20:09:27.911Z,1570651767.911 [Micromodem](INFO): Nmea out: $CCTXD,1,9,1,47E7AEE66600*77

2019-10-09T20:09:28.309Z,1570651768.309 [Micromodem](INFO): Nmea in: $CATXD,1,9,1,6*45

2019-10-09T20:09:28.710Z,1570651768.710 [Micromodem](INFO): Nmea in: $CATXP,70*75

2019-10-09T20:09:31.130Z,1570651771.130 [Micromodem](INFO): Nmea in: $CATXF,70*63

2019-10-09T20:09:31.271Z,1570651771.271 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191009T190759/Courier0034.lzma
2019-10-09T20:09:31.535Z,1570651771.535 [Micromodem](INFO): Nmea in: $CAXST,6,20191009,200928.259685,3,0,200,4000,10000,1,1,9,1,2,2,3,70*7B

2019-10-09T20:09:33.278Z,1570651773.278 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Courier0034.lzma.bak
2019-10-09T20:09:33.278Z,1570651773.278 [DataOverHttps](INFO): SBD MOMSN=11866153
2019-10-09T20:09:34.162Z,1570651774.162 [CommandLine](IMPORTANT): got command show stack
2019-10-09T20:09:34.162Z,1570651774.162 [CommandLine](IMPORTANT): Behavior Stack:

2019-10-09T20:09:34.163Z,1570651774.163 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2019-10-09T20:09:34.163Z,1570651774.163 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_Iridium
2019-10-09T20:09:55.015Z,1570651795.015 [DataOverHttps](INFO): Sending 1506 bytes from file Logs/20191009T190759/Express0035.lzma
2019-10-09T20:09:56.986Z,1570651796.986 [NAL9602](INFO): Not Powering down - fast GPS
2019-10-09T20:09:57.018Z,1570651797.018 [DataOverHttps](INFO): Moved sent file to Logs/20191009T190759/Express0035.lzma.bak
2019-10-09T20:09:57.019Z,1570651797.019 [DataOverHttps](INFO): SBD MOMSN=11866156
2019-10-09T20:10:02.692Z,1570651802.692 [Default:CheckIn:Read_Iridium] Stopped
2019-10-09T20:10:02.692Z,1570651802.692 [Default:CheckIn:C.Wait] Running Loop=1
2019-10-09T20:10:02.692Z,1570651802.692 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-10-09T20:11:50.140Z,1570651910.140 [CommandLine](IMPORTANT): got command restart logs