2022-05-11T01:10:51.677Z,1652231451.677 [Supervisor](DEBUG): Initializing supervisor.
2022-05-11T01:10:51.681Z,1652231451.681 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-05-11T01:10:51.682Z,1652231451.682 [SyncHandler](INFO): Protected caller Thread ID is 827
2022-05-11T01:10:51.682Z,1652231451.682 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-05-11T01:10:51.683Z,1652231451.683 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-05-11T01:10:51.683Z,1652231451.683 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 828
2022-05-11T01:10:51.687Z,1652231451.687 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-05-11T01:10:51.705Z,1652231451.705 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-05-11T01:10:51.706Z,1652231451.706 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-05-11T01:10:51.707Z,1652231451.707 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 829
2022-05-11T01:10:51.711Z,1652231451.711 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-05-11T01:10:51.712Z,1652231451.712 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-05-11T01:10:51.712Z,1652231451.712 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 830
2022-05-11T01:10:51.714Z,1652231451.714 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-05-11T01:10:51.715Z,1652231451.715 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-05-11T01:10:51.715Z,1652231451.715 [logger ThreadHandler](INFO): Protected caller Thread ID is 831
2022-05-11T01:10:51.719Z,1652231451.719 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-05-11T01:10:51.719Z,1652231451.719 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-05-11T01:10:51.723Z,1652231451.723 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-05-11T01:10:52.040Z,1652231452.040 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-05-11T01:10:52.041Z,1652231452.041 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-05-11T01:10:52.686Z,1652231452.686 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-05-11T01:10:52.687Z,1652231452.687 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-05-11T01:10:52.794Z,1652231452.794 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-05-11T01:10:52.796Z,1652231452.796 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-05-11T01:10:53.347Z,1652231453.347 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-05-11T01:10:53.347Z,1652231453.347 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-05-11T01:10:53.444Z,1652231453.444 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-05-11T01:10:53.445Z,1652231453.445 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-05-11T01:10:53.528Z,1652231453.528 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-05-11T01:10:53.897Z,1652231453.897 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-05-11T01:10:53.898Z,1652231453.898 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-05-11T01:10:54.119Z,1652231454.119 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-05-11T01:10:54.121Z,1652231454.121 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-05-11T01:10:54.247Z,1652231454.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-05-11T01:10:54.247Z,1652231454.247 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-05-11T01:10:54.472Z,1652231454.472 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-05-11T01:10:54.474Z,1652231454.474 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-05-11T01:10:54.949Z,1652231454.949 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-05-11T01:10:55.473Z,1652231455.473 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-05-11T01:10:56.000Z,1652231456.000 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-05-11T01:10:56.002Z,1652231456.002 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-05-11T01:10:56.083Z,1652231456.083 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-05-11T01:10:56.277Z,1652231456.277 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-05-11T01:10:56.278Z,1652231456.278 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-05-11T01:10:56.497Z,1652231456.497 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-05-11T01:10:56.498Z,1652231456.498 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-05-11T01:10:56.793Z,1652231456.793 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-05-11T01:10:56.795Z,1652231456.795 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2022-05-11T01:10:56.800Z,1652231456.800 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2022-05-11T01:10:56.908Z,1652231456.908 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2022-05-11T01:10:57.057Z,1652231457.057 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2022-05-11T01:10:57.144Z,1652231457.144 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2022-05-11T01:10:57.229Z,1652231457.229 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2022-05-11T01:10:57.342Z,1652231457.342 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2022-05-11T01:10:57.517Z,1652231457.517 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2022-05-11T01:10:57.779Z,1652231457.779 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-05-11T01:10:57.780Z,1652231457.780 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2022-05-11T01:10:57.912Z,1652231457.912 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2022-05-11T01:10:58.007Z,1652231458.007 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2022-05-11T01:10:58.111Z,1652231458.111 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2022-05-11T01:10:58.211Z,1652231458.211 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2022-05-11T01:10:58.214Z,1652231458.214 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-05-11T01:10:58.335Z,1652231458.335 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-05-11T01:10:58.336Z,1652231458.336 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-05-11T01:10:58.352Z,1652231458.352 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-05-11T01:10:58.352Z,1652231458.352 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-05-11T01:10:58.424Z,1652231458.424 [DepthRateCalculator] Loaded
2022-05-11T01:10:58.424Z,1652231458.424 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-05-11T01:10:58.429Z,1652231458.429 [PitchRateCalculator] Loaded
2022-05-11T01:10:58.429Z,1652231458.429 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-05-11T01:10:58.440Z,1652231458.440 [SpeedCalculator] Loaded
2022-05-11T01:10:58.440Z,1652231458.440 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-05-11T01:10:58.445Z,1652231458.445 [YawRateCalculator] Loaded
2022-05-11T01:10:58.445Z,1652231458.445 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-05-11T01:10:58.465Z,1652231458.465 [ElevatorOffsetCalculator] Loaded
2022-05-11T01:10:58.466Z,1652231458.466 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-05-11T01:10:58.466Z,1652231458.466 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-05-11T01:10:58.467Z,1652231458.467 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-05-11T01:10:58.534Z,1652231458.534 [VerticalControl](DEBUG): Construct VerticalControl.
2022-05-11T01:10:58.590Z,1652231458.590 [VerticalControl] Loaded
2022-05-11T01:10:58.590Z,1652231458.590 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-05-11T01:10:58.592Z,1652231458.592 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-05-11T01:10:58.631Z,1652231458.631 [HorizontalControl] Loaded
2022-05-11T01:10:58.631Z,1652231458.631 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-05-11T01:10:58.634Z,1652231458.634 [SpeedControl](DEBUG): Construct SpeedControl.
2022-05-11T01:10:58.636Z,1652231458.636 [SpeedControl] Loaded
2022-05-11T01:10:58.636Z,1652231458.636 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-05-11T01:10:58.639Z,1652231458.639 [LoopControl](DEBUG): Construct LoopControl.
2022-05-11T01:10:58.640Z,1652231458.640 [LoopControl] Loaded
2022-05-11T01:10:58.640Z,1652231458.640 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-05-11T01:10:58.640Z,1652231458.640 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-05-11T01:10:58.641Z,1652231458.641 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-05-11T01:10:58.775Z,1652231458.775 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-05-11T01:10:58.775Z,1652231458.775 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-05-11T01:10:58.788Z,1652231458.788 [NavChart] Loaded
2022-05-11T01:10:58.788Z,1652231458.788 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-05-11T01:10:58.794Z,1652231458.794 [UniversalFixResidualReporter] Loaded
2022-05-11T01:10:58.794Z,1652231458.794 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-05-11T01:10:58.795Z,1652231458.795 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-05-11T01:10:58.796Z,1652231458.796 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-05-11T01:10:58.936Z,1652231458.936 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-05-11T01:10:58.937Z,1652231458.937 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-05-11T01:10:59.720Z,1652231459.720 [AHRS_M2] Loaded
2022-05-11T01:10:59.721Z,1652231459.721 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-05-11T01:10:59.970Z,1652231459.970 [BackseatComponent] Loaded
2022-05-11T01:10:59.970Z,1652231459.970 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-05-11T01:10:59.971Z,1652231459.971 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408DD4E0
2022-05-11T01:10:59.972Z,1652231459.972 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 913
2022-05-11T01:10:59.974Z,1652231459.974 [LcmUniversalReporter] Loaded
2022-05-11T01:10:59.974Z,1652231459.974 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-05-11T01:11:00.199Z,1652231460.199 [DataOverHttps] Loaded
2022-05-11T01:11:00.199Z,1652231460.199 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-05-11T01:11:00.210Z,1652231460.210 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0
2022-05-11T01:11:00.210Z,1652231460.210 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 914
2022-05-11T01:11:00.275Z,1652231460.275 [Depth_Keller] Loaded
2022-05-11T01:11:00.276Z,1652231460.276 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-05-11T01:11:00.280Z,1652231460.280 [DropWeight] Loaded
2022-05-11T01:11:00.281Z,1652231460.281 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2022-05-11T01:11:00.317Z,1652231460.317 [DVL_micro] Loaded
2022-05-11T01:11:00.317Z,1652231460.317 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2022-05-11T01:11:00.580Z,1652231460.580 [NAL9602] Loaded
2022-05-11T01:11:00.580Z,1652231460.580 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-05-11T01:11:00.645Z,1652231460.645 [Onboard] Loaded
2022-05-11T01:11:00.645Z,1652231460.645 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-05-11T01:11:00.646Z,1652231460.646 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0
2022-05-11T01:11:00.646Z,1652231460.646 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 915
2022-05-11T01:11:00.658Z,1652231460.658 [Power24vConverter] Loaded
2022-05-11T01:11:00.658Z,1652231460.658 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-05-11T01:11:00.671Z,1652231460.671 [Radio_Surface] Loaded
2022-05-11T01:11:00.671Z,1652231460.671 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-05-11T01:11:00.672Z,1652231460.672 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0
2022-05-11T01:11:00.672Z,1652231460.672 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 916
2022-05-11T01:11:00.834Z,1652231460.834 [DAT] Loaded
2022-05-11T01:11:00.835Z,1652231460.835 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-05-11T01:11:00.836Z,1652231460.836 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 4099D4E0
2022-05-11T01:11:00.836Z,1652231460.836 [DAT ThreadHandler](INFO): Protected caller Thread ID is 917
2022-05-11T01:11:00.836Z,1652231460.836 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-05-11T01:11:00.837Z,1652231460.837 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-05-11T01:11:00.986Z,1652231460.986 [BuoyancyServo] Loaded
2022-05-11T01:11:00.987Z,1652231460.987 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-05-11T01:11:01.006Z,1652231461.006 [ElevatorServo] Loaded
2022-05-11T01:11:01.006Z,1652231461.006 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-05-11T01:11:01.025Z,1652231461.025 [MassServo] Loaded
2022-05-11T01:11:01.025Z,1652231461.025 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-05-11T01:11:01.043Z,1652231461.043 [RudderServo] Loaded
2022-05-11T01:11:01.044Z,1652231461.044 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-05-11T01:11:01.059Z,1652231461.059 [ThrusterHE] Loaded
2022-05-11T01:11:01.059Z,1652231461.059 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-05-11T01:11:01.059Z,1652231461.059 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-05-11T01:11:01.060Z,1652231461.060 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-05-11T01:11:01.143Z,1652231461.143 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-05-11T01:11:01.144Z,1652231461.144 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-05-11T01:11:01.186Z,1652231461.186 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-05-11T01:11:01.187Z,1652231461.187 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-05-11T01:11:01.548Z,1652231461.548 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-05-11T01:11:01.549Z,1652231461.549 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-05-11T01:11:01.764Z,1652231461.764 [CTD_Seabird] Loaded
2022-05-11T01:11:01.764Z,1652231461.764 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2022-05-11T01:11:01.765Z,1652231461.765 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B394E0
2022-05-11T01:11:01.766Z,1652231461.766 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 918
2022-05-11T01:11:01.797Z,1652231461.797 [ESPComponent] Loaded
2022-05-11T01:11:01.798Z,1652231461.798 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2022-05-11T01:11:01.817Z,1652231461.817 [PAR_Licor] Loaded
2022-05-11T01:11:01.817Z,1652231461.817 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-05-11T01:11:01.848Z,1652231461.848 [WetLabsBB2FL] Loaded
2022-05-11T01:11:01.848Z,1652231461.848 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-05-11T01:11:01.849Z,1652231461.849 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B694E0
2022-05-11T01:11:01.849Z,1652231461.849 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 919
2022-05-11T01:11:01.850Z,1652231461.850 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-05-11T01:11:01.851Z,1652231461.851 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-05-11T01:11:02.020Z,1652231462.020 [SBIT](DEBUG): Construct Startup Built In Test.
2022-05-11T01:11:02.029Z,1652231462.029 [SBIT] Loaded
2022-05-11T01:11:02.029Z,1652231462.029 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-05-11T01:11:02.032Z,1652231462.032 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-05-11T01:11:02.045Z,1652231462.045 [IBIT] Loaded
2022-05-11T01:11:02.045Z,1652231462.045 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-05-11T01:11:02.051Z,1652231462.051 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-05-11T01:11:02.278Z,1652231462.278 [CBIT] Loaded
2022-05-11T01:11:02.279Z,1652231462.279 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-05-11T01:11:02.279Z,1652231462.279 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-05-11T01:11:02.285Z,1652231462.285 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-05-11T01:11:02.288Z,1652231462.288 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-05-11T01:11:02.298Z,1652231462.298 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-05-11T01:11:02.299Z,1652231462.299 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BD74E0
2022-05-11T01:11:02.300Z,1652231462.300 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 920
2022-05-11T01:11:02.304Z,1652231462.304 [Supervisor](INFO): Main Thread ID is 822
2022-05-11T01:11:02.304Z,1652231462.304 [Supervisor](DEBUG): Running supervisor.
2022-05-11T01:11:02.305Z,1652231462.305 [CommandExec ThreadHandler](INFO): Handler Thread ID is 921
2022-05-11T01:11:02.305Z,1652231462.305 [CommandExec](INFO): Initializing the command executive.
2022-05-11T01:11:02.307Z,1652231462.307 [CommandLine ThreadHandler](INFO): Handler Thread ID is 922
2022-05-11T01:11:02.309Z,1652231462.309 [controlThread ThreadHandler](INFO): Handler Thread ID is 923
2022-05-11T01:11:02.309Z,1652231462.309 [controlThread](DEBUG): Initializing ControlThread
2022-05-11T01:11:02.310Z,1652231462.310 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-05-11T01:11:02.310Z,1652231462.310 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-05-11T01:11:02.311Z,1652231462.311 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-05-11T01:11:02.311Z,1652231462.311 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-05-11T01:11:02.312Z,1652231462.312 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-05-11T01:11:02.312Z,1652231462.312 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-05-11T01:11:02.314Z,1652231462.314 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-05-11T01:11:02.314Z,1652231462.314 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-05-11T01:11:02.315Z,1652231462.315 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-05-11T01:11:02.316Z,1652231462.316 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-05-11T01:11:02.316Z,1652231462.316 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-05-11T01:11:02.322Z,1652231462.322 [SBIT](INFO): Initialize SBIT Component.
2022-05-11T01:11:02.323Z,1652231462.323 [SBIT](IMPORTANT): git: 2022-05-11
2022-05-11T01:11:02.323Z,1652231462.323 [SBIT](INFO): git hash: 7696a1969a630744ed6dd937befa6455a7154426
2022-05-11T01:11:02.323Z,1652231462.323 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-05-11T01:11:02.324Z,1652231462.324 [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-05-11T01:11:02.325Z,1652231462.325 [SBIT](INFO): Beginning SBIT in 39.000000 seconds.
2022-05-11T01:11:02.326Z,1652231462.326 [IBIT](INFO): Initialize IBIT Component.
2022-05-11T01:11:02.327Z,1652231462.327 [CBIT](DEBUG): Initialize CBIT Component.
2022-05-11T01:11:02.328Z,1652231462.328 [logger ThreadHandler](INFO): Handler Thread ID is 924
2022-05-11T01:11:02.338Z,1652231462.338 [CBIT](DEBUG): Initialized mux pins.
2022-05-11T01:11:02.338Z,1652231462.338 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2022-05-11T01:11:02.338Z,1652231462.338 [CBIT](DEBUG): Initializing the watchdog timer.
2022-05-11T01:11:02.346Z,1652231462.346 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 925
2022-05-11T01:11:02.358Z,1652231462.358 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 926
2022-05-11T01:11:02.359Z,1652231462.359 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-05-11T01:11:02.362Z,1652231462.362 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-05-11T01:11:02.368Z,1652231462.368 [CBIT](FAULT): Found backtrace file:
1652231125.585586 [CBIT]: Backtrace:
./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x1abde0]
./bin/LRAUV(_ZN7PCaller10PThreadRunEPv+0xc8) [0x1ab82c]


2022-05-11T01:11:02.371Z,1652231462.371 [CBIT](FAULT): Renaming backtrace file to Data/backtrace12
2022-05-11T01:11:02.371Z,1652231462.371 [CBIT](DEBUG): Initializing heartbeat.
2022-05-11T01:11:02.367Z,1652231462.367 [Onboard ThreadHandler](INFO): Handler Thread ID is 927
2022-05-11T01:11:02.390Z,1652231462.390 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 928
2022-05-11T01:11:02.407Z,1652231462.407 [DAT ThreadHandler](INFO): Handler Thread ID is 929
2022-05-11T01:11:02.408Z,1652231462.408 [DAT](INFO): Powering up
2022-05-11T01:11:02.408Z,1652231462.408 [DAT](DEBUG): Initializing DAT.
2022-05-11T01:11:02.411Z,1652231462.411 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 931
2022-05-11T01:11:02.412Z,1652231462.412 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2022-05-11T01:11:02.415Z,1652231462.415 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 933
2022-05-11T01:11:02.418Z,1652231462.418 [WetLabsBB2FL](INFO): Powering up
2022-05-11T01:11:02.420Z,1652231462.420 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 935
2022-05-11T01:11:02.427Z,1652231462.427 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2022-05-11T01:11:02.428Z,1652231462.428 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2022-05-11T01:11:02.429Z,1652231462.429 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000
2022-05-11T01:11:02.429Z,1652231462.429 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000
2022-05-11T01:11:02.442Z,1652231462.442 [CBIT](DEBUG): Deactivating GF circuits.
2022-05-11T01:11:02.442Z,1652231462.442 [CBIT](DEBUG): Deactivating emergency mode.
2022-05-11T01:11:02.478Z,1652231462.478 [CBIT](DEBUG): Backplane powered.
2022-05-11T01:11:02.479Z,1652231462.479 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2022-05-11T01:11:02.526Z,1652231462.526 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-05-11T01:11:02.553Z,1652231462.553 [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-05-11T01:11:02.554Z,1652231462.554 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-05-11T01:11:02.620Z,1652231462.620 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-05-11T01:11:02.642Z,1652231462.642 [Default:A.Wait](DEBUG): Construct Wait.
2022-05-11T01:11:02.644Z,1652231462.644 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-05-11T01:11:02.687Z,1652231462.687 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-05-11T01:11:02.689Z,1652231462.689 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-05-11T01:11:02.712Z,1652231462.712 [Default:E.Execute](DEBUG): Construct Execute.
2022-05-11T01:11:02.727Z,1652231462.727 [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-05-11T01:11:02.732Z,1652231462.732 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,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-05-11T01:11:02.742Z,1652231462.742 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-05-11T01:11:02.798Z,1652231462.798 [Radio_Surface](INFO): Powering up
2022-05-11T01:11:02.898Z,1652231462.898 [Depth_Keller](ERROR): Pressure reading out of range: 1829.595459 decibar
2022-05-11T01:11:02.907Z,1652231462.907 [Power24vConverter](INFO): Powering up.
2022-05-11T01:11:02.916Z,1652231462.916 [DepthRateCalculator](ERROR): Depth measurement is not active
2022-05-11T01:11:02.981Z,1652231462.981 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:02.986Z,1652231462.986 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-05-11T01:11:02.987Z,1652231462.987 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:02.994Z,1652231462.994 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-05-11T01:11:02.995Z,1652231462.995 [MassServo](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:03.002Z,1652231463.002 [MassServo](DEBUG): Initializing MassServo.
2022-05-11T01:11:03.003Z,1652231463.003 [RudderServo](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:03.010Z,1652231463.010 [RudderServo](DEBUG): Initializing RudderServo.
2022-05-11T01:11:03.011Z,1652231463.011 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:03.038Z,1652231463.038 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-05-11T01:11:03.878Z,1652231463.878 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2022-05-11T01:11:03.878Z,1652231463.878 [RudderServo](FAULT): Rudder failed to initialize
2022-05-11T01:11:03.878Z,1652231463.878 [RudderServo] Communications Fault, FailCount= 1
2022-05-11T01:11:03.878Z,1652231463.878 [RudderServo](ERROR): Communications Fault
2022-05-11T01:11:03.882Z,1652231463.882 [CBIT](ERROR): Communications Fault in component: RudderServo
2022-05-11T01:11:04.099Z,1652231464.099 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-05-11T01:11:04.099Z,1652231464.099 [RudderServo](INFO): Powering down
2022-05-11T01:11:04.782Z,1652231464.782 [RudderServo](DEBUG): Initializing EZServoServo.
2022-05-11T01:11:04.903Z,1652231464.903 [RudderServo](DEBUG): Initializing RudderServo.
2022-05-11T01:11:04.907Z,1652231464.907 [CBIT](INFO): Clearing failed state for component RudderServo
2022-05-11T01:11:04.907Z,1652231464.907 [RudderServo] No Fault, FailCount= 1
2022-05-11T01:11:05.030Z,1652231465.030 [WetLabsBB2FL](INFO): Powering down
2022-05-11T01:11:08.711Z,1652231468.711 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-05-11T01:11:09.442Z,1652231469.442 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2022-05-11T01:11:17.276Z,1652231477.276 [DAT](INFO): commRate: 800
2022-05-11T01:11:19.342Z,1652231479.342 [DAT](INFO): entering command mode
2022-05-11T01:11:19.543Z,1652231479.543 [DAT](INFO): setting verbose to 3
2022-05-11T01:11:19.795Z,1652231479.795 [DAT](INFO): set verbose to 3
2022-05-11T01:11:19.796Z,1652231479.796 [DAT](INFO): setting DatVerbose to 27440
2022-05-11T01:11:20.047Z,1652231480.047 [DAT](INFO): set DatVerbose to 27440
2022-05-11T01:11:20.048Z,1652231480.048 [DAT](INFO): setting transmit power to 8
2022-05-11T01:11:20.299Z,1652231480.299 [DAT](INFO): set transmit power to 8
2022-05-11T01:11:20.300Z,1652231480.300 [DAT](INFO): setting local address to 8
2022-05-11T01:11:20.551Z,1652231480.551 [DAT](INFO): set local address to 8
2022-05-11T01:11:20.552Z,1652231480.552 [DAT](INFO): Setting time to: 1:11:20 And date to:5/11/2022
2022-05-11T01:11:20.803Z,1652231480.803 [DAT](INFO): Local DAT time set to Wed May 11, 2022  01:11:20  

2022-05-11T01:11:30.617Z,1652231490.617 [NAL9602](INFO): Powering up NAL9602
2022-05-11T01:11:41.529Z,1652231501.529 [NAL9602](INFO): NAL9602 initialized
2022-05-11T01:11:41.945Z,1652231501.945 [SBIT](IMPORTANT): Beginning Startup BIT
2022-05-11T01:11:41.969Z,1652231501.969 [CBIT](IMPORTANT): Beginning ground fault scan
2022-05-11T01:11:52.899Z,1652231512.899 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.005069
CHAN A1 (24V): -0.001768
CHAN A2 (12V): -0.000461
CHAN A3 (5V): 0.000579
CHAN B0 (3.3V): 0.000063
CHAN B1 (3.15aV): 0.000160
CHAN B2 (3.15bV): 0.000404
CHAN B3 (GND): 0.000332
OPEN: 0.002634
Full Scale: +/- 1 mA
2022-05-11T01:12:22.032Z,1652231542.032 [SBIT](FAULT): Rudder: EXPECTED:-15.000000 ACTUAL:-14.797676
2022-05-11T01:12:22.032Z,1652231542.032 [SBIT](FAULT): Control surface position failure.
2022-05-11T01:12:35.713Z,1652231555.713 [SBIT](FAULT): Mass: EXPECTED:0.004770 ACTUAL:0.003575
2022-05-11T01:12:35.713Z,1652231555.713 [SBIT](FAULT): Control surface position failure.
2022-05-11T01:12:36.135Z,1652231556.135 [SBIT](CRITICAL): SBIT FAILED
2022-05-11T01:12:36.135Z,1652231556.135 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2022-05-11T01:12:36.136Z,1652231556.136 [CommandExec](FAULT): Scheduling is paused
2022-05-11T01:12:36.137Z,1652231556.137 [CBIT](INFO): Critical error at 20220511T011236
2022-05-11T01:12:36.137Z,1652231556.137 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2022-05-11T01:12:36.483Z,1652231556.483 [MissionManager](IMPORTANT): Started mission Startup
2022-05-11T01:12:36.484Z,1652231556.484 [Startup] Running Loop=1
2022-05-11T01:12:36.484Z,1652231556.484 [Startup](DEBUG): Aggregate::initialize Startup
2022-05-11T01:12:36.484Z,1652231556.484 [Startup:A.GoToSurface] Running Loop=1
2022-05-11T01:12:36.484Z,1652231556.484 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-05-11T01:12:36.485Z,1652231556.485 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-05-11T01:12:36.485Z,1652231556.485 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-05-11T01:12:36.485Z,1652231556.485 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-05-11T01:12:36.486Z,1652231556.486 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-05-11T01:12:36.486Z,1652231556.486 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-05-11T01:12:36.487Z,1652231556.487 [Startup:StartupSatComms] Running Loop=1
2022-05-11T01:12:36.488Z,1652231556.488 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2022-05-11T01:12:36.488Z,1652231556.488 [Startup:StartupSatComms:A] Running Loop=1
2022-05-11T01:12:36.889Z,1652231556.889 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2022-05-11T01:13:36.689Z,1652231616.689 [Startup:StartupSatComms:A](INFO): Timed out from 2022-05-11T01:12:36.5Z
2022-05-11T01:13:36.689Z,1652231616.689 [Startup:StartupSatComms:A] Stopped
2022-05-11T01:13:36.689Z,1652231616.689 [Startup:StartupSatComms:B] Running Loop=1
2022-05-11T01:13:37.084Z,1652231617.084 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-05-11T01:14:02.404Z,1652231642.404 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004370
2022-05-11T01:14:02.559Z,1652231642.559 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2022-05-11T01:14:02.559Z,1652231642.559 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-05-11T01:14:02.569Z,1652231642.569 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-05-11T01:14:02.941Z,1652231642.941 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-05-11T01:14:02.941Z,1652231642.941 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2022-05-11T01:14:09.687Z,1652231649.687 [DataOverHttps](INFO): Sending 70 bytes from file Logs/20220511T002713/Courier0016.lzma
2022-05-11T01:14:10.688Z,1652231650.688 [DataOverHttps](INFO): Moved sent file to Logs/20220511T002713/Courier0016.lzma.bak
2022-05-11T01:14:10.688Z,1652231650.688 [DataOverHttps](INFO): SBD MOMSN=16735564
2022-05-11T01:14:26.205Z,1652231666.205 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220511T002713/Courier0019.lzma
2022-05-11T01:14:27.213Z,1652231667.213 [DataOverHttps](INFO): Moved sent file to Logs/20220511T002713/Courier0019.lzma.bak
2022-05-11T01:14:27.214Z,1652231667.214 [DataOverHttps](INFO): SBD MOMSN=16735567
2022-05-11T01:14:36.888Z,1652231676.888 [Startup:StartupSatComms:B](INFO): Timed out from 2022-05-11T01:13:36.7Z
2022-05-11T01:14:36.889Z,1652231676.889 [Startup:StartupSatComms:B] Stopped
2022-05-11T01:14:36.889Z,1652231676.889 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2022-05-11T01:14:36.889Z,1652231676.889 [Startup:StartupSatComms] Stopped
2022-05-11T01:14:36.889Z,1652231676.889 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2022-05-11T01:14:36.890Z,1652231676.890 [Startup](INFO): Completed Startup
2022-05-11T01:14:36.890Z,1652231676.890 [MissionManager](INFO): Startup is completed.
2022-05-11T01:14:36.890Z,1652231676.890 [MissionManager](INFO): Uninitializing Mission Startup
2022-05-11T01:14:36.890Z,1652231676.890 [Startup] Stopped
2022-05-11T01:14:36.890Z,1652231676.890 [Startup](DEBUG): Aggregate::uninitialize Startup
2022-05-11T01:14:36.890Z,1652231676.890 [Startup:A.GoToSurface] Stopped
2022-05-11T01:14:36.891Z,1652231676.891 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-05-11T01:14:37.308Z,1652231677.308 [MissionManager](IMPORTANT): Started mission Default
2022-05-11T01:14:37.308Z,1652231677.308 [Default] Running Loop=1
2022-05-11T01:14:37.308Z,1652231677.308 [Default](DEBUG): Aggregate::initialize Default
2022-05-11T01:14:37.308Z,1652231677.308 [Default:B.GoToSurface] Running Loop=1
2022-05-11T01:14:37.309Z,1652231677.309 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-05-11T01:14:37.309Z,1652231677.309 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-05-11T01:14:37.309Z,1652231677.309 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-05-11T01:14:37.309Z,1652231677.309 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-05-11T01:14:37.310Z,1652231677.310 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-05-11T01:14:37.310Z,1652231677.310 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-05-11T01:14:37.311Z,1652231677.311 [Default:A.Wait] Running Loop=1
2022-05-11T01:14:37.311Z,1652231677.311 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:14:42.815Z,1652231682.815 [DataOverHttps](INFO): Sending 228 bytes from file Logs/20220511T010508/Courier0000.lzma
2022-05-11T01:14:43.816Z,1652231683.816 [DataOverHttps](INFO): Moved sent file to Logs/20220511T010508/Courier0000.lzma.bak
2022-05-11T01:14:43.816Z,1652231683.816 [DataOverHttps](INFO): SBD MOMSN=16735569
2022-05-11T01:14:50.629Z,1652231690.629 [Default:A.Wait](INFO): Done Waiting.
2022-05-11T01:14:50.629Z,1652231690.629 [Default:A.Wait] Stopped
2022-05-11T01:14:50.629Z,1652231690.629 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:14:51.037Z,1652231691.037 [Default:CheckIn] Running Loop=1
2022-05-11T01:14:51.037Z,1652231691.037 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:14:51.037Z,1652231691.037 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:14:51.447Z,1652231691.447 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-05-11T01:16:14.653Z,1652231774.653 [DVL_micro](ERROR): Failed to parse:
:SA,-01.03,+02.88,211.7
2022-05-11T01:16:44.928Z,1652231804.928 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T01:16:54.640Z,1652231814.640 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,011654.00,A,3648.16549,N,12147.28184,W,0.272,186.25,110522,,,A*71
2022-05-11T01:16:54.643Z,1652231814.643 [NAL9602](INFO): GPS fix at 20220511T011654: (36.802758, -121.788031)
2022-05-11T01:16:54.654Z,1652231814.654 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:16:54.654Z,1652231814.654 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:16:55.070Z,1652231815.070 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-05-11T01:17:02.269Z,1652231822.269 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220511T010508/Courier0004.lzma
2022-05-11T01:17:03.272Z,1652231823.272 [DataOverHttps](INFO): Moved sent file to Logs/20220511T010508/Courier0004.lzma.bak
2022-05-11T01:17:03.272Z,1652231823.272 [DataOverHttps](INFO): SBD MOMSN=16735574
2022-05-11T01:17:20.118Z,1652231840.118 [DataOverHttps](INFO): Sending 185 bytes from file Logs/20220511T011051/Courier0000.lzma
2022-05-11T01:17:21.120Z,1652231841.120 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0000.lzma.bak
2022-05-11T01:17:21.120Z,1652231841.120 [DataOverHttps](INFO): SBD MOMSN=16735576
2022-05-11T01:17:27.355Z,1652231847.355 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T01:17:37.042Z,1652231857.042 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20220511T011051/Courier0004.lzma
2022-05-11T01:17:38.044Z,1652231858.044 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0004.lzma.bak
2022-05-11T01:17:38.044Z,1652231858.044 [DataOverHttps](INFO): SBD MOMSN=16735580
2022-05-11T01:17:54.108Z,1652231874.108 [DataOverHttps](INFO): Sending 587 bytes from file Logs/20220511T002713/Express0017.lzma
2022-05-11T01:17:55.108Z,1652231875.108 [DataOverHttps](INFO): Moved sent file to Logs/20220511T002713/Express0017.lzma.bak
2022-05-11T01:17:55.108Z,1652231875.108 [DataOverHttps](INFO): SBD MOMSN=16735583
2022-05-11T01:18:11.065Z,1652231891.065 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220511T002713/Express0020.lzma
2022-05-11T01:18:12.068Z,1652231892.068 [DataOverHttps](INFO): Moved sent file to Logs/20220511T002713/Express0020.lzma.bak
2022-05-11T01:18:12.068Z,1652231892.068 [DataOverHttps](INFO): SBD MOMSN=16735597
2022-05-11T01:18:27.912Z,1652231907.912 [DataOverHttps](INFO): Sending 929 bytes from file Logs/20220511T010508/Express0001.lzma
2022-05-11T01:18:28.912Z,1652231908.912 [DataOverHttps](INFO): Moved sent file to Logs/20220511T010508/Express0001.lzma.bak
2022-05-11T01:18:28.912Z,1652231908.912 [DataOverHttps](INFO): SBD MOMSN=16735599
2022-05-11T01:18:44.909Z,1652231924.909 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220511T010508/Express0005.lzma
2022-05-11T01:18:45.912Z,1652231925.912 [DataOverHttps](INFO): Moved sent file to Logs/20220511T010508/Express0005.lzma.bak
2022-05-11T01:18:45.912Z,1652231925.912 [DataOverHttps](INFO): SBD MOMSN=16735623
2022-05-11T01:19:01.947Z,1652231941.947 [DataOverHttps](INFO): Sending 896 bytes from file Logs/20220511T011051/Express0001.lzma
2022-05-11T01:19:02.948Z,1652231942.948 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0001.lzma.bak
2022-05-11T01:19:02.948Z,1652231942.948 [DataOverHttps](INFO): SBD MOMSN=16735625
2022-05-11T01:19:18.930Z,1652231958.930 [DataOverHttps](INFO): Sending 312 bytes from file Logs/20220511T011051/Express0005.lzma
2022-05-11T01:19:19.932Z,1652231959.932 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0005.lzma.bak
2022-05-11T01:19:19.932Z,1652231959.932 [DataOverHttps](INFO): SBD MOMSN=16735644
2022-05-11T01:19:21.343Z,1652231961.343 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:19:21.343Z,1652231961.343 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:19:21.343Z,1652231961.343 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:22:50.601Z,1652232170.601 [DVL_micro](ERROR): Failed to parse:
:WI,+00094,-01408,+00680,+

2022-05-11T01:24:21.910Z,1652232261.910 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:24:21.911Z,1652232261.911 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:24:21.911Z,1652232261.911 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:24:21.911Z,1652232261.911 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:24:22.350Z,1652232262.349 [Default:CheckIn:D] Stopped
2022-05-11T01:24:22.350Z,1652232262.350 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:24:22.734Z,1652232262.734 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.750686 min 
2022-05-11T01:24:22.734Z,1652232262.734 [Default:CheckIn:E] Stopped
2022-05-11T01:24:22.734Z,1652232262.734 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:24:22.734Z,1652232262.734 [Default:CheckIn] Stopped
2022-05-11T01:24:22.734Z,1652232262.734 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:24:22.735Z,1652232262.735 [Default:CheckIn](INFO): Running loop #2
2022-05-11T01:24:22.735Z,1652232262.735 [Default:CheckIn] Running Loop=2
2022-05-11T01:24:22.735Z,1652232262.735 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:24:22.735Z,1652232262.735 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:24:24.731Z,1652232264.731 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012424.00,A,3648.16087,N,12147.28176,W,0.972,239.22,110522,,,A*76
2022-05-11T01:24:24.733Z,1652232264.733 [NAL9602](INFO): GPS fix at 20220511T012424: (36.802681, -121.788029)
2022-05-11T01:24:24.744Z,1652232264.744 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:24:24.744Z,1652232264.744 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:24:32.529Z,1652232272.529 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0007.lzma
2022-05-11T01:24:40.973Z,1652232280.973 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0007.lzma
2022-05-11T01:24:41.976Z,1652232281.976 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0007.lzma.bak
2022-05-11T01:24:41.976Z,1652232281.976 [DataOverHttps](INFO): SBD MOMSN=16735648
2022-05-11T01:24:55.440Z,1652232295.440 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T01:24:55.514Z,1652232295.514 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T01:24:56.913Z,1652232296.913 [DataOverHttps](INFO): Sending 158 bytes from file Logs/20220511T011051/Express0008.lzma
2022-05-11T01:24:57.916Z,1652232297.916 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0008.lzma.bak
2022-05-11T01:24:57.916Z,1652232297.916 [DataOverHttps](INFO): SBD MOMSN=16735651
2022-05-11T01:24:59.080Z,1652232299.080 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:24:59.080Z,1652232299.080 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:24:59.080Z,1652232299.080 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:27:20.885Z,1652232440.885 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T01:27:20.885Z,1652232440.885 [DVL_micro](ERROR): Failed to parse:
:BI,01185,+00240,+00000,I
2022-05-11T01:29:26.928Z,1652232566.928 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T01:29:57.631Z,1652232597.631 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T01:29:59.659Z,1652232599.659 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:29:59.659Z,1652232599.659 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:29:59.659Z,1652232599.659 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:29:59.659Z,1652232599.659 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:30:00.073Z,1652232600.073 [Default:CheckIn:D] Stopped
2022-05-11T01:30:00.073Z,1652232600.073 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 15.379415 min 
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn:E] Stopped
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn] Stopped
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn](INFO): Running loop #3
2022-05-11T01:30:00.471Z,1652232600.471 [Default:CheckIn] Running Loop=3
2022-05-11T01:30:00.472Z,1652232600.472 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:30:00.472Z,1652232600.472 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:30:02.483Z,1652232602.483 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013002.00,A,3648.16757,N,12147.27320,W,0.505,0.00,110522,,,A*77
2022-05-11T01:30:02.485Z,1652232602.485 [NAL9602](INFO): GPS fix at 20220511T013002: (36.802793, -121.787887)
2022-05-11T01:30:02.495Z,1652232602.495 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:30:02.495Z,1652232602.495 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:30:09.865Z,1652232609.865 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0010.lzma
2022-05-11T01:30:10.868Z,1652232610.868 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0010.lzma.bak
2022-05-11T01:30:10.868Z,1652232610.868 [DataOverHttps](INFO): SBD MOMSN=16735654
2022-05-11T01:30:26.742Z,1652232626.742 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220511T011051/Express0011.lzma
2022-05-11T01:30:27.744Z,1652232627.744 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0011.lzma.bak
2022-05-11T01:30:27.744Z,1652232627.744 [DataOverHttps](INFO): SBD MOMSN=16735657
2022-05-11T01:30:29.160Z,1652232629.160 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:30:29.160Z,1652232629.160 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:30:29.161Z,1652232629.161 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:30:33.180Z,1652232633.180 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T01:30:33.258Z,1652232633.258 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T01:32:57.416Z,1652232777.416 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T01:32:57.416Z,1652232777.416 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0,000
2022-05-11T01:35:05.084Z,1652232905.084 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T01:35:29.745Z,1652232929.745 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:35:29.746Z,1652232929.746 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:35:29.746Z,1652232929.746 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:35:29.746Z,1652232929.746 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:35:30.174Z,1652232930.174 [Default:CheckIn:D] Stopped
2022-05-11T01:35:30.174Z,1652232930.174 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.881022 min 
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn:E] Stopped
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn] Stopped
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:35:30.544Z,1652232930.544 [Default:CheckIn](INFO): Running loop #4
2022-05-11T01:35:30.545Z,1652232930.545 [Default:CheckIn] Running Loop=4
2022-05-11T01:35:30.545Z,1652232930.545 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:35:30.545Z,1652232930.545 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:35:32.557Z,1652232932.557 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013532.00,A,3648.16419,N,12147.27555,W,0.739,199.37,110522,,,A*74
2022-05-11T01:35:32.560Z,1652232932.560 [NAL9602](INFO): GPS fix at 20220511T013532: (36.802737, -121.787926)
2022-05-11T01:35:32.570Z,1652232932.570 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:35:32.570Z,1652232932.570 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:35:40.393Z,1652232940.393 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0013.lzma
2022-05-11T01:35:41.396Z,1652232941.396 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0013.lzma.bak
2022-05-11T01:35:41.396Z,1652232941.396 [DataOverHttps](INFO): SBD MOMSN=16735661
2022-05-11T01:35:57.238Z,1652232957.238 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220511T011051/Express0014.lzma
2022-05-11T01:35:58.240Z,1652232958.240 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0014.lzma.bak
2022-05-11T01:35:58.240Z,1652232958.240 [DataOverHttps](INFO): SBD MOMSN=16735664
2022-05-11T01:35:59.627Z,1652232959.627 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:35:59.627Z,1652232959.627 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:35:59.627Z,1652232959.627 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:36:05.280Z,1652232965.280 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T01:41:00.223Z,1652233260.223 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:41:00.223Z,1652233260.223 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:41:00.223Z,1652233260.223 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:41:00.223Z,1652233260.223 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:41:00.618Z,1652233260.618 [Default:CheckIn:D] Stopped
2022-05-11T01:41:00.626Z,1652233260.626 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:41:01.027Z,1652233261.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.388487 min 
2022-05-11T01:41:01.027Z,1652233261.027 [Default:CheckIn:E] Stopped
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn] Stopped
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn](INFO): Running loop #5
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn] Running Loop=5
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:41:01.028Z,1652233261.028 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:41:03.039Z,1652233263.039 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,014102.00,A,3648.16063,N,12147.28465,W,0.797,199.37,110522,,,A*74
2022-05-11T01:41:03.041Z,1652233263.041 [NAL9602](INFO): GPS fix at 20220511T014102: (36.802677, -121.788077)
2022-05-11T01:41:03.052Z,1652233263.052 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:41:03.052Z,1652233263.052 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:41:13.981Z,1652233273.981 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T01:41:13.981Z,1652233273.981 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+17.7,0000.0,1489:WI,-01015,-01106,+00211,+00000,A
2022-05-11T01:41:14.797Z,1652233274.797 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0016.lzma
2022-05-11T01:41:15.800Z,1652233275.800 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0016.lzma.bak
2022-05-11T01:41:15.800Z,1652233275.800 [DataOverHttps](INFO): SBD MOMSN=16735668
2022-05-11T01:41:31.753Z,1652233291.753 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220511T011051/Express0017.lzma
2022-05-11T01:41:32.756Z,1652233292.756 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0017.lzma.bak
2022-05-11T01:41:32.756Z,1652233292.756 [DataOverHttps](INFO): SBD MOMSN=16735671
2022-05-11T01:41:33.725Z,1652233293.725 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T01:41:33.798Z,1652233293.798 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T01:41:33.814Z,1652233293.814 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:41:33.814Z,1652233293.814 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:41:33.814Z,1652233293.814 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:44:33.114Z,1652233473.114 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T01:44:33.114Z,1652233473.114 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+99999.99,+9999.99
2022-05-11T01:45:44.220Z,1652233544.220 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T01:45:44.220Z,1652233544.220 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2022-05-11T01:46:05.219Z,1652233565.219 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T01:46:34.317Z,1652233594.317 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:46:34.317Z,1652233594.317 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:46:34.317Z,1652233594.317 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:46:34.317Z,1652233594.317 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:46:34.731Z,1652233594.731 [Default:CheckIn:D] Stopped
2022-05-11T01:46:34.731Z,1652233594.731 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.957037 min 
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn:E] Stopped
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn] Stopped
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn](INFO): Running loop #6
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn] Running Loop=6
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:46:35.149Z,1652233595.149 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:46:37.137Z,1652233597.137 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,014636.00,A,3648.15596,N,12147.27973,W,1.652,0.00,110522,,,A*71
2022-05-11T01:46:37.140Z,1652233597.140 [NAL9602](INFO): GPS fix at 20220511T014636: (36.802599, -121.787995)
2022-05-11T01:46:37.150Z,1652233597.150 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:46:37.150Z,1652233597.150 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:46:44.653Z,1652233604.653 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0019.lzma
2022-05-11T01:46:45.676Z,1652233605.676 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0019.lzma.bak
2022-05-11T01:46:45.676Z,1652233605.676 [DataOverHttps](INFO): SBD MOMSN=16735674
2022-05-11T01:47:01.474Z,1652233621.474 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220511T011051/Express0020.lzma
2022-05-11T01:47:02.476Z,1652233622.476 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0020.lzma.bak
2022-05-11T01:47:02.476Z,1652233622.476 [DataOverHttps](INFO): SBD MOMSN=16735677
2022-05-11T01:47:03.805Z,1652233623.805 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:47:03.805Z,1652233623.805 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:47:03.806Z,1652233623.806 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:47:10.264Z,1652233630.264 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T01:48:04.399Z,1652233684.399 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T01:48:04.400Z,1652233684.400 [DVL_micro](ERROR): Failed to parse:
:BI,-01436,-02023,+0043,I
2022-05-11T01:50:32.262Z,1652233832.262 [DVL_micro](ERROR): Failed to parse:
:WI,-0060,+00832,+00000,A
2022-05-11T01:51:15.489Z,1652233875.489 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T01:51:15.490Z,1652233875.490 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000,+17.9,0000.0,1489.0,000
2022-05-11T01:52:04.393Z,1652233924.393 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:52:04.393Z,1652233924.393 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:52:04.394Z,1652233924.394 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:52:04.394Z,1652233924.394 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:52:04.787Z,1652233924.787 [Default:CheckIn:D] Stopped
2022-05-11T01:52:04.787Z,1652233924.787 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:52:05.189Z,1652233925.189 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 37.457975 min 
2022-05-11T01:52:05.189Z,1652233925.189 [Default:CheckIn:E] Stopped
2022-05-11T01:52:05.189Z,1652233925.189 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn] Stopped
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn](INFO): Running loop #7
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn] Running Loop=7
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:52:05.190Z,1652233925.190 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:52:07.201Z,1652233927.201 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,015206.00,A,3648.16431,N,12147.28128,W,1.400,0.00,110522,,,A*74
2022-05-11T01:52:07.203Z,1652233927.203 [NAL9602](INFO): GPS fix at 20220511T015206: (36.802738, -121.788021)
2022-05-11T01:52:07.213Z,1652233927.213 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:52:07.214Z,1652233927.214 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:52:14.789Z,1652233934.789 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0022.lzma
2022-05-11T01:52:15.792Z,1652233935.792 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0022.lzma.bak
2022-05-11T01:52:15.792Z,1652233935.792 [DataOverHttps](INFO): SBD MOMSN=16735681
2022-05-11T01:52:31.789Z,1652233951.789 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220511T011051/Express0023.lzma
2022-05-11T01:52:32.792Z,1652233952.792 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0023.lzma.bak
2022-05-11T01:52:32.792Z,1652233952.792 [DataOverHttps](INFO): SBD MOMSN=16735684
2022-05-11T01:52:33.877Z,1652233953.877 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:52:33.877Z,1652233953.877 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:52:33.877Z,1652233953.877 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:52:37.904Z,1652233957.904 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T01:52:37.978Z,1652233957.978 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T01:55:22.351Z,1652234122.351 [DVL_micro](ERROR): Failed to parse:
9.99,+99999.99,+9999.99
2022-05-11T01:57:08.985Z,1652234228.985 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T01:57:34.453Z,1652234254.453 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T01:57:34.453Z,1652234254.453 [Default:CheckIn:C.Wait] Stopped
2022-05-11T01:57:34.453Z,1652234254.453 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T01:57:34.453Z,1652234254.453 [Default:CheckIn:D] Running Loop=1
2022-05-11T01:57:34.867Z,1652234254.867 [Default:CheckIn:D] Stopped
2022-05-11T01:57:34.867Z,1652234254.867 [Default:CheckIn:E] Running Loop=1
2022-05-11T01:57:35.262Z,1652234255.262 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.959302 min 
2022-05-11T01:57:35.262Z,1652234255.262 [Default:CheckIn:E] Stopped
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn] Stopped
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn](INFO): Running loop #8
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn] Running Loop=8
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T01:57:35.263Z,1652234255.263 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T01:57:37.290Z,1652234257.290 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,015736.00,A,3648.16138,N,12147.28221,W,0.408,0.00,110522,,,A*7D
2022-05-11T01:57:37.292Z,1652234257.292 [NAL9602](INFO): GPS fix at 20220511T015736: (36.802690, -121.788037)
2022-05-11T01:57:37.303Z,1652234257.303 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T01:57:37.303Z,1652234257.303 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T01:57:44.525Z,1652234264.525 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220511T011051/Courier0025.lzma
2022-05-11T01:57:45.528Z,1652234265.528 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0025.lzma.bak
2022-05-11T01:57:45.528Z,1652234265.528 [DataOverHttps](INFO): SBD MOMSN=16735687
2022-05-11T01:58:01.470Z,1652234281.470 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220511T011051/Express0026.lzma
2022-05-11T01:58:02.474Z,1652234282.474 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0026.lzma.bak
2022-05-11T01:58:02.474Z,1652234282.474 [DataOverHttps](INFO): SBD MOMSN=16735690
2022-05-11T01:58:03.557Z,1652234283.557 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T01:58:03.557Z,1652234283.557 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T01:58:03.557Z,1652234283.557 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T01:58:10.001Z,1652234290.001 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:00:07.561Z,1652234407.561 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:00:07.561Z,1652234407.561 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0000.0,1489.WI,-0025,+01062,+00000,A
2022-05-11T02:01:03.717Z,1652234463.717 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:01:03.718Z,1652234463.718 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000018.0,0000.0,1489.0,000
2022-05-11T02:03:04.173Z,1652234584.173 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:03:04.173Z,1652234584.173 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:03:04.173Z,1652234584.173 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:03:04.173Z,1652234584.173 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:03:04.589Z,1652234584.589 [Default:CheckIn:D] Stopped
2022-05-11T02:03:04.589Z,1652234584.589 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.454675 min 
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn:E] Stopped
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn] Stopped
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn](INFO): Running loop #9
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn] Running Loop=9
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:03:05.024Z,1652234585.024 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:03:06.999Z,1652234586.999 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,020306.00,A,3648.17049,N,12147.27663,W,0.253,0.00,110522,,,A*7F
2022-05-11T02:03:07.001Z,1652234587.001 [NAL9602](INFO): GPS fix at 20220511T020306: (36.802841, -121.787944)
2022-05-11T02:03:07.011Z,1652234587.011 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:03:07.012Z,1652234587.012 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:03:15.177Z,1652234595.177 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0028.lzma
2022-05-11T02:03:16.180Z,1652234596.180 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0028.lzma.bak
2022-05-11T02:03:16.180Z,1652234596.180 [DataOverHttps](INFO): SBD MOMSN=16735694
2022-05-11T02:03:32.066Z,1652234612.066 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220511T011051/Express0029.lzma
2022-05-11T02:03:33.068Z,1652234613.068 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0029.lzma.bak
2022-05-11T02:03:33.068Z,1652234613.068 [DataOverHttps](INFO): SBD MOMSN=16735697
2022-05-11T02:03:34.133Z,1652234614.133 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:03:34.133Z,1652234614.133 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:03:34.133Z,1652234614.133 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:03:37.700Z,1652234617.700 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T02:03:37.774Z,1652234617.774 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T02:04:25.373Z,1652234665.373 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:04:25.373Z,1652234665.373 [DVL_micro](ERROR): Failed to parse:
:TS,000000005.0,+18.1,489.0,000
2022-05-11T02:08:09.184Z,1652234889.184 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T02:08:34.650Z,1652234914.650 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:08:34.651Z,1652234914.651 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:08:34.651Z,1652234914.651 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:08:34.651Z,1652234914.651 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:08:35.059Z,1652234915.059 [Default:CheckIn:D] Stopped
2022-05-11T02:08:35.059Z,1652234915.059 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:08:35.465Z,1652234915.465 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.962504 min 
2022-05-11T02:08:35.465Z,1652234915.465 [Default:CheckIn:E] Stopped
2022-05-11T02:08:35.465Z,1652234915.465 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn] Stopped
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn](INFO): Running loop #10
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn] Running Loop=10
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:08:35.466Z,1652234915.466 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:08:37.463Z,1652234917.463 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,020837.00,A,3648.16117,N,12147.29105,W,1.147,0.00,110522,,,A*73
2022-05-11T02:08:37.465Z,1652234917.465 [NAL9602](INFO): GPS fix at 20220511T020837: (36.802686, -121.788184)
2022-05-11T02:08:37.476Z,1652234917.476 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:08:37.476Z,1652234917.476 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:08:45.081Z,1652234925.081 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0031.lzma
2022-05-11T02:08:46.084Z,1652234926.084 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0031.lzma.bak
2022-05-11T02:08:46.084Z,1652234926.084 [DataOverHttps](INFO): SBD MOMSN=16735700
2022-05-11T02:09:02.042Z,1652234942.042 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220511T011051/Express0032.lzma
2022-05-11T02:09:03.049Z,1652234943.049 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0032.lzma.bak
2022-05-11T02:09:03.050Z,1652234943.050 [DataOverHttps](INFO): SBD MOMSN=16735704
2022-05-11T02:09:04.144Z,1652234944.144 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:09:04.144Z,1652234944.144 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:09:04.144Z,1652234944.144 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:09:10.188Z,1652234950.188 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:14:04.721Z,1652235244.721 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:14:04.721Z,1652235244.721 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:14:04.721Z,1652235244.721 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:14:04.721Z,1652235244.721 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:14:05.132Z,1652235245.132 [Default:CheckIn:D] Stopped
2022-05-11T02:14:05.132Z,1652235245.132 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:14:05.567Z,1652235245.567 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.463721 min 
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn:E] Stopped
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn] Stopped
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn](INFO): Running loop #11
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn] Running Loop=11
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:14:05.568Z,1652235245.568 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:14:07.535Z,1652235247.535 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,021407.00,A,3648.17026,N,12147.28374,W,0.661,0.00,110522,,,A*78
2022-05-11T02:14:07.537Z,1652235247.537 [NAL9602](INFO): GPS fix at 20220511T021407: (36.802838, -121.788062)
2022-05-11T02:14:07.548Z,1652235247.548 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:14:07.548Z,1652235247.548 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:14:14.897Z,1652235254.897 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0034.lzma
2022-05-11T02:14:15.900Z,1652235255.900 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0034.lzma.bak
2022-05-11T02:14:15.900Z,1652235255.900 [DataOverHttps](INFO): SBD MOMSN=16735708
2022-05-11T02:14:31.837Z,1652235271.837 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20220511T011051/Express0035.lzma
2022-05-11T02:14:32.840Z,1652235272.840 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0035.lzma.bak
2022-05-11T02:14:32.840Z,1652235272.840 [DataOverHttps](INFO): SBD MOMSN=16735711
2022-05-11T02:14:34.221Z,1652235274.221 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:14:34.221Z,1652235274.221 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:14:34.222Z,1652235274.222 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:14:38.244Z,1652235278.244 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T02:14:38.322Z,1652235278.322 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T02:15:36.018Z,1652235336.018 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:15:36.018Z,1652235336.018 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000+18.3,0000.0,1489.0,,-01041,-00387,+00638,+00000,A
2022-05-11T02:19:10.136Z,1652235550.136 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T02:19:34.801Z,1652235574.801 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:19:34.801Z,1652235574.801 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:19:34.801Z,1652235574.801 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:19:34.802Z,1652235574.802 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:19:35.195Z,1652235575.195 [Default:CheckIn:D] Stopped
2022-05-11T02:19:35.195Z,1652235575.195 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.964771 min 
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn:E] Stopped
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn] Stopped
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn](INFO): Running loop #12
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn] Running Loop=12
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:19:35.604Z,1652235575.604 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:19:37.605Z,1652235577.605 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,021937.00,A,3648.17325,N,12147.28552,W,0.311,0.00,110522,,,A*76
2022-05-11T02:19:37.607Z,1652235577.607 [NAL9602](INFO): GPS fix at 20220511T021937: (36.802887, -121.788092)
2022-05-11T02:19:37.617Z,1652235577.617 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:19:37.618Z,1652235577.618 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:19:44.813Z,1652235584.813 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0037.lzma
2022-05-11T02:19:45.816Z,1652235585.816 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0037.lzma.bak
2022-05-11T02:19:45.816Z,1652235585.816 [DataOverHttps](INFO): SBD MOMSN=16735714
2022-05-11T02:20:01.614Z,1652235601.614 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220511T011051/Express0038.lzma
2022-05-11T02:20:02.616Z,1652235602.616 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0038.lzma.bak
2022-05-11T02:20:02.616Z,1652235602.616 [DataOverHttps](INFO): SBD MOMSN=16735717
2022-05-11T02:20:03.889Z,1652235603.889 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:20:03.889Z,1652235603.889 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:20:03.889Z,1652235603.889 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:20:10.325Z,1652235610.325 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:25:04.509Z,1652235904.509 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:25:04.509Z,1652235904.509 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:25:04.510Z,1652235904.510 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:25:04.510Z,1652235904.510 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:25:04.930Z,1652235904.930 [Default:CheckIn:D] Stopped
2022-05-11T02:25:04.930Z,1652235904.930 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.460352 min 
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn:E] Stopped
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn] Stopped
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:25:05.323Z,1652235905.323 [Default:CheckIn](INFO): Running loop #13
2022-05-11T02:25:05.324Z,1652235905.324 [Default:CheckIn] Running Loop=13
2022-05-11T02:25:05.324Z,1652235905.324 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:25:05.324Z,1652235905.324 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:25:07.328Z,1652235907.328 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,022506.00,A,3648.17938,N,12147.28041,W,0.467,0.00,110522,,,A*7C
2022-05-11T02:25:07.331Z,1652235907.331 [NAL9602](INFO): GPS fix at 20220511T022506: (36.802990, -121.788007)
2022-05-11T02:25:07.341Z,1652235907.341 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:25:07.341Z,1652235907.341 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:25:15.125Z,1652235915.125 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0040.lzma
2022-05-11T02:25:16.131Z,1652235916.131 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0040.lzma.bak
2022-05-11T02:25:16.131Z,1652235916.131 [DataOverHttps](INFO): SBD MOMSN=16735721
2022-05-11T02:25:32.009Z,1652235932.009 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20220511T011051/Express0041.lzma
2022-05-11T02:25:33.008Z,1652235933.008 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0041.lzma.bak
2022-05-11T02:25:33.008Z,1652235933.008 [DataOverHttps](INFO): SBD MOMSN=16735724
2022-05-11T02:25:34.406Z,1652235934.406 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:25:34.406Z,1652235934.406 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:25:34.406Z,1652235934.406 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:25:38.036Z,1652235938.036 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T02:25:38.110Z,1652235938.110 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T02:30:09.944Z,1652236209.944 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T02:30:34.989Z,1652236234.989 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:30:34.991Z,1652236234.991 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:30:34.991Z,1652236234.991 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:30:34.991Z,1652236234.991 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:30:35.399Z,1652236235.399 [Default:CheckIn:D] Stopped
2022-05-11T02:30:35.399Z,1652236235.399 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.968172 min 
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn:E] Stopped
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn] Stopped
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn](INFO): Running loop #14
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn] Running Loop=14
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:30:35.808Z,1652236235.808 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:30:37.799Z,1652236237.799 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,023037.00,A,3648.16543,N,12147.28541,W,1.536,0.00,110522,,,A*7A
2022-05-11T02:30:37.802Z,1652236237.802 [NAL9602](INFO): GPS fix at 20220511T023037: (36.802757, -121.788090)
2022-05-11T02:30:37.812Z,1652236237.812 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:30:37.812Z,1652236237.812 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:30:45.633Z,1652236245.633 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0043.lzma
2022-05-11T02:30:46.636Z,1652236246.636 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0043.lzma.bak
2022-05-11T02:30:46.636Z,1652236246.636 [DataOverHttps](INFO): SBD MOMSN=16735727
2022-05-11T02:31:04.162Z,1652236264.162 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20220511T011051/Express0044.lzma
2022-05-11T02:31:05.164Z,1652236265.164 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0044.lzma.bak
2022-05-11T02:31:05.164Z,1652236265.164 [DataOverHttps](INFO): SBD MOMSN=16735730
2022-05-11T02:31:06.501Z,1652236266.501 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:31:06.501Z,1652236266.501 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:31:06.501Z,1652236266.501 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:31:10.119Z,1652236270.119 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:31:36.795Z,1652236296.795 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T02:31:36.796Z,1652236296.796 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2022-05-11T02:36:07.080Z,1652236567.080 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:36:07.080Z,1652236567.080 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:36:07.080Z,1652236567.080 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:36:07.080Z,1652236567.080 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:36:07.477Z,1652236567.477 [Default:CheckIn:D] Stopped
2022-05-11T02:36:07.477Z,1652236567.477 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.502808 min 
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn:E] Stopped
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn] Stopped
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:36:07.883Z,1652236567.883 [Default:CheckIn](INFO): Running loop #15
2022-05-11T02:36:07.884Z,1652236567.884 [Default:CheckIn] Running Loop=15
2022-05-11T02:36:07.884Z,1652236567.884 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:36:07.884Z,1652236567.884 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:36:09.893Z,1652236569.893 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,023609.00,A,3648.16148,N,12147.28059,W,1.516,0.00,110522,,,A*70
2022-05-11T02:36:09.896Z,1652236569.896 [NAL9602](INFO): GPS fix at 20220511T023609: (36.802691, -121.788010)
2022-05-11T02:36:09.911Z,1652236569.911 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:36:09.911Z,1652236569.911 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:36:11.919Z,1652236571.919 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:36:11.919Z,1652236571.919 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+18.6,000.0,000
2022-05-11T02:36:16.881Z,1652236576.881 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220511T011051/Courier0046.lzma
2022-05-11T02:36:17.884Z,1652236577.884 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0046.lzma.bak
2022-05-11T02:36:17.884Z,1652236577.884 [DataOverHttps](INFO): SBD MOMSN=16735734
2022-05-11T02:36:33.805Z,1652236593.805 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220511T011051/Express0047.lzma
2022-05-11T02:36:34.808Z,1652236594.808 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0047.lzma.bak
2022-05-11T02:36:34.808Z,1652236594.808 [DataOverHttps](INFO): SBD MOMSN=16735737
2022-05-11T02:36:36.161Z,1652236596.161 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:36:36.161Z,1652236596.161 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:36:36.161Z,1652236596.161 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:36:40.592Z,1652236600.592 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T02:36:40.666Z,1652236600.666 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T02:40:47.039Z,1652236847.039 [DVL_micro](ERROR): only read 0 of 4 data items
2022-05-11T02:40:47.039Z,1652236847.039 [DVL_micro](ERROR): Failed to parse:
:RD,++9999.99,++9999.99
2022-05-11T02:41:12.080Z,1652236872.080 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T02:41:36.745Z,1652236896.745 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:41:36.745Z,1652236896.745 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:41:36.745Z,1652236896.745 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:41:36.745Z,1652236896.745 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:41:37.141Z,1652236897.141 [Default:CheckIn:D] Stopped
2022-05-11T02:41:37.141Z,1652236897.141 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:41:37.546Z,1652236897.546 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.997217 min 
2022-05-11T02:41:37.546Z,1652236897.546 [Default:CheckIn:E] Stopped
2022-05-11T02:41:37.546Z,1652236897.546 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:41:37.546Z,1652236897.546 [Default:CheckIn] Stopped
2022-05-11T02:41:37.546Z,1652236897.546 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:41:37.547Z,1652236897.547 [Default:CheckIn](INFO): Running loop #16
2022-05-11T02:41:37.547Z,1652236897.547 [Default:CheckIn] Running Loop=16
2022-05-11T02:41:37.547Z,1652236897.547 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:41:37.547Z,1652236897.547 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:43:07.231Z,1652236987.231 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T02:43:07.231Z,1652236987.231 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+99999.99,+9999.99
2022-05-11T02:45:27.410Z,1652237127.410 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+0000000000000.00,9999.99,000.00
2022-05-11T02:46:37.719Z,1652237197.719 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T02:41:37.5Z
2022-05-11T02:46:37.719Z,1652237197.719 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:46:37.719Z,1652237197.719 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:46:38.559Z,1652237198.559 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:46:38.559Z,1652237198.559 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:46:38.559Z,1652237198.559 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:47:09.229Z,1652237229.229 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:51:39.133Z,1652237499.133 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T02:51:39.133Z,1652237499.133 [Default:CheckIn:C.Wait] Stopped
2022-05-11T02:51:39.133Z,1652237499.133 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T02:51:39.133Z,1652237499.133 [Default:CheckIn:D] Running Loop=1
2022-05-11T02:51:39.553Z,1652237499.553 [Default:CheckIn:D] Stopped
2022-05-11T02:51:39.553Z,1652237499.553 [Default:CheckIn:E] Running Loop=1
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.037410 min 
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn:E] Stopped
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn] Stopped
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T02:51:39.943Z,1652237499.943 [Default:CheckIn](INFO): Running loop #17
2022-05-11T02:51:39.944Z,1652237499.944 [Default:CheckIn] Running Loop=17
2022-05-11T02:51:39.944Z,1652237499.944 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T02:51:39.944Z,1652237499.944 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T02:51:41.548Z,1652237501.548 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-05-11T02:51:41.548Z,1652237501.548 [NAL9602] Data Fault, FailCount= 1
2022-05-11T02:51:41.548Z,1652237501.548 [NAL9602](ERROR): Data Fault
2022-05-11T02:51:41.595Z,1652237501.595 [CBIT](ERROR): Data Fault in component: NAL9602
2022-05-11T02:51:41.957Z,1652237501.957 [NAL9602](INFO): Powering down
2022-05-11T02:51:42.785Z,1652237502.785 [CBIT](INFO): Clearing failed state for component NAL9602
2022-05-11T02:51:42.785Z,1652237502.785 [NAL9602] No Fault, FailCount= 1
2022-05-11T02:52:12.248Z,1652237532.248 [NAL9602](INFO): Powering up NAL9602
2022-05-11T02:52:23.156Z,1652237543.156 [NAL9602](INFO): NAL9602 initialized
2022-05-11T02:54:32.845Z,1652237672.845 [DVL_micro](ERROR): Failed to parse:
00000000008.8,0000.0,1489.0,000
2022-05-11T02:56:40.112Z,1652237800.112 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T02:51:39.9Z
2022-05-11T02:56:40.113Z,1652237800.113 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T02:56:40.113Z,1652237800.113 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T02:56:47.629Z,1652237807.629 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0049.lzma
2022-05-11T02:56:48.632Z,1652237808.632 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0049.lzma.bak
2022-05-11T02:56:48.632Z,1652237808.632 [DataOverHttps](INFO): SBD MOMSN=16735740
2022-05-11T02:56:50.618Z,1652237810.618 [DVL_micro](ERROR): Failed to parse:
:R99,+9999.999,+9999.99
2022-05-11T02:57:04.729Z,1652237824.729 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0052.lzma
2022-05-11T02:57:05.732Z,1652237825.732 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0052.lzma.bak
2022-05-11T02:57:05.732Z,1652237825.732 [DataOverHttps](INFO): SBD MOMSN=16735742
2022-05-11T02:57:21.718Z,1652237841.718 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220511T011051/Express0050.lzma
2022-05-11T02:57:22.720Z,1652237842.720 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0050.lzma.bak
2022-05-11T02:57:22.720Z,1652237842.720 [DataOverHttps](INFO): SBD MOMSN=16735744
2022-05-11T02:57:26.568Z,1652237846.568 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T02:57:38.669Z,1652237858.669 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20220511T011051/Express0053.lzma
2022-05-11T02:57:39.672Z,1652237859.672 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0053.lzma.bak
2022-05-11T02:57:39.672Z,1652237859.672 [DataOverHttps](INFO): SBD MOMSN=16735748
2022-05-11T02:57:40.720Z,1652237860.720 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T02:57:40.720Z,1652237860.720 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T02:57:40.720Z,1652237860.720 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T02:57:57.280Z,1652237877.280 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T02:59:43.929Z,1652237983.929 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T02:59:43.929Z,1652237983.929 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+18.,1489.0,000
2022-05-11T03:01:30.599Z,1652238090.599 [DVL_micro](ERROR): Failed to parse:
:SA,-00.66,+01.65,322.1
2022-05-11T03:02:41.309Z,1652238161.309 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:02:41.309Z,1652238161.309 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:02:41.309Z,1652238161.309 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:02:41.309Z,1652238161.309 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:02:41.710Z,1652238161.710 [Default:CheckIn:D] Stopped
2022-05-11T03:02:41.710Z,1652238161.710 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:02:42.125Z,1652238162.125 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.073364 min 
2022-05-11T03:02:42.125Z,1652238162.125 [Default:CheckIn:E] Stopped
2022-05-11T03:02:42.125Z,1652238162.125 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:02:42.125Z,1652238162.125 [Default:CheckIn] Stopped
2022-05-11T03:02:42.126Z,1652238162.126 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:02:42.126Z,1652238162.126 [Default:CheckIn](INFO): Running loop #18
2022-05-11T03:02:42.126Z,1652238162.126 [Default:CheckIn] Running Loop=18
2022-05-11T03:02:42.126Z,1652238162.126 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:02:42.126Z,1652238162.126 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:02:43.719Z,1652238163.719 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-05-11T03:02:43.720Z,1652238163.720 [NAL9602] Data Fault, FailCount= 2
2022-05-11T03:02:43.720Z,1652238163.720 [NAL9602](ERROR): Data Fault
2022-05-11T03:02:43.775Z,1652238163.775 [CBIT](ERROR): Data Fault in component: NAL9602
2022-05-11T03:02:44.124Z,1652238164.124 [NAL9602](INFO): Powering down
2022-05-11T03:02:44.946Z,1652238164.946 [CBIT](INFO): Clearing failed state for component NAL9602
2022-05-11T03:02:44.947Z,1652238164.947 [NAL9602] No Fault, FailCount= 2
2022-05-11T03:03:14.417Z,1652238194.417 [NAL9602](INFO): Powering up NAL9602
2022-05-11T03:03:25.338Z,1652238205.338 [NAL9602](INFO): NAL9602 initialized
2022-05-11T03:07:42.315Z,1652238462.315 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:02:42.1Z
2022-05-11T03:07:42.315Z,1652238462.315 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T03:07:42.315Z,1652238462.315 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T03:07:50.124Z,1652238470.124 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0055.lzma
2022-05-11T03:07:51.116Z,1652238471.116 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0055.lzma.bak
2022-05-11T03:07:51.116Z,1652238471.116 [DataOverHttps](INFO): SBD MOMSN=16735793
2022-05-11T03:08:07.042Z,1652238487.042 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20220511T011051/Express0056.lzma
2022-05-11T03:08:08.044Z,1652238488.044 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0056.lzma.bak
2022-05-11T03:08:08.044Z,1652238488.044 [DataOverHttps](INFO): SBD MOMSN=16735795
2022-05-11T03:08:09.381Z,1652238489.381 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T03:08:09.381Z,1652238489.381 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T03:08:09.381Z,1652238489.381 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T03:08:28.764Z,1652238508.764 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T03:08:59.453Z,1652238539.453 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T03:13:09.995Z,1652238789.995 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:13:09.995Z,1652238789.995 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:13:09.995Z,1652238789.995 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:13:09.995Z,1652238789.995 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:13:10.407Z,1652238790.407 [Default:CheckIn:D] Stopped
2022-05-11T03:13:10.407Z,1652238790.407 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:13:10.798Z,1652238790.798 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 118.551636 min 
2022-05-11T03:13:10.798Z,1652238790.798 [Default:CheckIn:E] Stopped
2022-05-11T03:13:10.798Z,1652238790.798 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:13:10.798Z,1652238790.798 [Default:CheckIn] Stopped
2022-05-11T03:13:10.798Z,1652238790.798 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:13:10.799Z,1652238790.799 [Default:CheckIn](INFO): Running loop #19
2022-05-11T03:13:10.799Z,1652238790.799 [Default:CheckIn] Running Loop=19
2022-05-11T03:13:10.799Z,1652238790.799 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:13:10.799Z,1652238790.799 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:18:10.994Z,1652239090.994 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:13:10.8Z
2022-05-11T03:18:10.994Z,1652239090.994 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T03:18:10.994Z,1652239090.994 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T03:18:14.601Z,1652239094.601 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T03:18:18.625Z,1652239098.625 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0058.lzma
2022-05-11T03:18:19.633Z,1652239099.633 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0058.lzma.bak
2022-05-11T03:18:19.634Z,1652239099.634 [DataOverHttps](INFO): SBD MOMSN=16735800
2022-05-11T03:18:35.642Z,1652239115.642 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220511T011051/Express0059.lzma
2022-05-11T03:18:36.644Z,1652239116.644 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0059.lzma.bak
2022-05-11T03:18:36.644Z,1652239116.644 [DataOverHttps](INFO): SBD MOMSN=16735802
2022-05-11T03:18:37.683Z,1652239117.683 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T03:18:37.683Z,1652239117.683 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T03:18:37.683Z,1652239117.683 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T03:18:45.314Z,1652239125.314 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T03:19:54.001Z,1652239194.001 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T03:19:54.001Z,1652239194.001 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000009.0,0000.0,1489.0,000
2022-05-11T03:20:12.187Z,1652239212.187 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T03:20:12.187Z,1652239212.187 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,1489.0,000
2022-05-11T03:23:38.266Z,1652239418.266 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:23:38.270Z,1652239418.270 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:23:38.270Z,1652239418.270 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:23:38.270Z,1652239418.270 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:23:38.637Z,1652239418.637 [Default:CheckIn:D] Stopped
2022-05-11T03:23:38.637Z,1652239418.637 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:23:39.044Z,1652239419.044 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 129.022152 min 
2022-05-11T03:23:39.044Z,1652239419.044 [Default:CheckIn:E] Stopped
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn] Stopped
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn](INFO): Running loop #20
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn] Running Loop=20
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:23:39.045Z,1652239419.045 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:23:40.647Z,1652239420.647 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-05-11T03:23:40.648Z,1652239420.648 [NAL9602] Data Fault, FailCount= 3
2022-05-11T03:23:40.648Z,1652239420.648 [NAL9602](ERROR): Data Fault
2022-05-11T03:23:40.667Z,1652239420.667 [CBIT](ERROR): Data Fault in component: NAL9602
2022-05-11T03:23:41.066Z,1652239421.066 [NAL9602](INFO): Powering down
2022-05-11T03:23:41.879Z,1652239421.879 [CBIT](INFO): Clearing failed state for component NAL9602
2022-05-11T03:23:41.879Z,1652239421.879 [NAL9602] No Fault, FailCount= 3
2022-05-11T03:23:56.401Z,1652239436.401 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T03:23:56.401Z,1652239436.401 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,.0,0000.0,1489.0,000
2022-05-11T03:24:11.386Z,1652239451.386 [NAL9602](INFO): Powering up NAL9602
2022-05-11T03:24:22.256Z,1652239462.256 [NAL9602](INFO): NAL9602 initialized
2022-05-11T03:24:31.967Z,1652239471.967 [DVL_micro](ERROR): Failed to parse:
:R99,+9999..99,+9999.99
2022-05-11T03:28:39.218Z,1652239719.218 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:23:39.0Z
2022-05-11T03:28:39.218Z,1652239719.218 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T03:28:39.218Z,1652239719.218 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T03:28:46.929Z,1652239726.929 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0061.lzma
2022-05-11T03:28:47.932Z,1652239727.932 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0061.lzma.bak
2022-05-11T03:28:47.932Z,1652239727.932 [DataOverHttps](INFO): SBD MOMSN=16735806
2022-05-11T03:29:03.954Z,1652239743.954 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20220511T011051/Express0062.lzma
2022-05-11T03:29:04.956Z,1652239744.956 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0062.lzma.bak
2022-05-11T03:29:04.956Z,1652239744.956 [DataOverHttps](INFO): SBD MOMSN=16735808
2022-05-11T03:29:06.279Z,1652239746.279 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T03:29:06.279Z,1652239746.279 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T03:29:06.279Z,1652239746.279 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T03:29:25.658Z,1652239765.658 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T03:29:56.367Z,1652239796.367 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T03:34:06.857Z,1652240046.857 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:34:06.857Z,1652240046.857 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:34:06.857Z,1652240046.857 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:34:06.857Z,1652240046.857 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:34:07.261Z,1652240047.261 [Default:CheckIn:D] Stopped
2022-05-11T03:34:07.261Z,1652240047.261 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:34:07.661Z,1652240047.661 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 139.499202 min 
2022-05-11T03:34:07.661Z,1652240047.661 [Default:CheckIn:E] Stopped
2022-05-11T03:34:07.661Z,1652240047.661 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:34:07.661Z,1652240047.661 [Default:CheckIn] Stopped
2022-05-11T03:34:07.661Z,1652240047.661 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:34:07.662Z,1652240047.662 [Default:CheckIn](INFO): Running loop #21
2022-05-11T03:34:07.662Z,1652240047.662 [Default:CheckIn] Running Loop=21
2022-05-11T03:34:07.662Z,1652240047.662 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:34:07.662Z,1652240047.662 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:38:17.731Z,1652240297.731 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T03:38:17.732Z,1652240297.732 [DVL_micro](ERROR): Failed to parse::BI,-00356,+01025,+0032,I
2022-05-11T03:39:07.843Z,1652240347.843 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:34:07.7Z
2022-05-11T03:39:07.843Z,1652240347.843 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T03:39:07.843Z,1652240347.843 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T03:39:11.872Z,1652240351.872 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T03:39:15.073Z,1652240355.073 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0064.lzma
2022-05-11T03:39:16.076Z,1652240356.076 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0064.lzma.bak
2022-05-11T03:39:16.076Z,1652240356.076 [DataOverHttps](INFO): SBD MOMSN=16735813
2022-05-11T03:39:32.030Z,1652240372.030 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220511T011051/Express0065.lzma
2022-05-11T03:39:33.032Z,1652240373.032 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0065.lzma.bak
2022-05-11T03:39:33.032Z,1652240373.032 [DataOverHttps](INFO): SBD MOMSN=16735815
2022-05-11T03:39:34.114Z,1652240374.114 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T03:39:34.115Z,1652240374.115 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T03:39:34.115Z,1652240374.115 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T03:39:42.575Z,1652240382.575 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T03:40:30.265Z,1652240430.265 [DVL_micro](ERROR): only read 1 of 4 data items
2022-05-11T03:40:30.265Z,1652240430.265 [DVL_micro](ERROR): Failed to parse:
:RD,+999

2022-05-11T03:44:34.694Z,1652240674.694 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:44:34.695Z,1652240674.695 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:44:34.695Z,1652240674.695 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:44:34.695Z,1652240674.695 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:44:35.106Z,1652240675.106 [Default:CheckIn:D] Stopped
2022-05-11T03:44:35.106Z,1652240675.106 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:44:35.497Z,1652240675.497 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 149.963298 min 
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn:E] Stopped
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn] Stopped
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn](INFO): Running loop #22
2022-05-11T03:44:35.498Z,1652240675.498 [Default:CheckIn] Running Loop=22
2022-05-11T03:44:35.499Z,1652240675.499 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:44:35.499Z,1652240675.499 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:44:37.097Z,1652240677.097 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-05-11T03:44:37.097Z,1652240677.097 [NAL9602] Data Fault, FailCount= 4
2022-05-11T03:44:37.097Z,1652240677.097 [NAL9602](ERROR): Data Fault
2022-05-11T03:44:37.122Z,1652240677.122 [CBIT](ERROR): Data Fault in component: NAL9602
2022-05-11T03:44:37.524Z,1652240677.524 [NAL9602](INFO): Powering down
2022-05-11T03:44:38.346Z,1652240678.346 [CBIT](INFO): Clearing failed state for component NAL9602
2022-05-11T03:44:38.346Z,1652240678.346 [NAL9602] No Fault, FailCount= 4
2022-05-11T03:45:07.811Z,1652240707.811 [NAL9602](INFO): Powering up NAL9602
2022-05-11T03:45:15.486Z,1652240715.486 [DVL_micro](ERROR): Failed to parse:
:WI,-01596,+00150,+00832,+00000,A
2022-05-11T03:45:18.712Z,1652240718.712 [NAL9602](INFO): NAL9602 initialized
2022-05-11T03:49:35.670Z,1652240975.670 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:44:35.5Z
2022-05-11T03:49:35.670Z,1652240975.670 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T03:49:35.670Z,1652240975.670 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T03:49:43.218Z,1652240983.218 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0067.lzma
2022-05-11T03:49:44.220Z,1652240984.220 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0067.lzma.bak
2022-05-11T03:49:44.220Z,1652240984.220 [DataOverHttps](INFO): SBD MOMSN=16735819
2022-05-11T03:50:00.314Z,1652241000.314 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20220511T011051/Express0068.lzma
2022-05-11T03:50:01.316Z,1652241001.316 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0068.lzma.bak
2022-05-11T03:50:01.316Z,1652241001.316 [DataOverHttps](INFO): SBD MOMSN=16735821
2022-05-11T03:50:02.357Z,1652241002.357 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T03:50:02.357Z,1652241002.357 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T03:50:02.357Z,1652241002.357 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T03:50:05.956Z,1652241005.956 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T03:50:05.956Z,1652241005.956 [DVL_micro](ERROR): Failed to parse:
:BI,-02778,-0068,+00000,I
2022-05-11T03:50:22.111Z,1652241022.111 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T03:50:52.815Z,1652241052.815 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T03:55:02.908Z,1652241302.908 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T03:55:02.908Z,1652241302.908 [Default:CheckIn:C.Wait] Stopped
2022-05-11T03:55:02.909Z,1652241302.909 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T03:55:02.909Z,1652241302.909 [Default:CheckIn:D] Running Loop=1
2022-05-11T03:55:03.316Z,1652241303.316 [Default:CheckIn:D] Stopped
2022-05-11T03:55:03.317Z,1652241303.317 [Default:CheckIn:E] Running Loop=1
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 160.433464 min 
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn:E] Stopped
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn] Stopped
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn](INFO): Running loop #23
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn] Running Loop=23
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T03:55:03.732Z,1652241303.732 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T03:57:06.117Z,1652241426.117 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T03:57:06.118Z,1652241426.118 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+1.0,1489.0,000
2022-05-11T04:00:03.881Z,1652241603.881 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T03:55:03.7Z
2022-05-11T04:00:03.881Z,1652241603.881 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T04:00:03.881Z,1652241603.881 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T04:00:07.916Z,1652241607.916 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T04:00:11.641Z,1652241611.641 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T011051/Courier0070.lzma
2022-05-11T04:00:12.644Z,1652241612.644 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0070.lzma.bak
2022-05-11T04:00:12.644Z,1652241612.644 [DataOverHttps](INFO): SBD MOMSN=16735826
2022-05-11T04:00:28.645Z,1652241628.645 [DataOverHttps](INFO): Sending 207 bytes from file Logs/20220511T011051/Express0071.lzma
2022-05-11T04:00:29.648Z,1652241629.648 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0071.lzma.bak
2022-05-11T04:00:29.648Z,1652241629.648 [DataOverHttps](INFO): SBD MOMSN=16735828
2022-05-11T04:00:30.965Z,1652241630.965 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T04:00:30.965Z,1652241630.965 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T04:00:30.965Z,1652241630.965 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T04:00:38.615Z,1652241638.615 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T04:01:36.462Z,1652241696.462 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T04:01:36.462Z,1652241696.462 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+9999.99,+9999.99
2022-05-11T04:05:31.597Z,1652241931.597 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-11T04:05:31.597Z,1652241931.597 [Default:CheckIn:C.Wait] Stopped
2022-05-11T04:05:31.597Z,1652241931.597 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T04:05:31.597Z,1652241931.597 [Default:CheckIn:D] Running Loop=1
2022-05-11T04:05:32.008Z,1652241932.008 [Default:CheckIn:D] Stopped
2022-05-11T04:05:32.008Z,1652241932.008 [Default:CheckIn:E] Running Loop=1
2022-05-11T04:05:32.418Z,1652241932.418 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 170.911654 min 
2022-05-11T04:05:32.418Z,1652241932.418 [Default:CheckIn:E] Stopped
2022-05-11T04:05:32.418Z,1652241932.418 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn] Stopped
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn](INFO): Running loop #24
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn] Running Loop=24
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T04:05:32.419Z,1652241932.419 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T04:05:34.012Z,1652241934.012 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-05-11T04:05:34.012Z,1652241934.012 [NAL9602] Data Fault, FailCount= 5
2022-05-11T04:05:34.012Z,1652241934.012 [NAL9602](ERROR): Data Fault
2022-05-11T04:05:34.052Z,1652241934.052 [CBIT](ERROR): Data Fault in component: NAL9602
2022-05-11T04:05:34.053Z,1652241934.053 [CBIT](CRITICAL): Data Fault in component: NAL9602
2022-05-11T04:05:34.409Z,1652241934.409 [NAL9602](INFO): Powering down
2022-05-11T04:05:34.427Z,1652241934.427 [CBIT](INFO): Critical error at 20220511T040534
2022-05-11T04:07:34.035Z,1652242054.035 [CBIT](INFO): Clearing failed state for component NAL9602
2022-05-11T04:07:34.035Z,1652242054.035 [NAL9602] No Fault, FailCount= 5
2022-05-11T04:07:34.400Z,1652242054.400 [NAL9602](INFO): Powering up NAL9602
2022-05-11T04:07:45.305Z,1652242065.305 [NAL9602](INFO): NAL9602 initialized
2022-05-11T04:10:32.587Z,1652242232.587 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T04:05:32.4Z
2022-05-11T04:10:32.587Z,1652242232.587 [Default:CheckIn:Read_GPS] Stopped
2022-05-11T04:10:32.587Z,1652242232.587 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-11T04:10:40.357Z,1652242240.357 [DataOverHttps](INFO): Sending 105 bytes from file Logs/20220511T011051/Courier0073.lzma
2022-05-11T04:10:41.360Z,1652242241.360 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Courier0073.lzma.bak
2022-05-11T04:10:41.360Z,1652242241.360 [DataOverHttps](INFO): SBD MOMSN=16735832
2022-05-11T04:10:57.209Z,1652242257.209 [DataOverHttps](INFO): Sending 224 bytes from file Logs/20220511T011051/Express0074.lzma
2022-05-11T04:10:58.212Z,1652242258.212 [DataOverHttps](INFO): Moved sent file to Logs/20220511T011051/Express0074.lzma.bak
2022-05-11T04:10:58.212Z,1652242258.212 [DataOverHttps](INFO): SBD MOMSN=16735835
2022-05-11T04:10:59.259Z,1652242259.259 [Default:CheckIn:Read_Iridium] Stopped
2022-05-11T04:10:59.259Z,1652242259.259 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-11T04:10:59.259Z,1652242259.259 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-11T04:11:45.747Z,1652242305.747 [CommandExec](IMPORTANT): got command show variable amph
2022-05-11T04:11:45.947Z,1652242305.947 [CommandExec](IMPORTANT): CBIT.ampHoursUsed (ampere_hour)
2022-05-11T04:11:52.159Z,1652242312.159 [CommandExec](IMPORTANT): got command get CBIT.ampHoursUsed
2022-05-11T04:11:52.159Z,1652242312.159 [CommandExec](IMPORTANT): CBIT.ampHoursUsed 37.653378 Ah
2022-05-11T04:12:48.796Z,1652242368.796 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-11T04:13:19.504Z,1652242399.504 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-11T04:14:02.295Z,1652242442.295 [CommandExec](IMPORTANT): got command failComponent
2022-05-11T04:14:02.295Z,1652242442.295 [CommandExec](IMPORTANT): Failed components:
2022-05-11T04:14:02.295Z,1652242442.295 [CommandExec](IMPORTANT): No failed Components.
2022-05-11T04:14:53.171Z,1652242493.171 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/tank_ballast_and_trim.xml
2022-05-11T04:14:53.172Z,1652242493.172 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/tank_ballast_and_trim.xml
2022-05-11T04:14:53.313Z,1652242493.313 [MissionManager](INFO): DefineArg ballast_and_trim.MissionTimeout = 120.000000 min
2022-05-11T04:14:53.316Z,1652242493.316 [MissionManager](INFO): DefineArg ballast_and_trim.SkipComms = 0 bool
2022-05-11T04:14:53.319Z,1652242493.319 [MissionManager](INFO): DefineArg ballast_and_trim.Depth1 = 7.000000 m
2022-05-11T04:14:53.321Z,1652242493.321 [MissionManager](INFO): DefineArg ballast_and_trim.Depth2 = nan m
2022-05-11T04:14:53.325Z,1652242493.325 [MissionManager](INFO): DefineArg ballast_and_trim.DepthDeadband = 0.100000 m
2022-05-11T04:14:53.328Z,1652242493.328 [MissionManager](INFO): DefineArg ballast_and_trim.SurfaceThreshold = 2.500000 m
2022-05-11T04:14:53.331Z,1652242493.331 [MissionManager](INFO): DefineArg ballast_and_trim.MaxWaitOnSurface = 20.000000 min
2022-05-11T04:14:53.333Z,1652242493.333 [MissionManager](INFO): DefineArg ballast_and_trim.SettleTime = 10.000000 min
2022-05-11T04:14:53.337Z,1652242493.337 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationTimeout = 45.000000 min
2022-05-11T04:14:53.340Z,1652242493.340 [MissionManager](INFO): DefineArg ballast_and_trim.MinEstimationTime = 10.000000 min
2022-05-11T04:14:53.363Z,1652242493.363 [MissionManager](INFO): DefineArg ballast_and_trim.MassEstimationErrorBound = 0.250000 mm
2022-05-11T04:14:53.374Z,1652242493.374 [MissionManager](INFO): DefineArg ballast_and_trim.BuoyEstimationErrorBound = 15.000000 cc
2022-05-11T04:14:53.377Z,1652242493.377 [MissionManager](INFO): DefineArg ballast_and_trim.EstimationConfidence = 99.900002 %
2022-05-11T04:14:53.385Z,1652242493.385 [MissionManager](INFO): DefineArg ballast_and_trim.WaitToFloat = 5.000000 min
2022-05-11T04:14:53.386Z,1652242493.386 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/Science.xml
2022-05-11T04:14:53.825Z,1652242493.825 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectChlActive = 0 bool
2022-05-11T04:14:53.828Z,1652242493.828 [MissionManager](INFO): DefineArg ballast_and_trim:Science.TimeWindowPeakReport = nan min
2022-05-11T04:14:53.831Z,1652242493.831 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestChlPeakReportActive = 0 bool
2022-05-11T04:14:53.834Z,1652242493.834 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestSaltPeakReportActive = 0 bool
2022-05-11T04:14:53.836Z,1652242493.836 [MissionManager](INFO): DefineArg ballast_and_trim:Science.HighestOilPeakReportActive = 0 bool
2022-05-11T04:14:53.839Z,1652242493.839 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PatchTracking = 0 bool
2022-05-11T04:14:53.882Z,1652242493.882 [MissionManager](INFO): DefineArg ballast_and_trim:Science.DetectTrough = 0 bool
2022-05-11T04:14:53.885Z,1652242493.885 [MissionManager](INFO): DefineArg ballast_and_trim:Science.FilterWidthHorizontal = 3.000000 count
2022-05-11T04:14:53.892Z,1652242493.892 [MissionManager](INFO): DefineArg ballast_and_trim:Science.NumProfilesSlidingwindow = 100.000000 count
2022-05-11T04:14:53.897Z,1652242493.897 [MissionManager](INFO): DefineArg ballast_and_trim:Science.OffPeakFractionHorizontal = 80.000000 %
2022-05-11T04:14:53.911Z,1652242493.911 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectNO3Active = 0 bool
2022-05-11T04:14:53.918Z,1652242493.918 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectOilActive = 0 bool
2022-05-11T04:14:53.928Z,1652242493.928 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectFDOMActive = 0 bool
2022-05-11T04:14:53.951Z,1652242493.951 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDetectSalinityActive = 0 bool
2022-05-11T04:14:53.953Z,1652242493.953 [MissionManager](INFO): DefineArg ballast_and_trim:Science.UpwardDerivativeOfTemperatureActive = 0 bool
2022-05-11T04:14:53.961Z,1652242493.961 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledAanderaaO2 = 0 bool
2022-05-11T04:14:53.979Z,1652242493.979 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledNeilBrown = 0 bool
2022-05-11T04:14:53.984Z,1652242493.984 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledSeabird = 1 bool
2022-05-11T04:14:53.989Z,1652242493.989 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsBB2FL = 1 bool
2022-05-11T04:14:53.997Z,1652242493.997 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsSeaOWL_UV_A = 0 bool
2022-05-11T04:14:54.051Z,1652242494.051 [MissionManager](INFO): DefineArg ballast_and_trim:Science.EnabledWetLabsUBAT = 0 bool
2022-05-11T04:14:54.062Z,1652242494.062 [MissionManager](INFO): DefineArg ballast_and_trim:Science.LowPassWindowLength = 20.000000 count
2022-05-11T04:14:54.065Z,1652242494.065 [MissionManager](INFO): DefineArg ballast_and_trim:Science.MedianFilterLen = 5.000000 count
2022-05-11T04:14:54.076Z,1652242494.076 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakShallowBound = nan m
2022-05-11T04:14:54.089Z,1652242494.089 [MissionManager](INFO): DefineArg ballast_and_trim:Science.PeakDeepBound = nan m
2022-05-11T04:14:54.118Z,1652242494.118 [MissionManager](INFO): DefineArg ballast_and_trim:Science.DepChangeThreshForAttitudeFlip = 2.000000 m
2022-05-11T04:14:54.121Z,1652242494.121 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChl = 0.000000 ug/l
2022-05-11T04:14:54.133Z,1652242494.133 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlDepth = 0.000000 m
2022-05-11T04:14:54.165Z,1652242494.165 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlTemperature = 0.000000 degC
2022-05-11T04:14:54.173Z,1652242494.173 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLatitude = nan arcdeg
2022-05-11T04:14:54.187Z,1652242494.187 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakChlLongitude = nan arcdeg
2022-05-11T04:14:54.205Z,1652242494.205 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3 = 0.000000 umol/l
2022-05-11T04:14:54.213Z,1652242494.213 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Depth = 0.000000 m
2022-05-11T04:14:54.225Z,1652242494.225 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Latitude = nan arcdeg
2022-05-11T04:14:54.233Z,1652242494.233 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakNO3Longitude = nan arcdeg
2022-05-11T04:14:54.241Z,1652242494.241 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOil = 0.000000 kg/m3
2022-05-11T04:14:54.245Z,1652242494.245 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilDepth = 0.000000 m
2022-05-11T04:14:54.260Z,1652242494.260 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLatitude = nan arcdeg
2022-05-11T04:14:54.268Z,1652242494.268 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakOilLongitude = nan arcdeg
2022-05-11T04:14:54.276Z,1652242494.276 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOM = 0.000000 ppb
2022-05-11T04:14:54.292Z,1652242494.292 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMDepth = 0.000000 m
2022-05-11T04:14:54.299Z,1652242494.299 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMTemperature = nan degC
2022-05-11T04:14:54.307Z,1652242494.307 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLatitude = nan arcdeg
2022-05-11T04:14:54.310Z,1652242494.310 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakFDOMLongitude = nan arcdeg
2022-05-11T04:14:54.317Z,1652242494.317 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchFDOMDistance = nan m
2022-05-11T04:14:54.324Z,1652242494.324 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSalt = 0.000000 psu
2022-05-11T04:14:54.329Z,1652242494.329 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltDepth = 0.000000 m
2022-05-11T04:14:54.344Z,1652242494.344 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltTemperature = 0.000000 degC
2022-05-11T04:14:54.348Z,1652242494.348 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltLatitude = nan arcdeg
2022-05-11T04:14:54.359Z,1652242494.359 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PeakSaltLongitude = nan arcdeg
2022-05-11T04:14:54.366Z,1652242494.366 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChl = 0.000000 ug/l
2022-05-11T04:14:54.374Z,1652242494.374 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDepth = 0.000000 m
2022-05-11T04:14:54.377Z,1652242494.377 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLatitude = nan arcdeg
2022-05-11T04:14:54.384Z,1652242494.384 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlLongitude = nan arcdeg
2022-05-11T04:14:54.388Z,1652242494.388 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchChlDistance = nan m
2022-05-11T04:14:54.399Z,1652242494.399 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSalt = 0.000000 psu
2022-05-11T04:14:54.403Z,1652242494.403 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltDepth = 0.000000 m
2022-05-11T04:14:54.406Z,1652242494.406 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltLatitude = nan arcdeg
2022-05-11T04:14:54.409Z,1652242494.409 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltLongitude = nan arcdeg
2022-05-11T04:14:54.468Z,1652242494.468 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchSaltDistance = nan m
2022-05-11T04:14:54.471Z,1652242494.471 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOil = 0.000000 psu
2022-05-11T04:14:54.500Z,1652242494.500 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilDepth = 0.000000 m
2022-05-11T04:14:54.503Z,1652242494.503 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilLatitude = nan arcdeg
2022-05-11T04:14:54.506Z,1652242494.506 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilLongitude = nan arcdeg
2022-05-11T04:14:54.509Z,1652242494.509 [MissionManager](INFO): DefineOutput ballast_and_trim:Science.PatchOilDistance = nan m
2022-05-11T04:14:54.583Z,1652242494.583 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2022-05-11T04:14:54.619Z,1652242494.619 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2022-05-11T04:14:54.664Z,1652242494.664 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2022-05-11T04:14:54.689Z,1652242494.689 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2022-05-11T04:14:54.736Z,1652242494.736 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2022-05-11T04:14:54.765Z,1652242494.765 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2022-05-11T04:14:54.798Z,1652242494.798 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth.
2022-05-11T04:14:54.867Z,1652242494.867 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal.
2022-05-11T04:14:54.913Z,1652242494.913 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/BallastAndTrim.xml
2022-05-11T04:14:55.135Z,1652242495.135 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepth = 25.000000 m
2022-05-11T04:14:55.147Z,1652242495.147 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSpeed = 0.000000 m/s
2022-05-11T04:14:55.150Z,1652242495.150 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthRate = 0.400000 m/s
2022-05-11T04:14:55.153Z,1652242495.153 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachPitchLimit = 20.000000 arcdeg
2022-05-11T04:14:55.183Z,1652242495.183 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachSettleTimePreDive = 0.000000 min
2022-05-11T04:14:55.186Z,1652242495.186 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = 20.000000 min
2022-05-11T04:14:55.189Z,1652242495.189 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = 10.000000 min
2022-05-11T04:14:55.206Z,1652242495.206 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = 45.000000 min
2022-05-11T04:14:55.209Z,1652242495.209 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = 10.000000 min
2022-05-11T04:14:55.212Z,1652242495.212 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = 0.250000 mm
2022-05-11T04:14:55.229Z,1652242495.229 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = 15.000000 cc
2022-05-11T04:14:55.289Z,1652242495.289 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = 99.900002 %
2022-05-11T04:14:55.303Z,1652242495.303 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = 1.000000 m
2022-05-11T04:14:55.325Z,1652242495.325 [MissionManager](INFO): DefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertMassDeadband = 0.250000 mm
2022-05-11T04:14:55.369Z,1652242495.369 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Construct.
2022-05-11T04:14:55.390Z,1652242495.390 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Construct Buoyancy.
2022-05-11T04:14:55.397Z,1652242495.397 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Construct.
2022-05-11T04:14:55.418Z,1652242495.418 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Construct Wait.
2022-05-11T04:14:55.438Z,1652242495.438 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Construct.
2022-05-11T04:14:55.446Z,1652242495.446 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Construct.
2022-05-11T04:14:55.464Z,1652242495.464 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2022-05-11T04:14:55.478Z,1652242495.478 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:A.SetSpeed](DEBUG): Construct.
2022-05-11T04:14:55.485Z,1652242495.485 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:B.Pitch](DEBUG): Construct.
2022-05-11T04:14:55.505Z,1652242495.505 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:D.Wait](DEBUG): Construct Wait.
2022-05-11T04:14:55.516Z,1652242495.516 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:BallastAndTrimAtTargetDepth:F.](DEBUG): Construct BallastAndTrim.
2022-05-11T04:14:55.558Z,1652242495.558 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertDepthDeadband = reader:ballast_and_trim.DepthDeadband
2022-05-11T04:14:55.560Z,1652242495.560 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertApproachDepthTimeout = reader:ballast_and_trim.MaxWaitOnSurface
2022-05-11T04:14:55.563Z,1652242495.563 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.InsertSettleTime = reader:ballast_and_trim.SettleTime
2022-05-11T04:14:55.567Z,1652242495.567 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstTimeout = reader:ballast_and_trim.EstimationTimeout
2022-05-11T04:14:55.570Z,1652242495.570 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MinEstTime = reader:ballast_and_trim.MinEstimationTime
2022-05-11T04:14:55.576Z,1652242495.576 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.MassEstErrorBound = reader:ballast_and_trim.MassEstimationErrorBound
2022-05-11T04:14:55.577Z,1652242495.577 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.BuoyEstErrorBound = reader:ballast_and_trim.BuoyEstimationErrorBound
2022-05-11T04:14:55.586Z,1652242495.586 [MissionManager](INFO): RedefineArg ballast_and_trim:RunBallastAndTrim:BallastAndTrim.EstConfidence = reader:ballast_and_trim.EstimationConfidence
2022-05-11T04:14:55.600Z,1652242495.600 [ballast_and_trim:Float_Up:A.Buoyancy](DEBUG): Construct Buoyancy.
2022-05-11T04:14:55.607Z,1652242495.607 [ballast_and_trim:Float_Up:B.Wait](DEBUG): Construct Wait.
2022-05-11T04:14:55.705Z,1652242495.705 [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="ballast_and_trim">

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:minute/><Value>120</Value></DefineArg>

    <DefineArg Name="SkipComms"><Description>
        Skip communications at start of mission.
    </Description><False/></DefineArg>

    <DefineArg Name="Depth1"><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="Depth2"><Units:meter/><Value>NaN</Value></DefineArg>

    <DefineArg Name="DepthDeadband"><Description>
        How much vertical drift from the specified depth is allowed durnig the
        mission.
    </Description><Units:meter/><Value>0.1</Value></DefineArg>

    <DefineArg Name="SurfaceThreshold"><Description>
        Surface threshold depth.
    </Description><Units:meter/><Value>2.5</Value></DefineArg>

    <DefineArg Name="MaxWaitOnSurface"><Description>
        Maximum wait time for the vehicle to go under the surface (i.e., reach
        the surface threshold depth).
    </Description><Units:minute/><Value>20</Value></DefineArg>

    <DefineArg Name="SettleTime"><Description>
        How long to wait after reaching target depth before starting ballast and
        trim.
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="EstimationTimeout"><Description>
        Timeout for ballast and trim estimation.
    </Description><Units:minute/><Value>45</Value></DefineArg>

    <DefineArg Name="MinEstimationTime"><Description>
        Minimum time to run ballast and trim estimation before determining
        convergence (must be shorter than timeout).
    </Description><Units:minute/><Value>10</Value></DefineArg>

    <DefineArg Name="MassEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:millimeter/><Value>0.25</Value></DefineArg>

    <DefineArg Name="BuoyEstimationErrorBound"><Description>
        Desired range of the estimated sample mean from the true mean statistic
        (smaller values take longer to converge).
    </Description><Units:cubic_centimeter/><Value>15</Value></DefineArg>

    <DefineArg Name="EstimationConfidence"><Description>
        Confidence level that the estimator has reached the desired error range
        (larger values take longer to converge).
    </Description><Units:percent/><Value>99.9</Value></DefineArg>

    <DefineArg Name="WaitToFloat"><Units:minute/><Value>5</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Insert Filename="Insert/Science.xml"/>

    <Aggregate Id="RunBallastAndTrim">

        <Sequence/>

        <Insert Filename="Insert/BallastAndTrim.xml">
            <RedefineArg Name="InsertDepthDeadband"><Arg Name="DepthDeadband"/></RedefineArg>
            <RedefineArg Name="InsertApproachDepthTimeout"><Arg Name="MaxWaitOnSurface"/></RedefineArg>
            <RedefineArg Name="InsertSettleTime"><Arg Name="SettleTime"/></RedefineArg>
            <RedefineArg Name="EstTimeout"><Arg Name="EstimationTimeout"/></RedefineArg>
            <RedefineArg Name="MinEstTime"><Arg Name="MinEstimationTime"/></RedefineArg>
            <RedefineArg Name="MassEstErrorBound"><Arg Name="MassEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="BuoyEstErrorBound"><Arg Name="BuoyEstimationErrorBound"/></RedefineArg>
            <RedefineArg Name="EstConfidence"><Arg Name="EstimationConfidence"/></RedefineArg>
        </Insert>

        <Aggregate Id="Depth1">

            <Sequence/>

            <Break>
                <IsNaN><Arg Name="Depth1"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

        <Aggregate Id="Depth2">

            <Sequence/>

            <Break>
                <IsNaN><Arg Name="Depth2"/>
                </IsNaN>
            </Break>

            <Assign><Sequence/><Arg Name="BallastAndTrim:InsertDepth"/><Arg Name="Depth1"/></Assign>

            <Call RefId="BallastAndTrim"/>

        </Aggregate>

    </Aggregate>

    <Aggregate Id="Float_Up">

        <Description>
            Float to surface instead of driving.
        </Description>

        <Sequence/>

        <Break>
            <Universal:depth/>
            <Lt><Control:VerticalControl.surfaceThreshold/></Lt>
        </Break>

        <Guidance:Buoyancy>
            <Parallel/>
            <Setting><Guidance:Buoyancy.position/><Control:VerticalControl.buoyancyDefault/></Setting>
        </Guidance:Buoyancy>

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

    </Aggregate>

</Mission>


2022-05-11T04:14:55.717Z,1652242495.717 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/tank_ballast_and_trim.xml
2022-05-11T04:14:56.081Z,1652242496.081 [Default] Stopped
2022-05-11T04:14:56.090Z,1652242496.090 [Default](DEBUG): Aggregate::uninitialize Default
2022-05-11T04:14:56.091Z,1652242496.091 [Default:B.GoToSurface] Stopped
2022-05-11T04:14:56.091Z,1652242496.091 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-05-11T04:14:56.091Z,1652242496.091 [Default:CheckIn] Stopped
2022-05-11T04:14:56.091Z,1652242496.091 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-11T04:14:56.106Z,1652242496.106 [Default:CheckIn:C.Wait] Stopped
2022-05-11T04:14:56.106Z,1652242496.106 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T04:14:56.106Z,1652242496.106 [MissionManager](IMPORTANT): Started mission ballast_and_trim
2022-05-11T04:14:56.106Z,1652242496.106 [ballast_and_trim] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim](DEBUG): Aggregate::initialize ballast_and_trim
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science](DEBUG): Aggregate::initialize ballast_and_trim:Science
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:A] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:B] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:C] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:D] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:E] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:F] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:Read_Oil] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:PeakDetectChl] Running Loop=1
2022-05-11T04:14:56.107Z,1652242496.107 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectChl
2022-05-11T04:14:56.108Z,1652242496.108 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Running Loop=1
2022-05-11T04:14:56.108Z,1652242496.108 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Initialize.
2022-05-11T04:14:56.110Z,1652242496.110 [ballast_and_trim:Science:HighestChlPeakReport] Running Loop=1
2022-05-11T04:14:56.122Z,1652242496.122 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestChlPeakReport
2022-05-11T04:14:56.122Z,1652242496.122 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Running Loop=1
2022-05-11T04:14:56.122Z,1652242496.122 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2022-05-11T04:14:56.123Z,1652242496.123 [ballast_and_trim:Science:PeakDetectNO3] Running Loop=1
2022-05-11T04:14:56.123Z,1652242496.123 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectNO3
2022-05-11T04:14:56.123Z,1652242496.123 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Running Loop=1
2022-05-11T04:14:56.123Z,1652242496.123 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Initialize.
2022-05-11T04:14:56.125Z,1652242496.125 [ballast_and_trim:Science:PeakDetectOil] Running Loop=1
2022-05-11T04:14:56.125Z,1652242496.125 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectOil
2022-05-11T04:14:56.125Z,1652242496.125 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Running Loop=1
2022-05-11T04:14:56.125Z,1652242496.125 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Initialize.
2022-05-11T04:14:56.135Z,1652242496.135 [ballast_and_trim:Science:HighestOilPeakReport] Running Loop=1
2022-05-11T04:14:56.135Z,1652242496.135 [ballast_and_trim:Science:HighestOilPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestOilPeakReport
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal] Running Loop=1
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:PeakDetectFDOM] Running Loop=1
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectFDOM
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Running Loop=1
2022-05-11T04:14:56.136Z,1652242496.136 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Initialize.
2022-05-11T04:14:56.140Z,1652242496.140 [ballast_and_trim:Science:PeakDetectSalinity] Running Loop=1
2022-05-11T04:14:56.140Z,1652242496.140 [ballast_and_trim:Science:PeakDetectSalinity](DEBUG): Aggregate::initialize ballast_and_trim:Science:PeakDetectSalinity
2022-05-11T04:14:56.140Z,1652242496.140 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth] Running Loop=1
2022-05-11T04:14:56.140Z,1652242496.140 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Initialize.
2022-05-11T04:14:56.142Z,1652242496.142 [ballast_and_trim:Science:HighestSaltPeakReport] Running Loop=1
2022-05-11T04:14:56.150Z,1652242496.150 [ballast_and_trim:Science:HighestSaltPeakReport](DEBUG): Aggregate::initialize ballast_and_trim:Science:HighestSaltPeakReport
2022-05-11T04:14:56.150Z,1652242496.150 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal] Running Loop=1
2022-05-11T04:14:56.150Z,1652242496.150 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](INFO): Initialize.
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:Science:OceanCurrent] Running Loop=1
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:Science:OceanCurrent](DEBUG): Aggregate::initialize ballast_and_trim:Science:OceanCurrent
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:Science:OceanCurrent:A.] Running Loop=1
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:Science:OceanCurrent:A.](INFO): Initializing CurrentEstimator.
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:RunBallastAndTrim] Running Loop=1
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim
2022-05-11T04:14:56.151Z,1652242496.151 [ballast_and_trim:RunBallastAndTrim:Depth1] Running Loop=1
2022-05-11T04:14:56.152Z,1652242496.152 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1
2022-05-11T04:14:56.152Z,1652242496.152 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Running Loop=1
2022-05-11T04:14:56.153Z,1652242496.153 [ballast_and_trim:RunBallastAndTrim:Depth1:A] Stopped
2022-05-11T04:14:56.153Z,1652242496.153 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Running Loop=1
2022-05-11T04:14:56.153Z,1652242496.153 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2022-05-11T04:14:56.153Z,1652242496.153 [ballast_and_trim:Science] Running Loop=1
2022-05-11T04:14:56.154Z,1652242496.154 [ballast_and_trim:Science:HighestSaltPeakReport] Stopped
2022-05-11T04:14:56.154Z,1652242496.154 [ballast_and_trim:Science:HighestSaltPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestSaltPeakReport
2022-05-11T04:14:56.154Z,1652242496.154 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:HighestSaltPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectSalinity] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectSalinity](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectSalinity
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectSalinity:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectFDOM] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectFDOM](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectFDOM
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:HighestOilPeakReport] Stopped
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:HighestOilPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestOilPeakReport
2022-05-11T04:14:56.155Z,1652242496.155 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:HighestOilPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectOil] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectOil](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectOil
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectNO3] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectNO3](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectNO3
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:HighestChlPeakReport] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:HighestChlPeakReport](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:HighestChlPeakReport
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal] Stopped
2022-05-11T04:14:56.156Z,1652242496.156 [ballast_and_trim:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Uninitialize.
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:PeakDetectChl] Stopped
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:PeakDetectChl](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:PeakDetectChl
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth] Stopped
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Uninitialize.
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:OceanCurrent:A.] Running Loop=1
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:Read_Oil] Stopped
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:F] Stopped
2022-05-11T04:14:56.157Z,1652242496.157 [ballast_and_trim:Science:E] Running Loop=1
2022-05-11T04:14:56.158Z,1652242496.158 [ballast_and_trim:Science:E](DEBUG): Initialize ReadDataComponent to sense mass_concentration_of_chlorophyll_in_sea_water
2022-05-11T04:14:56.159Z,1652242496.159 [ballast_and_trim:Science:D] Stopped
2022-05-11T04:14:56.159Z,1652242496.159 [ballast_and_trim:Science:C] Running Loop=1
2022-05-11T04:14:56.159Z,1652242496.159 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_temperature
2022-05-11T04:14:56.160Z,1652242496.160 [ballast_and_trim:Science:C](DEBUG): Initialize ReadDataComponent to sense CTD_Seabird.sea_water_salinity
2022-05-11T04:14:56.160Z,1652242496.160 [ballast_and_trim:Science:B] Running Loop=1
2022-05-11T04:14:56.161Z,1652242496.161 [ballast_and_trim:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_temperature
2022-05-11T04:14:56.161Z,1652242496.161 [ballast_and_trim:Science:B](DEBUG): Initialize ReadDataComponent to sense sea_water_salinity
2022-05-11T04:14:56.161Z,1652242496.161 [ballast_and_trim:Science:A] Stopped
2022-05-11T04:14:56.179Z,1652242496.179 [WetLabsBB2FL](INFO): Powering up
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2022-05-11T04:14:56.495Z,1652242496.495 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Running Loop=1
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F](INFO): Going to target depth. Speed set to 0.000000 m/s 
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:F] Stopped
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Running Loop=1
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2022-05-11T04:14:56.497Z,1652242496.497 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Running Loop=1
2022-05-11T04:14:56.499Z,1652242496.499 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2022-05-11T04:14:56.499Z,1652242496.499 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Running Loop=1
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point](DEBUG): Initialize.
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Running Loop=1
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Initialize Buoyancy Component.
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Running Loop=1
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch](DEBUG): Initialize.
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Running Loop=1
2022-05-11T04:14:56.500Z,1652242496.500 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2022-05-11T04:14:56.501Z,1652242496.501 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Running Loop=1
2022-05-11T04:14:56.501Z,1652242496.501 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Running Loop=1
2022-05-11T04:14:56.501Z,1652242496.501 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Running Loop=1
2022-05-11T04:14:56.501Z,1652242496.501 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Running Loop=1
2022-05-11T04:14:56.501Z,1652242496.501 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Running Loop=1
2022-05-11T04:14:56.502Z,1652242496.502 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Running Loop=1
2022-05-11T04:14:56.899Z,1652242496.899 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A](INFO): Waiting for 0.000000 min while pumping down to neutral.
2022-05-11T04:14:56.899Z,1652242496.899 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:A] Stopped
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait] Running Loop=1
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Initialize Wait Component.
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold] Stopped
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:A.Point] Stopped
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy] Stopped
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:B.Buoyancy](DEBUG): Uninitialize Buoyancy Component.
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ActuatorHold:C.Pitch] Stopped
2022-05-11T04:14:56.900Z,1652242496.900 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Running Loop=1
2022-05-11T04:14:57.314Z,1652242497.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](INFO): Done Waiting.
2022-05-11T04:14:57.314Z,1652242497.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait] Stopped
2022-05-11T04:14:57.314Z,1652242497.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive:B.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T04:14:57.314Z,1652242497.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](INFO): Completed ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2022-05-11T04:14:57.314Z,1652242497.314 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive] Stopped
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:WaitPreDive
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Running Loop=1
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::initialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Initialize.
2022-05-11T04:14:57.315Z,1652242497.315 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Running Loop=1
2022-05-11T04:14:57.686Z,1652242497.686 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Running Loop=1
2022-05-11T04:14:57.687Z,1652242497.687 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A](INFO): Moving to 7.000000 m 
2022-05-11T04:14:57.687Z,1652242497.687 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:A] Stopped
2022-05-11T04:14:57.687Z,1652242497.687 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Running Loop=1
2022-05-11T04:14:57.687Z,1652242497.687 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch](DEBUG): Initialize.
2022-05-11T04:14:59.967Z,1652242499.967 [CTD_Seabird](ERROR): Failed to parse device response: <!--startlogging-->
2022-05-11T04:15:00.323Z,1652242500.323 [CommandExec](IMPORTANT): got command stop
2022-05-11T04:15:00.324Z,1652242500.324 [CommandExec](IMPORTANT): Scheduling is paused
2022-05-11T04:15:00.324Z,1652242500.324 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2022-05-11T04:15:00.513Z,1652242500.513 [MissionManager](INFO): MissionManager is completed.
2022-05-11T04:15:00.513Z,1652242500.513 [MissionManager](INFO): Uninitializing Mission ballast_and_trim
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim] Stopped
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim](DEBUG): Aggregate::uninitialize ballast_and_trim
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim:Science] Stopped
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim:Science](DEBUG): Aggregate::uninitialize ballast_and_trim:Science
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim:Science:B] Stopped
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim:Science:C] Stopped
2022-05-11T04:15:00.513Z,1652242500.513 [ballast_and_trim:Science:E] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:Science:OceanCurrent] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:Science:OceanCurrent](DEBUG): Aggregate::uninitialize ballast_and_trim:Science:OceanCurrent
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:Science:OceanCurrent:A.] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:A] Stopped
2022-05-11T04:15:00.514Z,1652242500.514 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:B] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:C] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:D] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:E] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:A] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth] Stopped
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth
2022-05-11T04:15:00.515Z,1652242500.515 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed] Stopped
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:B.SetSpeed](DEBUG): Uninitialize.
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:BallastAndTrim:GoToTargetDepth:ApproachDepth:C.Pitch] Stopped
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:Depth1] Stopped
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:Depth1](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:Depth1:B] Stopped
2022-05-11T04:15:00.516Z,1652242500.516 [ballast_and_trim:RunBallastAndTrim:Depth1:B](DEBUG): Aggregate::uninitialize ballast_and_trim:RunBallastAndTrim:Depth1:B
2022-05-11T04:15:00.810Z,1652242500.810 [WetLabsBB2FL](INFO): Powering down
2022-05-11T04:15:00.917Z,1652242500.917 [MissionManager](IMPORTANT): Started mission Default
2022-05-11T04:15:00.917Z,1652242500.917 [Default] Running Loop=1
2022-05-11T04:15:00.917Z,1652242500.917 [Default](DEBUG): Aggregate::initialize Default
2022-05-11T04:15:00.917Z,1652242500.917 [Default:B.GoToSurface] Running Loop=1
2022-05-11T04:15:00.917Z,1652242500.917 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-05-11T04:15:00.918Z,1652242500.918 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-05-11T04:15:00.918Z,1652242500.918 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-05-11T04:15:00.919Z,1652242500.919 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-05-11T04:15:00.919Z,1652242500.919 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-05-11T04:15:00.919Z,1652242500.919 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-05-11T04:15:00.919Z,1652242500.919 [Default:A.Wait] Running Loop=1
2022-05-11T04:15:00.920Z,1652242500.920 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-05-11T04:15:11.850Z,1652242511.850 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-11T04:15:11.850Z,1652242511.850 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+9999.99,+9999.99
2022-05-11T04:15:14.255Z,1652242514.255 [Default:A.Wait](INFO): Done Waiting.
2022-05-11T04:15:14.255Z,1652242514.255 [Default:A.Wait] Stopped
2022-05-11T04:15:14.255Z,1652242514.255 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-05-11T04:15:14.679Z,1652242514.679 [Default:CheckIn] Running Loop=1
2022-05-11T04:15:14.679Z,1652242514.679 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-11T04:15:14.679Z,1652242514.679 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-11T04:15:47.364Z,1652242547.364 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2022-05-11T04:15:47.438Z,1652242547.438 [NAL9602](ERROR): received: 
+CSQ:0

OK
2022-05-11T04:16:30.093Z,1652242590.093 [CommandExec](IMPORTANT): got command get BuoyancyServo.limitLo
2022-05-11T04:16:30.094Z,1652242590.094 [CommandExec](IMPORTANT): BuoyancyServo.limitLo 1750 count
2022-05-11T04:18:41.101Z,1652242721.101 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-11T04:18:41.101Z,1652242721.101 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.3,0000.0,00
2022-05-11T04:19:29.468Z,1652242769.468 [CommandExec](IMPORTANT): got command restart system
2022-05-11T04:19:31.534Z,1652242771.534 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-11T04:19:31.534Z,1652242771.534 [CommandExec](INFO): Uninitializing the command executive.
2022-05-11T04:19:31.534Z,1652242771.534 [CommandExec](INFO): Uninitializing the command scheduler.
2022-05-11T04:19:31.535Z,1652242771.535 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:31.650Z,1652242771.650 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2022-05-11T04:19:31.650Z,1652242771.650 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2022-05-11T04:19:31.650Z,1652242771.650 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:31.653Z,1652242771.653 [NavChartDb](INFO): Join timeout helper Thread ID is 1066
2022-05-11T04:19:31.802Z,1652242771.802 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-11T04:19:31.802Z,1652242771.802 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:31.822Z,1652242771.822 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2022-05-11T04:19:31.822Z,1652242771.822 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:31.823Z,1652242771.823 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 1067
2022-05-11T04:19:32.003Z,1652242772.003 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-11T04:19:32.003Z,1652242772.003 [WetLabsBB2FL](INFO): Powering down
2022-05-11T04:19:32.004Z,1652242772.004 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:32.014Z,1652242772.014 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2022-05-11T04:19:32.014Z,1652242772.014 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:32.015Z,1652242772.015 [CTD_Seabird](INFO): Join timeout helper Thread ID is 1068
2022-05-11T04:19:32.138Z,1652242772.138 [CTD_Seabird](INFO): Powering down
2022-05-11T04:19:32.150Z,1652242772.150 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-11T04:19:32.150Z,1652242772.150 [CTD_Seabird](INFO): Powering down
2022-05-11T04:19:32.162Z,1652242772.162 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:32.174Z,1652242772.174 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2022-05-11T04:19:32.174Z,1652242772.174 [DAT ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:32.175Z,1652242772.175 [DAT](INFO): Join timeout helper Thread ID is 1069
2022-05-11T04:19:32.238Z,1652242772.238 [DAT](INFO): Powering down
2022-05-11T04:19:32.311Z,1652242772.311 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-11T04:19:32.311Z,1652242772.311 [DAT](INFO): Powering down
2022-05-11T04:19:32.312Z,1652242772.312 [DAT ThreadHandler](INFO): Thread cancelled.
2022-05-11T04:19:32.318Z,1652242772.318 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2022-05-11T04:19:32.318Z,1652242772.318 [Radio_Surface ThreadHandler](INFO): Thread cancelled.