2023-05-12T16:54:10.015Z,1683910450.015 [Supervisor](DEBUG): Initializing supervisor.
2023-05-12T16:54:10.019Z,1683910450.019 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-05-12T16:54:10.020Z,1683910450.020 [SyncHandler](INFO): Protected caller Thread ID is 3050
2023-05-12T16:54:10.020Z,1683910450.020 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-05-12T16:54:10.021Z,1683910450.021 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-05-12T16:54:10.021Z,1683910450.021 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3051
2023-05-12T16:54:10.025Z,1683910450.025 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-05-12T16:54:10.043Z,1683910450.043 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-05-12T16:54:10.044Z,1683910450.044 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-05-12T16:54:10.044Z,1683910450.044 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 3052
2023-05-12T16:54:10.048Z,1683910450.048 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-05-12T16:54:10.049Z,1683910450.049 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-05-12T16:54:10.050Z,1683910450.050 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3053
2023-05-12T16:54:10.052Z,1683910450.052 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-05-12T16:54:10.053Z,1683910450.053 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-05-12T16:54:10.053Z,1683910450.053 [logger ThreadHandler](INFO): Protected caller Thread ID is 3054
2023-05-12T16:54:10.057Z,1683910450.057 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-05-12T16:54:10.057Z,1683910450.057 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-05-12T16:54:10.059Z,1683910450.059 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-05-12T16:54:10.156Z,1683910450.156 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-05-12T16:54:10.157Z,1683910450.157 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-05-12T16:54:10.922Z,1683910450.922 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-05-12T16:54:10.923Z,1683910450.923 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-05-12T16:54:11.154Z,1683910451.154 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-05-12T16:54:11.154Z,1683910451.154 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-05-12T16:54:11.234Z,1683910451.234 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-05-12T16:54:11.369Z,1683910451.369 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-05-12T16:54:11.370Z,1683910451.370 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-05-12T16:54:11.453Z,1683910451.453 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-05-12T16:54:11.562Z,1683910451.562 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-05-12T16:54:11.563Z,1683910451.563 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-05-12T16:54:11.951Z,1683910451.951 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-05-12T16:54:11.951Z,1683910451.951 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-05-12T16:54:12.516Z,1683910452.516 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-05-12T16:54:12.517Z,1683910452.517 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-05-12T16:54:12.741Z,1683910452.741 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-05-12T16:54:12.742Z,1683910452.742 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-05-12T16:54:12.931Z,1683910452.931 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-05-12T16:54:12.932Z,1683910452.932 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-05-12T16:54:13.439Z,1683910453.439 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-05-12T16:54:13.440Z,1683910453.440 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-05-12T16:54:13.738Z,1683910453.738 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-05-12T16:54:13.739Z,1683910453.739 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-05-12T16:54:13.955Z,1683910453.955 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-05-12T16:54:13.956Z,1683910453.956 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-05-12T16:54:14.321Z,1683910454.321 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-05-12T16:54:14.322Z,1683910454.322 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-05-12T16:54:14.661Z,1683910454.661 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-05-12T16:54:14.663Z,1683910454.663 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2023-05-12T16:54:14.664Z,1683910454.664 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2023-05-12T16:54:14.748Z,1683910454.748 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2023-05-12T16:54:14.908Z,1683910454.908 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2023-05-12T16:54:15.011Z,1683910455.011 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2023-05-12T16:54:15.098Z,1683910455.098 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2023-05-12T16:54:15.193Z,1683910455.193 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2023-05-12T16:54:15.376Z,1683910455.376 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2023-05-12T16:54:15.641Z,1683910455.641 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-05-12T16:54:15.641Z,1683910455.641 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2023-05-12T16:54:15.737Z,1683910455.737 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2023-05-12T16:54:15.836Z,1683910455.836 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2023-05-12T16:54:15.988Z,1683910455.988 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2023-05-12T16:54:16.300Z,1683910456.300 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2023-05-12T16:54:16.301Z,1683910456.301 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-05-12T16:54:16.309Z,1683910456.309 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-05-12T16:54:16.447Z,1683910456.447 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-05-12T16:54:16.448Z,1683910456.448 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-05-12T16:54:16.600Z,1683910456.600 [VerticalControl](DEBUG): Construct VerticalControl.
2023-05-12T16:54:16.778Z,1683910456.778 [VerticalControl] Loaded
2023-05-12T16:54:16.778Z,1683910456.778 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-05-12T16:54:16.781Z,1683910456.781 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-05-12T16:54:16.963Z,1683910456.963 [HorizontalControl] Loaded
2023-05-12T16:54:16.963Z,1683910456.963 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-05-12T16:54:16.966Z,1683910456.966 [SpeedControl](DEBUG): Construct SpeedControl.
2023-05-12T16:54:16.969Z,1683910456.969 [SpeedControl] Loaded
2023-05-12T16:54:16.969Z,1683910456.969 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-05-12T16:54:16.972Z,1683910456.972 [LoopControl](DEBUG): Construct LoopControl.
2023-05-12T16:54:16.972Z,1683910456.972 [LoopControl] Loaded
2023-05-12T16:54:16.972Z,1683910456.972 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-05-12T16:54:16.973Z,1683910456.973 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-05-12T16:54:16.973Z,1683910456.973 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-05-12T16:54:17.029Z,1683910457.029 [DepthRateCalculator] Loaded
2023-05-12T16:54:17.029Z,1683910457.029 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-05-12T16:54:17.046Z,1683910457.046 [PitchRateCalculator] Loaded
2023-05-12T16:54:17.046Z,1683910457.046 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-05-12T16:54:17.064Z,1683910457.064 [SpeedCalculator] Loaded
2023-05-12T16:54:17.065Z,1683910457.065 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-05-12T16:54:17.081Z,1683910457.081 [YawRateCalculator] Loaded
2023-05-12T16:54:17.081Z,1683910457.081 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-05-12T16:54:17.123Z,1683910457.123 [ElevatorOffsetCalculator] Loaded
2023-05-12T16:54:17.123Z,1683910457.123 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-05-12T16:54:17.124Z,1683910457.124 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-05-12T16:54:17.124Z,1683910457.124 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-05-12T16:54:17.252Z,1683910457.252 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-05-12T16:54:17.253Z,1683910457.253 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-05-12T16:54:17.320Z,1683910457.320 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-05-12T16:54:17.321Z,1683910457.321 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-05-12T16:54:17.616Z,1683910457.616 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-05-12T16:54:17.616Z,1683910457.616 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-05-12T16:54:17.755Z,1683910457.755 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-05-12T16:54:17.756Z,1683910457.756 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-05-12T16:54:18.178Z,1683910458.178 [AHRS_M2] Loaded
2023-05-12T16:54:18.178Z,1683910458.178 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2023-05-12T16:54:18.213Z,1683910458.213 [BackseatComponent] Loaded
2023-05-12T16:54:18.213Z,1683910458.213 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-05-12T16:54:18.214Z,1683910458.214 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 409994E0
2023-05-12T16:54:18.215Z,1683910458.215 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 3137
2023-05-12T16:54:18.217Z,1683910458.217 [LcmUniversalReporter] Loaded
2023-05-12T16:54:18.218Z,1683910458.218 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-05-12T16:54:19.021Z,1683910459.021 [BPC1] Loaded
2023-05-12T16:54:19.021Z,1683910459.021 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-05-12T16:54:19.104Z,1683910459.104 [DATMMP] Loaded
2023-05-12T16:54:19.104Z,1683910459.104 [ComponentRegistry](DEBUG): Component "DATMMP" handled in its own thread.
2023-05-12T16:54:19.105Z,1683910459.105 [DATMMP ThreadHandler](DEBUG): Created PCaller Thread at 409CA4E0
2023-05-12T16:54:19.105Z,1683910459.105 [DATMMP ThreadHandler](INFO): Protected caller Thread ID is 3138
2023-05-12T16:54:19.179Z,1683910459.179 [DataOverHttps] Loaded
2023-05-12T16:54:19.179Z,1683910459.179 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-05-12T16:54:19.180Z,1683910459.180 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409FA4E0
2023-05-12T16:54:19.181Z,1683910459.181 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 3139
2023-05-12T16:54:19.201Z,1683910459.201 [Depth_Keller] Loaded
2023-05-12T16:54:19.201Z,1683910459.201 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-05-12T16:54:19.265Z,1683910459.265 [NAL9602] Loaded
2023-05-12T16:54:19.265Z,1683910459.265 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-05-12T16:54:19.294Z,1683910459.294 [Onboard] Loaded
2023-05-12T16:54:19.295Z,1683910459.295 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-05-12T16:54:19.296Z,1683910459.296 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A2A4E0
2023-05-12T16:54:19.296Z,1683910459.296 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 3140
2023-05-12T16:54:19.308Z,1683910459.308 [Power24vConverter] Loaded
2023-05-12T16:54:19.309Z,1683910459.309 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-05-12T16:54:19.321Z,1683910459.321 [Radio_Surface] Loaded
2023-05-12T16:54:19.322Z,1683910459.322 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-05-12T16:54:19.323Z,1683910459.323 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40A5A4E0
2023-05-12T16:54:19.323Z,1683910459.323 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3141
2023-05-12T16:54:19.368Z,1683910459.368 [RDI_Pathfinder] Loaded
2023-05-12T16:54:19.368Z,1683910459.368 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2023-05-12T16:54:19.369Z,1683910459.369 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-05-12T16:54:19.370Z,1683910459.370 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-05-12T16:54:19.477Z,1683910459.477 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-05-12T16:54:19.478Z,1683910459.478 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-05-12T16:54:19.491Z,1683910459.491 [NavChart] Loaded
2023-05-12T16:54:19.491Z,1683910459.491 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-05-12T16:54:19.497Z,1683910459.497 [UniversalFixResidualReporter] Loaded
2023-05-12T16:54:19.497Z,1683910459.497 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-05-12T16:54:19.498Z,1683910459.498 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-05-12T16:54:19.498Z,1683910459.498 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-05-12T16:54:19.632Z,1683910459.632 [SBIT](DEBUG): Construct Startup Built In Test.
2023-05-12T16:54:19.641Z,1683910459.641 [SBIT] Loaded
2023-05-12T16:54:19.642Z,1683910459.642 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-05-12T16:54:19.644Z,1683910459.644 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-05-12T16:54:19.657Z,1683910459.657 [IBIT] Loaded
2023-05-12T16:54:19.657Z,1683910459.657 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-05-12T16:54:19.663Z,1683910459.663 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-05-12T16:54:19.766Z,1683910459.766 [CBIT] Loaded
2023-05-12T16:54:19.766Z,1683910459.766 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-05-12T16:54:19.766Z,1683910459.766 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-05-12T16:54:19.767Z,1683910459.767 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-05-12T16:54:19.896Z,1683910459.896 [BuoyancyServo] Loaded
2023-05-12T16:54:19.896Z,1683910459.896 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-05-12T16:54:19.917Z,1683910459.917 [ElevatorServo] Loaded
2023-05-12T16:54:19.917Z,1683910459.917 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-05-12T16:54:19.937Z,1683910459.937 [MassServo] Loaded
2023-05-12T16:54:19.937Z,1683910459.937 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-05-12T16:54:19.955Z,1683910459.955 [RudderServo] Loaded
2023-05-12T16:54:19.956Z,1683910459.956 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-05-12T16:54:19.973Z,1683910459.973 [ThrusterServo] Loaded
2023-05-12T16:54:19.973Z,1683910459.973 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2023-05-12T16:54:19.973Z,1683910459.973 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-05-12T16:54:19.974Z,1683910459.974 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-05-12T16:54:19.984Z,1683910459.984 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-05-12T16:54:19.984Z,1683910459.984 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-05-12T16:54:20.150Z,1683910460.150 [CTD_Seabird] Loaded
2023-05-12T16:54:20.151Z,1683910460.151 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2023-05-12T16:54:20.152Z,1683910460.152 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40BA24E0
2023-05-12T16:54:20.152Z,1683910460.152 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 3142
2023-05-12T16:54:20.172Z,1683910460.172 [PAR_Licor] Loaded
2023-05-12T16:54:20.173Z,1683910460.173 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-05-12T16:54:20.203Z,1683910460.203 [WetLabsBB2FL] Loaded
2023-05-12T16:54:20.204Z,1683910460.204 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2023-05-12T16:54:20.205Z,1683910460.205 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40BD24E0
2023-05-12T16:54:20.205Z,1683910460.205 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 3143
2023-05-12T16:54:20.225Z,1683910460.225 [WetLabsUBAT] Loaded
2023-05-12T16:54:20.225Z,1683910460.225 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2023-05-12T16:54:20.226Z,1683910460.226 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40C024E0
2023-05-12T16:54:20.226Z,1683910460.226 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 3144
2023-05-12T16:54:20.227Z,1683910460.227 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-05-12T16:54:20.233Z,1683910460.233 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-05-12T16:54:20.236Z,1683910460.236 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-05-12T16:54:20.247Z,1683910460.247 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-05-12T16:54:20.248Z,1683910460.248 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C324E0
2023-05-12T16:54:20.248Z,1683910460.248 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3145
2023-05-12T16:54:20.253Z,1683910460.253 [Supervisor](INFO): Main Thread ID is 3049
2023-05-12T16:54:20.253Z,1683910460.253 [Supervisor](DEBUG): Running supervisor.
2023-05-12T16:54:20.254Z,1683910460.254 [CommandExec ThreadHandler](INFO): Handler Thread ID is 3146
2023-05-12T16:54:20.254Z,1683910460.254 [CommandExec](INFO): Initializing the command executive.
2023-05-12T16:54:20.256Z,1683910460.256 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3147
2023-05-12T16:54:20.258Z,1683910460.258 [controlThread ThreadHandler](INFO): Handler Thread ID is 3148
2023-05-12T16:54:20.258Z,1683910460.258 [controlThread](DEBUG): Initializing ControlThread
2023-05-12T16:54:20.259Z,1683910460.259 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-05-12T16:54:20.261Z,1683910460.261 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-05-12T16:54:20.261Z,1683910460.261 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-05-12T16:54:20.262Z,1683910460.262 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-05-12T16:54:20.262Z,1683910460.262 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-05-12T16:54:20.263Z,1683910460.263 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-05-12T16:54:20.263Z,1683910460.263 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-05-12T16:54:20.263Z,1683910460.263 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-05-12T16:54:20.264Z,1683910460.264 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-05-12T16:54:20.269Z,1683910460.269 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-05-12T16:54:20.269Z,1683910460.269 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-05-12T16:54:20.270Z,1683910460.270 [SBIT](INFO): Initialize SBIT Component.
2023-05-12T16:54:20.270Z,1683910460.270 [SBIT](IMPORTANT): git: 2023-04-26-68-gd8052d973
2023-05-12T16:54:20.270Z,1683910460.270 [SBIT](INFO): git hash: d8052d9734beefc1bd50265fa9cca972428f086c
2023-05-12T16:54:20.271Z,1683910460.271 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-05-12T16:54:20.272Z,1683910460.272 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2023-05-12T16:54:20.273Z,1683910460.273 [SBIT](INFO): Beginning SBIT in 51.000000 seconds.
2023-05-12T16:54:20.273Z,1683910460.273 [IBIT](INFO): Initialize IBIT Component.
2023-05-12T16:54:20.274Z,1683910460.274 [CBIT](DEBUG): Initialize CBIT Component.
2023-05-12T16:54:20.275Z,1683910460.275 [logger ThreadHandler](INFO): Handler Thread ID is 3149
2023-05-12T16:54:20.288Z,1683910460.288 [CBIT](DEBUG): Initialized mux pins.
2023-05-12T16:54:20.288Z,1683910460.288 [CBIT](DEBUG): Initializing the watchdog timer.
2023-05-12T16:54:20.292Z,1683910460.292 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 3150
2023-05-12T16:54:20.300Z,1683910460.300 [DATMMP ThreadHandler](INFO): Handler Thread ID is 3151
2023-05-12T16:54:20.301Z,1683910460.301 [DATMMP](INFO): Start
2023-05-12T16:54:20.301Z,1683910460.301 [DATMMP](INFO): Powering up
2023-05-12T16:54:20.301Z,1683910460.301 [DATMMP](DEBUG): Initializing DATMMP.
2023-05-12T16:54:20.305Z,1683910460.305 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 3153
2023-05-12T16:54:20.306Z,1683910460.306 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-05-12T16:54:20.312Z,1683910460.312 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-05-12T16:54:20.312Z,1683910460.312 [CBIT](DEBUG): Initializing heartbeat.
2023-05-12T16:54:20.320Z,1683910460.320 [Onboard ThreadHandler](INFO): Handler Thread ID is 3154
2023-05-12T16:54:20.338Z,1683910460.338 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3155
2023-05-12T16:54:20.364Z,1683910460.364 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 3156
2023-05-12T16:54:20.365Z,1683910460.365 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2023-05-12T16:54:20.369Z,1683910460.369 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 3158
2023-05-12T16:54:20.372Z,1683910460.372 [WetLabsBB2FL](INFO): Powering up
2023-05-12T16:54:20.373Z,1683910460.373 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 3160
2023-05-12T16:54:20.376Z,1683910460.376 [WetLabsUBAT](INFO): Powering up
2023-05-12T16:54:20.377Z,1683910460.377 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3162
2023-05-12T16:54:20.381Z,1683910460.381 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-05-12T16:54:20.381Z,1683910460.381 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-05-12T16:54:20.381Z,1683910460.381 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-05-12T16:54:20.381Z,1683910460.381 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-05-12T16:54:20.381Z,1683910460.381 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-05-12T16:54:20.382Z,1683910460.382 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-05-12T16:54:20.382Z,1683910460.382 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-05-12T16:54:20.382Z,1683910460.382 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-05-12T16:54:20.384Z,1683910460.384 [CBIT](DEBUG): Deactivating GF circuits.
2023-05-12T16:54:20.384Z,1683910460.384 [CBIT](DEBUG): Deactivating emergency mode.
2023-05-12T16:54:20.424Z,1683910460.424 [CBIT](DEBUG): Backplane powered.
2023-05-12T16:54:20.429Z,1683910460.429 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-05-12T16:54:20.458Z,1683910460.458 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-12T16:54:20.501Z,1683910460.501 [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>


2023-05-12T16:54:20.502Z,1683910460.502 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-05-12T16:54:20.552Z,1683910460.552 [DATMMP](INFO): Starting
2023-05-12T16:54:20.589Z,1683910460.589 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-05-12T16:54:20.591Z,1683910460.591 [Default:A.Wait](DEBUG): Construct Wait.
2023-05-12T16:54:20.593Z,1683910460.593 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-12T16:54:20.647Z,1683910460.647 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-05-12T16:54:20.649Z,1683910460.649 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-05-12T16:54:20.660Z,1683910460.660 [Default:E.Execute](DEBUG): Construct Execute.
2023-05-12T16:54:20.663Z,1683910460.663 [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="P4H">
                <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>


2023-05-12T16:54:20.672Z,1683910460.672 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,NAL9602,Power24vConverter,RDI_Pathfinder,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T16:54:20.681Z,1683910460.681 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2023-05-12T16:54:20.744Z,1683910460.744 [Radio_Surface](INFO): Powering up
2023-05-12T16:54:20.754Z,1683910460.754 [Depth_Keller](ERROR): Pressure or depth reading out of range: -1.000394 decibar, -0.993016 m
2023-05-12T16:54:20.754Z,1683910460.754 [Power24vConverter](INFO): Powering up.
2023-05-12T16:54:20.755Z,1683910460.755 [RDI_Pathfinder](IMPORTANT): Expecting PD13 message format
2023-05-12T16:54:20.804Z,1683910460.804 [DATMMP](INFO): Starting
2023-05-12T16:54:20.813Z,1683910460.813 [DepthRateCalculator](ERROR): Depth measurement is not active
2023-05-12T16:54:20.848Z,1683910460.848 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:54:20.856Z,1683910460.856 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-05-12T16:54:20.857Z,1683910460.857 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:54:20.864Z,1683910460.864 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-05-12T16:54:20.865Z,1683910460.865 [MassServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:54:20.872Z,1683910460.872 [MassServo](DEBUG): Initializing MassServo.
2023-05-12T16:54:20.873Z,1683910460.873 [RudderServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:54:20.880Z,1683910460.880 [RudderServo](DEBUG): Initializing RudderServo.
2023-05-12T16:54:20.881Z,1683910460.881 [ThrusterServo](DEBUG): Initializing EZServoServo.
2023-05-12T16:54:20.888Z,1683910460.888 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2023-05-12T16:54:21.056Z,1683910461.056 [DATMMP](INFO): Starting
2023-05-12T16:54:21.308Z,1683910461.308 [DATMMP](INFO): Starting
2023-05-12T16:54:21.560Z,1683910461.560 [DATMMP](INFO): Starting
2023-05-12T16:54:21.812Z,1683910461.812 [DATMMP](INFO): Starting
2023-05-12T16:54:22.064Z,1683910462.064 [DATMMP](INFO): Starting
2023-05-12T16:54:22.316Z,1683910462.316 [DATMMP](INFO): Starting
2023-05-12T16:54:22.568Z,1683910462.568 [DATMMP](INFO): Starting
2023-05-12T16:54:22.820Z,1683910462.820 [DATMMP](INFO): Starting
2023-05-12T16:54:22.984Z,1683910462.984 [WetLabsBB2FL](INFO): Powering down
2023-05-12T16:54:23.072Z,1683910463.072 [DATMMP](INFO): Starting
2023-05-12T16:54:23.324Z,1683910463.324 [DATMMP](INFO): Starting
2023-05-12T16:54:23.576Z,1683910463.576 [DATMMP](INFO): Starting
2023-05-12T16:54:23.828Z,1683910463.828 [DATMMP](INFO): Starting
2023-05-12T16:54:24.080Z,1683910464.080 [DATMMP](INFO): Starting
2023-05-12T16:54:24.332Z,1683910464.332 [DATMMP](INFO): Starting
2023-05-12T16:54:24.584Z,1683910464.584 [DATMMP](INFO): Starting
2023-05-12T16:54:24.837Z,1683910464.837 [DATMMP](INFO): Starting
2023-05-12T16:54:25.088Z,1683910465.088 [DATMMP](INFO): Starting
2023-05-12T16:54:25.341Z,1683910465.341 [DATMMP](INFO): Starting
2023-05-12T16:54:25.592Z,1683910465.592 [DATMMP](INFO): Starting
2023-05-12T16:54:25.844Z,1683910465.844 [DATMMP](INFO): Starting
2023-05-12T16:54:26.096Z,1683910466.096 [DATMMP](INFO): Starting
2023-05-12T16:54:26.349Z,1683910466.349 [DATMMP](INFO): Starting
2023-05-12T16:54:26.600Z,1683910466.600 [DATMMP](INFO): Starting
2023-05-12T16:54:26.852Z,1683910466.852 [DATMMP](INFO): Starting
2023-05-12T16:54:27.104Z,1683910467.104 [DATMMP](INFO): Starting
2023-05-12T16:54:27.356Z,1683910467.356 [DATMMP](INFO): Starting
2023-05-12T16:54:27.608Z,1683910467.608 [DATMMP](INFO): Starting
2023-05-12T16:54:27.860Z,1683910467.860 [DATMMP](INFO): Starting
2023-05-12T16:54:28.112Z,1683910468.112 [DATMMP](INFO): Starting
2023-05-12T16:54:28.366Z,1683910468.366 [DATMMP](INFO): Starting
2023-05-12T16:54:28.616Z,1683910468.616 [DATMMP](INFO): Starting
2023-05-12T16:54:28.868Z,1683910468.868 [DATMMP](INFO): Starting
2023-05-12T16:54:29.120Z,1683910469.120 [DATMMP](INFO): Starting
2023-05-12T16:54:29.372Z,1683910469.372 [DATMMP](INFO): Starting
2023-05-12T16:54:29.620Z,1683910469.620 [WetLabsUBAT](INFO): Powering down
2023-05-12T16:54:29.624Z,1683910469.624 [DATMMP](INFO): Starting
2023-05-12T16:54:29.876Z,1683910469.876 [DATMMP](INFO): Starting
2023-05-12T16:54:30.128Z,1683910470.128 [DATMMP](INFO): Starting
2023-05-12T16:54:30.380Z,1683910470.380 [DATMMP](INFO): Starting
2023-05-12T16:54:30.632Z,1683910470.632 [DATMMP](INFO): Starting
2023-05-12T16:54:30.884Z,1683910470.884 [DATMMP](INFO): Starting
2023-05-12T16:54:31.136Z,1683910471.136 [DATMMP](INFO): Starting
2023-05-12T16:54:31.388Z,1683910471.388 [DATMMP](INFO): Starting
2023-05-12T16:54:31.640Z,1683910471.640 [DATMMP](INFO): Starting
2023-05-12T16:54:31.892Z,1683910471.892 [DATMMP](INFO): Starting
2023-05-12T16:54:32.144Z,1683910472.144 [DATMMP](INFO): Starting
2023-05-12T16:54:32.396Z,1683910472.396 [DATMMP](INFO): Starting
2023-05-12T16:54:32.396Z,1683910472.396 [DATMMP](INFO): DAT read: 

2023-05-12T16:54:32.397Z,1683910472.397 [DATMMP](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-05-12T16:54:32.648Z,1683910472.648 [DATMMP](INFO): Starting
2023-05-12T16:54:32.900Z,1683910472.900 [DATMMP](INFO): Starting
2023-05-12T16:54:33.152Z,1683910473.152 [DATMMP](INFO): Starting
2023-05-12T16:54:33.404Z,1683910473.404 [DATMMP](INFO): Starting
2023-05-12T16:54:33.656Z,1683910473.656 [DATMMP](INFO): Starting
2023-05-12T16:54:33.908Z,1683910473.908 [DATMMP](INFO): Starting
2023-05-12T16:54:34.150Z,1683910474.150 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004538
2023-05-12T16:54:34.160Z,1683910474.160 [DATMMP](INFO): Starting
2023-05-12T16:54:34.161Z,1683910474.161 [DATMMP](INFO): DAT read: MF Frequency Band

2023-05-12T16:54:34.162Z,1683910474.162 [DATMMP](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-05-12T16:54:34.162Z,1683910474.162 [DATMMP](INFO): DAT read: Apr 12 2000 16:44:02 

2023-05-12T16:54:34.412Z,1683910474.412 [DATMMP](INFO): Starting
2023-05-12T16:54:34.664Z,1683910474.664 [DATMMP](INFO): Starting
2023-05-12T16:54:34.916Z,1683910474.916 [DATMMP](INFO): Starting
2023-05-12T16:54:35.168Z,1683910475.168 [DATMMP](INFO): Starting
2023-05-12T16:54:35.169Z,1683910475.169 [DATMMP](INFO): DAT read: Features enabled [Bearing]

2023-05-12T16:54:35.170Z,1683910475.170 [DATMMP](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2023-05-12T16:54:35.170Z,1683910475.170 [DATMMP](INFO): commRate: 800
2023-05-12T16:54:35.420Z,1683910475.420 [DATMMP](INFO): Starting
2023-05-12T16:54:35.672Z,1683910475.672 [DATMMP](INFO): Starting
2023-05-12T16:54:35.924Z,1683910475.924 [DATMMP](INFO): Starting
2023-05-12T16:54:36.176Z,1683910476.176 [DATMMP](INFO): Starting
2023-05-12T16:54:36.428Z,1683910476.428 [DATMMP](INFO): Starting
2023-05-12T16:54:36.681Z,1683910476.681 [DATMMP](INFO): Starting
2023-05-12T16:54:36.932Z,1683910476.932 [DATMMP](INFO): Starting
2023-05-12T16:54:37.184Z,1683910477.184 [DATMMP](INFO): Starting
2023-05-12T16:54:37.236Z,1683910477.236 [DATMMP](INFO): entering command mode
2023-05-12T16:54:37.436Z,1683910477.436 [DATMMP](INFO): Starting
2023-05-12T16:54:37.436Z,1683910477.436 [DATMMP](INFO): DAT read: 

2023-05-12T16:54:37.437Z,1683910477.437 [DATMMP](INFO): DAT read: user:1>

2023-05-12T16:54:37.437Z,1683910477.437 [DATMMP](DEBUG): read user prompt 1: user:1>

2023-05-12T16:54:37.437Z,1683910477.437 [DATMMP](INFO): entering MMP mode
2023-05-12T16:54:37.688Z,1683910477.688 [DATMMP](INFO): Starting
2023-05-12T16:54:37.689Z,1683910477.689 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:54:37.690Z,1683910477.690 [DATMMP](INFO): status rx: 	 x1
2023-05-12T16:54:37.690Z,1683910477.690 [DATMMP](INFO): MMP status: 1: started
2023-05-12T16:54:37.691Z,1683910477.691 [DATMMP](INFO): Received message type: status
2023-05-12T16:54:37.691Z,1683910477.691 [DATMMP](INFO): Handled
2023-05-12T16:54:37.940Z,1683910477.940 [DATMMP](INFO): Starting
2023-05-12T16:54:37.941Z,1683910477.941 [DATMMP](INFO): Sent Tx Power Config 8
2023-05-12T16:54:37.941Z,1683910477.941 [DATMMP](INFO): Setting local address: 10
2023-05-12T16:54:37.943Z,1683910477.943 [DATMMP](INFO): Setting time to: 16:54:37 And date to:5/12/2023
2023-05-12T16:54:38.192Z,1683910478.192 [DATMMP](INFO): Starting
2023-05-12T16:54:38.192Z,1683910478.192 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:54:38.193Z,1683910478.193 [DATMMP](INFO): mdmpower rx: 	 x8	 x0	 x5	 x0
2023-05-12T16:54:38.193Z,1683910478.193 [DATMMP](INFO): Received message type: mdmpower
2023-05-12T16:54:38.194Z,1683910478.194 [DATMMP](INFO): Handled
2023-05-12T16:54:38.444Z,1683910478.444 [DATMMP](INFO): Starting
2023-05-12T16:54:38.445Z,1683910478.445 [DATMMP](INFO): GSXN notify for xid: 10
2023-05-12T16:54:38.445Z,1683910478.445 [DATMMP](INFO): sreg_txpower rx: 	 x8
2023-05-12T16:54:38.445Z,1683910478.445 [DATMMP](INFO): Received message type: sreg_txpower
2023-05-12T16:54:38.446Z,1683910478.446 [DATMMP](INFO): Match for : sreg_txpower
2023-05-12T16:54:38.446Z,1683910478.446 [DATMMP](INFO): ACK
2023-05-12T16:54:38.696Z,1683910478.696 [DATMMP](INFO): Starting
2023-05-12T16:54:38.696Z,1683910478.696 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:54:38.697Z,1683910478.697 [DATMMP](INFO): mdmlocal rx: 	 xA	 x0	 x0	 x0
2023-05-12T16:54:38.697Z,1683910478.697 [DATMMP](INFO): Received message type: mdmlocal
2023-05-12T16:54:38.697Z,1683910478.697 [DATMMP](INFO): Handled
2023-05-12T16:54:38.948Z,1683910478.948 [DATMMP](INFO): Starting
2023-05-12T16:54:38.948Z,1683910478.948 [DATMMP](INFO): GSXN notify for xid: 11
2023-05-12T16:54:38.949Z,1683910478.949 [DATMMP](INFO): sreg_locaddr rx: 	 xA
2023-05-12T16:54:38.949Z,1683910478.949 [DATMMP](INFO): Received message type: sreg_locaddr
2023-05-12T16:54:38.949Z,1683910478.949 [DATMMP](INFO): Match for : sreg_locaddr
2023-05-12T16:54:38.949Z,1683910478.949 [DATMMP](INFO): ACK
2023-05-12T16:54:39.200Z,1683910479.200 [DATMMP](INFO): Starting
2023-05-12T16:54:39.200Z,1683910479.200 [DATMMP](INFO): GSXN notify for xid: 12
2023-05-12T16:54:39.202Z,1683910479.202 [DATMMP](INFO): timedate rx: 	 x0	 x10	 x36	 x25	 x4	 xC	 x7B	 x0
2023-05-12T16:54:39.202Z,1683910479.202 [DATMMP](INFO): Received message type: timedate
2023-05-12T16:54:39.202Z,1683910479.202 [DATMMP](INFO): Match for : timedate
2023-05-12T16:54:39.202Z,1683910479.202 [DATMMP](INFO): ACK
2023-05-12T16:54:39.452Z,1683910479.452 [DATMMP](INFO): Starting
2023-05-12T16:54:39.452Z,1683910479.452 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:54:39.453Z,1683910479.453 [DATMMP](INFO): sys_verb rx: 	 x0	 x0	 x0	 x0
2023-05-12T16:54:39.453Z,1683910479.453 [DATMMP](INFO): Received message type: sys_verb
2023-05-12T16:54:39.454Z,1683910479.454 [DATMMP](INFO): Handled
2023-05-12T16:54:39.704Z,1683910479.704 [DATMMP](INFO): Starting
2023-05-12T16:54:39.704Z,1683910479.704 [DATMMP](INFO): GSXN notify for xid: 13
2023-05-12T16:54:39.705Z,1683910479.705 [DATMMP](INFO): sreg_verbosity rx: 	 x0
2023-05-12T16:54:39.705Z,1683910479.705 [DATMMP](INFO): Received message type: sreg_verbosity
2023-05-12T16:54:39.705Z,1683910479.705 [DATMMP](INFO): Match for : sreg_verbosity
2023-05-12T16:54:39.705Z,1683910479.705 [DATMMP](INFO): ACK
2023-05-12T16:54:39.956Z,1683910479.956 [DATMMP](INFO): Starting
2023-05-12T16:54:39.956Z,1683910479.956 [DATMMP](INFO): GSXN notify for xid: 14
2023-05-12T16:54:39.957Z,1683910479.957 [DATMMP](INFO): version rx: 	 x2	 x5
2023-05-12T16:54:39.958Z,1683910479.958 [DATMMP](INFO): DatMMPVersion: 2.5
2023-05-12T16:54:39.958Z,1683910479.958 [DATMMP](INFO): Received message type: version
2023-05-12T16:54:39.958Z,1683910479.958 [DATMMP](INFO): Match for : version
2023-05-12T16:54:39.958Z,1683910479.958 [DATMMP](INFO): ACK
2023-05-12T16:54:39.958Z,1683910479.958 [DATMMP](INFO): in MMP mode: config complete going to runnable
2023-05-12T16:54:49.369Z,1683910489.369 [NAL9602](INFO): Powering up NAL9602
2023-05-12T16:55:00.313Z,1683910500.313 [NAL9602](INFO): NAL9602 initialized
2023-05-12T16:55:03.144Z,1683910503.144 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:03.145Z,1683910503.145 [DATMMP](INFO): timesync rx: 	 x0	 x1	 x1	 x0
2023-05-12T16:55:03.145Z,1683910503.145 [DATMMP](INFO): Received message type: timesync
2023-05-12T16:55:03.145Z,1683910503.145 [DATMMP](INFO): Handled
2023-05-12T16:55:07.802Z,1683910507.802 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.8 degree
2023-05-12T16:55:07.814Z,1683910507.814 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2023-05-12T16:55:07.814Z,1683910507.814 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.9 degree
2023-05-12T16:55:07.826Z,1683910507.826 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2023-05-12T16:55:07.827Z,1683910507.827 [CommandExec](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.8 meter
2023-05-12T16:55:07.838Z,1683910507.838 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2023-05-12T16:55:07.839Z,1683910507.839 [CommandExec](IMPORTANT): got command report touch DATMMP.acoustic_contact_range
2023-05-12T16:55:07.848Z,1683910507.848 [CommandExec](IMPORTANT): got command report touch acoustic_contact_range
2023-05-12T16:55:08.059Z,1683910508.059 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,NAL9602,Power24vConverter,RDI_Pathfinder,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-12T16:55:11.541Z,1683910511.541 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1683910503 second
2023-05-12T16:55:11.677Z,1683910511.677 [SBIT](IMPORTANT): Beginning Startup BIT
2023-05-12T16:55:11.689Z,1683910511.689 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-12T16:55:13.232Z,1683910513.232 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:13.233Z,1683910513.233 [DATMMP](INFO): timesync rx: 	 x1	 x0	 x1	 x0
2023-05-12T16:55:13.233Z,1683910513.233 [DATMMP](INFO): Received message type: timesync
2023-05-12T16:55:13.233Z,1683910513.233 [DATMMP](INFO): Handled
2023-05-12T16:55:22.672Z,1683910522.672 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.001928
CHAN A1 (24V): 0.000792
CHAN A2 (12V): -0.007615
CHAN A3 (5V): -0.002543
CHAN B0 (3.3V): 0.000211
CHAN B1 (3.15aV): -0.000451
CHAN B2 (3.15bV): 0.000205
CHAN B3 (GND): 0.002045
OPEN: 0.005235
Full Scale: +/- 1 mA
2023-05-12T16:55:29.624Z,1683910529.624 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:29.625Z,1683910529.625 [DATMMP](INFO): doppler rx: 	 x0
2023-05-12T16:55:29.625Z,1683910529.625 [DATMMP](INFO): Received message type: doppler
2023-05-12T16:55:29.625Z,1683910529.625 [DATMMP](INFO): Handled
2023-05-12T16:55:29.876Z,1683910529.876 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:29.877Z,1683910529.877 [DATMMP](INFO): timestamp rx: 	 x1	 x10	 x37	 x1C	 x764
2023-05-12T16:55:29.878Z,1683910529.878 [DATMMP](INFO): Rx dataTimestamp_ set to:1683910546.499712
2023-05-12T16:55:29.879Z,1683910529.879 [DATMMP](INFO): Rx ping set to:1683910529.877455
2023-05-12T16:55:29.879Z,1683910529.879 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:29.879Z,1683910529.879 [DATMMP](INFO): Handled
2023-05-12T16:55:30.128Z,1683910530.128 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:30.130Z,1683910530.130 [DATMMP](INFO): remote_header rx: 	 xF	 x4	 x5	 x22	 x0	 xA	 xC	 x0
2023-05-12T16:55:30.130Z,1683910530.130 [DATMMP](INFO): DATA Src=12, Dst=10
2023-05-12T16:55:30.130Z,1683910530.130 [DATMMP](INFO): Received message type: remote_header
2023-05-12T16:55:30.130Z,1683910530.130 [DATMMP](INFO): Handled
2023-05-12T16:55:30.633Z,1683910530.633 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:30.633Z,1683910530.633 [DATMMP](INFO): nav_stat rx: 	 x0	 x1	 x1
2023-05-12T16:55:30.634Z,1683910530.634 [DATMMP](INFO): Received message type: nav_stat
2023-05-12T16:55:30.634Z,1683910530.634 [DATMMP](INFO): Handled
2023-05-12T16:55:30.884Z,1683910530.884 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:30.886Z,1683910530.886 [DATMMP](INFO): directional_debug rx: 	 x18A	 xF3	 x22	 x1D5	 x2AA0	 x4131	 x68F2	 x5973
2023-05-12T16:55:30.887Z,1683910530.887 [DATMMP](INFO): Received message type: directional_debug
2023-05-12T16:55:30.887Z,1683910530.887 [DATMMP](INFO): Handled
2023-05-12T16:55:31.136Z,1683910531.136 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:31.138Z,1683910531.138 [DATMMP](INFO): directional rx: 	 x1AD	 xE5	 x452	 xFF0D	 xB0C	 xFF0D	 x0	 x6BB	 x2	 x0	 x27B5966	 x-43569E0
2023-05-12T16:55:31.140Z,1683910531.140 [DATMMP](INFO): Received message type: directional
2023-05-12T16:55:31.140Z,1683910531.140 [DATMMP](INFO): Handled
2023-05-12T16:55:31.389Z,1683910531.389 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:31.390Z,1683910531.390 [DATMMP](INFO): acstats rx: 	 xC	 x5	 x0	 x289	 x23	 x79	 xB4	 xB4	 xD	 xFFFF	 xAA	 x21	 xB	 x0
2023-05-12T16:55:31.391Z,1683910531.391 [DATMMP](INFO): Received message type: acstats
2023-05-12T16:55:31.391Z,1683910531.391 [DATMMP](INFO): Handled
2023-05-12T16:55:31.640Z,1683910531.640 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:31.641Z,1683910531.641 [DATMMP](INFO): data_rx rx: 	 xC	 x0	 x0	 x22
2023-05-12T16:55:31.641Z,1683910531.641 [DATMMP](INFO): Check CRC
2023-05-12T16:55:31.642Z,1683910531.642 [DATMMP](INFO): data rx parseDataResponse 34
2023-05-12T16:55:31.642Z,1683910531.642 [DATMMP](INFO): Got DATA: len 34
2023-05-12T16:55:31.642Z,1683910531.642 [DATMMP](INFO): Received command: set _.pressure 0.743017 atmosphere
2023-05-12T16:55:31.643Z,1683910531.643 [DATMMP](INFO): #Outgoing data=1
2023-05-12T16:55:31.643Z,1683910531.643 [DATMMP](INFO): Sending ack
2023-05-12T16:55:31.643Z,1683910531.643 [DATMMP](INFO): Received message type: data_rx
2023-05-12T16:55:31.643Z,1683910531.643 [DATMMP](INFO): Handled
2023-05-12T16:55:31.643Z,1683910531.643 [DATMMP](INFO): *** SENDING_FILL_BUFFER ***
2023-05-12T16:55:31.644Z,1683910531.644 [DATMMP](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_NAV_DATA
2023-05-12T16:55:31.892Z,1683910531.892 [DATMMP](INFO): *** SENDING_NAV_DATA ***
2023-05-12T16:55:31.893Z,1683910531.893 [DATMMP](DEBUG): In sendingNavData, set commsState_ = SENDING_TRANSMIT
2023-05-12T16:55:32.144Z,1683910532.144 [DATMMP](INFO): *** SENDING_TRANSMIT ***
2023-05-12T16:55:32.145Z,1683910532.145 [DATMMP](INFO): Tx to 12 len 4 xid 15
2023-05-12T16:55:32.145Z,1683910532.145 [DATMMP](INFO): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-12T16:55:32.146Z,1683910532.146 [DATMMP](INFO): *** SENDING_TRANSMIT_VERIFY ***
2023-05-12T16:55:32.396Z,1683910532.396 [DATMMP](INFO): GSXN notify for xid: 15
2023-05-12T16:55:32.397Z,1683910532.397 [DATMMP](INFO): cmd_result rx: 	 x1	 x7	 x0	 x1
2023-05-12T16:55:32.398Z,1683910532.398 [DATMMP](DEBUG): In rxCmdResult, sent ack so set commsState_ = SENDING_VERIFIED
2023-05-12T16:55:32.398Z,1683910532.398 [DATMMP](DEBUG): Command complete send
2023-05-12T16:55:32.399Z,1683910532.399 [DATMMP](ERROR): 1:COMPLETE
2023-05-12T16:55:32.399Z,1683910532.399 [DATMMP](INFO): Received message type: cmd_result
2023-05-12T16:55:32.399Z,1683910532.399 [DATMMP](INFO): Handled
2023-05-12T16:55:32.399Z,1683910532.399 [DATMMP](INFO): *** SENDING_VERIFIED ***
2023-05-12T16:55:32.399Z,1683910532.399 [DATMMP](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-12T16:55:32.648Z,1683910532.648 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:32.649Z,1683910532.649 [DATMMP](INFO): timestamp rx: 	 x0	 x10	 x37	 x1F	 x1029
2023-05-12T16:55:32.650Z,1683910532.650 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:32.650Z,1683910532.650 [DATMMP](INFO): Handled
2023-05-12T16:55:32.918Z,1683910532.918 [CommandExec](IMPORTANT): got command set _.pressure 0.743017 atmosphere
2023-05-12T16:55:36.936Z,1683910536.936 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:36.937Z,1683910536.937 [DATMMP](INFO): doppler rx: 	 x0
2023-05-12T16:55:36.937Z,1683910536.937 [DATMMP](INFO): Received message type: doppler
2023-05-12T16:55:36.937Z,1683910536.937 [DATMMP](INFO): Handled
2023-05-12T16:55:37.188Z,1683910537.188 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:37.189Z,1683910537.189 [DATMMP](INFO): timestamp rx: 	 x1	 x10	 x37	 x23	 x132A
2023-05-12T16:55:37.190Z,1683910537.190 [DATMMP](INFO): Rx dataTimestamp_ set to:1683910582.954368
2023-05-12T16:55:37.190Z,1683910537.190 [DATMMP](INFO): Rx ping set to:1683910537.189413
2023-05-12T16:55:37.190Z,1683910537.190 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:37.190Z,1683910537.190 [DATMMP](INFO): Handled
2023-05-12T16:55:37.440Z,1683910537.440 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:37.442Z,1683910537.442 [DATMMP](INFO): remote_header rx: 	 xF	 x4	 x5	 x23	 x0	 xA	 xC	 x0
2023-05-12T16:55:37.442Z,1683910537.442 [DATMMP](INFO): DATA Src=12, Dst=10
2023-05-12T16:55:37.442Z,1683910537.442 [DATMMP](INFO): Received message type: remote_header
2023-05-12T16:55:37.442Z,1683910537.442 [DATMMP](INFO): Handled
2023-05-12T16:55:37.945Z,1683910537.945 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:37.959Z,1683910537.959 [DATMMP](INFO): nav_stat rx: 	 x0	 x1	 x1
2023-05-12T16:55:37.960Z,1683910537.960 [DATMMP](INFO): Received message type: nav_stat
2023-05-12T16:55:37.960Z,1683910537.960 [DATMMP](INFO): Handled
2023-05-12T16:55:38.196Z,1683910538.196 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:38.198Z,1683910538.198 [DATMMP](INFO): directional_debug rx: 	 x1B4	 x110	 x21	 x19D	 x2A60	 x4351	 x6E32	 x7F13
2023-05-12T16:55:38.199Z,1683910538.199 [DATMMP](INFO): Received message type: directional_debug
2023-05-12T16:55:38.199Z,1683910538.199 [DATMMP](INFO): Handled
2023-05-12T16:55:38.448Z,1683910538.448 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:38.450Z,1683910538.450 [DATMMP](INFO): directional rx: 	 x1D9	 xFB	 x428	 xFEF0	 xAE1	 xFEF1	 x0	 x6B9	 x1	 xFFFE	 x27B5966	 x-43569E0
2023-05-12T16:55:38.452Z,1683910538.452 [DATMMP](INFO): Received message type: directional
2023-05-12T16:55:38.452Z,1683910538.452 [DATMMP](INFO): Handled
2023-05-12T16:55:38.701Z,1683910538.701 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:38.702Z,1683910538.702 [DATMMP](INFO): acstats rx: 	 xC	 x5	 x0	 x29B	 x23	 x7B	 xCF	 xCB	 xD	 xFFFF	 xA5	 x25	 xB	 x0
2023-05-12T16:55:38.703Z,1683910538.703 [DATMMP](INFO): Received message type: acstats
2023-05-12T16:55:38.703Z,1683910538.703 [DATMMP](INFO): Handled
2023-05-12T16:55:38.952Z,1683910538.952 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:38.953Z,1683910538.953 [DATMMP](INFO): data_rx rx: 	 xC	 x0	 x0	 x23
2023-05-12T16:55:38.953Z,1683910538.953 [DATMMP](INFO): Check CRC
2023-05-12T16:55:38.954Z,1683910538.954 [DATMMP](INFO): data rx parseDataResponse 35
2023-05-12T16:55:38.954Z,1683910538.954 [DATMMP](INFO): Got DATA: len 35
2023-05-12T16:55:38.954Z,1683910538.954 [DATMMP](INFO): Received command: set _.temperature 24.420710 celsius
2023-05-12T16:55:38.954Z,1683910538.954 [DATMMP](INFO): #Outgoing data=1
2023-05-12T16:55:38.954Z,1683910538.954 [DATMMP](INFO): Sending ack
2023-05-12T16:55:38.955Z,1683910538.955 [DATMMP](INFO): Received message type: data_rx
2023-05-12T16:55:38.955Z,1683910538.955 [DATMMP](INFO): Handled
2023-05-12T16:55:38.955Z,1683910538.955 [DATMMP](INFO): *** SENDING_FILL_BUFFER ***
2023-05-12T16:55:38.955Z,1683910538.955 [DATMMP](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_NAV_DATA
2023-05-12T16:55:39.204Z,1683910539.204 [DATMMP](INFO): *** SENDING_NAV_DATA ***
2023-05-12T16:55:39.204Z,1683910539.204 [DATMMP](DEBUG): In sendingNavData, set commsState_ = SENDING_TRANSMIT
2023-05-12T16:55:39.456Z,1683910539.456 [DATMMP](INFO): *** SENDING_TRANSMIT ***
2023-05-12T16:55:39.457Z,1683910539.457 [DATMMP](INFO): Tx to 12 len 4 xid 16
2023-05-12T16:55:39.468Z,1683910539.468 [DATMMP](INFO): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-12T16:55:39.468Z,1683910539.468 [DATMMP](INFO): *** SENDING_TRANSMIT_VERIFY ***
2023-05-12T16:55:39.708Z,1683910539.708 [DATMMP](INFO): GSXN notify for xid: 16
2023-05-12T16:55:39.709Z,1683910539.709 [DATMMP](INFO): cmd_result rx: 	 x1	 x7	 x0	 x1
2023-05-12T16:55:39.709Z,1683910539.709 [DATMMP](DEBUG): In rxCmdResult, sent ack so set commsState_ = SENDING_VERIFIED
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](DEBUG): Command complete send
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](ERROR): 1:COMPLETE
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](INFO): Received message type: cmd_result
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](INFO): Handled
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](INFO): *** SENDING_VERIFIED ***
2023-05-12T16:55:39.710Z,1683910539.710 [DATMMP](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-12T16:55:39.960Z,1683910539.960 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:39.961Z,1683910539.961 [DATMMP](INFO): timestamp rx: 	 x0	 x10	 x37	 x26	 x1BD4
2023-05-12T16:55:39.962Z,1683910539.962 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:39.962Z,1683910539.962 [DATMMP](INFO): Handled
2023-05-12T16:55:40.533Z,1683910540.533 [CommandExec](IMPORTANT): got command set _.temperature 24.420710 celsius
2023-05-12T16:55:44.250Z,1683910544.250 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:44.251Z,1683910544.251 [DATMMP](INFO): doppler rx: 	 x0
2023-05-12T16:55:44.252Z,1683910544.252 [DATMMP](INFO): Received message type: doppler
2023-05-12T16:55:44.252Z,1683910544.252 [DATMMP](INFO): Handled
2023-05-12T16:55:44.500Z,1683910544.500 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:44.501Z,1683910544.501 [DATMMP](INFO): timestamp rx: 	 x1	 x10	 x37	 x2A	 x20C7
2023-05-12T16:55:44.502Z,1683910544.502 [DATMMP](INFO): Rx dataTimestamp_ set to:1683910559.989184
2023-05-12T16:55:44.502Z,1683910544.502 [DATMMP](INFO): Rx ping set to:1683910544.501360
2023-05-12T16:55:44.502Z,1683910544.502 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:44.502Z,1683910544.502 [DATMMP](INFO): Handled
2023-05-12T16:55:44.752Z,1683910544.752 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:44.754Z,1683910544.754 [DATMMP](INFO): remote_header rx: 	 xF	 x4	 x5	 x20	 x0	 xA	 xC	 x0
2023-05-12T16:55:44.754Z,1683910544.754 [DATMMP](INFO): DATA Src=12, Dst=10
2023-05-12T16:55:44.754Z,1683910544.754 [DATMMP](INFO): Received message type: remote_header
2023-05-12T16:55:44.754Z,1683910544.754 [DATMMP](INFO): Handled
2023-05-12T16:55:45.257Z,1683910545.257 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:45.258Z,1683910545.258 [DATMMP](INFO): nav_stat rx: 	 x0	 x1	 x1
2023-05-12T16:55:45.258Z,1683910545.258 [DATMMP](INFO): Received message type: nav_stat
2023-05-12T16:55:45.258Z,1683910545.258 [DATMMP](INFO): Handled
2023-05-12T16:55:45.508Z,1683910545.508 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:45.510Z,1683910545.510 [DATMMP](INFO): directional_debug rx: 	 x18E	 xFB	 x20	 x1BB	 x2A70	 x40F1	 x6842	 x75D3
2023-05-12T16:55:45.511Z,1683910545.511 [DATMMP](INFO): Received message type: directional_debug
2023-05-12T16:55:45.511Z,1683910545.511 [DATMMP](INFO): Handled
2023-05-12T16:55:45.760Z,1683910545.760 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:45.762Z,1683910545.762 [DATMMP](INFO): directional rx: 	 x1B1	 xEB	 x44E	 xFF05	 xB06	 xFF06	 x0	 x6B9	 x2	 xFFFE	 x27B5966	 x-43569E0
2023-05-12T16:55:45.764Z,1683910545.764 [DATMMP](INFO): Received message type: directional
2023-05-12T16:55:45.764Z,1683910545.764 [DATMMP](INFO): Handled
2023-05-12T16:55:46.012Z,1683910546.012 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:46.014Z,1683910546.014 [DATMMP](INFO): acstats rx: 	 xC	 x5	 x0	 x2D0	 x23	 x7C	 xB4	 xBA	 xD	 xFFFF	 xA8	 x21	 xB	 x0
2023-05-12T16:55:46.014Z,1683910546.014 [DATMMP](INFO): Received message type: acstats
2023-05-12T16:55:46.014Z,1683910546.014 [DATMMP](INFO): Handled
2023-05-12T16:55:46.266Z,1683910546.266 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:46.268Z,1683910546.268 [DATMMP](INFO): data_rx rx: 	 xC	 x0	 x0	 x20
2023-05-12T16:55:46.269Z,1683910546.269 [DATMMP](INFO): Check CRC
2023-05-12T16:55:46.269Z,1683910546.269 [DATMMP](INFO): data rx parseDataResponse 32
2023-05-12T16:55:46.269Z,1683910546.269 [DATMMP](INFO): Got DATA: len 32
2023-05-12T16:55:46.270Z,1683910546.270 [DATMMP](INFO): Received command: set _.humidity 12.916615 percent
2023-05-12T16:55:46.271Z,1683910546.271 [DATMMP](INFO): #Outgoing data=1
2023-05-12T16:55:46.271Z,1683910546.271 [DATMMP](INFO): Sending ack
2023-05-12T16:55:46.272Z,1683910546.272 [DATMMP](INFO): Received message type: data_rx
2023-05-12T16:55:46.272Z,1683910546.272 [DATMMP](INFO): Handled
2023-05-12T16:55:46.273Z,1683910546.273 [DATMMP](INFO): *** SENDING_FILL_BUFFER ***
2023-05-12T16:55:46.274Z,1683910546.274 [DATMMP](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_NAV_DATA
2023-05-12T16:55:46.516Z,1683910546.516 [DATMMP](INFO): *** SENDING_NAV_DATA ***
2023-05-12T16:55:46.516Z,1683910546.516 [DATMMP](DEBUG): In sendingNavData, set commsState_ = SENDING_TRANSMIT
2023-05-12T16:55:46.768Z,1683910546.768 [DATMMP](INFO): *** SENDING_TRANSMIT ***
2023-05-12T16:55:46.768Z,1683910546.768 [DATMMP](INFO): Tx to 12 len 4 xid 17
2023-05-12T16:55:46.769Z,1683910546.769 [DATMMP](INFO): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-12T16:55:46.769Z,1683910546.769 [DATMMP](INFO): *** SENDING_TRANSMIT_VERIFY ***
2023-05-12T16:55:47.020Z,1683910547.020 [DATMMP](INFO): GSXN notify for xid: 17
2023-05-12T16:55:47.021Z,1683910547.021 [DATMMP](INFO): cmd_result rx: 	 x1	 x7	 x0	 x1
2023-05-12T16:55:47.021Z,1683910547.021 [DATMMP](DEBUG): In rxCmdResult, sent ack so set commsState_ = SENDING_VERIFIED
2023-05-12T16:55:47.021Z,1683910547.021 [DATMMP](DEBUG): Command complete send
2023-05-12T16:55:47.022Z,1683910547.022 [DATMMP](ERROR): 1:COMPLETE
2023-05-12T16:55:47.022Z,1683910547.022 [DATMMP](INFO): Received message type: cmd_result
2023-05-12T16:55:47.022Z,1683910547.022 [DATMMP](INFO): Handled
2023-05-12T16:55:47.022Z,1683910547.022 [DATMMP](INFO): *** SENDING_VERIFIED ***
2023-05-12T16:55:47.022Z,1683910547.022 [DATMMP](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-12T16:55:47.272Z,1683910547.272 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:47.273Z,1683910547.273 [DATMMP](INFO): timestamp rx: 	 x0	 x10	 x37	 x2E	 x89
2023-05-12T16:55:47.274Z,1683910547.274 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:47.274Z,1683910547.274 [DATMMP](INFO): Handled
2023-05-12T16:55:47.396Z,1683910547.396 [CommandExec](IMPORTANT): got command set _.humidity 12.916615 percent
2023-05-12T16:55:51.573Z,1683910551.573 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:51.574Z,1683910551.574 [DATMMP](INFO): doppler rx: 	 x0
2023-05-12T16:55:51.574Z,1683910551.574 [DATMMP](INFO): Received message type: doppler
2023-05-12T16:55:51.574Z,1683910551.574 [DATMMP](INFO): Handled
2023-05-12T16:55:51.824Z,1683910551.824 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:51.825Z,1683910551.825 [DATMMP](INFO): timestamp rx: 	 x1	 x10	 x37	 x32	 x57C
2023-05-12T16:55:51.826Z,1683910551.826 [DATMMP](INFO): Rx dataTimestamp_ set to:1683910563.745472
2023-05-12T16:55:51.826Z,1683910551.826 [DATMMP](INFO): Rx ping set to:1683910551.825316
2023-05-12T16:55:51.826Z,1683910551.826 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:51.826Z,1683910551.826 [DATMMP](INFO): Handled
2023-05-12T16:55:52.076Z,1683910552.076 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:52.078Z,1683910552.078 [DATMMP](INFO): remote_header rx: 	 xF	 x4	 x5	 x22	 x0	 xA	 xC	 x0
2023-05-12T16:55:52.078Z,1683910552.078 [DATMMP](INFO): DATA Src=12, Dst=10
2023-05-12T16:55:52.078Z,1683910552.078 [DATMMP](INFO): Received message type: remote_header
2023-05-12T16:55:52.078Z,1683910552.078 [DATMMP](INFO): Handled
2023-05-12T16:55:52.580Z,1683910552.580 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:52.581Z,1683910552.581 [DATMMP](INFO): nav_stat rx: 	 x0	 x1	 x1
2023-05-12T16:55:52.581Z,1683910552.581 [DATMMP](INFO): Received message type: nav_stat
2023-05-12T16:55:52.581Z,1683910552.581 [DATMMP](INFO): Handled
2023-05-12T16:55:52.832Z,1683910552.832 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:52.833Z,1683910552.833 [DATMMP](INFO): directional_debug rx: 	 x193	 xCC	 x21	 x1AD	 x3220	 x4171	 x69C2	 x5BF3
2023-05-12T16:55:52.834Z,1683910552.834 [DATMMP](INFO): Received message type: directional_debug
2023-05-12T16:55:52.835Z,1683910552.835 [DATMMP](INFO): Handled
2023-05-12T16:55:53.084Z,1683910553.084 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:53.086Z,1683910553.086 [DATMMP](INFO): directional rx: 	 x1BB	 xC8	 x449	 xFF34	 xB03	 xFF33	 x0	 x6BB	 x3	 x0	 x27B5966	 x-43569E0
2023-05-12T16:55:53.088Z,1683910553.088 [DATMMP](INFO): Received message type: directional
2023-05-12T16:55:53.088Z,1683910553.088 [DATMMP](INFO): Handled
2023-05-12T16:55:53.336Z,1683910553.336 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:53.338Z,1683910553.338 [DATMMP](INFO): acstats rx: 	 xC	 x5	 x0	 x2D0	 x23	 x79	 xC8	 xBC	 xD	 xFFFF	 xA6	 x23	 xB	 x0
2023-05-12T16:55:53.338Z,1683910553.338 [DATMMP](INFO): Received message type: acstats
2023-05-12T16:55:53.338Z,1683910553.338 [DATMMP](INFO): Handled
2023-05-12T16:55:53.588Z,1683910553.588 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:53.589Z,1683910553.589 [DATMMP](INFO): data_rx rx: 	 xC	 x0	 x0	 x22
2023-05-12T16:55:53.589Z,1683910553.589 [DATMMP](INFO): Check CRC
2023-05-12T16:55:53.589Z,1683910553.589 [DATMMP](INFO): data rx parseDataResponse 34
2023-05-12T16:55:53.590Z,1683910553.590 [DATMMP](INFO): Got DATA: len 34
2023-05-12T16:55:53.590Z,1683910553.590 [DATMMP](INFO): Received command: set _.pressure 0.745180 atmosphere
2023-05-12T16:55:53.590Z,1683910553.590 [DATMMP](INFO): #Outgoing data=1
2023-05-12T16:55:53.590Z,1683910553.590 [DATMMP](INFO): Sending ack
2023-05-12T16:55:53.590Z,1683910553.590 [DATMMP](INFO): Received message type: data_rx
2023-05-12T16:55:53.591Z,1683910553.591 [DATMMP](INFO): Handled
2023-05-12T16:55:53.591Z,1683910553.591 [DATMMP](INFO): *** SENDING_FILL_BUFFER ***
2023-05-12T16:55:53.591Z,1683910553.591 [DATMMP](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_NAV_DATA
2023-05-12T16:55:53.840Z,1683910553.840 [DATMMP](INFO): *** SENDING_NAV_DATA ***
2023-05-12T16:55:53.840Z,1683910553.840 [DATMMP](DEBUG): In sendingNavData, set commsState_ = SENDING_TRANSMIT
2023-05-12T16:55:54.092Z,1683910554.092 [DATMMP](INFO): *** SENDING_TRANSMIT ***
2023-05-12T16:55:54.093Z,1683910554.093 [DATMMP](INFO): Tx to 12 len 4 xid 18
2023-05-12T16:55:54.093Z,1683910554.093 [DATMMP](INFO): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-12T16:55:54.093Z,1683910554.093 [DATMMP](INFO): *** SENDING_TRANSMIT_VERIFY ***
2023-05-12T16:55:54.344Z,1683910554.344 [DATMMP](INFO): GSXN notify for xid: 18
2023-05-12T16:55:54.345Z,1683910554.345 [DATMMP](INFO): cmd_result rx: 	 x1	 x7	 x0	 x1
2023-05-12T16:55:54.345Z,1683910554.345 [DATMMP](DEBUG): In rxCmdResult, sent ack so set commsState_ = SENDING_VERIFIED
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](DEBUG): Command complete send
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](ERROR): 1:COMPLETE
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](INFO): Received message type: cmd_result
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](INFO): Handled
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](INFO): *** SENDING_VERIFIED ***
2023-05-12T16:55:54.346Z,1683910554.346 [DATMMP](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-12T16:55:54.597Z,1683910554.597 [DATMMP](INFO): GSXN notify for xid: 0
2023-05-12T16:55:54.598Z,1683910554.598 [DATMMP](INFO): timestamp rx: 	 x0	 x10	 x37	 x35	 xE28
2023-05-12T16:55:54.598Z,1683910554.598 [DATMMP](INFO): Received message type: timestamp
2023-05-12T16:55:54.598Z,1683910554.598 [DATMMP](INFO): Handled
2023-05-12T16:55:55.026Z,1683910555.026 [CommandExec](IMPORTANT): got command set _.pressure 0.745180 atmosphere
2023-05-12T16:56:05.147Z,1683910565.147 [SBIT](IMPORTANT): SBIT PASSED
2023-05-12T16:56:05.148Z,1683910565.148 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-05-12T16:56:05.148Z,1683910565.148 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): CBIT.gf24Offset=143 microampere;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 0.300000 liter_per_second;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=279.582187 cubic_centimeter;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): VerticalControl.massDefault=7.892016 millimeter;

2023-05-12T16:56:05.149Z,1683910565.149 [SBIT](IMPORTANT): WetLabsUBAT.loadAtStartup=1 bool;

2023-05-12T16:56:05.533Z,1683910565.533 [MissionManager](IMPORTANT): Started mission Startup
2023-05-12T16:56:05.533Z,1683910565.533 [Startup] Running Loop=1
2023-05-12T16:56:05.533Z,1683910565.533 [Startup](DEBUG): Aggregate::initialize Startup
2023-05-12T16:56:05.533Z,1683910565.533 [Startup:A.GoToSurface] Running Loop=1
2023-05-12T16:56:05.533Z,1683910565.533 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-12T16:56:05.534Z,1683910565.534 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-12T16:56:05.534Z,1683910565.534 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-12T16:56:05.534Z,1683910565.534 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-12T16:56:05.535Z,1683910565.535 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-12T16:56:05.535Z,1683910565.535 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-12T16:56:05.537Z,1683910565.537 [Startup:StartupSatComms] Running Loop=1
2023-05-12T16:56:05.537Z,1683910565.537 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-05-12T16:56:05.537Z,1683910565.537 [Startup:StartupSatComms:A] Running Loop=1
2023-05-12T16:56:05.927Z,1683910565.927 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-05-12T16:56:05.928Z,1683910565.928 [Startup:StartupSatComms:A] Stopped
2023-05-12T16:56:05.928Z,1683910565.928 [Startup:StartupSatComms:B] Running Loop=1
2023-05-12T16:56:06.356Z,1683910566.356 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-12T16:56:13.211Z,1683910573.211 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230512T161739/Courier0010.lzma
2023-05-12T16:56:14.214Z,1683910574.214 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161739/Courier0010.lzma.bak
2023-05-12T16:56:14.214Z,1683910574.214 [DataOverHttps](INFO): SBD MOMSN=18296184
2023-05-12T16:56:22.969Z,1683910582.969 [CommandExec](IMPORTANT): got command failComponent
2023-05-12T16:56:22.969Z,1683910582.969 [CommandExec](IMPORTANT): Failed components:
2023-05-12T16:56:22.969Z,1683910582.969 [CommandExec](IMPORTANT): No failed Components.
2023-05-12T16:56:30.423Z,1683910590.423 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20230512T165409/Courier0000.lzma
2023-05-12T16:56:31.425Z,1683910591.425 [DataOverHttps](INFO): Moved sent file to Logs/20230512T165409/Courier0000.lzma.bak
2023-05-12T16:56:31.426Z,1683910591.426 [DataOverHttps](INFO): SBD MOMSN=18296186
2023-05-12T16:56:48.791Z,1683910608.791 [DataOverHttps](INFO): Sending 178 bytes from file Logs/20230512T161739/Express0011.lzma
2023-05-12T16:56:49.793Z,1683910609.793 [DataOverHttps](INFO): Moved sent file to Logs/20230512T161739/Express0011.lzma.bak
2023-05-12T16:56:49.794Z,1683910609.794 [DataOverHttps](INFO): SBD MOMSN=18296189
2023-05-12T16:56:55.051Z,1683910615.051 [CommandExec](IMPORTANT): got command get depth
2023-05-12T16:56:55.056Z,1683910615.056 [CommandExec](IMPORTANT): depth 0.800000 m
2023-05-12T16:57:06.110Z,1683910626.110 [Startup:StartupSatComms:B](INFO): Timed out from 2023-05-12T16:56:05.9Z
2023-05-12T16:57:06.110Z,1683910626.110 [Startup:StartupSatComms:B] Stopped
2023-05-12T16:57:06.111Z,1683910626.111 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-05-12T16:57:06.111Z,1683910626.111 [Startup:StartupSatComms] Stopped
2023-05-12T16:57:06.111Z,1683910626.111 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-05-12T16:57:06.112Z,1683910626.112 [Startup](INFO): Completed Startup
2023-05-12T16:57:06.112Z,1683910626.112 [MissionManager](INFO): Startup is completed.
2023-05-12T16:57:06.113Z,1683910626.113 [MissionManager](INFO): Uninitializing Mission Startup
2023-05-12T16:57:06.113Z,1683910626.113 [Startup] Stopped
2023-05-12T16:57:06.113Z,1683910626.113 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-05-12T16:57:06.113Z,1683910626.113 [Startup:A.GoToSurface] Stopped
2023-05-12T16:57:06.113Z,1683910626.113 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-12T16:57:06.337Z,1683910626.337 [DataOverHttps](INFO): Sending 1142 bytes from file Logs/20230512T165409/Express0001.lzma
2023-05-12T16:57:06.540Z,1683910626.540 [MissionManager](IMPORTANT): Started mission Default
2023-05-12T16:57:06.541Z,1683910626.541 [Default] Running Loop=1
2023-05-12T16:57:06.541Z,1683910626.541 [Default](DEBUG): Aggregate::initialize Default
2023-05-12T16:57:06.541Z,1683910626.541 [Default:B.GoToSurface] Running Loop=1
2023-05-12T16:57:06.541Z,1683910626.541 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-12T16:57:06.541Z,1683910626.541 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-12T16:57:06.541Z,1683910626.541 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-12T16:57:06.542Z,1683910626.542 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-12T16:57:06.542Z,1683910626.542 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-12T16:57:06.542Z,1683910626.542 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-12T16:57:06.543Z,1683910626.543 [Default:A.Wait] Running Loop=1
2023-05-12T16:57:06.543Z,1683910626.543 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-12T16:57:07.337Z,1683910627.337 [DataOverHttps](INFO): Moved sent file to Logs/20230512T165409/Express0001.lzma.bak
2023-05-12T16:57:07.337Z,1683910627.337 [DataOverHttps](INFO): SBD MOMSN=18296193
2023-05-12T16:57:19.869Z,1683910639.869 [Default:A.Wait](INFO): Done Waiting.
2023-05-12T16:57:19.869Z,1683910639.869 [Default:A.Wait] Stopped
2023-05-12T16:57:19.869Z,1683910639.869 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-12T16:57:20.304Z,1683910640.304 [Default:CheckIn] Running Loop=1
2023-05-12T16:57:20.305Z,1683910640.305 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-12T16:57:20.305Z,1683910640.305 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-12T16:57:20.678Z,1683910640.678 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-05-12T16:59:24.335Z,1683910764.335 [RDI_Pathfinder](ERROR): only read -1 of 1 data item for altitude
2023-05-12T17:00:03.869Z,1683910803.869 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-12T17:01:01.240Z,1683910861.240 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-62 in onboard configuration file).
2023-05-12T17:01:50.135Z,1683910910.135 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2023-05-12T17:01:50.138Z,1683910910.138 [BPC1](INFO): Received data from all battery sticks.
2023-05-12T17:02:20.474Z,1683910940.474 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-12T16:57:20.3Z
2023-05-12T17:02:20.475Z,1683910940.475 [Default:CheckIn:Read_GPS] Stopped
2023-05-12T17:02:20.475Z,1683910940.475 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-12T17:02:20.881Z,1683910940.881 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-12T17:02:27.449Z,1683910947.449 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20230512T165409/Courier0004.lzma
2023-05-12T17:02:28.449Z,1683910948.449 [DataOverHttps](INFO): Moved sent file to Logs/20230512T165409/Courier0004.lzma.bak
2023-05-12T17:02:28.450Z,1683910948.450 [DataOverHttps](INFO): SBD MOMSN=18297413
2023-05-12T17:02:44.680Z,1683910964.680 [DataOverHttps](INFO): Sending 393 bytes from file Logs/20230512T165409/Express0005.lzma
2023-05-12T17:02:45.682Z,1683910965.682 [DataOverHttps](INFO): Moved sent file to Logs/20230512T165409/Express0005.lzma.bak
2023-05-12T17:02:45.682Z,1683910965.682 [DataOverHttps](INFO): SBD MOMSN=18297447
2023-05-12T17:02:53.573Z,1683910973.573 [NAL9602](INFO): Not Powering down - fast GPS