2022-08-20T15:25:23.852Z,1661009123.852 [Supervisor](DEBUG): Initializing supervisor.
2022-08-20T15:25:23.856Z,1661009123.856 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-08-20T15:25:23.857Z,1661009123.857 [SyncHandler](INFO): Protected caller Thread ID is 1364
2022-08-20T15:25:23.857Z,1661009123.857 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-08-20T15:25:23.858Z,1661009123.858 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-08-20T15:25:23.858Z,1661009123.858 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1365
2022-08-20T15:25:23.862Z,1661009123.862 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-08-20T15:25:23.879Z,1661009123.879 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-08-20T15:25:23.880Z,1661009123.880 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-08-20T15:25:23.881Z,1661009123.881 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 1366
2022-08-20T15:25:23.885Z,1661009123.885 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-08-20T15:25:23.886Z,1661009123.886 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-08-20T15:25:23.886Z,1661009123.886 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1367
2022-08-20T15:25:23.888Z,1661009123.888 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-08-20T15:25:23.889Z,1661009123.889 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-08-20T15:25:23.890Z,1661009123.890 [logger ThreadHandler](INFO): Protected caller Thread ID is 1368
2022-08-20T15:25:23.893Z,1661009123.893 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-08-20T15:25:23.893Z,1661009123.893 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-08-20T15:25:23.895Z,1661009123.895 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-08-20T15:25:24.197Z,1661009124.197 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-08-20T15:25:24.198Z,1661009124.198 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-08-20T15:25:24.809Z,1661009124.809 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-08-20T15:25:24.810Z,1661009124.810 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-08-20T15:25:24.916Z,1661009124.916 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-08-20T15:25:24.917Z,1661009124.917 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-08-20T15:25:25.381Z,1661009125.381 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-08-20T15:25:25.382Z,1661009125.382 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-08-20T15:25:25.477Z,1661009125.477 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-08-20T15:25:25.478Z,1661009125.478 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-08-20T15:25:25.557Z,1661009125.557 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-08-20T15:25:25.915Z,1661009125.915 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-08-20T15:25:25.916Z,1661009125.916 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-08-20T15:25:26.130Z,1661009126.130 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-08-20T15:25:26.131Z,1661009126.131 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-08-20T15:25:26.265Z,1661009126.265 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-08-20T15:25:26.265Z,1661009126.265 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-08-20T15:25:26.488Z,1661009126.488 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-08-20T15:25:26.489Z,1661009126.489 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-08-20T15:25:26.963Z,1661009126.963 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-08-20T15:25:26.964Z,1661009126.964 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-08-20T15:25:27.322Z,1661009127.322 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-08-20T15:25:27.322Z,1661009127.322 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-08-20T15:25:27.454Z,1661009127.454 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-08-20T15:25:27.857Z,1661009127.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-08-20T15:25:27.858Z,1661009127.858 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-08-20T15:25:28.067Z,1661009128.067 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-08-20T15:25:28.068Z,1661009128.068 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-08-20T15:25:28.346Z,1661009128.346 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-08-20T15:25:28.348Z,1661009128.348 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2022-08-20T15:25:28.349Z,1661009128.349 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2022-08-20T15:25:28.457Z,1661009128.457 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2022-08-20T15:25:28.602Z,1661009128.602 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2022-08-20T15:25:28.687Z,1661009128.687 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2022-08-20T15:25:28.770Z,1661009128.770 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2022-08-20T15:25:28.884Z,1661009128.884 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2022-08-20T15:25:29.058Z,1661009129.058 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2022-08-20T15:25:29.317Z,1661009129.317 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-08-20T15:25:29.318Z,1661009129.318 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2022-08-20T15:25:29.445Z,1661009129.445 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2022-08-20T15:25:29.536Z,1661009129.536 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2022-08-20T15:25:29.638Z,1661009129.638 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2022-08-20T15:25:29.739Z,1661009129.739 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2022-08-20T15:25:29.748Z,1661009129.748 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-08-20T15:25:29.841Z,1661009129.841 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-08-20T15:25:29.841Z,1661009129.841 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-08-20T15:25:29.852Z,1661009129.852 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-08-20T15:25:29.852Z,1661009129.852 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-08-20T15:25:29.901Z,1661009129.901 [DepthRateCalculator] Loaded
2022-08-20T15:25:29.901Z,1661009129.901 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-08-20T15:25:29.907Z,1661009129.907 [PitchRateCalculator] Loaded
2022-08-20T15:25:29.907Z,1661009129.907 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-08-20T15:25:29.917Z,1661009129.917 [SpeedCalculator] Loaded
2022-08-20T15:25:29.917Z,1661009129.917 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-08-20T15:25:29.922Z,1661009129.922 [YawRateCalculator] Loaded
2022-08-20T15:25:29.922Z,1661009129.922 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-08-20T15:25:29.943Z,1661009129.943 [ElevatorOffsetCalculator] Loaded
2022-08-20T15:25:29.944Z,1661009129.944 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-08-20T15:25:29.944Z,1661009129.944 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-08-20T15:25:29.945Z,1661009129.945 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-08-20T15:25:29.994Z,1661009129.994 [VerticalControl](DEBUG): Construct VerticalControl.
2022-08-20T15:25:30.048Z,1661009130.048 [VerticalControl] Loaded
2022-08-20T15:25:30.049Z,1661009130.049 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-08-20T15:25:30.051Z,1661009130.051 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-08-20T15:25:30.092Z,1661009130.092 [HorizontalControl] Loaded
2022-08-20T15:25:30.092Z,1661009130.092 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-08-20T15:25:30.094Z,1661009130.094 [SpeedControl](DEBUG): Construct SpeedControl.
2022-08-20T15:25:30.097Z,1661009130.097 [SpeedControl] Loaded
2022-08-20T15:25:30.097Z,1661009130.097 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-08-20T15:25:30.100Z,1661009130.100 [LoopControl](DEBUG): Construct LoopControl.
2022-08-20T15:25:30.100Z,1661009130.100 [LoopControl] Loaded
2022-08-20T15:25:30.101Z,1661009130.101 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-08-20T15:25:30.101Z,1661009130.101 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-08-20T15:25:30.101Z,1661009130.101 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-08-20T15:25:30.210Z,1661009130.210 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-08-20T15:25:30.210Z,1661009130.210 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-08-20T15:25:30.223Z,1661009130.223 [NavChart] Loaded
2022-08-20T15:25:30.224Z,1661009130.224 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-08-20T15:25:30.229Z,1661009130.229 [UniversalFixResidualReporter] Loaded
2022-08-20T15:25:30.229Z,1661009130.229 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-08-20T15:25:30.230Z,1661009130.230 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-08-20T15:25:30.230Z,1661009130.230 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-08-20T15:25:30.374Z,1661009130.374 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-08-20T15:25:30.375Z,1661009130.375 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-08-20T15:25:30.777Z,1661009130.777 [AHRS_M2] Loaded
2022-08-20T15:25:30.777Z,1661009130.777 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-08-20T15:25:30.811Z,1661009130.811 [BackseatComponent] Loaded
2022-08-20T15:25:30.812Z,1661009130.812 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-08-20T15:25:30.813Z,1661009130.813 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408E44E0
2022-08-20T15:25:30.813Z,1661009130.813 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1450
2022-08-20T15:25:30.816Z,1661009130.816 [LcmUniversalReporter] Loaded
2022-08-20T15:25:30.816Z,1661009130.816 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-08-20T15:25:31.607Z,1661009131.607 [BPC1] Loaded
2022-08-20T15:25:31.607Z,1661009131.607 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2022-08-20T15:25:31.681Z,1661009131.681 [DataOverHttps] Loaded
2022-08-20T15:25:31.681Z,1661009131.681 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-08-20T15:25:31.682Z,1661009131.682 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409144E0
2022-08-20T15:25:31.683Z,1661009131.683 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 1451
2022-08-20T15:25:31.703Z,1661009131.703 [Depth_Keller] Loaded
2022-08-20T15:25:31.703Z,1661009131.703 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-08-20T15:25:31.708Z,1661009131.708 [DropWeight] Loaded
2022-08-20T15:25:31.708Z,1661009131.708 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2022-08-20T15:25:31.746Z,1661009131.746 [DVL_micro] Loaded
2022-08-20T15:25:31.746Z,1661009131.746 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2022-08-20T15:25:31.807Z,1661009131.807 [NAL9602] Loaded
2022-08-20T15:25:31.807Z,1661009131.807 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-08-20T15:25:31.836Z,1661009131.836 [Onboard] Loaded
2022-08-20T15:25:31.836Z,1661009131.836 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-08-20T15:25:31.837Z,1661009131.837 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409444E0
2022-08-20T15:25:31.838Z,1661009131.838 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1452
2022-08-20T15:25:31.850Z,1661009131.850 [Power24vConverter] Loaded
2022-08-20T15:25:31.850Z,1661009131.850 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-08-20T15:25:31.863Z,1661009131.863 [Radio_Surface] Loaded
2022-08-20T15:25:31.863Z,1661009131.863 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-08-20T15:25:31.864Z,1661009131.864 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409744E0
2022-08-20T15:25:31.865Z,1661009131.865 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1453
2022-08-20T15:25:31.956Z,1661009131.956 [DAT] Loaded
2022-08-20T15:25:31.956Z,1661009131.956 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-08-20T15:25:31.957Z,1661009131.957 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409A44E0
2022-08-20T15:25:31.957Z,1661009131.957 [DAT ThreadHandler](INFO): Protected caller Thread ID is 1454
2022-08-20T15:25:31.958Z,1661009131.958 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-08-20T15:25:31.958Z,1661009131.958 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-08-20T15:25:32.078Z,1661009132.078 [BuoyancyServo] Loaded
2022-08-20T15:25:32.079Z,1661009132.079 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-08-20T15:25:32.099Z,1661009132.099 [ElevatorServo] Loaded
2022-08-20T15:25:32.099Z,1661009132.099 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-08-20T15:25:32.118Z,1661009132.118 [MassServo] Loaded
2022-08-20T15:25:32.119Z,1661009132.119 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-08-20T15:25:32.137Z,1661009132.137 [RudderServo] Loaded
2022-08-20T15:25:32.137Z,1661009132.137 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-08-20T15:25:32.152Z,1661009132.152 [ThrusterHE] Loaded
2022-08-20T15:25:32.152Z,1661009132.152 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-08-20T15:25:32.153Z,1661009132.153 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-08-20T15:25:32.153Z,1661009132.153 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-08-20T15:25:32.208Z,1661009132.208 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-08-20T15:25:32.208Z,1661009132.208 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-08-20T15:25:32.234Z,1661009132.234 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-08-20T15:25:32.234Z,1661009132.234 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-08-20T15:25:32.622Z,1661009132.622 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-08-20T15:25:32.623Z,1661009132.623 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-08-20T15:25:33.047Z,1661009133.047 [CTD_Seabird] Loaded
2022-08-20T15:25:33.048Z,1661009133.048 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2022-08-20T15:25:33.049Z,1661009133.049 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B304E0
2022-08-20T15:25:33.049Z,1661009133.049 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1455
2022-08-20T15:25:33.082Z,1661009133.082 [ESPComponent] Loaded
2022-08-20T15:25:33.082Z,1661009133.082 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2022-08-20T15:25:33.102Z,1661009133.102 [PAR_Licor] Loaded
2022-08-20T15:25:33.102Z,1661009133.102 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-08-20T15:25:33.133Z,1661009133.133 [WetLabsBB2FL] Loaded
2022-08-20T15:25:33.133Z,1661009133.133 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-08-20T15:25:33.134Z,1661009133.134 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B604E0
2022-08-20T15:25:33.135Z,1661009133.135 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1456
2022-08-20T15:25:33.135Z,1661009133.135 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-08-20T15:25:33.136Z,1661009133.136 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-08-20T15:25:33.271Z,1661009133.271 [SBIT](DEBUG): Construct Startup Built In Test.
2022-08-20T15:25:33.280Z,1661009133.280 [SBIT] Loaded
2022-08-20T15:25:33.281Z,1661009133.281 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-08-20T15:25:33.285Z,1661009133.285 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-08-20T15:25:33.297Z,1661009133.297 [IBIT] Loaded
2022-08-20T15:25:33.297Z,1661009133.297 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-08-20T15:25:33.303Z,1661009133.303 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-08-20T15:25:33.408Z,1661009133.408 [CBIT] Loaded
2022-08-20T15:25:33.408Z,1661009133.408 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-08-20T15:25:33.408Z,1661009133.408 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-08-20T15:25:33.414Z,1661009133.414 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-08-20T15:25:33.417Z,1661009133.417 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-08-20T15:25:33.428Z,1661009133.428 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-08-20T15:25:33.429Z,1661009133.429 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BCE4E0
2022-08-20T15:25:33.429Z,1661009133.429 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1457
2022-08-20T15:25:33.434Z,1661009133.434 [Supervisor](INFO): Main Thread ID is 829
2022-08-20T15:25:33.434Z,1661009133.434 [Supervisor](DEBUG): Running supervisor.
2022-08-20T15:25:33.434Z,1661009133.434 [CommandExec ThreadHandler](INFO): Handler Thread ID is 1458
2022-08-20T15:25:33.435Z,1661009133.435 [CommandExec](INFO): Initializing the command executive.
2022-08-20T15:25:33.436Z,1661009133.436 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1459
2022-08-20T15:25:33.438Z,1661009133.438 [controlThread ThreadHandler](INFO): Handler Thread ID is 1460
2022-08-20T15:25:33.439Z,1661009133.439 [controlThread](DEBUG): Initializing ControlThread
2022-08-20T15:25:33.440Z,1661009133.440 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-08-20T15:25:33.440Z,1661009133.440 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-08-20T15:25:33.440Z,1661009133.440 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-08-20T15:25:33.441Z,1661009133.441 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-08-20T15:25:33.441Z,1661009133.441 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-08-20T15:25:33.442Z,1661009133.442 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-08-20T15:25:33.443Z,1661009133.443 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-08-20T15:25:33.444Z,1661009133.444 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-08-20T15:25:33.445Z,1661009133.445 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-08-20T15:25:33.446Z,1661009133.446 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-08-20T15:25:33.446Z,1661009133.446 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-08-20T15:25:33.452Z,1661009133.452 [SBIT](INFO): Initialize SBIT Component.
2022-08-20T15:25:33.453Z,1661009133.453 [SBIT](IMPORTANT): git: 2022-08-02
2022-08-20T15:25:33.453Z,1661009133.453 [SBIT](INFO): git hash: f84e5919489b70ff94ab72b61eefa777bac519a0
2022-08-20T15:25:33.453Z,1661009133.453 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-08-20T15:25:33.454Z,1661009133.454 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Tue Sep 24 11:12:27 PDT 2019
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2022-08-20T15:25:33.455Z,1661009133.455 [SBIT](INFO): Beginning SBIT in 79.000000 seconds.
2022-08-20T15:25:33.456Z,1661009133.456 [IBIT](INFO): Initialize IBIT Component.
2022-08-20T15:25:33.457Z,1661009133.457 [CBIT](DEBUG): Initialize CBIT Component.
2022-08-20T15:25:33.458Z,1661009133.458 [logger ThreadHandler](INFO): Handler Thread ID is 1461
2022-08-20T15:25:33.468Z,1661009133.468 [CBIT](DEBUG): Initialized mux pins.
2022-08-20T15:25:33.468Z,1661009133.468 [CBIT](DEBUG): Initializing the watchdog timer.
2022-08-20T15:25:33.477Z,1661009133.477 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1462
2022-08-20T15:25:33.489Z,1661009133.489 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 1463
2022-08-20T15:25:33.490Z,1661009133.490 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-08-20T15:25:33.492Z,1661009133.492 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-08-20T15:25:33.493Z,1661009133.493 [CBIT](DEBUG): Initializing heartbeat.
2022-08-20T15:25:33.501Z,1661009133.501 [Onboard ThreadHandler](INFO): Handler Thread ID is 1464
2022-08-20T15:25:33.518Z,1661009133.518 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1465
2022-08-20T15:25:33.537Z,1661009133.537 [DAT ThreadHandler](INFO): Handler Thread ID is 1466
2022-08-20T15:25:33.538Z,1661009133.538 [DAT](INFO): Powering up
2022-08-20T15:25:33.538Z,1661009133.538 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:25:33.541Z,1661009133.541 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1468
2022-08-20T15:25:33.542Z,1661009133.542 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2022-08-20T15:25:33.545Z,1661009133.545 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1470
2022-08-20T15:25:33.549Z,1661009133.549 [WetLabsBB2FL](INFO): Powering up
2022-08-20T15:25:33.550Z,1661009133.550 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1472
2022-08-20T15:25:33.553Z,1661009133.553 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2MI01M.000
2022-08-20T15:25:33.553Z,1661009133.553 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2MI01M.000
2022-08-20T15:25:33.553Z,1661009133.553 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2MI80M.000
2022-08-20T15:25:33.553Z,1661009133.553 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2MI80M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4MI57M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4MI57M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4MI56M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4MI56M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4MI90M.000
2022-08-20T15:25:33.554Z,1661009133.554 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4MI90M.000
2022-08-20T15:25:33.555Z,1661009133.555 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4MI89M.000
2022-08-20T15:25:33.555Z,1661009133.555 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4MI89M.000
2022-08-20T15:25:33.564Z,1661009133.564 [CBIT](DEBUG): Deactivating GF circuits.
2022-08-20T15:25:33.564Z,1661009133.564 [CBIT](DEBUG): Deactivating emergency mode.
2022-08-20T15:25:33.600Z,1661009133.600 [CBIT](DEBUG): Backplane powered.
2022-08-20T15:25:33.601Z,1661009133.601 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2022-08-20T15:25:33.613Z,1661009133.613 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-08-20T15:25:33.641Z,1661009133.641 [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>


2022-08-20T15:25:33.642Z,1661009133.642 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-08-20T15:25:33.718Z,1661009133.718 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-08-20T15:25:33.719Z,1661009133.719 [Default:A.Wait](DEBUG): Construct Wait.
2022-08-20T15:25:33.738Z,1661009133.738 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-08-20T15:25:33.758Z,1661009133.758 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-08-20T15:25:33.785Z,1661009133.785 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-08-20T15:25:33.807Z,1661009133.807 [Default:E.Execute](DEBUG): Construct Execute.
2022-08-20T15:25:33.810Z,1661009133.810 [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>


2022-08-20T15:25:33.814Z,1661009133.814 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2022-08-20T15:25:33.837Z,1661009133.837 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-08-20T15:25:33.917Z,1661009133.917 [Power24vConverter](INFO): Powering up.
2022-08-20T15:25:33.924Z,1661009133.924 [Radio_Surface](INFO): Powering up
2022-08-20T15:25:33.964Z,1661009133.964 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:25:33.972Z,1661009133.972 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-08-20T15:25:33.973Z,1661009133.973 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:25:33.980Z,1661009133.980 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-08-20T15:25:33.981Z,1661009133.981 [MassServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:25:33.988Z,1661009133.988 [MassServo](DEBUG): Initializing MassServo.
2022-08-20T15:25:33.989Z,1661009133.989 [RudderServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:25:33.996Z,1661009133.996 [RudderServo](DEBUG): Initializing RudderServo.
2022-08-20T15:25:33.997Z,1661009133.997 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-08-20T15:25:34.004Z,1661009134.004 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-08-20T15:25:36.160Z,1661009136.160 [WetLabsBB2FL](INFO): Powering down
2022-08-20T15:25:39.606Z,1661009139.606 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-08-20T15:26:00.220Z,1661009160.220 [MassServo](ERROR): getPosition uart error serial timeout
2022-08-20T15:26:00.221Z,1661009160.221 [MassServo](FAULT): Invalid EZ Servo response:"\r"
2022-08-20T15:26:00.221Z,1661009160.221 [MassServo] Communications Fault, FailCount= 1
2022-08-20T15:26:00.221Z,1661009160.221 [MassServo](ERROR): Communications Fault
2022-08-20T15:26:00.241Z,1661009160.241 [CBIT](ERROR): Communications Fault in component: MassServo
2022-08-20T15:26:00.523Z,1661009160.523 [MassServo](DEBUG): Uninitialize Mass Servo.
2022-08-20T15:26:00.523Z,1661009160.523 [MassServo](INFO): Powering down
2022-08-20T15:26:01.386Z,1661009161.386 [MassServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:26:01.505Z,1661009161.505 [MassServo](DEBUG): Initializing MassServo.
2022-08-20T15:26:01.510Z,1661009161.510 [CBIT](INFO): Clearing failed state for component MassServo
2022-08-20T15:26:01.510Z,1661009161.510 [MassServo] No Fault, FailCount= 1
2022-08-20T15:26:02.106Z,1661009162.106 [NAL9602](INFO): Powering up NAL9602
2022-08-20T15:26:05.893Z,1661009165.893 [MassServo](ERROR): getPosition uart error serial timeout
2022-08-20T15:26:05.894Z,1661009165.894 [MassServo](FAULT): Invalid EZ Servo response:"\n"
2022-08-20T15:26:05.894Z,1661009165.894 [MassServo] Communications Fault, FailCount= 2
2022-08-20T15:26:05.894Z,1661009165.894 [MassServo](ERROR): Communications Fault
2022-08-20T15:26:05.898Z,1661009165.898 [CBIT](ERROR): Communications Fault in component: MassServo
2022-08-20T15:26:06.169Z,1661009166.169 [MassServo](DEBUG): Uninitialize Mass Servo.
2022-08-20T15:26:06.169Z,1661009166.169 [MassServo](INFO): Powering down
2022-08-20T15:26:06.970Z,1661009166.970 [MassServo](DEBUG): Initializing EZServoServo.
2022-08-20T15:26:07.086Z,1661009167.086 [MassServo](DEBUG): Initializing MassServo.
2022-08-20T15:26:07.090Z,1661009167.090 [CBIT](INFO): Clearing failed state for component MassServo
2022-08-20T15:26:07.090Z,1661009167.090 [MassServo] No Fault, FailCount= 2
2022-08-20T15:26:13.019Z,1661009173.019 [NAL9602](INFO): NAL9602 initialized
2022-08-20T15:26:33.784Z,1661009193.784 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:26:33.785Z,1661009193.785 [DAT] Communications Fault, FailCount= 1
2022-08-20T15:26:33.785Z,1661009193.785 [DAT](ERROR): Communications Fault
2022-08-20T15:26:34.071Z,1661009194.071 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:26:34.188Z,1661009194.188 [DAT](INFO): Powering down
2022-08-20T15:26:35.270Z,1661009195.270 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:26:35.270Z,1661009195.270 [DAT] No Fault, FailCount= 1
2022-08-20T15:26:37.236Z,1661009197.236 [DAT](INFO): Powering up
2022-08-20T15:26:37.236Z,1661009197.236 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:26:53.027Z,1661009213.027 [SBIT](IMPORTANT): Beginning Startup BIT
2022-08-20T15:26:53.031Z,1661009213.031 [CBIT](IMPORTANT): Beginning ground fault scan
2022-08-20T15:27:03.993Z,1661009223.993 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004956
CHAN A1 (24V): -0.002544
CHAN A2 (12V): -0.000743
CHAN A3 (5V): -0.000537
CHAN B0 (3.3V): 0.000243
CHAN B1 (3.15aV): 0.000069
CHAN B2 (3.15bV): 0.000132
CHAN B3 (GND): 0.000729
OPEN: 0.004568
Full Scale: +/- 1 mA
2022-08-20T15:27:37.253Z,1661009257.253 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:27:37.253Z,1661009257.253 [DAT] Communications Fault, FailCount= 2
2022-08-20T15:27:37.253Z,1661009257.253 [DAT](ERROR): Communications Fault
2022-08-20T15:27:37.581Z,1661009257.581 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:27:37.656Z,1661009257.656 [DAT](INFO): Powering down
2022-08-20T15:27:38.556Z,1661009258.556 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:27:38.556Z,1661009258.556 [DAT] No Fault, FailCount= 2
2022-08-20T15:27:40.704Z,1661009260.704 [DAT](INFO): Powering up
2022-08-20T15:27:40.705Z,1661009260.705 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:27:47.174Z,1661009267.174 [SBIT](IMPORTANT): SBIT PASSED
2022-08-20T15:27:47.174Z,1661009267.174 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=10 count;

2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): CTD_Seabird.minSalinityBound=0 practical_salinity_unit;

2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): Depth_Keller.offset=3.9 decibar;

2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2022-08-20T15:27:47.175Z,1661009267.175 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=400 cubic_centimeter;

2022-08-20T15:27:47.176Z,1661009267.176 [SBIT](IMPORTANT): VerticalControl.massDefault=-15 millimeter;

2022-08-20T15:27:47.176Z,1661009267.176 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-28 millimeter;

2022-08-20T15:27:47.176Z,1661009267.176 [SBIT](IMPORTANT): VerticalControl.massPositionLimitFwd=32 millimeter;

2022-08-20T15:27:47.176Z,1661009267.176 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=1.5 meter;

2022-08-20T15:27:47.580Z,1661009267.580 [MissionManager](IMPORTANT): Started mission Startup
2022-08-20T15:27:47.581Z,1661009267.581 [Startup] Running Loop=1
2022-08-20T15:27:47.581Z,1661009267.581 [Startup](DEBUG): Aggregate::initialize Startup
2022-08-20T15:27:47.581Z,1661009267.581 [Startup:A.GoToSurface] Running Loop=1
2022-08-20T15:27:47.581Z,1661009267.581 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-08-20T15:27:47.582Z,1661009267.582 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-08-20T15:27:47.582Z,1661009267.582 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-08-20T15:27:47.582Z,1661009267.582 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-08-20T15:27:47.583Z,1661009267.583 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-08-20T15:27:47.583Z,1661009267.583 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-08-20T15:27:47.585Z,1661009267.585 [Startup:StartupSatComms] Running Loop=1
2022-08-20T15:27:47.585Z,1661009267.585 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2022-08-20T15:27:47.585Z,1661009267.585 [Startup:StartupSatComms:A] Running Loop=1
2022-08-20T15:27:47.967Z,1661009267.967 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2022-08-20T15:28:33.628Z,1661009313.628 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2022-08-20T15:28:33.628Z,1661009313.628 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-08-20T15:28:33.647Z,1661009313.647 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-08-20T15:28:34.165Z,1661009314.165 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-08-20T15:28:34.165Z,1661009314.165 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2022-08-20T15:28:36.614Z,1661009316.614 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004369
2022-08-20T15:28:40.728Z,1661009320.728 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:28:40.729Z,1661009320.729 [DAT] Communications Fault, FailCount= 3
2022-08-20T15:28:40.729Z,1661009320.729 [DAT](ERROR): Communications Fault
2022-08-20T15:28:40.922Z,1661009320.922 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:28:41.132Z,1661009321.132 [DAT](INFO): Powering down
2022-08-20T15:28:42.122Z,1661009322.122 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:28:42.122Z,1661009322.122 [DAT] No Fault, FailCount= 3
2022-08-20T15:28:44.181Z,1661009324.181 [DAT](INFO): Powering up
2022-08-20T15:28:44.182Z,1661009324.182 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:28:47.758Z,1661009327.758 [Startup:StartupSatComms:A](INFO): Timed out from 2022-08-20T15:27:47.6Z
2022-08-20T15:28:47.758Z,1661009327.758 [Startup:StartupSatComms:A] Stopped
2022-08-20T15:28:47.758Z,1661009327.758 [Startup:StartupSatComms:B] Running Loop=1
2022-08-20T15:28:48.162Z,1661009328.162 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-08-20T15:28:56.284Z,1661009336.284 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220820T151700/Courier0007.lzma
2022-08-20T15:28:57.286Z,1661009337.286 [DataOverHttps](INFO): Moved sent file to Logs/20220820T151700/Courier0007.lzma.bak
2022-08-20T15:28:57.286Z,1661009337.286 [DataOverHttps](INFO): SBD MOMSN=17117951
2022-08-20T15:29:14.168Z,1661009354.168 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20220820T152523/Courier0000.lzma
2022-08-20T15:29:15.170Z,1661009355.170 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0000.lzma.bak
2022-08-20T15:29:15.170Z,1661009355.170 [DataOverHttps](INFO): SBD MOMSN=17117953
2022-08-20T15:29:33.448Z,1661009373.448 [DataOverHttps](INFO): Sending 382 bytes from file Logs/20220820T151700/Express0008.lzma
2022-08-20T15:29:34.450Z,1661009374.450 [DataOverHttps](INFO): Moved sent file to Logs/20220820T151700/Express0008.lzma.bak
2022-08-20T15:29:34.450Z,1661009374.450 [DataOverHttps](INFO): SBD MOMSN=17117956
2022-08-20T15:29:44.193Z,1661009384.193 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:29:44.193Z,1661009384.193 [DAT] Communications Fault, FailCount= 4
2022-08-20T15:29:44.193Z,1661009384.193 [DAT](ERROR): Communications Fault
2022-08-20T15:29:44.373Z,1661009384.373 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:29:44.596Z,1661009384.596 [DAT](INFO): Powering down
2022-08-20T15:29:45.542Z,1661009385.542 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:29:45.542Z,1661009385.542 [DAT] No Fault, FailCount= 4
2022-08-20T15:29:47.644Z,1661009387.644 [DAT](INFO): Powering up
2022-08-20T15:29:47.645Z,1661009387.645 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:29:47.951Z,1661009387.951 [NAL9602](INFO): SBD MO Status=2, MOMSN=12882, MT Status=2, MTMSN=0
2022-08-20T15:29:47.951Z,1661009387.951 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T15:29:47.966Z,1661009387.966 [Startup:StartupSatComms:B](INFO): Timed out from 2022-08-20T15:28:47.8Z
2022-08-20T15:29:47.966Z,1661009387.966 [Startup:StartupSatComms:B] Stopped
2022-08-20T15:29:47.967Z,1661009387.967 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2022-08-20T15:29:47.967Z,1661009387.967 [Startup:StartupSatComms] Stopped
2022-08-20T15:29:47.967Z,1661009387.967 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2022-08-20T15:29:47.967Z,1661009387.967 [Startup](INFO): Completed Startup
2022-08-20T15:29:47.968Z,1661009387.968 [MissionManager](INFO): Startup is completed.
2022-08-20T15:29:47.968Z,1661009387.968 [MissionManager](INFO): Uninitializing Mission Startup
2022-08-20T15:29:47.968Z,1661009387.968 [Startup] Stopped
2022-08-20T15:29:47.968Z,1661009387.968 [Startup](DEBUG): Aggregate::uninitialize Startup
2022-08-20T15:29:47.968Z,1661009387.968 [Startup:A.GoToSurface] Stopped
2022-08-20T15:29:47.968Z,1661009387.968 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-08-20T15:29:48.378Z,1661009388.378 [MissionManager](IMPORTANT): Started mission Default
2022-08-20T15:29:48.378Z,1661009388.378 [Default] Running Loop=1
2022-08-20T15:29:48.378Z,1661009388.378 [Default](DEBUG): Aggregate::initialize Default
2022-08-20T15:29:48.379Z,1661009388.379 [Default:B.GoToSurface] Running Loop=1
2022-08-20T15:29:48.379Z,1661009388.379 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-08-20T15:29:48.379Z,1661009388.379 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-08-20T15:29:48.379Z,1661009388.379 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-08-20T15:29:48.380Z,1661009388.380 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-08-20T15:29:48.381Z,1661009388.381 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-08-20T15:29:48.381Z,1661009388.381 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-08-20T15:29:48.382Z,1661009388.382 [Default:A.Wait] Running Loop=1
2022-08-20T15:29:48.382Z,1661009388.382 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-08-20T15:29:54.673Z,1661009394.673 [DataOverHttps](INFO): Sending 1003 bytes from file Logs/20220820T152523/Express0001.lzma
2022-08-20T15:29:55.686Z,1661009395.686 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0001.lzma.bak
2022-08-20T15:29:55.686Z,1661009395.686 [DataOverHttps](INFO): SBD MOMSN=17117968
2022-08-20T15:30:01.691Z,1661009401.691 [Default:A.Wait](INFO): Done Waiting.
2022-08-20T15:30:01.691Z,1661009401.691 [Default:A.Wait] Stopped
2022-08-20T15:30:01.691Z,1661009401.691 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T15:30:02.094Z,1661009402.094 [Default:CheckIn] Running Loop=1
2022-08-20T15:30:02.094Z,1661009402.094 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T15:30:02.094Z,1661009402.094 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T15:30:02.500Z,1661009402.500 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-08-20T15:30:18.256Z,1661009418.256 [NAL9602](INFO): SBD MO Status=2, MOMSN=12882, MT Status=2, MTMSN=0
2022-08-20T15:30:18.256Z,1661009418.256 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T15:30:33.745Z,1661009433.745 [CommandExec](IMPORTANT): got command get platform_pitch_angle degree
2022-08-20T15:30:33.746Z,1661009433.746 [CommandExec](IMPORTANT): platform_pitch_angle -1.550433 arcdeg
2022-08-20T15:30:42.155Z,1661009442.155 [CommandExec](IMPORTANT): got command show best platform_pitch_angle
2022-08-20T15:30:42.155Z,1661009442.155 [CommandExec](IMPORTANT): platform_pitch_angle best is AHRS_M2.platform_pitch_angle
2022-08-20T15:30:47.696Z,1661009447.696 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:30:47.697Z,1661009447.697 [DAT] Communications Fault, FailCount= 5
2022-08-20T15:30:47.697Z,1661009447.697 [DAT](ERROR): Communications Fault
2022-08-20T15:30:47.803Z,1661009447.803 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:30:48.100Z,1661009448.100 [DAT](INFO): Powering down
2022-08-20T15:30:48.998Z,1661009448.998 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:30:48.998Z,1661009448.998 [DAT] No Fault, FailCount= 5
2022-08-20T15:30:51.144Z,1661009451.144 [DAT](INFO): Powering up
2022-08-20T15:30:51.144Z,1661009451.144 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:31:00.069Z,1661009460.069 [CommandExec](IMPORTANT): got command failComponent
2022-08-20T15:31:00.069Z,1661009460.069 [CommandExec](IMPORTANT): Failed components:
2022-08-20T15:31:00.069Z,1661009460.069 [CommandExec](IMPORTANT): No failed Components.
2022-08-20T15:31:16.454Z,1661009476.454 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T15:31:17.668Z,1661009477.668 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153117.00,A,4313.60954,N,08620.33515,W,1.225,180.22,200822,,,A*7D
2022-08-20T15:31:17.671Z,1661009477.671 [NAL9602](INFO): GPS fix at 20220820T153117: (43.226826, -86.338919)
2022-08-20T15:31:17.703Z,1661009477.703 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T15:31:17.703Z,1661009477.703 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T15:31:18.133Z,1661009478.133 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-08-20T15:31:29.304Z,1661009489.304 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20220820T152523/Courier0004.lzma
2022-08-20T15:31:30.306Z,1661009490.306 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0004.lzma.bak
2022-08-20T15:31:30.306Z,1661009490.306 [DataOverHttps](INFO): SBD MOMSN=17117994
2022-08-20T15:31:50.442Z,1661009510.442 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T15:31:50.853Z,1661009510.853 [DataOverHttps](INFO): Sending 529 bytes from file Logs/20220820T152523/Express0005.lzma
2022-08-20T15:31:51.157Z,1661009511.157 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:31:51.157Z,1661009511.157 [DAT] Communications Fault, FailCount= 6
2022-08-20T15:31:51.157Z,1661009511.157 [DAT](ERROR): Communications Fault
2022-08-20T15:31:51.268Z,1661009511.268 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:31:51.560Z,1661009511.560 [DAT](INFO): Powering down
2022-08-20T15:31:51.854Z,1661009511.854 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0005.lzma.bak
2022-08-20T15:31:51.854Z,1661009511.854 [DataOverHttps](INFO): SBD MOMSN=17117997
2022-08-20T15:31:52.477Z,1661009512.477 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:31:52.477Z,1661009512.477 [DAT] No Fault, FailCount= 6
2022-08-20T15:31:54.616Z,1661009514.616 [DAT](INFO): Powering up
2022-08-20T15:31:54.617Z,1661009514.617 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:31:55.719Z,1661009515.719 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T15:31:55.719Z,1661009515.719 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T15:31:55.719Z,1661009515.719 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T15:32:54.677Z,1661009574.677 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:32:54.677Z,1661009574.677 [DAT] Communications Fault, FailCount= 7
2022-08-20T15:32:54.677Z,1661009574.677 [DAT](ERROR): Communications Fault
2022-08-20T15:32:54.742Z,1661009574.742 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:32:55.080Z,1661009575.080 [DAT](INFO): Powering down
2022-08-20T15:32:55.980Z,1661009575.980 [CBIT](INFO): Clearing failed state for component DAT
2022-08-20T15:32:55.980Z,1661009575.980 [DAT] No Fault, FailCount= 7
2022-08-20T15:32:58.136Z,1661009578.136 [DAT](INFO): Powering up
2022-08-20T15:32:58.136Z,1661009578.136 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:33:56.916Z,1661009636.916 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:33:58.172Z,1661009638.172 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2022-08-20T15:33:58.173Z,1661009638.173 [DAT] Communications Fault, FailCount= 8
2022-08-20T15:33:58.173Z,1661009638.173 [DAT](ERROR): Communications Fault
2022-08-20T15:33:58.206Z,1661009638.206 [CBIT](ERROR): Communications Fault in component: DAT
2022-08-20T15:33:58.206Z,1661009638.206 [CBIT](FAULT): Communications Fault in component: DAT
2022-08-20T15:33:58.576Z,1661009638.576 [DAT](INFO): Powering down
2022-08-20T15:34:02.580Z,1661009642.580 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:34:21.154Z,1661009661.154 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:34:38.597Z,1661009678.597 [CommandExec](IMPORTANT): got command failComponent
2022-08-20T15:34:38.597Z,1661009678.597 [CommandExec](IMPORTANT): Failed components:
2022-08-20T15:34:38.597Z,1661009678.597 [CommandExec](IMPORTANT): DAT: Communications Fault
2022-08-20T15:34:39.738Z,1661009679.738 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:34:45.696Z,1661009685.696 [CommandExec](IMPORTANT): got command failComponent none DAT
2022-08-20T15:34:45.696Z,1661009685.696 [DAT] No Fault, FailCount= 8
2022-08-20T15:34:45.697Z,1661009685.697 [CommandExec](IMPORTANT): DAT failureMode is No Fault
2022-08-20T15:34:45.924Z,1661009685.924 [DAT](INFO): Powering up
2022-08-20T15:34:45.924Z,1661009685.924 [DAT](DEBUG): Initializing DAT.
2022-08-20T15:34:49.039Z,1661009689.039 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T15:34:49.039Z,1661009689.039 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.999,+9999.99
2022-08-20T15:34:54.364Z,1661009694.364 [DVL_micro](ERROR): DVL uart error: serial timeout
2022-08-20T15:34:54.364Z,1661009694.364 [DVL_micro] Communications Fault, FailCount= 1
2022-08-20T15:34:54.364Z,1661009694.364 [DVL_micro](ERROR): Communications Fault
2022-08-20T15:34:54.365Z,1661009694.365 [DVL_micro](ERROR): Failed to parse:
2022-08-20T15:34:54.437Z,1661009694.437 [CBIT](ERROR): Communications Fault in component: DVL_micro
2022-08-20T15:34:54.764Z,1661009694.764 [DVL_micro](INFO): Powering down
2022-08-20T15:34:55.520Z,1661009695.520 [CBIT](INFO): Clearing failed state for component DVL_micro
2022-08-20T15:34:55.520Z,1661009695.520 [DVL_micro] No Fault, FailCount= 1
2022-08-20T15:34:58.322Z,1661009698.322 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:35:00.295Z,1661009700.295 [DAT](INFO): commRate: 800
2022-08-20T15:35:02.360Z,1661009702.360 [DAT](INFO): entering command mode
2022-08-20T15:35:02.561Z,1661009702.561 [DAT](INFO): setting verbose to 3
2022-08-20T15:35:02.814Z,1661009702.814 [DAT](INFO): set verbose to 3
2022-08-20T15:35:02.814Z,1661009702.814 [DAT](INFO): setting DatVerbose to 27440
2022-08-20T15:35:03.066Z,1661009703.066 [DAT](INFO): set DatVerbose to 27440
2022-08-20T15:35:03.066Z,1661009703.066 [DAT](INFO): setting transmit power to 8
2022-08-20T15:35:03.318Z,1661009703.318 [DAT](INFO): set transmit power to 8
2022-08-20T15:35:03.318Z,1661009703.318 [DAT](INFO): setting local address to 8
2022-08-20T15:35:03.570Z,1661009703.570 [DAT](INFO): set local address to 8
2022-08-20T15:35:03.571Z,1661009703.571 [DAT](INFO): Setting time to: 15:35:3 And date to:8/20/2022
2022-08-20T15:35:03.822Z,1661009703.822 [DAT](INFO): Local DAT time set to Sat Aug 20, 2022  15:35:03  

2022-08-20T15:35:07.485Z,1661009707.485 [CommandExec](IMPORTANT): got command failComponent
2022-08-20T15:35:07.485Z,1661009707.485 [CommandExec](IMPORTANT): Failed components:
2022-08-20T15:35:07.485Z,1661009707.485 [CommandExec](IMPORTANT): No failed Components.
2022-08-20T15:35:10.401Z,1661009710.401 [CommandExec](IMPORTANT): got command ibit
2022-08-20T15:35:10.480Z,1661009710.480 [IBIT](IMPORTANT): Beginning Initiated BIT
2022-08-20T15:35:10.480Z,1661009710.480 [IBIT](IMPORTANT): Beginning control surface checks.
2022-08-20T15:35:10.495Z,1661009710.495 [CBIT](IMPORTANT): Beginning ground fault scan
2022-08-20T15:35:12.063Z,1661009712.063 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,153511.00,A,4313.63394,N,08620.33488,W,0.467,176.98,200822,,,A*76
2022-08-20T15:35:12.066Z,1661009712.066 [NAL9602](INFO): GPS fix at 20220820T153511: (43.227232, -86.338915)
2022-08-20T15:35:16.916Z,1661009716.916 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:35:21.383Z,1661009721.383 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004585
CHAN A1 (24V): -0.002530
CHAN A2 (12V): -0.000467
CHAN A3 (5V): 0.000331
CHAN B0 (3.3V): 0.001649
CHAN B1 (3.15aV): 0.000537
CHAN B2 (3.15bV): 0.000515
CHAN B3 (GND): 0.001114
OPEN: 0.004794
Full Scale: +/- 1 mA
2022-08-20T15:35:29.186Z,1661009729.186 [CommandExec](IMPORTANT): got command get platform_orientation degree
2022-08-20T15:35:29.187Z,1661009729.187 [CommandExec](IMPORTANT): platform_orientation 143.842855 arcdeg
2022-08-20T15:35:35.498Z,1661009735.498 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:35:42.778Z,1661009742.778 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-08-20T15:35:42.852Z,1661009742.852 [NAL9602](ERROR): received: 
+CSQ:0

OK882, 2, 0, 0, 0

OK
2022-08-20T15:35:54.082Z,1661009754.082 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:36:12.679Z,1661009772.679 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:36:18.762Z,1661009778.762 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T15:36:18.762Z,1661009778.762 [DVL_micro](ERROR): Failed to parse:
:BI,+0045,-00127,+00000,I
2022-08-20T15:37:01.689Z,1661009821.689 [IBIT](FAULT): Error acquiring IBIT communications status. Timeout expired.
2022-08-20T15:37:02.038Z,1661009822.038 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2022-08-20T15:37:02.454Z,1661009822.454 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2022-08-20T15:37:02.454Z,1661009822.454 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2022-08-20T15:37:02.455Z,1661009822.455 [IBIT](IMPORTANT): Pressure:8.012242 PSI
2022-08-20T15:37:02.455Z,1661009822.455 [IBIT](IMPORTANT): Humidity:18.465389 %
2022-08-20T15:37:02.846Z,1661009822.846 [IBIT](IMPORTANT): Vehicle Pitch:-1.589514 degrees
2022-08-20T15:37:02.846Z,1661009822.846 [IBIT](IMPORTANT): Vehicle  Roll:0.422699 degrees
2022-08-20T15:37:02.846Z,1661009822.846 [IBIT](IMPORTANT): Vehicle  Heading:143.843414 degrees
2022-08-20T15:37:03.253Z,1661009823.253 [IBIT](IMPORTANT): surfaceThreshold: 1.500000 m
2022-08-20T15:37:03.253Z,1661009823.253 [IBIT](IMPORTANT): buoyancyNeutral: 400.000000 cc
2022-08-20T15:37:03.253Z,1661009823.253 [IBIT](IMPORTANT): massDefault: -1.500000 cm
2022-08-20T15:37:03.254Z,1661009823.254 [IBIT](IMPORTANT): stopDepth: 265.000000 m
2022-08-20T15:37:03.254Z,1661009823.254 [IBIT](IMPORTANT): abortDepth: 300.000000 m
2022-08-20T15:37:03.254Z,1661009823.254 [IBIT](IMPORTANT): IBIT FAILED
2022-08-20T15:37:03.669Z,1661009823.669 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T15:37:03.670Z,1661009823.670 [Default:CheckIn:C.Wait] Stopped
2022-08-20T15:37:03.670Z,1661009823.670 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T15:37:03.670Z,1661009823.670 [Default:CheckIn:D] Running Loop=1
2022-08-20T15:37:04.086Z,1661009824.086 [Default:CheckIn:D] Stopped
2022-08-20T15:37:04.086Z,1661009824.086 [Default:CheckIn:E] Running Loop=1
2022-08-20T15:37:04.483Z,1661009824.483 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.261798 min 
2022-08-20T15:37:04.483Z,1661009824.483 [Default:CheckIn:E] Stopped
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn] Stopped
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn](INFO): Running loop #2
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn] Running Loop=2
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T15:37:04.484Z,1661009824.484 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T15:38:44.302Z,1661009924.302 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,,+9999.99,+9999.99
2022-08-20T15:39:21.886Z,1661009961.886 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T15:39:21.887Z,1661009961.887 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2022-08-20T15:39:52.975Z,1661009992.975 [NAL9602](INFO): SBD MO Status=2, MOMSN=12882, MT Status=2, MTMSN=0
2022-08-20T15:39:52.975Z,1661009992.975 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T15:40:14.390Z,1661010014.390 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T15:40:18.846Z,1661010018.846 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154018.00,A,4313.62074,N,08620.33532,W,0.000,168.21,200822,,,A*79
2022-08-20T15:40:18.848Z,1661010018.848 [NAL9602](INFO): GPS fix at 20220820T154018: (43.227012, -86.338922)
2022-08-20T15:40:18.859Z,1661010018.859 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T15:40:18.859Z,1661010018.859 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T15:40:31.683Z,1661010031.683 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220820T152523/Courier0007.lzma
2022-08-20T15:40:32.686Z,1661010032.686 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0007.lzma.bak
2022-08-20T15:40:32.686Z,1661010032.686 [DataOverHttps](INFO): SBD MOMSN=17118049
2022-08-20T15:40:51.266Z,1661010051.266 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T15:40:53.369Z,1661010053.369 [DataOverHttps](INFO): Sending 1001 bytes from file Logs/20220820T152523/Express0008.lzma
2022-08-20T15:40:54.370Z,1661010054.370 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0008.lzma.bak
2022-08-20T15:40:54.370Z,1661010054.370 [DataOverHttps](INFO): SBD MOMSN=17118053
2022-08-20T15:40:58.157Z,1661010058.157 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T15:40:58.157Z,1661010058.157 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T15:40:58.157Z,1661010058.157 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T15:43:44.231Z,1661010224.231 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:44:02.814Z,1661010242.814 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:44:21.460Z,1661010261.460 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:44:40.047Z,1661010280.047 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:44:58.631Z,1661010298.631 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:45:11.569Z,1661010311.569 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2022-08-20T15:45:16.597Z,1661010316.597 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.655663
2022-08-20T15:45:17.216Z,1661010317.216 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:45:35.798Z,1661010335.798 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:45:54.385Z,1661010354.385 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:45:58.886Z,1661010358.886 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T15:45:58.886Z,1661010358.886 [Default:CheckIn:C.Wait] Stopped
2022-08-20T15:45:58.886Z,1661010358.886 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T15:45:58.886Z,1661010358.886 [Default:CheckIn:D] Running Loop=1
2022-08-20T15:45:59.262Z,1661010359.262 [Default:CheckIn:D] Stopped
2022-08-20T15:45:59.262Z,1661010359.262 [Default:CheckIn:E] Running Loop=1
2022-08-20T15:45:59.668Z,1661010359.668 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.181386 min 
2022-08-20T15:45:59.672Z,1661010359.672 [Default:CheckIn:E] Stopped
2022-08-20T15:45:59.672Z,1661010359.672 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T15:45:59.672Z,1661010359.672 [Default:CheckIn] Stopped
2022-08-20T15:45:59.672Z,1661010359.672 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T15:45:59.672Z,1661010359.672 [Default:CheckIn](INFO): Running loop #3
2022-08-20T15:45:59.673Z,1661010359.673 [Default:CheckIn] Running Loop=3
2022-08-20T15:45:59.673Z,1661010359.673 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T15:45:59.673Z,1661010359.673 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T15:46:01.659Z,1661010361.659 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,154601.00,A,4313.63115,N,08620.32937,W,0.058,168.21,200822,,,A*75
2022-08-20T15:46:01.670Z,1661010361.670 [NAL9602](INFO): GPS fix at 20220820T154601: (43.227186, -86.338823)
2022-08-20T15:46:01.681Z,1661010361.681 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T15:46:01.681Z,1661010361.681 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T15:46:02.216Z,1661010362.216 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002860
2022-08-20T15:46:15.524Z,1661010375.524 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0010.lzma
2022-08-20T15:46:16.526Z,1661010376.526 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0010.lzma.bak
2022-08-20T15:46:16.526Z,1661010376.526 [DataOverHttps](INFO): SBD MOMSN=17118098
2022-08-20T15:46:32.219Z,1661010392.219 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-08-20T15:46:32.292Z,1661010392.292 [NAL9602](ERROR): received: 
+CSQ:0

OK882, 2, 0, 0, 0

OK
2022-08-20T15:46:43.472Z,1661010403.472 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220820T152523/Express0011.lzma
2022-08-20T15:46:44.474Z,1661010404.474 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0011.lzma.bak
2022-08-20T15:46:44.474Z,1661010404.474 [DataOverHttps](INFO): SBD MOMSN=17118101
2022-08-20T15:46:48.402Z,1661010408.402 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T15:46:48.402Z,1661010408.402 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T15:46:48.402Z,1661010408.402 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T15:47:18.549Z,1661010438.549 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2022-08-20T15:47:44.653Z,1661010464.653 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.179836
2022-08-20T15:48:02.128Z,1661010482.128 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002856
2022-08-20T15:48:02.299Z,1661010482.299 [NAL9602](INFO): SBD MO Status=0, MOMSN=12882, MT Status=0, MTMSN=0
2022-08-20T15:48:02.299Z,1661010482.299 [NAL9602](INFO): No messages in MT queue
2022-08-20T15:48:33.025Z,1661010513.025 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T15:49:45.038Z,1661010585.038 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2022-08-20T15:49:52.617Z,1661010592.617 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T15:49:52.617Z,1661010592.617 [DVL_micro](ERROR): Failed to parse:
:TS,000000035.0,+27.1,0000.0,1489.0,000
2022-08-20T15:51:49.031Z,1661010709.031 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T15:51:49.031Z,1661010709.031 [Default:CheckIn:C.Wait] Stopped
2022-08-20T15:51:49.031Z,1661010709.031 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T15:51:49.031Z,1661010709.031 [Default:CheckIn:D] Running Loop=1
2022-08-20T15:51:49.437Z,1661010709.437 [Default:CheckIn:D] Stopped
2022-08-20T15:51:49.437Z,1661010709.437 [Default:CheckIn:E] Running Loop=1
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.017641 min 
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn:E] Stopped
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn] Stopped
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T15:51:49.857Z,1661010709.857 [Default:CheckIn](INFO): Running loop #4
2022-08-20T15:51:49.858Z,1661010709.858 [Default:CheckIn] Running Loop=4
2022-08-20T15:51:49.858Z,1661010709.858 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T15:51:49.858Z,1661010709.858 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T15:51:51.851Z,1661010711.851 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,155151.00,A,4313.62796,N,08620.32783,W,0.117,168.21,200822,,,A*71
2022-08-20T15:51:51.853Z,1661010711.853 [NAL9602](INFO): GPS fix at 20220820T155151: (43.227133, -86.338797)
2022-08-20T15:51:51.863Z,1661010711.863 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T15:51:51.863Z,1661010711.863 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T15:52:00.396Z,1661010720.396 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0013.lzma
2022-08-20T15:52:01.398Z,1661010721.398 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0013.lzma.bak
2022-08-20T15:52:01.398Z,1661010721.398 [DataOverHttps](INFO): SBD MOMSN=17118114
2022-08-20T15:52:05.640Z,1661010725.640 [DVL_micro](ERROR): Failed to parse:
:WI,+02836,+02220,-00836,+00000,A
2022-08-20T15:52:28.695Z,1661010748.695 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220820T152523/Express0014.lzma
2022-08-20T15:52:29.698Z,1661010749.698 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0014.lzma.bak
2022-08-20T15:52:29.699Z,1661010749.699 [DataOverHttps](INFO): SBD MOMSN=17118117
2022-08-20T15:52:33.662Z,1661010753.662 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T15:52:33.662Z,1661010753.662 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T15:52:33.662Z,1661010753.662 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T15:53:26.948Z,1661010806.948 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:53:32.602Z,1661010812.602 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:53:51.186Z,1661010831.186 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:54:09.770Z,1661010849.770 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:54:28.362Z,1661010868.362 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:54:46.938Z,1661010886.938 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:55:05.523Z,1661010905.523 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:55:24.106Z,1661010924.106 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:55:42.693Z,1661010942.693 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T15:55:54.423Z,1661010954.423 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T15:55:54.423Z,1661010954.423 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2022-08-20T15:56:34.055Z,1661010994.055 [BPC1](INFO): Calculating totals. Valid battery stick count: 27. Valid reserve battery stick count: 2.
2022-08-20T15:56:34.058Z,1661010994.058 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle.
2022-08-20T15:56:35.279Z,1661010995.279 [NAL9602](INFO): SBD MO Status=2, MOMSN=12883, MT Status=2, MTMSN=0
2022-08-20T15:56:35.279Z,1661010995.279 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T15:56:54.672Z,1661011014.672 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T15:57:25.369Z,1661011045.369 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T15:57:34.263Z,1661011054.263 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T15:57:34.264Z,1661011054.263 [Default:CheckIn:C.Wait] Stopped
2022-08-20T15:57:34.264Z,1661011054.264 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T15:57:34.264Z,1661011054.264 [Default:CheckIn:D] Running Loop=1
2022-08-20T15:57:34.682Z,1661011054.682 [Default:CheckIn:D] Stopped
2022-08-20T15:57:34.682Z,1661011054.682 [Default:CheckIn:E] Running Loop=1
2022-08-20T15:57:35.076Z,1661011055.076 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.771722 min 
2022-08-20T15:57:35.076Z,1661011055.076 [Default:CheckIn:E] Stopped
2022-08-20T15:57:35.076Z,1661011055.076 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T15:57:35.076Z,1661011055.076 [Default:CheckIn] Stopped
2022-08-20T15:57:35.076Z,1661011055.076 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T15:57:35.077Z,1661011055.077 [Default:CheckIn](INFO): Running loop #5
2022-08-20T15:57:35.077Z,1661011055.077 [Default:CheckIn] Running Loop=5
2022-08-20T15:57:35.077Z,1661011055.077 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T15:57:35.077Z,1661011055.077 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T15:57:37.114Z,1661011057.114 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,155736.00,A,4313.63111,N,08620.32729,W,0.447,73.31,200822,,,A*44
2022-08-20T15:57:37.116Z,1661011057.116 [NAL9602](INFO): GPS fix at 20220820T155736: (43.227185, -86.338788)
2022-08-20T15:57:37.127Z,1661011057.127 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T15:57:37.127Z,1661011057.127 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T15:57:45.592Z,1661011065.592 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20220820T152523/Courier0016.lzma
2022-08-20T15:57:46.594Z,1661011066.594 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0016.lzma.bak
2022-08-20T15:57:46.594Z,1661011066.594 [DataOverHttps](INFO): SBD MOMSN=17118133
2022-08-20T15:58:07.790Z,1661011087.790 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-08-20T15:58:07.865Z,1661011087.865 [NAL9602](ERROR): received: 
+CSQ:0

OK883, 2, 0, 0, 0

OK
2022-08-20T15:58:47.501Z,1661011127.501 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.907585
2022-08-20T15:58:58.633Z,1661011138.633 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002910
2022-08-20T15:59:09.268Z,1661011149.268 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220820T152523/Express0017.lzma
2022-08-20T15:59:10.270Z,1661011150.270 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0017.lzma.bak
2022-08-20T15:59:10.270Z,1661011150.270 [DataOverHttps](INFO): SBD MOMSN=17118145
2022-08-20T15:59:14.127Z,1661011154.127 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T15:59:14.127Z,1661011154.127 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T15:59:14.127Z,1661011154.127 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:00:13.133Z,1661011213.133 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T16:00:13.133Z,1661011213.133 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+27.3,0000.0000
2022-08-20T16:02:39.382Z,1661011359.382 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T16:03:10.091Z,1661011390.091 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:04:14.766Z,1661011454.766 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:04:14.766Z,1661011454.766 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:04:14.766Z,1661011454.766 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:04:14.766Z,1661011454.766 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:04:15.152Z,1661011455.152 [Default:CheckIn:D] Stopped
2022-08-20T16:04:15.152Z,1661011455.152 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:04:15.605Z,1661011455.605 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.446232 min 
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn:E] Stopped
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn] Stopped
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn](INFO): Running loop #6
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn] Running Loop=6
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:04:15.606Z,1661011455.606 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:04:17.555Z,1661011457.555 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,160416.00,A,4313.58464,N,08620.31233,W,2.527,73.31,200822,,,A*44
2022-08-20T16:04:17.558Z,1661011457.558 [NAL9602](INFO): GPS fix at 20220820T160416: (43.226411, -86.338539)
2022-08-20T16:04:17.598Z,1661011457.598 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:04:17.598Z,1661011457.598 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:04:41.095Z,1661011481.095 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220820T152523/Courier0019.lzma
2022-08-20T16:04:42.098Z,1661011482.098 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0019.lzma.bak
2022-08-20T16:04:42.098Z,1661011482.098 [DataOverHttps](INFO): SBD MOMSN=17118151
2022-08-20T16:05:03.632Z,1661011503.632 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220820T152523/Express0020.lzma
2022-08-20T16:05:04.634Z,1661011504.634 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0020.lzma.bak
2022-08-20T16:05:04.634Z,1661011504.634 [DataOverHttps](INFO): SBD MOMSN=17118154
2022-08-20T16:05:08.540Z,1661011508.540 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:05:08.541Z,1661011508.541 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:05:08.541Z,1661011508.541 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:06:20.032Z,1661011580.032 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T16:06:20.032Z,1661011580.032 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+27.4,00000,000
2022-08-20T16:07:00.548Z,1661011620.548 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2022-08-20T16:07:02.556Z,1661011622.556 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.955231
2022-08-20T16:07:24.044Z,1661011644.044 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002901
2022-08-20T16:08:11.228Z,1661011691.228 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:08:25.249Z,1661011705.249 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=61.208157
2022-08-20T16:09:19.441Z,1661011759.441 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T16:09:21.472Z,1661011761.472 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:09:50.148Z,1661011790.148 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:09:56.214Z,1661011796.214 [DVL_micro](ERROR): only read 2 of 4 data items
2022-08-20T16:09:56.214Z,1661011796.214 [DVL_micro](ERROR): Failed to parse:
:BI,+3112,+01614,
2022-08-20T16:09:56.612Z,1661011796.612 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:10:09.300Z,1661011809.300 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:10:09.300Z,1661011809.300 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:10:09.300Z,1661011809.300 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:10:09.300Z,1661011809.300 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:10:09.692Z,1661011809.692 [Default:CheckIn:D] Stopped
2022-08-20T16:10:09.692Z,1661011809.692 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:10:10.048Z,1661011810.048 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.355160 min 
2022-08-20T16:10:10.048Z,1661011810.048 [Default:CheckIn:E] Stopped
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn] Stopped
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn](INFO): Running loop #7
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn] Running Loop=7
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:10:10.049Z,1661011810.049 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:10:11.796Z,1661011811.796 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002904
2022-08-20T16:10:12.051Z,1661011812.051 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,161011.00,A,4312.74119,N,08619.60607,W,0.253,187.38,200822,,,A*7E
2022-08-20T16:10:12.054Z,1661011812.054 [NAL9602](INFO): GPS fix at 20220820T161011: (43.212353, -86.326768)
2022-08-20T16:10:12.090Z,1661011812.090 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:10:12.090Z,1661011812.090 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:10:26.092Z,1661011826.092 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220820T152523/Courier0022.lzma
2022-08-20T16:10:27.094Z,1661011827.094 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0022.lzma.bak
2022-08-20T16:10:27.094Z,1661011827.094 [DataOverHttps](INFO): SBD MOMSN=17118164
2022-08-20T16:10:42.594Z,1661011842.594 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-08-20T16:10:42.668Z,1661011842.668 [NAL9602](ERROR): received: 
+CSQ:0

OK883, 2, 0, 0, 0

OK
2022-08-20T16:10:47.480Z,1661011847.480 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20220820T152523/Express0023.lzma
2022-08-20T16:10:48.483Z,1661011848.483 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0023.lzma.bak
2022-08-20T16:10:48.483Z,1661011848.483 [DataOverHttps](INFO): SBD MOMSN=17118167
2022-08-20T16:10:52.313Z,1661011852.313 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:10:52.313Z,1661011852.313 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:10:52.314Z,1661011852.314 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:11:02.391Z,1661011862.391 [NAL9602](INFO): SBD MO Status=2, MOMSN=12883, MT Status=2, MTMSN=0
2022-08-20T16:11:02.391Z,1661011862.391 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:11:33.095Z,1661011893.095 [NAL9602](INFO): SBD MO Status=0, MOMSN=12883, MT Status=0, MTMSN=0
2022-08-20T16:11:33.095Z,1661011893.095 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:12:03.793Z,1661011923.793 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:15:52.933Z,1661012152.933 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:15:52.933Z,1661012152.933 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:15:52.933Z,1661012152.933 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:15:52.933Z,1661012152.933 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:15:53.331Z,1661012153.331 [Default:CheckIn:D] Stopped
2022-08-20T16:15:53.331Z,1661012153.331 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:15:53.735Z,1661012153.735 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.082548 min 
2022-08-20T16:15:53.735Z,1661012153.735 [Default:CheckIn:E] Stopped
2022-08-20T16:15:53.735Z,1661012153.735 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:15:53.735Z,1661012153.735 [Default:CheckIn] Stopped
2022-08-20T16:15:53.736Z,1661012153.736 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:15:53.736Z,1661012153.736 [Default:CheckIn](INFO): Running loop #8
2022-08-20T16:15:53.736Z,1661012153.736 [Default:CheckIn] Running Loop=8
2022-08-20T16:15:53.736Z,1661012153.736 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:15:53.736Z,1661012153.736 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:15:55.744Z,1661012155.744 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,161555.00,A,4312.75911,N,08619.61188,W,0.389,9.13,200822,,,A*73
2022-08-20T16:15:55.746Z,1661012155.746 [NAL9602](INFO): GPS fix at 20220820T161555: (43.212652, -86.326865)
2022-08-20T16:15:55.777Z,1661012155.777 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:15:55.777Z,1661012155.777 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:16:05.148Z,1661012165.148 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0025.lzma
2022-08-20T16:16:06.150Z,1661012166.150 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0025.lzma.bak
2022-08-20T16:16:06.150Z,1661012166.150 [DataOverHttps](INFO): SBD MOMSN=17118181
2022-08-20T16:16:34.773Z,1661012194.773 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220820T152523/Express0026.lzma
2022-08-20T16:16:35.774Z,1661012195.774 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0026.lzma.bak
2022-08-20T16:16:35.774Z,1661012195.774 [DataOverHttps](INFO): SBD MOMSN=17118185
2022-08-20T16:16:39.433Z,1661012199.433 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:16:39.433Z,1661012199.433 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:16:39.433Z,1661012199.433 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:16:42.644Z,1661012202.644 [NAL9602](INFO): SBD MO Status=2, MOMSN=12884, MT Status=2, MTMSN=0
2022-08-20T16:16:42.644Z,1661012202.644 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:18:03.497Z,1661012283.497 [NAL9602](INFO): SBD MO Status=2, MOMSN=12884, MT Status=2, MTMSN=0
2022-08-20T16:18:03.498Z,1661012283.498 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:18:36.310Z,1661012316.310 [NAL9602](INFO): SBD MO Status=2, MOMSN=12884, MT Status=2, MTMSN=0
2022-08-20T16:18:36.310Z,1661012316.310 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:18:48.802Z,1661012328.802 [NAL9602](INFO): SBD MO Status=2, MOMSN=12884, MT Status=2, MTMSN=0
2022-08-20T16:18:48.802Z,1661012328.802 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:20:11.637Z,1661012411.637 [NAL9602](INFO): SBD MO Status=0, MOMSN=12884, MT Status=0, MTMSN=0
2022-08-20T16:20:11.638Z,1661012411.638 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:20:42.398Z,1661012442.398 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:21:40.188Z,1661012500.188 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:21:40.188Z,1661012500.188 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:21:40.188Z,1661012500.188 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:21:40.188Z,1661012500.188 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:21:40.587Z,1661012500.587 [Default:CheckIn:D] Stopped
2022-08-20T16:21:40.587Z,1661012500.587 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:21:40.986Z,1661012500.986 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.870142 min 
2022-08-20T16:21:40.986Z,1661012500.986 [Default:CheckIn:E] Stopped
2022-08-20T16:21:40.986Z,1661012500.986 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:21:40.986Z,1661012500.986 [Default:CheckIn] Stopped
2022-08-20T16:21:40.986Z,1661012500.986 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:21:40.987Z,1661012500.987 [Default:CheckIn](INFO): Running loop #9
2022-08-20T16:21:40.987Z,1661012500.987 [Default:CheckIn] Running Loop=9
2022-08-20T16:21:40.987Z,1661012500.987 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:21:40.987Z,1661012500.987 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:21:43.003Z,1661012503.003 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162142.00,A,4312.74364,N,08619.61897,W,1.050,231.08,200822,,,A*79
2022-08-20T16:21:43.014Z,1661012503.014 [NAL9602](INFO): GPS fix at 20220820T162142: (43.212394, -86.326983)
2022-08-20T16:21:43.024Z,1661012503.024 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:21:43.024Z,1661012503.024 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:21:51.544Z,1661012511.544 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0028.lzma
2022-08-20T16:21:52.546Z,1661012512.546 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0028.lzma.bak
2022-08-20T16:21:52.546Z,1661012512.546 [DataOverHttps](INFO): SBD MOMSN=17118196
2022-08-20T16:22:16.020Z,1661012536.020 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220820T152523/Express0029.lzma
2022-08-20T16:22:17.022Z,1661012537.022 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0029.lzma.bak
2022-08-20T16:22:17.022Z,1661012537.022 [DataOverHttps](INFO): SBD MOMSN=17118199
2022-08-20T16:22:27.670Z,1661012547.670 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:22:27.670Z,1661012547.670 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:22:27.670Z,1661012547.670 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:22:56.704Z,1661012576.704 [NAL9602](INFO): SBD MO Status=2, MOMSN=12885, MT Status=2, MTMSN=0
2022-08-20T16:22:56.704Z,1661012576.704 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:25:22.538Z,1661012722.538 [NAL9602](INFO): SBD MO Status=2, MOMSN=12885, MT Status=2, MTMSN=0
2022-08-20T16:25:22.538Z,1661012722.538 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:26:00.121Z,1661012760.121 [NAL9602](INFO): SBD MO Status=2, MOMSN=12885, MT Status=2, MTMSN=0
2022-08-20T16:26:00.121Z,1661012760.121 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:26:30.006Z,1661012790.006 [NAL9602](INFO): SBD MO Status=2, MOMSN=12885, MT Status=2, MTMSN=0
2022-08-20T16:26:30.006Z,1661012790.006 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:26:45.367Z,1661012805.367 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-08-20T16:27:16.110Z,1661012836.110 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:27:28.253Z,1661012848.253 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:27:28.253Z,1661012848.253 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:27:28.253Z,1661012848.253 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:27:28.253Z,1661012848.253 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:27:28.666Z,1661012848.666 [Default:CheckIn:D] Stopped
2022-08-20T16:27:28.666Z,1661012848.666 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:27:29.093Z,1661012849.093 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.671460 min 
2022-08-20T16:27:29.093Z,1661012849.093 [Default:CheckIn:E] Stopped
2022-08-20T16:27:29.093Z,1661012849.093 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:27:29.093Z,1661012849.093 [Default:CheckIn] Stopped
2022-08-20T16:27:29.093Z,1661012849.093 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:27:29.094Z,1661012849.094 [Default:CheckIn](INFO): Running loop #10
2022-08-20T16:27:29.094Z,1661012849.094 [Default:CheckIn] Running Loop=10
2022-08-20T16:27:29.094Z,1661012849.094 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:27:29.094Z,1661012849.094 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:27:31.059Z,1661012851.059 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162730.00,A,4312.74819,N,08619.61069,W,0.117,236.14,200822,,,A*7B
2022-08-20T16:27:31.062Z,1661012851.062 [NAL9602](INFO): GPS fix at 20220820T162730: (43.212470, -86.326845)
2022-08-20T16:27:31.088Z,1661012851.088 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:27:31.088Z,1661012851.088 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:27:33.087Z,1661012853.087 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0031.lzma
2022-08-20T16:27:34.094Z,1661012854.094 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0031.lzma.bak
2022-08-20T16:27:34.094Z,1661012854.094 [DataOverHttps](INFO): SBD MOMSN=17118254
2022-08-20T16:27:52.544Z,1661012872.544 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20220820T152523/Express0032.lzma
2022-08-20T16:27:53.546Z,1661012873.546 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0032.lzma.bak
2022-08-20T16:27:53.546Z,1661012873.546 [DataOverHttps](INFO): SBD MOMSN=17118264
2022-08-20T16:27:56.627Z,1661012876.627 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T16:27:56.628Z,1661012876.628 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2022-08-20T16:27:57.440Z,1661012877.440 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:27:57.464Z,1661012877.464 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:27:57.464Z,1661012877.464 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:28:01.871Z,1661012881.871 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-08-20T16:28:01.944Z,1661012881.944 [NAL9602](ERROR): received: 
+CSQ:0

OK885, 2, 0, 0, 0

OK
2022-08-20T16:28:59.681Z,1661012939.681 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+0000+00000000.00,9999.99,000.00
2022-08-20T16:29:02.100Z,1661012942.100 [DVL_micro](ERROR): Failed to parse:
:000000000,35.0,+27.6,0000.0,1489:WI,-02303,-04365,+00814,+00000,A
2022-08-20T16:29:04.522Z,1661012944.522 [DVL_micro](ERROR): No DVL communication! Re-initializing
2022-08-20T16:29:04.522Z,1661012944.522 [DVL_micro] Communications Fault, FailCount= 1
2022-08-20T16:29:04.522Z,1661012944.522 [DVL_micro](ERROR): Communications Fault
2022-08-20T16:29:04.547Z,1661012944.547 [CBIT](ERROR): Communications Fault in component: DVL_micro
2022-08-20T16:29:05.000Z,1661012945.000 [DVL_micro](INFO): Powering down
2022-08-20T16:29:05.780Z,1661012945.780 [CBIT](INFO): Clearing failed state for component DVL_micro
2022-08-20T16:29:05.780Z,1661012945.780 [DVL_micro] No Fault, FailCount= 1
2022-08-20T16:29:31.201Z,1661012971.201 [NAL9602](INFO): SBD MO Status=0, MOMSN=12885, MT Status=0, MTMSN=0
2022-08-20T16:29:31.202Z,1661012971.202 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:30:01.885Z,1661013001.885 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:32:44.783Z,1661013164.783 [DVL_micro](ERROR): Failed to parse:
:SA,-00.94,+05.95,148.4
2022-08-20T16:32:47.192Z,1661013167.192 [DVL_micro](ERROR): Failed to parse:
:T00000000,35,00000,000
2022-08-20T16:32:49.617Z,1661013169.617 [DVL_micro](ERROR): No DVL communication! Re-initializing
2022-08-20T16:32:49.617Z,1661013169.617 [DVL_micro] Communications Fault, FailCount= 1
2022-08-20T16:32:49.617Z,1661013169.617 [DVL_micro](ERROR): Communications Fault
2022-08-20T16:32:49.667Z,1661013169.667 [CBIT](ERROR): Communications Fault in component: DVL_micro
2022-08-20T16:32:50.088Z,1661013170.088 [DVL_micro](INFO): Powering down
2022-08-20T16:32:50.857Z,1661013170.857 [CBIT](INFO): Clearing failed state for component DVL_micro
2022-08-20T16:32:50.857Z,1661013170.857 [DVL_micro] No Fault, FailCount= 1
2022-08-20T16:32:58.142Z,1661013178.142 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:32:58.142Z,1661013178.142 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:32:58.142Z,1661013178.142 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:32:58.142Z,1661013178.142 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:32:58.528Z,1661013178.528 [Default:CheckIn:D] Stopped
2022-08-20T16:32:58.528Z,1661013178.528 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.169088 min 
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn:E] Stopped
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn] Stopped
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:32:58.966Z,1661013178.966 [Default:CheckIn](INFO): Running loop #11
2022-08-20T16:32:58.967Z,1661013178.967 [Default:CheckIn] Running Loop=11
2022-08-20T16:32:58.967Z,1661013178.967 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:32:58.967Z,1661013178.967 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:33:00.931Z,1661013180.931 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163300.00,A,4312.75061,N,08619.61017,W,0.525,338.22,200822,,,A*7D
2022-08-20T16:33:00.940Z,1661013180.940 [NAL9602](INFO): GPS fix at 20220820T163300: (43.212510, -86.326836)
2022-08-20T16:33:00.951Z,1661013180.951 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:33:00.951Z,1661013180.951 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:33:10.679Z,1661013190.679 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220820T152523/Courier0034.lzma
2022-08-20T16:33:11.682Z,1661013191.682 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0034.lzma.bak
2022-08-20T16:33:11.682Z,1661013191.682 [DataOverHttps](INFO): SBD MOMSN=17118309
2022-08-20T16:34:02.348Z,1661013242.348 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220820T152523/Express0035.lzma
2022-08-20T16:34:09.374Z,1661013249.374 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0035.lzma.bak
2022-08-20T16:34:09.374Z,1661013249.374 [DataOverHttps](INFO): SBD MOMSN=17118313
2022-08-20T16:34:14.170Z,1661013254.170 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:34:14.170Z,1661013254.170 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:34:14.170Z,1661013254.170 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:34:15.707Z,1661013255.707 [NAL9602](INFO): SBD MO Status=2, MOMSN=12886, MT Status=2, MTMSN=0
2022-08-20T16:34:15.708Z,1661013255.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:34:51.733Z,1661013291.733 [NAL9602](INFO): SBD MO Status=0, MOMSN=12886, MT Status=0, MTMSN=0
2022-08-20T16:34:51.733Z,1661013291.733 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:35:06.693Z,1661013306.693 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T16:35:06.693Z,1661013306.693 [DVL_micro](ERROR): Failed to parse:
:BI,-05003,+01161,00000,I
2022-08-20T16:35:22.421Z,1661013322.421 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:35:43.968Z,1661013343.968 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting.
2022-08-20T16:36:00.033Z,1661013360.033 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.607433
2022-08-20T16:36:31.828Z,1661013391.828 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002914
2022-08-20T16:36:47.286Z,1661013407.286 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T16:36:47.286Z,1661013407.286 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.99,
2022-08-20T16:36:52.514Z,1661013412.514 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T16:36:52.514Z,1661013412.514 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,00
2022-08-20T16:38:41.060Z,1661013521.060 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:38:43.069Z,1661013523.069 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239429
2022-08-20T16:39:14.740Z,1661013554.740 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:39:14.740Z,1661013554.740 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:39:14.740Z,1661013554.740 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:39:14.741Z,1661013554.741 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:39:15.149Z,1661013555.149 [Default:CheckIn:D] Stopped
2022-08-20T16:39:15.149Z,1661013555.149 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:39:15.577Z,1661013555.577 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.446167 min 
2022-08-20T16:39:15.577Z,1661013555.577 [Default:CheckIn:E] Stopped
2022-08-20T16:39:15.577Z,1661013555.577 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn] Stopped
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn](INFO): Running loop #12
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn] Running Loop=12
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:39:15.578Z,1661013555.578 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:39:16.212Z,1661013556.212 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:39:17.564Z,1661013557.564 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163916.00,A,4312.74838,N,08619.61195,W,0.019,49.58,200822,,,A*4C
2022-08-20T16:39:17.566Z,1661013557.566 [NAL9602](INFO): GPS fix at 20220820T163916: (43.212473, -86.326866)
2022-08-20T16:39:17.576Z,1661013557.576 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:39:17.577Z,1661013557.577 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:39:51.352Z,1661013591.352 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:40:26.500Z,1661013626.500 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:41:01.652Z,1661013661.652 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:41:36.804Z,1661013696.804 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:41:53.192Z,1661013713.192 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002800
2022-08-20T16:42:02.535Z,1661013722.535 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220820T152523/Courier0037.lzma
2022-08-20T16:42:03.538Z,1661013723.538 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0037.lzma.bak
2022-08-20T16:42:03.538Z,1661013723.538 [DataOverHttps](INFO): SBD MOMSN=17118324
2022-08-20T16:42:26.134Z,1661013746.134 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:42:29.832Z,1661013749.832 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20220820T152523/Express0038.lzma
2022-08-20T16:42:30.834Z,1661013750.834 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0038.lzma.bak
2022-08-20T16:42:30.834Z,1661013750.834 [DataOverHttps](INFO): SBD MOMSN=17118330
2022-08-20T16:42:35.053Z,1661013755.053 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:42:35.053Z,1661013755.053 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:42:35.053Z,1661013755.053 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:43:47.417Z,1661013827.417 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.255428
2022-08-20T16:44:28.580Z,1661013868.580 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:45:03.736Z,1661013903.736 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:45:38.884Z,1661013938.884 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:45:57.835Z,1661013957.835 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T16:45:57.835Z,1661013957.835 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+27.7,0000.0,1489:WI,-03516,-05633,+00873,+00000,A
2022-08-20T16:46:02.709Z,1661013962.709 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T16:46:02.709Z,1661013962.709 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35,0000.0,1489.0,000
2022-08-20T16:46:14.040Z,1661013974.040 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:46:49.180Z,1661014009.180 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-08-20T16:47:02.197Z,1661014022.197 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002959
2022-08-20T16:47:35.620Z,1661014055.620 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:47:35.620Z,1661014055.620 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:47:35.620Z,1661014055.620 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:47:35.620Z,1661014055.620 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:47:36.039Z,1661014056.039 [Default:CheckIn:D] Stopped
2022-08-20T16:47:36.039Z,1661014056.039 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:47:36.427Z,1661014056.427 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.794336 min 
2022-08-20T16:47:36.427Z,1661014056.427 [Default:CheckIn:E] Stopped
2022-08-20T16:47:36.428Z,1661014056.428 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:47:36.428Z,1661014056.428 [Default:CheckIn] Stopped
2022-08-20T16:47:36.448Z,1661014056.448 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:47:36.448Z,1661014056.448 [Default:CheckIn](INFO): Running loop #13
2022-08-20T16:47:36.448Z,1661014056.448 [Default:CheckIn] Running Loop=13
2022-08-20T16:47:36.448Z,1661014056.448 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:47:36.449Z,1661014056.449 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:47:38.449Z,1661014058.449 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164737.00,A,4312.75290,N,08619.61266,W,0.039,327.34,200822,,,A*73
2022-08-20T16:47:38.452Z,1661014058.452 [NAL9602](INFO): GPS fix at 20220820T164737: (43.212548, -86.326878)
2022-08-20T16:47:38.478Z,1661014058.478 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:47:38.478Z,1661014058.478 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:47:47.475Z,1661014067.475 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0040.lzma
2022-08-20T16:47:48.478Z,1661014068.478 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0040.lzma.bak
2022-08-20T16:47:48.478Z,1661014068.478 [DataOverHttps](INFO): SBD MOMSN=17118343
2022-08-20T16:47:49.747Z,1661014069.747 [NAL9602](INFO): SBD MO Status=0, MOMSN=12887, MT Status=0, MTMSN=0
2022-08-20T16:47:49.747Z,1661014069.747 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:48:10.032Z,1661014090.032 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220820T152523/Express0041.lzma
2022-08-20T16:48:11.034Z,1661014091.034 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0041.lzma.bak
2022-08-20T16:48:11.035Z,1661014091.035 [DataOverHttps](INFO): SBD MOMSN=17118346
2022-08-20T16:48:16.916Z,1661014096.916 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:48:16.916Z,1661014096.916 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:48:16.916Z,1661014096.916 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:48:20.533Z,1661014100.533 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:50:28.593Z,1661014228.593 [DataOverHttps](IMPORTANT): SBD MTMSN=20220820T165027
2022-08-20T16:50:37.220Z,1661014237.220 [DataOverHttps](INFO): Received command: failc
2022-08-20T16:50:37.305Z,1661014237.305 [CommandExec](IMPORTANT): got command failComponent
2022-08-20T16:50:37.305Z,1661014237.305 [CommandExec](IMPORTANT): Failed components:
2022-08-20T16:50:37.305Z,1661014237.305 [CommandExec](IMPORTANT): No failed Components.
2022-08-20T16:53:17.643Z,1661014397.643 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:53:17.643Z,1661014397.643 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:53:17.643Z,1661014397.643 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:53:17.643Z,1661014397.643 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:53:18.059Z,1661014398.059 [Default:CheckIn:D] Stopped
2022-08-20T16:53:18.059Z,1661014398.059 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:53:18.451Z,1661014398.451 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 83.494678 min 
2022-08-20T16:53:18.451Z,1661014398.451 [Default:CheckIn:E] Stopped
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn] Stopped
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn](INFO): Running loop #14
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn] Running Loop=14
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:53:18.452Z,1661014398.452 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:53:20.461Z,1661014400.461 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165319.00,A,4312.75395,N,08619.61158,W,0.019,327.34,200822,,,D*77
2022-08-20T16:53:20.463Z,1661014400.463 [NAL9602](INFO): GPS fix at 20220820T165319: (43.212566, -86.326860)
2022-08-20T16:53:20.498Z,1661014400.498 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:53:20.498Z,1661014400.498 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:53:29.211Z,1661014409.211 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0043.lzma
2022-08-20T16:53:30.214Z,1661014410.214 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0043.lzma.bak
2022-08-20T16:53:30.215Z,1661014410.215 [DataOverHttps](INFO): SBD MOMSN=17118355
2022-08-20T16:53:51.052Z,1661014431.052 [DataOverHttps](INFO): Sending 247 bytes from file Logs/20220820T152523/Express0044.lzma
2022-08-20T16:53:52.054Z,1661014432.054 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0044.lzma.bak
2022-08-20T16:53:52.054Z,1661014432.054 [DataOverHttps](INFO): SBD MOMSN=17118361
2022-08-20T16:53:56.029Z,1661014436.029 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:53:56.029Z,1661014436.029 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:53:56.029Z,1661014436.029 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:54:04.891Z,1661014444.891 [NAL9602](INFO): SBD MO Status=2, MOMSN=12888, MT Status=2, MTMSN=0
2022-08-20T16:54:04.891Z,1661014444.891 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-08-20T16:54:44.115Z,1661014484.115 [NAL9602](INFO): SBD MO Status=0, MOMSN=12888, MT Status=0, MTMSN=0
2022-08-20T16:54:44.115Z,1661014484.115 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:55:08.357Z,1661014508.357 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T16:55:08.358Z,1661014508.358 [DVL_micro](ERROR): Failed to parse:
:BI,-03172,-0027,+00000,I
2022-08-20T16:55:14.814Z,1661014514.814 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T16:58:44.564Z,1661014724.564 [DVL_micro](ERROR): only read 2 of 4 data items
2022-08-20T16:58:44.564Z,1661014724.564 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,,+9999.99
2022-08-20T16:58:56.705Z,1661014736.705 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T16:58:56.705Z,1661014736.705 [Default:CheckIn:C.Wait] Stopped
2022-08-20T16:58:56.705Z,1661014736.705 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T16:58:56.705Z,1661014736.705 [Default:CheckIn:D] Running Loop=1
2022-08-20T16:58:57.097Z,1661014737.097 [Default:CheckIn:D] Stopped
2022-08-20T16:58:57.097Z,1661014737.097 [Default:CheckIn:E] Running Loop=1
2022-08-20T16:58:57.500Z,1661014737.500 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.145313 min 
2022-08-20T16:58:57.500Z,1661014737.500 [Default:CheckIn:E] Stopped
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn] Stopped
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn](INFO): Running loop #15
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn] Running Loop=15
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T16:58:57.501Z,1661014737.501 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T16:58:59.520Z,1661014739.520 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165858.00,A,4312.75403,N,08619.61147,W,0.039,327.34,200822,,,D*7D
2022-08-20T16:58:59.523Z,1661014739.523 [NAL9602](INFO): GPS fix at 20220820T165858: (43.212567, -86.326858)
2022-08-20T16:58:59.533Z,1661014739.533 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T16:58:59.533Z,1661014739.533 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T16:59:09.194Z,1661014749.194 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:10.375Z,1661014750.375 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0048.lzma
2022-08-20T16:59:11.378Z,1661014751.378 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0048.lzma.bak
2022-08-20T16:59:11.378Z,1661014751.378 [DataOverHttps](INFO): SBD MOMSN=17118376
2022-08-20T16:59:12.427Z,1661014752.427 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:15.659Z,1661014755.659 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:22.141Z,1661014762.141 [NAL9602](INFO): SBD MO Status=0, MOMSN=12889, MT Status=0, MTMSN=0
2022-08-20T16:59:22.141Z,1661014762.141 [NAL9602](INFO): No messages in MT queue
2022-08-20T16:59:29.394Z,1661014769.394 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:30.060Z,1661014770.060 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220820T152523/Express0047.lzma
2022-08-20T16:59:31.062Z,1661014771.062 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0047.lzma.bak
2022-08-20T16:59:31.062Z,1661014771.062 [DataOverHttps](INFO): SBD MOMSN=17118379
2022-08-20T16:59:34.242Z,1661014774.242 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:35.107Z,1661014775.107 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T16:59:35.107Z,1661014775.107 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T16:59:35.107Z,1661014775.107 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T16:59:46.362Z,1661014786.362 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:52.828Z,1661014792.828 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T16:59:52.836Z,1661014792.836 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T17:00:02.928Z,1661014802.928 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:11.425Z,1661014811.425 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:19.495Z,1661014819.495 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:29.998Z,1661014829.998 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:36.063Z,1661014836.063 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:48.582Z,1661014848.582 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:00:52.624Z,1661014852.624 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:01:07.167Z,1661014867.167 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:01:08.783Z,1661014868.783 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:01:25.389Z,1661014885.389 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:01:25.750Z,1661014885.750 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:04:35.661Z,1661015075.661 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T17:04:35.661Z,1661015075.661 [Default:CheckIn:C.Wait] Stopped
2022-08-20T17:04:35.661Z,1661015075.661 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T17:04:35.661Z,1661015075.661 [Default:CheckIn:D] Running Loop=1
2022-08-20T17:04:36.085Z,1661015076.085 [Default:CheckIn:D] Stopped
2022-08-20T17:04:36.085Z,1661015076.085 [Default:CheckIn:E] Running Loop=1
2022-08-20T17:04:36.490Z,1661015076.490 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 94.795117 min 
2022-08-20T17:04:36.490Z,1661015076.490 [Default:CheckIn:E] Stopped
2022-08-20T17:04:36.490Z,1661015076.490 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T17:04:36.490Z,1661015076.490 [Default:CheckIn] Stopped
2022-08-20T17:04:36.491Z,1661015076.491 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T17:04:36.491Z,1661015076.491 [Default:CheckIn](INFO): Running loop #16
2022-08-20T17:04:36.491Z,1661015076.491 [Default:CheckIn] Running Loop=16
2022-08-20T17:04:36.491Z,1661015076.491 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T17:04:36.491Z,1661015076.491 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T17:04:38.468Z,1661015078.468 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170437.00,A,4312.74794,N,08619.61777,W,0.019,233.15,200822,,,D*70
2022-08-20T17:04:38.470Z,1661015078.470 [NAL9602](INFO): GPS fix at 20220820T170437: (43.212466, -86.326963)
2022-08-20T17:04:38.480Z,1661015078.480 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T17:04:38.480Z,1661015078.480 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T17:04:49.739Z,1661015089.739 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0052.lzma
2022-08-20T17:04:49.788Z,1661015089.788 [NAL9602](INFO): SBD MO Status=0, MOMSN=12890, MT Status=0, MTMSN=0
2022-08-20T17:04:49.788Z,1661015089.788 [NAL9602](INFO): No messages in MT queue
2022-08-20T17:04:50.742Z,1661015090.742 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0052.lzma.bak
2022-08-20T17:04:50.742Z,1661015090.742 [DataOverHttps](INFO): SBD MOMSN=17118385
2022-08-20T17:04:56.266Z,1661015096.266 [DVL_micro](ERROR): only read 3 of 4 data items
2022-08-20T17:04:56.266Z,1661015096.266 [DVL_micro](ERROR): Failed to parse:
:BI,-0162,+00204,+00000,I
2022-08-20T17:05:09.452Z,1661015109.452 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220820T152523/Express0053.lzma
2022-08-20T17:05:10.454Z,1661015110.454 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0053.lzma.bak
2022-08-20T17:05:10.454Z,1661015110.454 [DataOverHttps](INFO): SBD MOMSN=17118390
2022-08-20T17:05:14.449Z,1661015114.449 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T17:05:14.449Z,1661015114.449 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T17:05:14.449Z,1661015114.449 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T17:05:20.478Z,1661015120.478 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T17:08:57.117Z,1661015337.117 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:02.744Z,1661015342.744 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:12.034Z,1661015352.034 [BPC1](ERROR): BPC1B got IPBS message with 5 sticks (min is 7).
2022-08-20T17:09:17.287Z,1661015357.287 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:21.328Z,1661015361.328 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:31.427Z,1661015371.427 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:39.911Z,1661015379.911 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:45.163Z,1661015385.163 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:58.502Z,1661015398.502 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:09:59.316Z,1661015399.316 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:13.039Z,1661015413.039 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:15.108Z,1661015415.108 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-08-20T17:10:15.108Z,1661015415.108 [Default:CheckIn:C.Wait] Stopped
2022-08-20T17:10:15.108Z,1661015415.108 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T17:10:15.108Z,1661015415.108 [Default:CheckIn:D] Running Loop=1
2022-08-20T17:10:15.530Z,1661015415.530 [Default:CheckIn:D] Stopped
2022-08-20T17:10:15.530Z,1661015415.530 [Default:CheckIn:E] Running Loop=1
2022-08-20T17:10:15.912Z,1661015415.912 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 100.452523 min 
2022-08-20T17:10:15.912Z,1661015415.912 [Default:CheckIn:E] Stopped
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn] Stopped
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn](INFO): Running loop #17
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn] Running Loop=17
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T17:10:15.913Z,1661015415.913 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T17:10:17.081Z,1661015417.081 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:17.948Z,1661015417.948 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171017.00,A,4312.73049,N,08619.65933,W,0.039,329.53,200822,,,D*77
2022-08-20T17:10:17.970Z,1661015417.970 [NAL9602](INFO): GPS fix at 20220820T171017: (43.212175, -86.327656)
2022-08-20T17:10:18.028Z,1661015418.028 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T17:10:18.028Z,1661015418.028 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T17:10:21.946Z,1661015421.946 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0055.lzma
2022-08-20T17:10:22.950Z,1661015422.950 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0055.lzma.bak
2022-08-20T17:10:22.950Z,1661015422.950 [DataOverHttps](INFO): SBD MOMSN=17118489
2022-08-20T17:10:26.950Z,1661015426.950 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:30.264Z,1661015430.264 [NAL9602](INFO): SBD MO Status=0, MOMSN=12891, MT Status=0, MTMSN=0
2022-08-20T17:10:30.265Z,1661015430.265 [NAL9602](INFO): No messages in MT queue
2022-08-20T17:10:35.859Z,1661015435.859 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:41.112Z,1661015441.112 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:44.320Z,1661015444.320 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220820T152523/Express0056.lzma
2022-08-20T17:10:45.322Z,1661015445.322 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Express0056.lzma.bak
2022-08-20T17:10:45.322Z,1661015445.322 [DataOverHttps](INFO): SBD MOMSN=17118492
2022-08-20T17:10:49.220Z,1661015449.220 [Default:CheckIn:Read_Iridium] Stopped
2022-08-20T17:10:49.220Z,1661015449.220 [Default:CheckIn:C.Wait] Running Loop=1
2022-08-20T17:10:49.220Z,1661015449.220 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-08-20T17:10:54.932Z,1661015454.932 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:10:55.251Z,1661015455.251 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:11:00.910Z,1661015460.910 [NAL9602](INFO): Not Powering down - fast GPS
2022-08-20T17:11:05.376Z,1661015465.376 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-08-20T17:11:05.382Z,1661015465.382 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.4,0000.0,1489.0,000
2022-08-20T17:11:09.001Z,1661015469.001 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:11:14.643Z,1661015474.643 [BPC1](ERROR): BPC1A got IPBS message with 6 sticks (min is 7).
2022-08-20T17:11:22.724Z,1661015482.724 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:11:36.863Z,1661015496.863 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2022-08-20T17:13:30.966Z,1661015610.966 [DataOverHttps](IMPORTANT): SBD MTMSN=20220820T171330
2022-08-20T17:13:38.428Z,1661015618.428 [DataOverHttps](INFO): Received command: load Transport/transit.tl;set transit.NeedCommsTime 15 min;set transit.Latitude 43.20017 degree;set transit.Longitude -86.3649 degree;set transit.Depth 3 m;set transit.MaxDepth 7 m;set transit.MinOffshore .1 km;run
2022-08-20T17:13:38.458Z,1661015618.458 [CommandExec](IMPORTANT): got command load ./Missions/Transport/transit.tl
2022-08-20T17:13:38.458Z,1661015618.458 [MissionManager](INFO): Loading Mission from file: ./Missions/Transport/transit.tl
2022-08-20T17:13:38.458Z,1661015618.458 [MissionManager](IMPORTANT): Loading Compiled TethysL script from file ./Missions/Transport/transit.tx
2022-08-20T17:13:38.619Z,1661015618.619 [MissionManager](INFO): DefineArg transit.MissionTimeout = 60.000000 min
2022-08-20T17:13:38.622Z,1661015618.622 [MissionManager](INFO): DefineArg transit.NeedCommsTime = 30.000000 min
2022-08-20T17:13:38.632Z,1661015618.632 [MissionManager](INFO): DefineArg transit.Latitude = nan arcdeg
2022-08-20T17:13:38.635Z,1661015618.635 [MissionManager](INFO): DefineArg transit.Longitude = nan arcdeg
2022-08-20T17:13:38.642Z,1661015618.642 [MissionManager](INFO): DefineArg transit.Northings = 0.000000 m
2022-08-20T17:13:38.646Z,1661015618.646 [MissionManager](INFO): DefineArg transit.Eastings = 0.000000 m
2022-08-20T17:13:38.658Z,1661015618.658 [MissionManager](INFO): DefineArg transit.Depth = 10.000000 m
2022-08-20T17:13:38.665Z,1661015618.665 [MissionManager](INFO): DefineArg transit.Speed = 1.000000 m/s
2022-08-20T17:13:38.667Z,1661015618.667 [MissionManager](INFO): DefineArg transit.MaxDepth = 20.000000 m
2022-08-20T17:13:38.674Z,1661015618.674 [MissionManager](INFO): DefineArg transit.MinOffshore = 1.000000 km
2022-08-20T17:13:38.693Z,1661015618.693 [MissionManager](INFO): DefineArg transit.MinAltitude = 7.000000 m
2022-08-20T17:13:38.696Z,1661015618.696 [MissionManager](INFO): DefineArg transit.MassHold = 1 bool
2022-08-20T17:13:38.711Z,1661015618.711 [MissionManager](INFO): DefineArg transit.BuoyancyHold = 1 bool
2022-08-20T17:13:38.711Z,1661015618.711 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/NeedComms.xml
2022-08-20T17:13:38.806Z,1661015618.806 [MissionManager](INFO): DefineArg transit:NeedComms.DiveInterval = 3.000000 h
2022-08-20T17:13:38.810Z,1661015618.810 [MissionManager](INFO): DefineArg transit:NeedComms.WaitForPitchUp = 10.000000 min
2022-08-20T17:13:38.821Z,1661015618.821 [MissionManager](INFO): DefineArg transit:NeedComms.SurfacePitch = 20.000000 arcdeg
2022-08-20T17:13:38.824Z,1661015618.824 [MissionManager](INFO): DefineArg transit:NeedComms.SurfaceDepthRate = nan m/s
2022-08-20T17:13:38.835Z,1661015618.835 [MissionManager](INFO): DefineArg transit:NeedComms.SurfaceSpeed = 1.000000 m/s
2022-08-20T17:13:38.838Z,1661015618.838 [MissionManager](INFO): DefineArg transit:NeedComms.GPSTimeout = 7.000000 min
2022-08-20T17:13:38.849Z,1661015618.849 [MissionManager](INFO): DefineArg transit:NeedComms.CommsTimeout = 30.000000 min
2022-08-20T17:13:38.864Z,1661015618.864 [transit:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-08-20T17:13:38.939Z,1661015618.939 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/StandardEnvelopes.xml
2022-08-20T17:13:38.989Z,1661015618.989 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MinAltitude = 5.000000 m
2022-08-20T17:13:38.991Z,1661015618.991 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MaxDepth = 200.000000 m
2022-08-20T17:13:39.011Z,1661015619.011 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MinOffshore = 2000.000000 m
2022-08-20T17:13:39.012Z,1661015619.012 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope.
2022-08-20T17:13:39.033Z,1661015619.033 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope.
2022-08-20T17:13:39.049Z,1661015619.049 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope.
2022-08-20T17:13:39.106Z,1661015619.106 [transit:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy.
2022-08-20T17:13:39.117Z,1661015619.117 [transit:MassHold.Pitch](DEBUG): Construct.
2022-08-20T17:13:39.129Z,1661015619.129 [transit:Transit:A.Pitch](DEBUG): Construct.
2022-08-20T17:13:39.135Z,1661015619.135 [transit:Transit:B.SetSpeed](DEBUG): Construct.
2022-08-20T17:13:39.146Z,1661015619.146 [transit:Transit:Wpt1.Waypoint](DEBUG): Construct Waypoint.
2022-08-20T17:13:39.193Z,1661015619.193 [MissionManager](DEBUG): 
mission transit {
  """
  Vehicle transits to desired waypoint and can be commanded to use/hold
  mass or buoyancy.
  """

  arguments {
    MissionTimeout = 60 minute
      """
      Maximum duration of mission
      """

    NeedCommsTime = 30 minute
      """
      How often to surface for commumications
      """

    Latitude = NaN degree
      """
      Latitude of waypoint to seek. If set to NaN, uses latitude at mission
      initialization.
      """

    Longitude = NaN degree
      """
      Longitude of waypoint to seek. If set to NaN, uses longitude at mission
      initialization.
      """

    Northings = 0 meter
      """
      Northward distance of the waypoint to seek. If combined with Latitude
      and/or Longitude, this is an offset from the specified Latitude and/or
      Longitude.
      """

    Eastings = 0 meter
      """
      Eastward distance of the waypoint to seek. If combined with Latitude
      and/or Longitude, this is an offset from the specified Latitude and/or
      Longitude.
      """

    Depth = 10 meter
      """
      Depth of flat and level flight during the mission.
      """

    Speed = 1 meter_per_second
      """
      Speed of vehicle (relative to water) during the mission.
      """

    MaxDepth = 20 meter
      """
      Maximum depth for the entire mission.
      """

    MinOffshore = 1 kilometer
      """
      Minimum distance offshore for the entire mission.
      """

    MinAltitude = 7 meter
      """
      Minimum height above the sea floor for the entire mission.
      """

    MassHold = true
      """
      Set to True in order to hold mass at default position, False to allow
      mass to run on its own.
      """

    BuoyancyHold = true
      """
      Set to True in order to hold buoyancy at neutral position, False to
      allow buoyancy to run on its own.
      """
  }

  timeout duration=MissionTimeout

  insert id="NeedComms" Insert/NeedComms.xml

  assign in sequence NeedComms:DiveInterval = NeedCommsTime

  assign in sequence NeedComms:WaitForPitchUp = 1 second

  insert Insert/StandardEnvelopes.xml

  assign in sequence StandardEnvelopes:MinAltitude = MinAltitude

  assign in sequence StandardEnvelopes:MaxDepth = MaxDepth

  assign in sequence StandardEnvelopes:MinOffshore = MinOffshore

  behavior Guidance:Buoyancy id="BuoyancyHold" {
    run while ( BuoyancyHold )

    set position = Control:VerticalControl.buoyancyNeutral
  }

  behavior Guidance:Pitch id="MassHold" {
    run while ( MassHold )

    set massPosition = Control:VerticalControl.massDefault
  }

  aggregate Transit {
    run in sequence

    behavior Guidance:Pitch {
      run in parallel

      set depth = Depth
    }

    behavior Guidance:SetSpeed {
      run in parallel

      set speed = Speed
    }

    behavior Guidance:Waypoint id="Wpt1" {
      run in sequence

      set latitude = Latitude
      set longitude = Longitude
      set northingsDelta = Northings
      set eastingsDelta = Eastings
    }

    call id="PhoneHome" refId="NeedComms"
  }
}


2022-08-20T17:13:39.194Z,1661015619.194 [CommandExec](IMPORTANT): Loaded ./Missions/Transport/transit.tl
2022-08-20T17:13:47.659Z,1661015627.659 [CommandExec](IMPORTANT): got command set transit.NeedCommsTime 15 minute
2022-08-20T17:13:47.660Z,1661015627.660 [CommandExec](IMPORTANT): got command set transit.Latitude 43.20017 degree
2022-08-20T17:13:47.661Z,1661015627.661 [CommandExec](IMPORTANT): got command set transit.Longitude -86.3649 degree
2022-08-20T17:13:47.662Z,1661015627.662 [CommandExec](IMPORTANT): got command set transit.Depth 3 meter
2022-08-20T17:13:47.662Z,1661015627.662 [CommandExec](IMPORTANT): got command set transit.MaxDepth 7 meter
2022-08-20T17:13:47.663Z,1661015627.663 [CommandExec](IMPORTANT): got command set transit.MinOffshore .1 kilometer
2022-08-20T17:13:47.663Z,1661015627.663 [CommandExec](IMPORTANT): got command run
2022-08-20T17:13:47.666Z,1661015627.666 [CommandExec](IMPORTANT): Running 
2022-08-20T17:13:47.816Z,1661015627.816 [Default] Stopped
2022-08-20T17:13:47.816Z,1661015627.816 [Default](DEBUG): Aggregate::uninitialize Default
2022-08-20T17:13:47.816Z,1661015627.816 [Default:B.GoToSurface] Stopped
2022-08-20T17:13:47.816Z,1661015627.816 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-08-20T17:13:47.816Z,1661015627.816 [Default:CheckIn] Stopped
2022-08-20T17:13:47.816Z,1661015627.816 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-08-20T17:13:47.816Z,1661015627.816 [Default:CheckIn:C.Wait] Stopped
2022-08-20T17:13:47.816Z,1661015627.816 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T17:13:47.817Z,1661015627.817 [MissionManager](IMPORTANT): Started mission transit
2022-08-20T17:13:47.817Z,1661015627.817 [transit] Running Loop=1
2022-08-20T17:13:47.817Z,1661015627.817 [transit](DEBUG): Aggregate::initialize transit
2022-08-20T17:13:47.817Z,1661015627.817 [transit:StandardEnvelopes] Running Loop=1
2022-08-20T17:13:47.817Z,1661015627.817 [transit:StandardEnvelopes](DEBUG): Aggregate::initialize transit:StandardEnvelopes
2022-08-20T17:13:47.817Z,1661015627.817 [transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2022-08-20T17:13:47.817Z,1661015627.817 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent.
2022-08-20T17:13:47.818Z,1661015627.818 [transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2022-08-20T17:13:47.818Z,1661015627.818 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent.
2022-08-20T17:13:47.818Z,1661015627.818 [transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2022-08-20T17:13:47.818Z,1661015627.818 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent.
2022-08-20T17:13:47.818Z,1661015627.818 [transit:BuoyancyHold.Buoyancy] Running Loop=1
2022-08-20T17:13:47.818Z,1661015627.818 [transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component.
2022-08-20T17:13:47.818Z,1661015627.818 [transit:MassHold.Pitch] Running Loop=1
2022-08-20T17:13:47.818Z,1661015627.818 [transit:MassHold.Pitch](DEBUG): Initialize.
2022-08-20T17:13:47.819Z,1661015627.819 [transit:B] Running Loop=1
2022-08-20T17:13:47.819Z,1661015627.819 [transit:MassHold.Pitch] Running Loop=1
2022-08-20T17:13:47.820Z,1661015627.820 [transit:BuoyancyHold.Buoyancy] Running Loop=1
2022-08-20T17:13:47.820Z,1661015627.820 [transit:StandardEnvelopes] Running Loop=1
2022-08-20T17:13:47.820Z,1661015627.820 [transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1
2022-08-20T17:13:47.829Z,1661015627.829 [transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1
2022-08-20T17:13:47.829Z,1661015627.829 [transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1
2022-08-20T17:13:47.830Z,1661015627.830 [transit:B] Stopped
2022-08-20T17:13:47.830Z,1661015627.830 [transit:C] Running Loop=1
2022-08-20T17:13:48.238Z,1661015628.238 [transit:C] Stopped
2022-08-20T17:13:48.238Z,1661015628.238 [transit:E] Running Loop=1
2022-08-20T17:13:48.625Z,1661015628.625 [transit:E] Stopped
2022-08-20T17:13:48.626Z,1661015628.626 [transit:F] Running Loop=1
2022-08-20T17:13:49.017Z,1661015629.017 [transit:F] Stopped
2022-08-20T17:13:49.018Z,1661015629.018 [transit:G] Running Loop=1
2022-08-20T17:13:49.432Z,1661015629.432 [transit:G] Stopped
2022-08-20T17:13:49.432Z,1661015629.432 [transit:Transit] Running Loop=1
2022-08-20T17:13:49.432Z,1661015629.432 [transit:Transit](DEBUG): Aggregate::initialize transit:Transit
2022-08-20T17:13:49.432Z,1661015629.432 [transit:Transit:A.Pitch] Running Loop=1
2022-08-20T17:13:49.432Z,1661015629.432 [transit:Transit:A.Pitch](DEBUG): Initialize.
2022-08-20T17:13:49.433Z,1661015629.433 [transit:Transit:B.SetSpeed] Running Loop=1
2022-08-20T17:13:49.433Z,1661015629.433 [transit:Transit:B.SetSpeed](DEBUG): Initialize.
2022-08-20T17:13:49.433Z,1661015629.433 [transit:Transit:Wpt1.Waypoint] Running Loop=1
2022-08-20T17:13:49.433Z,1661015629.433 [transit:Transit:Wpt1.Waypoint](DEBUG): Initialize WaypointComponent.
2022-08-20T17:13:49.435Z,1661015629.435 [transit:Transit:Wpt1.Waypoint](IMPORTANT): Navigating to waypoint: 43.200169,-86.364899
2022-08-20T17:13:49.444Z,1661015629.444 [transit:StandardEnvelopes:A.AltitudeEnvelope](ERROR): Altitude Measurement is not Active.
2022-08-20T17:13:49.829Z,1661015629.829 [transit:Transit:B.SetSpeed] Running Loop=1
2022-08-20T17:13:49.829Z,1661015629.829 [transit:Transit:A.Pitch] Running Loop=1
2022-08-20T17:14:19.381Z,1661015659.381 [DataOverHttps](IMPORTANT): SBD MTMSN=20220820T171418
2022-08-20T17:14:31.252Z,1661015671.252 [DataOverHttps](INFO): Received command: stop
2022-08-20T17:14:31.294Z,1661015671.294 [CommandExec](IMPORTANT): got command stop
2022-08-20T17:14:31.294Z,1661015671.294 [CommandExec](IMPORTANT): Scheduling is paused
2022-08-20T17:14:31.294Z,1661015671.294 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2022-08-20T17:14:31.695Z,1661015671.695 [MissionManager](INFO): MissionManager is completed.
2022-08-20T17:14:31.695Z,1661015671.695 [MissionManager](INFO): Uninitializing Mission transit
2022-08-20T17:14:31.695Z,1661015671.695 [transit] Stopped
2022-08-20T17:14:31.695Z,1661015671.695 [transit](DEBUG): Aggregate::uninitialize transit
2022-08-20T17:14:31.695Z,1661015671.695 [transit:StandardEnvelopes] Stopped
2022-08-20T17:14:31.695Z,1661015671.695 [transit:StandardEnvelopes](DEBUG): Aggregate::uninitialize transit:StandardEnvelopes
2022-08-20T17:14:31.695Z,1661015671.695 [transit:StandardEnvelopes:A.AltitudeEnvelope] Stopped
2022-08-20T17:14:31.695Z,1661015671.695 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent.
2022-08-20T17:14:31.696Z,1661015671.696 [transit:StandardEnvelopes:B.DepthEnvelope] Stopped
2022-08-20T17:14:31.696Z,1661015671.696 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize.
2022-08-20T17:14:31.696Z,1661015671.696 [transit:StandardEnvelopes:C.OffshoreEnvelope] Stopped
2022-08-20T17:14:31.700Z,1661015671.700 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent.
2022-08-20T17:14:31.700Z,1661015671.700 [transit:BuoyancyHold.Buoyancy] Stopped
2022-08-20T17:14:31.700Z,1661015671.700 [transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2022-08-20T17:14:31.700Z,1661015671.700 [transit:MassHold.Pitch] Stopped
2022-08-20T17:14:31.700Z,1661015671.700 [transit:Transit] Stopped
2022-08-20T17:14:31.700Z,1661015671.700 [transit:Transit](DEBUG): Aggregate::uninitialize transit:Transit
2022-08-20T17:14:31.700Z,1661015671.700 [transit:Transit:A.Pitch] Stopped
2022-08-20T17:14:31.701Z,1661015671.701 [transit:Transit:B.SetSpeed] Stopped
2022-08-20T17:14:31.701Z,1661015671.701 [transit:Transit:B.SetSpeed](DEBUG): Uninitialize.
2022-08-20T17:14:31.701Z,1661015671.701 [transit:Transit:Wpt1.Waypoint] Stopped
2022-08-20T17:14:31.701Z,1661015671.701 [transit:Transit:Wpt1.Waypoint](DEBUG): Uninitialize WaypointComponent.
2022-08-20T17:14:32.027Z,1661015672.027 [MissionManager](IMPORTANT): Started mission Default
2022-08-20T17:14:32.028Z,1661015672.028 [Default] Running Loop=1
2022-08-20T17:14:32.029Z,1661015672.029 [Default](DEBUG): Aggregate::initialize Default
2022-08-20T17:14:32.029Z,1661015672.029 [Default:B.GoToSurface] Running Loop=1
2022-08-20T17:14:32.030Z,1661015672.030 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-08-20T17:14:32.031Z,1661015672.031 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-08-20T17:14:32.056Z,1661015672.056 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-08-20T17:14:32.056Z,1661015672.056 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-08-20T17:14:32.057Z,1661015672.057 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-08-20T17:14:32.057Z,1661015672.057 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-08-20T17:14:32.058Z,1661015672.058 [Default:A.Wait] Running Loop=1
2022-08-20T17:14:32.058Z,1661015672.058 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-08-20T17:14:45.363Z,1661015685.363 [Default:A.Wait](INFO): Done Waiting.
2022-08-20T17:14:45.363Z,1661015685.363 [Default:A.Wait] Stopped
2022-08-20T17:14:45.363Z,1661015685.363 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-08-20T17:14:45.756Z,1661015685.756 [Default:CheckIn] Running Loop=1
2022-08-20T17:14:45.756Z,1661015685.756 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-08-20T17:14:45.756Z,1661015685.756 [Default:CheckIn:Read_GPS] Running Loop=1
2022-08-20T17:14:47.785Z,1661015687.785 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171447.00,A,4312.73082,N,08619.65918,W,0.039,329.53,200822,,,D*78
2022-08-20T17:14:47.788Z,1661015687.788 [NAL9602](INFO): GPS fix at 20220820T171447: (43.212180, -86.327653)
2022-08-20T17:14:47.811Z,1661015687.811 [Default:CheckIn:Read_GPS] Stopped
2022-08-20T17:14:47.811Z,1661015687.811 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-08-20T17:14:57.200Z,1661015697.200 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220820T152523/Courier0058.lzma
2022-08-20T17:14:58.202Z,1661015698.202 [DataOverHttps](INFO): Moved sent file to Logs/20220820T152523/Courier0058.lzma.bak
2022-08-20T17:14:58.202Z,1661015698.202 [DataOverHttps](INFO): SBD MOMSN=17118500
2022-08-20T17:15:09.749Z,1661015709.749 [DataOverHttps](IMPORTANT): SBD MTMSN=20220820T171508