2022-05-12T23:40:59.813Z,1652398859.813 [Supervisor](DEBUG): Initializing supervisor.
2022-05-12T23:40:59.818Z,1652398859.818 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-05-12T23:40:59.818Z,1652398859.818 [SyncHandler](INFO): Protected caller Thread ID is 828
2022-05-12T23:40:59.819Z,1652398859.819 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-05-12T23:40:59.820Z,1652398859.820 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-05-12T23:40:59.820Z,1652398859.820 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 829
2022-05-12T23:40:59.824Z,1652398859.824 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-05-12T23:40:59.842Z,1652398859.842 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-05-12T23:40:59.843Z,1652398859.843 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-05-12T23:40:59.843Z,1652398859.843 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 830
2022-05-12T23:40:59.847Z,1652398859.847 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-05-12T23:40:59.848Z,1652398859.848 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-05-12T23:40:59.849Z,1652398859.849 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 831
2022-05-12T23:40:59.851Z,1652398859.851 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-05-12T23:40:59.852Z,1652398859.852 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-05-12T23:40:59.852Z,1652398859.852 [logger ThreadHandler](INFO): Protected caller Thread ID is 832
2022-05-12T23:40:59.856Z,1652398859.856 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-05-12T23:40:59.856Z,1652398859.856 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-05-12T23:40:59.859Z,1652398859.859 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-05-12T23:41:00.189Z,1652398860.189 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-05-12T23:41:00.189Z,1652398860.189 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-05-12T23:41:00.834Z,1652398860.834 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-05-12T23:41:00.835Z,1652398860.835 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-05-12T23:41:00.942Z,1652398860.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-05-12T23:41:00.944Z,1652398860.944 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-05-12T23:41:01.495Z,1652398861.495 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-05-12T23:41:01.495Z,1652398861.495 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-05-12T23:41:01.593Z,1652398861.593 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-05-12T23:41:01.595Z,1652398861.595 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-05-12T23:41:01.677Z,1652398861.677 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-05-12T23:41:02.046Z,1652398862.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-05-12T23:41:02.046Z,1652398862.046 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-05-12T23:41:02.265Z,1652398862.265 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-05-12T23:41:02.267Z,1652398862.267 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-05-12T23:41:02.393Z,1652398862.393 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-05-12T23:41:02.393Z,1652398862.393 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-05-12T23:41:02.619Z,1652398862.619 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-05-12T23:41:02.620Z,1652398862.620 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-05-12T23:41:03.093Z,1652398863.093 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-05-12T23:41:03.095Z,1652398863.095 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-05-12T23:41:03.454Z,1652398863.454 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-05-12T23:41:03.948Z,1652398863.948 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-05-12T23:41:04.330Z,1652398864.330 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-05-12T23:41:04.524Z,1652398864.524 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-05-12T23:41:04.525Z,1652398864.525 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-05-12T23:41:04.743Z,1652398864.743 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-05-12T23:41:04.744Z,1652398864.744 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-05-12T23:41:05.056Z,1652398865.056 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-05-12T23:41:05.058Z,1652398865.058 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2022-05-12T23:41:05.062Z,1652398865.062 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2022-05-12T23:41:05.170Z,1652398865.170 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2022-05-12T23:41:05.318Z,1652398865.318 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2022-05-12T23:41:05.405Z,1652398865.405 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2022-05-12T23:41:05.489Z,1652398865.489 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2022-05-12T23:41:05.603Z,1652398865.603 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2022-05-12T23:41:05.778Z,1652398865.778 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2022-05-12T23:41:06.040Z,1652398866.040 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-05-12T23:41:06.041Z,1652398866.041 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2022-05-12T23:41:06.173Z,1652398866.173 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2022-05-12T23:41:06.267Z,1652398866.267 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2022-05-12T23:41:06.371Z,1652398866.371 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2022-05-12T23:41:06.470Z,1652398866.470 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2022-05-12T23:41:06.483Z,1652398866.483 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-05-12T23:41:06.604Z,1652398866.604 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-05-12T23:41:06.605Z,1652398866.605 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-05-12T23:41:06.620Z,1652398866.620 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-05-12T23:41:06.621Z,1652398866.621 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-05-12T23:41:06.693Z,1652398866.693 [DepthRateCalculator] Loaded
2022-05-12T23:41:06.693Z,1652398866.693 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-05-12T23:41:06.698Z,1652398866.698 [PitchRateCalculator] Loaded
2022-05-12T23:41:06.698Z,1652398866.698 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-05-12T23:41:06.709Z,1652398866.709 [SpeedCalculator] Loaded
2022-05-12T23:41:06.709Z,1652398866.709 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-05-12T23:41:06.714Z,1652398866.714 [YawRateCalculator] Loaded
2022-05-12T23:41:06.714Z,1652398866.714 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-05-12T23:41:06.734Z,1652398866.734 [ElevatorOffsetCalculator] Loaded
2022-05-12T23:41:06.735Z,1652398866.735 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-05-12T23:41:06.735Z,1652398866.735 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-05-12T23:41:06.736Z,1652398866.736 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-05-12T23:41:06.804Z,1652398866.804 [VerticalControl](DEBUG): Construct VerticalControl.
2022-05-12T23:41:06.859Z,1652398866.859 [VerticalControl] Loaded
2022-05-12T23:41:06.860Z,1652398866.860 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-05-12T23:41:06.862Z,1652398866.862 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-05-12T23:41:06.901Z,1652398866.901 [HorizontalControl] Loaded
2022-05-12T23:41:06.901Z,1652398866.901 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-05-12T23:41:06.904Z,1652398866.904 [SpeedControl](DEBUG): Construct SpeedControl.
2022-05-12T23:41:06.906Z,1652398866.906 [SpeedControl] Loaded
2022-05-12T23:41:06.907Z,1652398866.907 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-05-12T23:41:06.909Z,1652398866.909 [LoopControl](DEBUG): Construct LoopControl.
2022-05-12T23:41:06.909Z,1652398866.909 [LoopControl] Loaded
2022-05-12T23:41:06.910Z,1652398866.910 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-05-12T23:41:06.910Z,1652398866.910 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-05-12T23:41:06.911Z,1652398866.911 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-05-12T23:41:07.045Z,1652398867.045 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-05-12T23:41:07.045Z,1652398867.045 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-05-12T23:41:07.058Z,1652398867.058 [NavChart] Loaded
2022-05-12T23:41:07.059Z,1652398867.059 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-05-12T23:41:07.064Z,1652398867.064 [UniversalFixResidualReporter] Loaded
2022-05-12T23:41:07.065Z,1652398867.065 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-05-12T23:41:07.065Z,1652398867.065 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-05-12T23:41:07.066Z,1652398867.066 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-05-12T23:41:07.205Z,1652398867.205 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-05-12T23:41:07.205Z,1652398867.205 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-05-12T23:41:07.989Z,1652398867.989 [AHRS_M2] Loaded
2022-05-12T23:41:07.990Z,1652398867.990 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-05-12T23:41:08.239Z,1652398868.239 [BackseatComponent] Loaded
2022-05-12T23:41:08.239Z,1652398868.239 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-05-12T23:41:08.240Z,1652398868.240 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408DD4E0
2022-05-12T23:41:08.240Z,1652398868.240 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 914
2022-05-12T23:41:08.243Z,1652398868.243 [LcmUniversalReporter] Loaded
2022-05-12T23:41:08.243Z,1652398868.243 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-05-12T23:41:08.384Z,1652398868.384 [DataOverHttps] Loaded
2022-05-12T23:41:08.384Z,1652398868.384 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-05-12T23:41:08.385Z,1652398868.385 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0
2022-05-12T23:41:08.385Z,1652398868.385 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 915
2022-05-12T23:41:08.405Z,1652398868.405 [Depth_Keller] Loaded
2022-05-12T23:41:08.405Z,1652398868.405 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-05-12T23:41:08.410Z,1652398868.410 [DropWeight] Loaded
2022-05-12T23:41:08.410Z,1652398868.410 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2022-05-12T23:41:08.446Z,1652398868.446 [DVL_micro] Loaded
2022-05-12T23:41:08.447Z,1652398868.447 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2022-05-12T23:41:08.505Z,1652398868.505 [NAL9602] Loaded
2022-05-12T23:41:08.505Z,1652398868.505 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-05-12T23:41:08.533Z,1652398868.533 [Onboard] Loaded
2022-05-12T23:41:08.533Z,1652398868.533 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-05-12T23:41:08.534Z,1652398868.534 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0
2022-05-12T23:41:08.535Z,1652398868.535 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 916
2022-05-12T23:41:08.546Z,1652398868.546 [Power24vConverter] Loaded
2022-05-12T23:41:08.547Z,1652398868.547 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-05-12T23:41:08.559Z,1652398868.559 [Radio_Surface] Loaded
2022-05-12T23:41:08.559Z,1652398868.559 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-05-12T23:41:08.560Z,1652398868.560 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0
2022-05-12T23:41:08.561Z,1652398868.561 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 917
2022-05-12T23:41:08.646Z,1652398868.646 [DAT] Loaded
2022-05-12T23:41:08.646Z,1652398868.646 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-05-12T23:41:08.647Z,1652398868.647 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 4099D4E0
2022-05-12T23:41:08.648Z,1652398868.648 [DAT ThreadHandler](INFO): Protected caller Thread ID is 918
2022-05-12T23:41:08.648Z,1652398868.648 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-05-12T23:41:08.649Z,1652398868.649 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-05-12T23:41:08.798Z,1652398868.798 [BuoyancyServo] Loaded
2022-05-12T23:41:08.798Z,1652398868.798 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-05-12T23:41:08.818Z,1652398868.818 [ElevatorServo] Loaded
2022-05-12T23:41:08.818Z,1652398868.818 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-05-12T23:41:08.836Z,1652398868.836 [MassServo] Loaded
2022-05-12T23:41:08.837Z,1652398868.837 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-05-12T23:41:08.855Z,1652398868.855 [RudderServo] Loaded
2022-05-12T23:41:08.855Z,1652398868.855 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-05-12T23:41:08.870Z,1652398868.870 [ThrusterHE] Loaded
2022-05-12T23:41:08.870Z,1652398868.870 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-05-12T23:41:08.870Z,1652398868.870 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-05-12T23:41:08.871Z,1652398868.871 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-05-12T23:41:08.954Z,1652398868.954 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-05-12T23:41:08.955Z,1652398868.955 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-05-12T23:41:08.998Z,1652398868.998 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-05-12T23:41:08.998Z,1652398868.998 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-05-12T23:41:09.357Z,1652398869.357 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-05-12T23:41:09.357Z,1652398869.357 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-05-12T23:41:10.105Z,1652398870.105 [CTD_Seabird] Loaded
2022-05-12T23:41:10.105Z,1652398870.105 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2022-05-12T23:41:10.106Z,1652398870.106 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B394E0
2022-05-12T23:41:10.106Z,1652398870.106 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 919
2022-05-12T23:41:10.138Z,1652398870.138 [ESPComponent] Loaded
2022-05-12T23:41:10.138Z,1652398870.138 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2022-05-12T23:41:10.158Z,1652398870.158 [PAR_Licor] Loaded
2022-05-12T23:41:10.158Z,1652398870.158 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-05-12T23:41:10.189Z,1652398870.189 [WetLabsBB2FL] Loaded
2022-05-12T23:41:10.189Z,1652398870.189 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-05-12T23:41:10.190Z,1652398870.190 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B694E0
2022-05-12T23:41:10.191Z,1652398870.191 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 920
2022-05-12T23:41:10.191Z,1652398870.191 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-05-12T23:41:10.192Z,1652398870.192 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-05-12T23:41:10.359Z,1652398870.359 [SBIT](DEBUG): Construct Startup Built In Test.
2022-05-12T23:41:10.369Z,1652398870.369 [SBIT] Loaded
2022-05-12T23:41:10.369Z,1652398870.369 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-05-12T23:41:10.372Z,1652398870.372 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-05-12T23:41:10.385Z,1652398870.385 [IBIT] Loaded
2022-05-12T23:41:10.385Z,1652398870.385 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-05-12T23:41:10.391Z,1652398870.391 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-05-12T23:41:10.618Z,1652398870.618 [CBIT] Loaded
2022-05-12T23:41:10.618Z,1652398870.618 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-05-12T23:41:10.619Z,1652398870.619 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-05-12T23:41:10.625Z,1652398870.625 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-05-12T23:41:10.627Z,1652398870.627 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-05-12T23:41:10.638Z,1652398870.638 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-05-12T23:41:10.639Z,1652398870.639 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BD74E0
2022-05-12T23:41:10.639Z,1652398870.639 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 921
2022-05-12T23:41:10.644Z,1652398870.644 [Supervisor](INFO): Main Thread ID is 823
2022-05-12T23:41:10.644Z,1652398870.644 [Supervisor](DEBUG): Running supervisor.
2022-05-12T23:41:10.644Z,1652398870.644 [CommandExec ThreadHandler](INFO): Handler Thread ID is 922
2022-05-12T23:41:10.645Z,1652398870.645 [CommandExec](INFO): Initializing the command executive.
2022-05-12T23:41:10.646Z,1652398870.646 [CommandLine ThreadHandler](INFO): Handler Thread ID is 923
2022-05-12T23:41:10.648Z,1652398870.648 [controlThread ThreadHandler](INFO): Handler Thread ID is 924
2022-05-12T23:41:10.649Z,1652398870.649 [controlThread](DEBUG): Initializing ControlThread
2022-05-12T23:41:10.649Z,1652398870.649 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-05-12T23:41:10.650Z,1652398870.650 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-05-12T23:41:10.650Z,1652398870.650 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-05-12T23:41:10.651Z,1652398870.651 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-05-12T23:41:10.651Z,1652398870.651 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-05-12T23:41:10.652Z,1652398870.652 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-05-12T23:41:10.653Z,1652398870.653 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-05-12T23:41:10.654Z,1652398870.654 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-05-12T23:41:10.654Z,1652398870.654 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-05-12T23:41:10.655Z,1652398870.655 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-05-12T23:41:10.656Z,1652398870.656 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-05-12T23:41:10.663Z,1652398870.663 [SBIT](INFO): Initialize SBIT Component.
2022-05-12T23:41:10.664Z,1652398870.664 [SBIT](IMPORTANT): git: 2022-05-11
2022-05-12T23:41:10.664Z,1652398870.664 [SBIT](INFO): git hash: 7696a1969a630744ed6dd937befa6455a7154426
2022-05-12T23:41:10.664Z,1652398870.664 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-05-12T23:41:10.665Z,1652398870.665 [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-12T23:41:10.666Z,1652398870.666 [SBIT](INFO): Beginning SBIT in 22.000000 seconds.
2022-05-12T23:41:10.667Z,1652398870.667 [IBIT](INFO): Initialize IBIT Component.
2022-05-12T23:41:10.668Z,1652398870.668 [CBIT](DEBUG): Initialize CBIT Component.
2022-05-12T23:41:10.669Z,1652398870.669 [logger ThreadHandler](INFO): Handler Thread ID is 925
2022-05-12T23:41:10.679Z,1652398870.679 [CBIT](DEBUG): Initialized mux pins.
2022-05-12T23:41:10.679Z,1652398870.679 [CBIT](DEBUG): Initializing the watchdog timer.
2022-05-12T23:41:10.687Z,1652398870.687 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 926
2022-05-12T23:41:10.699Z,1652398870.699 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 927
2022-05-12T23:41:10.700Z,1652398870.700 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-05-12T23:41:10.703Z,1652398870.703 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-05-12T23:41:10.703Z,1652398870.703 [CBIT](DEBUG): Initializing heartbeat.
2022-05-12T23:41:10.711Z,1652398870.711 [Onboard ThreadHandler](INFO): Handler Thread ID is 928
2022-05-12T23:41:10.729Z,1652398870.729 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 929
2022-05-12T23:41:10.751Z,1652398870.751 [DAT ThreadHandler](INFO): Handler Thread ID is 930
2022-05-12T23:41:10.752Z,1652398870.752 [DAT](INFO): Powering up
2022-05-12T23:41:10.752Z,1652398870.752 [DAT](DEBUG): Initializing DAT.
2022-05-12T23:41:10.756Z,1652398870.756 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 932
2022-05-12T23:41:10.757Z,1652398870.757 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2022-05-12T23:41:10.760Z,1652398870.760 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 934
2022-05-12T23:41:10.763Z,1652398870.763 [WetLabsBB2FL](INFO): Powering up
2022-05-12T23:41:10.765Z,1652398870.765 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 936
2022-05-12T23:41:10.772Z,1652398870.772 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2022-05-12T23:41:10.772Z,1652398870.772 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2022-05-12T23:41:10.772Z,1652398870.772 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2022-05-12T23:41:10.773Z,1652398870.773 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000
2022-05-12T23:41:10.774Z,1652398870.774 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000
2022-05-12T23:41:10.775Z,1652398870.775 [CBIT](DEBUG): Deactivating GF circuits.
2022-05-12T23:41:10.775Z,1652398870.775 [CBIT](DEBUG): Deactivating emergency mode.
2022-05-12T23:41:10.811Z,1652398870.811 [CBIT](DEBUG): Backplane powered.
2022-05-12T23:41:10.812Z,1652398870.812 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2022-05-12T23:41:10.847Z,1652398870.847 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-05-12T23:41:10.871Z,1652398870.871 [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-12T23:41:10.872Z,1652398870.872 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-05-12T23:41:10.946Z,1652398870.946 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-05-12T23:41:10.963Z,1652398870.963 [Default:A.Wait](DEBUG): Construct Wait.
2022-05-12T23:41:10.966Z,1652398870.966 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-05-12T23:41:11.016Z,1652398871.016 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-05-12T23:41:11.018Z,1652398871.018 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-05-12T23:41:11.040Z,1652398871.040 [Default:E.Execute](DEBUG): Construct Execute.
2022-05-12T23:41:11.044Z,1652398871.044 [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-12T23:41:11.051Z,1652398871.051 [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-12T23:41:11.067Z,1652398871.067 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-05-12T23:41:11.136Z,1652398871.136 [Radio_Surface](INFO): Powering up
2022-05-12T23:41:11.199Z,1652398871.199 [Depth_Keller](ERROR): Pressure reading out of range: 1829.595459 decibar
2022-05-12T23:41:11.208Z,1652398871.208 [Power24vConverter](INFO): Powering up.
2022-05-12T23:41:11.225Z,1652398871.225 [DepthRateCalculator](ERROR): Depth measurement is not active
2022-05-12T23:41:11.284Z,1652398871.284 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:11.291Z,1652398871.291 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-05-12T23:41:11.292Z,1652398871.292 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:11.300Z,1652398871.300 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-05-12T23:41:11.300Z,1652398871.300 [MassServo](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:11.307Z,1652398871.307 [MassServo](DEBUG): Initializing MassServo.
2022-05-12T23:41:11.308Z,1652398871.308 [RudderServo](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:11.315Z,1652398871.315 [RudderServo](DEBUG): Initializing RudderServo.
2022-05-12T23:41:11.316Z,1652398871.316 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:11.323Z,1652398871.323 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-05-12T23:41:12.211Z,1652398872.211 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2022-05-12T23:41:12.211Z,1652398872.211 [RudderServo](FAULT): Rudder failed to initialize
2022-05-12T23:41:12.211Z,1652398872.211 [RudderServo] Communications Fault, FailCount= 1
2022-05-12T23:41:12.211Z,1652398872.211 [RudderServo](ERROR): Communications Fault
2022-05-12T23:41:12.215Z,1652398872.215 [CBIT](ERROR): Communications Fault in component: RudderServo
2022-05-12T23:41:12.425Z,1652398872.425 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-05-12T23:41:12.425Z,1652398872.425 [RudderServo](INFO): Powering down
2022-05-12T23:41:13.098Z,1652398873.098 [RudderServo](DEBUG): Initializing EZServoServo.
2022-05-12T23:41:13.232Z,1652398873.232 [RudderServo](DEBUG): Initializing RudderServo.
2022-05-12T23:41:13.236Z,1652398873.236 [CBIT](INFO): Clearing failed state for component RudderServo
2022-05-12T23:41:13.236Z,1652398873.236 [RudderServo] No Fault, FailCount= 1
2022-05-12T23:41:13.375Z,1652398873.375 [WetLabsBB2FL](INFO): Powering down
2022-05-12T23:41:16.988Z,1652398876.988 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-05-12T23:41:17.787Z,1652398877.787 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2022-05-12T23:41:25.117Z,1652398885.117 [DAT](INFO): commRate: 800
2022-05-12T23:41:27.183Z,1652398887.183 [DAT](INFO): entering command mode
2022-05-12T23:41:27.384Z,1652398887.384 [DAT](INFO): setting verbose to 3
2022-05-12T23:41:27.636Z,1652398887.636 [DAT](INFO): set verbose to 3
2022-05-12T23:41:27.637Z,1652398887.637 [DAT](INFO): setting DatVerbose to 27440
2022-05-12T23:41:27.888Z,1652398887.888 [DAT](INFO): set DatVerbose to 27440
2022-05-12T23:41:27.889Z,1652398887.889 [DAT](INFO): setting transmit power to 8
2022-05-12T23:41:28.140Z,1652398888.140 [DAT](INFO): set transmit power to 8
2022-05-12T23:41:28.141Z,1652398888.141 [DAT](INFO): setting local address to 8
2022-05-12T23:41:28.392Z,1652398888.392 [DAT](INFO): set local address to 8
2022-05-12T23:41:28.393Z,1652398888.393 [DAT](INFO): Setting time to: 23:41:28 And date to:5/12/2022
2022-05-12T23:41:28.644Z,1652398888.644 [DAT](INFO): Local DAT time set to Thu May 12, 2022  23:41:28  

2022-05-12T23:41:33.320Z,1652398893.320 [SBIT](IMPORTANT): Beginning Startup BIT
2022-05-12T23:41:33.327Z,1652398893.327 [CBIT](IMPORTANT): Beginning ground fault scan
2022-05-12T23:41:38.537Z,1652398898.537 [NAL9602](INFO): Powering up NAL9602
2022-05-12T23:41:44.327Z,1652398904.327 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.004017
CHAN A1 (24V): -0.002513
CHAN A2 (12V): -0.000982
CHAN A3 (5V): -0.000001
CHAN B0 (3.3V): 0.000355
CHAN B1 (3.15aV): 0.000197
CHAN B2 (3.15bV): 0.000298
CHAN B3 (GND): 0.000660
OPEN: -0.003494
Full Scale: +/- 1 mA
2022-05-12T23:41:49.445Z,1652398909.445 [NAL9602](INFO): NAL9602 initialized
2022-05-12T23:42:06.840Z,1652398926.840 [NAL9602](INFO): SBD MO Status=0, MOMSN=5474, MT Status=0, MTMSN=0
2022-05-12T23:42:06.840Z,1652398926.840 [NAL9602](INFO): No messages in MT queue
2022-05-12T23:42:16.931Z,1652398936.931 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-12T23:42:16.931Z,1652398936.931 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,00.0,1489.0,000
2022-05-12T23:42:27.048Z,1652398947.048 [SBIT](IMPORTANT): SBIT PASSED
2022-05-12T23:42:27.048Z,1652398947.048 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): Express linearApproximation CBIT.ampHoursUsed 1.000000 ampere_hour;

2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): Express linearApproximation CTD_Seabird.bin_median_sea_water_salinity 0.010000 practical_salinity_unit;

2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): Express linearApproximation WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 0.200000 microgram_per_liter;

2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=182.245027 cubic_centimeter;

2022-05-12T23:42:27.049Z,1652398947.049 [SBIT](IMPORTANT): VerticalControl.massDefault=0.679016 millimeter;

2022-05-12T23:42:27.050Z,1652398947.050 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-40 millimeter;

2022-05-12T23:42:27.436Z,1652398947.436 [MissionManager](IMPORTANT): Started mission Startup
2022-05-12T23:42:27.436Z,1652398947.436 [Startup] Running Loop=1
2022-05-12T23:42:27.436Z,1652398947.436 [Startup](DEBUG): Aggregate::initialize Startup
2022-05-12T23:42:27.436Z,1652398947.436 [Startup:A.GoToSurface] Running Loop=1
2022-05-12T23:42:27.436Z,1652398947.436 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-05-12T23:42:27.437Z,1652398947.437 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-05-12T23:42:27.437Z,1652398947.437 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-05-12T23:42:27.438Z,1652398947.438 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-05-12T23:42:27.438Z,1652398947.438 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-05-12T23:42:27.438Z,1652398947.438 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-05-12T23:42:27.464Z,1652398947.464 [Startup:StartupSatComms] Running Loop=1
2022-05-12T23:42:27.464Z,1652398947.464 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2022-05-12T23:42:27.464Z,1652398947.464 [Startup:StartupSatComms:A] Running Loop=1
2022-05-12T23:42:27.841Z,1652398947.841 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2022-05-12T23:42:35.095Z,1652398955.095 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234230.00,A,3648.13828,N,12147.21195,W,0.078,0.00,120522,,,A*77
2022-05-12T23:42:35.099Z,1652398955.099 [NAL9602](INFO): GPS fix at 20220512T234230: (36.802305, -121.786866)
2022-05-12T23:42:35.138Z,1652398955.138 [Startup:StartupSatComms:A] Stopped
2022-05-12T23:42:35.138Z,1652398955.138 [Startup:StartupSatComms:B] Running Loop=1
2022-05-12T23:42:35.548Z,1652398955.548 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-05-12T23:43:01.082Z,1652398981.082 [NAL9602](INFO): SBD MO Status=1, MOMSN=5475, MT Status=0, MTMSN=0
2022-05-12T23:43:01.135Z,1652398981.135 [NAL9602](INFO): Sent 74 bytes from file Logs/20220512T192924/Courier0076.lzma
2022-05-12T23:43:01.135Z,1652398981.135 [NAL9602](INFO): Packets left to send: 0
2022-05-12T23:43:16.918Z,1652398996.918 [NAL9602](INFO): SBD MO Status=2, MOMSN=5476, MT Status=2, MTMSN=0
2022-05-12T23:43:16.918Z,1652398996.918 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-12T23:43:35.536Z,1652399015.536 [Startup:StartupSatComms:B](INFO): Timed out from 2022-05-12T23:42:35.1Z
2022-05-12T23:43:35.536Z,1652399015.536 [Startup:StartupSatComms:B] Stopped
2022-05-12T23:43:35.536Z,1652399015.536 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2022-05-12T23:43:35.536Z,1652399015.536 [Startup:StartupSatComms] Stopped
2022-05-12T23:43:35.536Z,1652399015.536 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2022-05-12T23:43:35.537Z,1652399015.537 [Startup](INFO): Completed Startup
2022-05-12T23:43:35.537Z,1652399015.537 [MissionManager](INFO): Startup is completed.
2022-05-12T23:43:35.537Z,1652399015.537 [MissionManager](INFO): Uninitializing Mission Startup
2022-05-12T23:43:35.537Z,1652399015.537 [Startup] Stopped
2022-05-12T23:43:35.537Z,1652399015.537 [Startup](DEBUG): Aggregate::uninitialize Startup
2022-05-12T23:43:35.537Z,1652399015.537 [Startup:A.GoToSurface] Stopped
2022-05-12T23:43:35.537Z,1652399015.537 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-05-12T23:43:35.960Z,1652399015.960 [MissionManager](IMPORTANT): Started mission Default
2022-05-12T23:43:35.960Z,1652399015.960 [Default] Running Loop=1
2022-05-12T23:43:35.960Z,1652399015.960 [Default](DEBUG): Aggregate::initialize Default
2022-05-12T23:43:35.960Z,1652399015.960 [Default:B.GoToSurface] Running Loop=1
2022-05-12T23:43:35.961Z,1652399015.961 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-05-12T23:43:35.961Z,1652399015.961 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-05-12T23:43:35.961Z,1652399015.961 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-05-12T23:43:35.961Z,1652399015.961 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-05-12T23:43:35.962Z,1652399015.962 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-05-12T23:43:35.962Z,1652399015.962 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-05-12T23:43:35.962Z,1652399015.962 [Default:A.Wait] Running Loop=1
2022-05-12T23:43:35.962Z,1652399015.962 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-05-12T23:43:44.816Z,1652399024.816 [NAL9602](INFO): SBD MO Status=1, MOMSN=5476, MT Status=0, MTMSN=0
2022-05-12T23:43:44.919Z,1652399024.919 [NAL9602](INFO): Sent 18 bytes from file Logs/20220512T192924/Courier0079.lzma
2022-05-12T23:43:44.919Z,1652399024.919 [NAL9602](INFO): Packets left to send: 0
2022-05-12T23:43:46.037Z,1652399026.037 [DVL_micro](ERROR): only read 2 of 4 data items
2022-05-12T23:43:46.037Z,1652399026.037 [DVL_micro](ERROR): Failed to parse:
:RD,+99999.99,+99999.99
2022-05-12T23:43:49.274Z,1652399029.274 [Default:A.Wait](INFO): Done Waiting.
2022-05-12T23:43:49.274Z,1652399029.274 [Default:A.Wait] Stopped
2022-05-12T23:43:49.275Z,1652399029.275 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-05-12T23:43:49.678Z,1652399029.678 [Default:CheckIn] Running Loop=1
2022-05-12T23:43:49.679Z,1652399029.679 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-12T23:43:49.679Z,1652399029.679 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-12T23:43:50.100Z,1652399030.100 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-05-12T23:43:51.690Z,1652399031.690 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234349.00,A,3648.13710,N,12147.21456,W,1.477,214.38,120522,,,A*70
2022-05-12T23:43:51.693Z,1652399031.693 [NAL9602](INFO): GPS fix at 20220512T234349: (36.802285, -121.786909)
2022-05-12T23:43:51.703Z,1652399031.703 [Default:CheckIn:Read_GPS] Stopped
2022-05-12T23:43:51.703Z,1652399031.703 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-12T23:43:52.123Z,1652399032.123 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-05-12T23:44:09.530Z,1652399049.530 [NAL9602](INFO): SBD MO Status=1, MOMSN=5477, MT Status=0, MTMSN=0
2022-05-12T23:44:09.579Z,1652399049.579 [NAL9602](INFO): Sent 268 bytes from file Logs/20220512T234059/Courier0000.lzma
2022-05-12T23:44:09.579Z,1652399049.579 [NAL9602](INFO): Packets left to send: 0
2022-05-12T23:44:17.953Z,1652399057.953 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004489
2022-05-12T23:44:18.478Z,1652399058.478 [NAL9602](INFO): SBD MO Status=1, MOMSN=5478, MT Status=0, MTMSN=0
2022-05-12T23:44:18.529Z,1652399058.529 [NAL9602](INFO): Sent 74 bytes from file Logs/20220512T234059/Courier0004.lzma
2022-05-12T23:44:18.529Z,1652399058.529 [NAL9602](INFO): Packets left to send: 0
2022-05-12T23:44:18.559Z,1652399058.559 [Default:CheckIn:Read_Iridium] Stopped
2022-05-12T23:44:18.559Z,1652399058.559 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-12T23:44:18.560Z,1652399058.560 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-12T23:44:49.174Z,1652399089.174 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-12T23:48:56.445Z,1652399336.445 [DVL_micro](ERROR): Failed to parse:
:WI,+05557,-0032,+00000,A
2022-05-12T23:49:19.073Z,1652399359.073 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-12T23:49:19.073Z,1652399359.073 [Default:CheckIn:C.Wait] Stopped
2022-05-12T23:49:19.073Z,1652399359.073 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-12T23:49:19.073Z,1652399359.073 [Default:CheckIn:D] Running Loop=1
2022-05-12T23:49:19.466Z,1652399359.466 [Default:CheckIn:D] Stopped
2022-05-12T23:49:19.466Z,1652399359.466 [Default:CheckIn:E] Running Loop=1
2022-05-12T23:49:19.870Z,1652399359.870 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 5.725095 min 
2022-05-12T23:49:19.870Z,1652399359.870 [Default:CheckIn:E] Stopped
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn] Stopped
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn](INFO): Running loop #2
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn] Running Loop=2
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-12T23:49:19.887Z,1652399359.887 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-12T23:49:21.892Z,1652399361.892 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234920.00,A,3648.13211,N,12147.21819,W,0.000,237.40,120522,,,D*78
2022-05-12T23:49:21.894Z,1652399361.894 [NAL9602](INFO): GPS fix at 20220512T234920: (36.802202, -121.786970)
2022-05-12T23:49:21.905Z,1652399361.905 [Default:CheckIn:Read_GPS] Stopped
2022-05-12T23:49:21.905Z,1652399361.905 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-12T23:49:29.662Z,1652399369.662 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0007.lzma
2022-05-12T23:49:30.665Z,1652399370.665 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0007.lzma.bak
2022-05-12T23:49:30.665Z,1652399370.665 [DataOverHttps](INFO): SBD MOMSN=16773235
2022-05-12T23:49:30.770Z,1652399370.770 [NAL9602](INFO): SBD MO Status=0, MOMSN=5479, MT Status=0, MTMSN=0
2022-05-12T23:49:30.770Z,1652399370.770 [NAL9602](INFO): No messages in MT queue
2022-05-12T23:49:46.544Z,1652399386.544 [DataOverHttps](INFO): Sending 295 bytes from file Logs/20220512T192924/Express0077.lzma
2022-05-12T23:49:47.545Z,1652399387.545 [DataOverHttps](INFO): Moved sent file to Logs/20220512T192924/Express0077.lzma.bak
2022-05-12T23:49:47.545Z,1652399387.545 [DataOverHttps](INFO): SBD MOMSN=16773240
2022-05-12T23:50:01.484Z,1652399401.484 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-12T23:50:03.530Z,1652399403.530 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220512T192924/Express0080.lzma
2022-05-12T23:50:04.533Z,1652399404.533 [DataOverHttps](INFO): Moved sent file to Logs/20220512T192924/Express0080.lzma.bak
2022-05-12T23:50:04.533Z,1652399404.533 [DataOverHttps](INFO): SBD MOMSN=16773287
2022-05-12T23:50:20.556Z,1652399420.556 [DataOverHttps](INFO): Sending 898 bytes from file Logs/20220512T234059/Express0001.lzma
2022-05-12T23:50:21.557Z,1652399421.557 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0001.lzma.bak
2022-05-12T23:50:21.557Z,1652399421.557 [DataOverHttps](INFO): SBD MOMSN=16773291
2022-05-12T23:50:37.526Z,1652399437.526 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20220512T234059/Express0005.lzma
2022-05-12T23:50:38.529Z,1652399438.529 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0005.lzma.bak
2022-05-12T23:50:38.529Z,1652399438.529 [DataOverHttps](INFO): SBD MOMSN=16773352
2022-05-12T23:50:54.426Z,1652399454.426 [DataOverHttps](INFO): Sending 158 bytes from file Logs/20220512T234059/Express0008.lzma
2022-05-12T23:50:55.429Z,1652399455.429 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0008.lzma.bak
2022-05-12T23:50:55.429Z,1652399455.429 [DataOverHttps](INFO): SBD MOMSN=16773408
2022-05-12T23:50:56.861Z,1652399456.861 [Default:CheckIn:Read_Iridium] Stopped
2022-05-12T23:50:56.861Z,1652399456.861 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-12T23:50:56.861Z,1652399456.861 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-12T23:53:02.883Z,1652399582.883 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-12T23:53:02.883Z,1652399582.883 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000001.5,0000.0,1489.0,000
2022-05-12T23:54:06.714Z,1652399646.714 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-12T23:54:06.714Z,1652399646.714 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000+21.5,0000.0,1489.0,000
2022-05-12T23:55:57.416Z,1652399757.416 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-12T23:55:57.416Z,1652399757.416 [Default:CheckIn:C.Wait] Stopped
2022-05-12T23:55:57.416Z,1652399757.416 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-12T23:55:57.417Z,1652399757.417 [Default:CheckIn:D] Running Loop=1
2022-05-12T23:55:57.828Z,1652399757.828 [Default:CheckIn:D] Stopped
2022-05-12T23:55:57.828Z,1652399757.828 [Default:CheckIn:E] Running Loop=1
2022-05-12T23:55:58.230Z,1652399758.230 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.364456 min 
2022-05-12T23:55:58.230Z,1652399758.230 [Default:CheckIn:E] Stopped
2022-05-12T23:55:58.230Z,1652399758.230 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-12T23:55:58.230Z,1652399758.230 [Default:CheckIn] Stopped
2022-05-12T23:55:58.231Z,1652399758.231 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-12T23:55:58.231Z,1652399758.231 [Default:CheckIn](INFO): Running loop #3
2022-05-12T23:55:58.231Z,1652399758.231 [Default:CheckIn] Running Loop=3
2022-05-12T23:55:58.232Z,1652399758.232 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-12T23:55:58.232Z,1652399758.232 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-12T23:56:00.236Z,1652399760.236 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235558.00,A,3648.13020,N,12147.21988,W,0.194,272.71,120522,,,D*7C
2022-05-12T23:56:00.239Z,1652399760.239 [NAL9602](INFO): GPS fix at 20220512T235558: (36.802170, -121.786998)
2022-05-12T23:56:00.276Z,1652399760.276 [Default:CheckIn:Read_GPS] Stopped
2022-05-12T23:56:00.276Z,1652399760.276 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-12T23:56:08.046Z,1652399768.046 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0010.lzma
2022-05-12T23:56:09.049Z,1652399769.049 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0010.lzma.bak
2022-05-12T23:56:09.049Z,1652399769.049 [DataOverHttps](INFO): SBD MOMSN=16774022
2022-05-12T23:56:24.922Z,1652399784.922 [DataOverHttps](INFO): Sending 250 bytes from file Logs/20220512T234059/Express0011.lzma
2022-05-12T23:56:25.924Z,1652399785.924 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0011.lzma.bak
2022-05-12T23:56:25.925Z,1652399785.925 [DataOverHttps](INFO): SBD MOMSN=16774027
2022-05-12T23:56:27.326Z,1652399787.326 [Default:CheckIn:Read_Iridium] Stopped
2022-05-12T23:56:27.327Z,1652399787.327 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-12T23:56:27.327Z,1652399787.327 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-12T23:57:04.882Z,1652399824.882 [NAL9602](INFO): SBD MO Status=0, MOMSN=5480, MT Status=0, MTMSN=0
2022-05-12T23:57:04.882Z,1652399824.882 [NAL9602](INFO): No messages in MT queue
2022-05-12T23:57:35.588Z,1652399855.588 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-12T23:59:16.993Z,1652399956.993 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-12T23:59:16.993Z,1652399956.993 [DVL_micro](ERROR): Failed to parse:
:BI,+00775,+0004,+00000,I
2022-05-13T00:01:27.901Z,1652400087.901 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:01:27.901Z,1652400087.901 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:01:27.901Z,1652400087.901 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:01:27.901Z,1652400087.901 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:01:28.299Z,1652400088.299 [Default:CheckIn:D] Stopped
2022-05-13T00:01:28.300Z,1652400088.300 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:01:28.703Z,1652400088.703 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.872319 min 
2022-05-13T00:01:28.703Z,1652400088.703 [Default:CheckIn:E] Stopped
2022-05-13T00:01:28.703Z,1652400088.703 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:01:28.703Z,1652400088.703 [Default:CheckIn] Stopped
2022-05-13T00:01:28.704Z,1652400088.704 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:01:28.704Z,1652400088.704 [Default:CheckIn](INFO): Running loop #4
2022-05-13T00:01:28.704Z,1652400088.704 [Default:CheckIn] Running Loop=4
2022-05-13T00:01:28.704Z,1652400088.704 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:01:28.704Z,1652400088.704 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:01:30.708Z,1652400090.708 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000128.00,A,3648.13352,N,12147.22143,W,0.058,322.34,130522,,,D*74
2022-05-13T00:01:30.710Z,1652400090.710 [NAL9602](INFO): GPS fix at 20220513T000128: (36.802225, -121.787024)
2022-05-13T00:01:30.737Z,1652400090.737 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:01:30.737Z,1652400090.737 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:01:38.494Z,1652400098.494 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0013.lzma
2022-05-13T00:01:39.497Z,1652400099.497 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0013.lzma.bak
2022-05-13T00:01:39.497Z,1652400099.497 [DataOverHttps](INFO): SBD MOMSN=16774582
2022-05-13T00:01:51.321Z,1652400111.321 [NAL9602](INFO): SBD MO Status=2, MOMSN=5481, MT Status=2, MTMSN=0
2022-05-13T00:01:51.322Z,1652400111.322 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:01:51.783Z,1652400111.783 [DVL_micro](ERROR): only read 0 of 4 data items
2022-05-13T00:01:51.784Z,1652400111.784 [DVL_micro](ERROR): Failed to parse:
:RD9,+9999.999,+9999.99
2022-05-13T00:01:55.386Z,1652400115.386 [DataOverHttps](INFO): Sending 138 bytes from file Logs/20220512T234059/Express0014.lzma
2022-05-13T00:01:56.389Z,1652400116.389 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0014.lzma.bak
2022-05-13T00:01:56.389Z,1652400116.389 [DataOverHttps](INFO): SBD MOMSN=16774627
2022-05-13T00:01:57.795Z,1652400117.795 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:01:57.795Z,1652400117.795 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:01:57.795Z,1652400117.795 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:02:01.818Z,1652400121.818 [NAL9602](INFO): SBD MO Status=0, MOMSN=5481, MT Status=0, MTMSN=0
2022-05-13T00:02:01.818Z,1652400121.818 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:02:32.535Z,1652400152.535 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:06:47.053Z,1652400407.053 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T00:06:47.053Z,1652400407.053 [DVL_micro](ERROR): Failed to parse:
:BI,+00544,-00012,+01418I
2022-05-13T00:06:58.369Z,1652400418.369 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:06:58.369Z,1652400418.369 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:06:58.370Z,1652400418.370 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:06:58.370Z,1652400418.370 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:06:58.779Z,1652400418.779 [Default:CheckIn:D] Stopped
2022-05-13T00:06:58.779Z,1652400418.779 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:06:59.174Z,1652400419.174 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.380312 min 
2022-05-13T00:06:59.174Z,1652400419.174 [Default:CheckIn:E] Stopped
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn] Stopped
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn](INFO): Running loop #5
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn] Running Loop=5
2022-05-13T00:06:59.175Z,1652400419.175 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:06:59.176Z,1652400419.176 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:07:01.181Z,1652400421.181 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000659.00,A,3648.13223,N,12147.22323,W,0.019,322.34,130522,,,D*73
2022-05-13T00:07:01.183Z,1652400421.183 [NAL9602](INFO): GPS fix at 20220513T000659: (36.802204, -121.787054)
2022-05-13T00:07:01.193Z,1652400421.193 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:07:01.193Z,1652400421.193 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:07:08.998Z,1652400428.998 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0016.lzma
2022-05-13T00:07:10.001Z,1652400430.001 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0016.lzma.bak
2022-05-13T00:07:10.001Z,1652400430.001 [DataOverHttps](INFO): SBD MOMSN=16775190
2022-05-13T00:07:25.886Z,1652400445.886 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220512T234059/Express0017.lzma
2022-05-13T00:07:26.889Z,1652400446.889 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0017.lzma.bak
2022-05-13T00:07:26.889Z,1652400446.889 [DataOverHttps](INFO): SBD MOMSN=16775195
2022-05-13T00:07:27.042Z,1652400447.042 [NAL9602](INFO): SBD MO Status=0, MOMSN=5482, MT Status=0, MTMSN=0
2022-05-13T00:07:27.042Z,1652400447.042 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:07:28.261Z,1652400448.261 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:07:28.261Z,1652400448.261 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:07:28.261Z,1652400448.261 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:07:57.738Z,1652400477.738 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:12:28.848Z,1652400748.848 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:12:28.848Z,1652400748.848 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:12:28.848Z,1652400748.848 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:12:28.848Z,1652400748.848 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:12:29.244Z,1652400749.244 [Default:CheckIn:D] Stopped
2022-05-13T00:12:29.244Z,1652400749.244 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:12:29.646Z,1652400749.646 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.888055 min 
2022-05-13T00:12:29.646Z,1652400749.646 [Default:CheckIn:E] Stopped
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn] Stopped
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn](INFO): Running loop #6
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn] Running Loop=6
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:12:29.647Z,1652400749.647 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:12:31.659Z,1652400751.659 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001229.00,A,3648.13244,N,12147.22357,W,0.000,322.34,130522,,,D*7B
2022-05-13T00:12:31.661Z,1652400751.661 [NAL9602](INFO): GPS fix at 20220513T001229: (36.802207, -121.787059)
2022-05-13T00:12:31.671Z,1652400751.671 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:12:31.672Z,1652400751.672 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:12:38.854Z,1652400758.854 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0019.lzma
2022-05-13T00:12:39.857Z,1652400759.856 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0019.lzma.bak
2022-05-13T00:12:39.857Z,1652400759.857 [DataOverHttps](INFO): SBD MOMSN=16775733
2022-05-13T00:12:48.222Z,1652400768.222 [NAL9602](INFO): SBD MO Status=0, MOMSN=5483, MT Status=0, MTMSN=0
2022-05-13T00:12:48.222Z,1652400768.222 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:12:55.778Z,1652400775.778 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20220512T234059/Express0020.lzma
2022-05-13T00:12:56.781Z,1652400776.781 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0020.lzma.bak
2022-05-13T00:12:56.781Z,1652400776.781 [DataOverHttps](INFO): SBD MOMSN=16775736
2022-05-13T00:12:57.950Z,1652400777.950 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:12:57.950Z,1652400777.950 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:12:57.950Z,1652400777.950 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:13:18.925Z,1652400798.925 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:17:32.643Z,1652401052.643 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T00:17:32.643Z,1652401052.643 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2022-05-13T00:17:58.534Z,1652401078.534 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:17:58.534Z,1652401078.534 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:17:58.534Z,1652401078.534 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:17:58.534Z,1652401078.534 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:17:58.938Z,1652401078.938 [Default:CheckIn:D] Stopped
2022-05-13T00:17:58.938Z,1652401078.938 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:17:59.350Z,1652401079.350 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.382967 min 
2022-05-13T00:17:59.350Z,1652401079.350 [Default:CheckIn:E] Stopped
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn] Stopped
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn](INFO): Running loop #7
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn] Running Loop=7
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:17:59.351Z,1652401079.351 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:18:01.348Z,1652401081.348 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001759.00,A,3648.13193,N,12147.22416,W,0.019,322.34,130522,,,D*7A
2022-05-13T00:18:01.351Z,1652401081.351 [NAL9602](INFO): GPS fix at 20220513T001759: (36.802199, -121.787069)
2022-05-13T00:18:01.361Z,1652401081.361 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:18:01.361Z,1652401081.361 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:18:08.342Z,1652401088.342 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0022.lzma
2022-05-13T00:18:09.345Z,1652401089.345 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0022.lzma.bak
2022-05-13T00:18:09.345Z,1652401089.345 [DataOverHttps](INFO): SBD MOMSN=16775863
2022-05-13T00:18:25.250Z,1652401105.250 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220512T234059/Express0023.lzma
2022-05-13T00:18:25.588Z,1652401105.588 [NAL9602](INFO): SBD MO Status=0, MOMSN=5484, MT Status=0, MTMSN=0
2022-05-13T00:18:25.588Z,1652401105.588 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:18:26.253Z,1652401106.253 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0023.lzma.bak
2022-05-13T00:18:26.253Z,1652401106.253 [DataOverHttps](INFO): SBD MOMSN=16775904
2022-05-13T00:18:27.623Z,1652401107.623 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:18:27.623Z,1652401107.623 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:18:27.624Z,1652401107.624 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:18:56.292Z,1652401136.292 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:23:28.198Z,1652401408.198 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:23:28.199Z,1652401408.199 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:23:28.199Z,1652401408.199 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:23:28.199Z,1652401408.199 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:23:28.612Z,1652401408.612 [Default:CheckIn:D] Stopped
2022-05-13T00:23:28.612Z,1652401408.612 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.877527 min 
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn:E] Stopped
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn] Stopped
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn](INFO): Running loop #8
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn] Running Loop=8
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:23:29.014Z,1652401409.014 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:23:31.029Z,1652401411.029 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002329.00,A,3648.13265,N,12147.22212,W,0.019,322.34,130522,,,D*72
2022-05-13T00:23:31.031Z,1652401411.031 [NAL9602](INFO): GPS fix at 20220513T002329: (36.802211, -121.787035)
2022-05-13T00:23:31.062Z,1652401411.062 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:23:31.062Z,1652401411.062 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:23:38.766Z,1652401418.766 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0025.lzma
2022-05-13T00:23:39.769Z,1652401419.769 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0025.lzma.bak
2022-05-13T00:23:39.769Z,1652401419.769 [DataOverHttps](INFO): SBD MOMSN=16775999
2022-05-13T00:23:55.676Z,1652401435.676 [NAL9602](INFO): SBD MO Status=2, MOMSN=5485, MT Status=2, MTMSN=0
2022-05-13T00:23:55.676Z,1652401435.676 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:23:55.698Z,1652401435.698 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20220512T234059/Express0026.lzma
2022-05-13T00:23:56.701Z,1652401436.701 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0026.lzma.bak
2022-05-13T00:23:56.701Z,1652401436.701 [DataOverHttps](INFO): SBD MOMSN=16776002
2022-05-13T00:23:58.134Z,1652401438.134 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:23:58.134Z,1652401438.134 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:23:58.134Z,1652401438.134 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:24:11.034Z,1652401451.034 [NAL9602](INFO): SBD MO Status=2, MOMSN=5485, MT Status=2, MTMSN=0
2022-05-13T00:24:11.034Z,1652401451.034 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:24:31.230Z,1652401471.230 [NAL9602](INFO): SBD MO Status=0, MOMSN=5485, MT Status=0, MTMSN=0
2022-05-13T00:24:31.230Z,1652401471.230 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:25:01.933Z,1652401501.933 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:25:07.994Z,1652401507.994 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T00:25:08.001Z,1652401508.001 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000001.0,0000.0,1489.0,000
2022-05-13T00:28:00.918Z,1652401680.918 [DVL_micro](ERROR): Failed to parse:
9.99,+99999.99,+9999.99
2022-05-13T00:28:58.698Z,1652401738.698 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:28:58.698Z,1652401738.698 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:28:58.698Z,1652401738.698 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:28:58.698Z,1652401738.698 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:28:59.125Z,1652401739.125 [Default:CheckIn:D] Stopped
2022-05-13T00:28:59.125Z,1652401739.125 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 45.386072 min 
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn:E] Stopped
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn] Stopped
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:28:59.499Z,1652401739.499 [Default:CheckIn](INFO): Running loop #9
2022-05-13T00:28:59.500Z,1652401739.500 [Default:CheckIn] Running Loop=9
2022-05-13T00:28:59.500Z,1652401739.500 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:28:59.500Z,1652401739.500 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:29:01.504Z,1652401741.504 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002859.00,A,3648.13427,N,12147.22137,W,0.078,322.34,130522,,,D*7D
2022-05-13T00:29:01.510Z,1652401741.510 [NAL9602](INFO): GPS fix at 20220513T002859: (36.802238, -121.787023)
2022-05-13T00:29:01.553Z,1652401741.553 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:29:01.553Z,1652401741.553 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:29:09.278Z,1652401749.278 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0028.lzma
2022-05-13T00:29:10.281Z,1652401750.281 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0028.lzma.bak
2022-05-13T00:29:10.281Z,1652401750.281 [DataOverHttps](INFO): SBD MOMSN=16776038
2022-05-13T00:29:26.174Z,1652401766.174 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220512T234059/Express0029.lzma
2022-05-13T00:29:27.177Z,1652401767.177 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0029.lzma.bak
2022-05-13T00:29:27.177Z,1652401767.177 [DataOverHttps](INFO): SBD MOMSN=16776042
2022-05-13T00:29:28.168Z,1652401768.168 [NAL9602](INFO): SBD MO Status=2, MOMSN=5486, MT Status=2, MTMSN=0
2022-05-13T00:29:28.168Z,1652401768.168 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:29:28.607Z,1652401768.607 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:29:28.607Z,1652401768.607 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:29:28.608Z,1652401768.608 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:29:44.330Z,1652401784.330 [NAL9602](INFO): SBD MO Status=2, MOMSN=5486, MT Status=2, MTMSN=0
2022-05-13T00:29:44.331Z,1652401784.331 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:29:54.834Z,1652401794.834 [NAL9602](INFO): SBD MO Status=0, MOMSN=5486, MT Status=0, MTMSN=0
2022-05-13T00:29:54.834Z,1652401794.834 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:30:25.557Z,1652401825.557 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:30:33.227Z,1652401833.227 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T00:30:33.227Z,1652401833.227 [DVL_micro](ERROR): Failed to parse:
:BI,+0390,+00510,+000D,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2022-05-13T00:32:56.079Z,1652401976.079 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:32:58.090Z,1652401978.090 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.252586
2022-05-13T00:33:08.354Z,1652401988.354 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T00:33:08.354Z,1652401988.354 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.8,089.0,000
2022-05-13T00:33:31.227Z,1652402011.227 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:34:06.375Z,1652402046.375 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:34:29.163Z,1652402069.163 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:34:29.163Z,1652402069.163 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:34:29.163Z,1652402069.163 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:34:29.163Z,1652402069.163 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:34:29.566Z,1652402069.566 [Default:CheckIn:D] Stopped
2022-05-13T00:34:29.566Z,1652402069.566 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:34:29.998Z,1652402069.998 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.893433 min 
2022-05-13T00:34:29.998Z,1652402069.998 [Default:CheckIn:E] Stopped
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn] Stopped
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn](INFO): Running loop #10
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn] Running Loop=10
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:34:29.999Z,1652402069.999 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:34:31.982Z,1652402071.982 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,003430.00,A,3648.13171,N,12147.22243,W,0.097,322.34,130522,,,D*78
2022-05-13T00:34:31.985Z,1652402071.985 [NAL9602](INFO): GPS fix at 20220513T003430: (36.802195, -121.787041)
2022-05-13T00:34:31.996Z,1652402071.996 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:34:31.996Z,1652402071.996 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:34:34.806Z,1652402074.806 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T00:34:34.806Z,1652402074.806 [DVL_micro](ERROR): Failed to parse:
:BI,-0189,+01467,+00000,I
2022-05-13T00:34:41.515Z,1652402081.515 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:35:16.655Z,1652402116.655 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:35:21.316Z,1652402121.316 [NAL9602](INFO): SBD MO Status=2, MOMSN=5487, MT Status=2, MTMSN=0
2022-05-13T00:35:21.316Z,1652402121.316 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:35:43.531Z,1652402143.531 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T00:35:43.531Z,1652402143.531 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.8,000.0,000
2022-05-13T00:35:51.795Z,1652402151.795 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:36:26.939Z,1652402186.939 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:37:02.079Z,1652402222.079 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:37:37.219Z,1652402257.219 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:37:41.940Z,1652402261.940 [NAL9602](INFO): SBD MO Status=2, MOMSN=5487, MT Status=2, MTMSN=0
2022-05-13T00:37:41.940Z,1652402261.940 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:38:12.375Z,1652402292.375 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:38:16.285Z,1652402296.285 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T00:38:16.285Z,1652402296.285 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.,1489.0,000
2022-05-13T00:38:40.962Z,1652402320.962 [NAL9602](INFO): SBD MO Status=1, MOMSN=5487, MT Status=0, MTMSN=0
2022-05-13T00:38:41.015Z,1652402321.015 [NAL9602](INFO): Sent 73 bytes from file Logs/20220512T234059/Courier0031.lzma
2022-05-13T00:38:41.015Z,1652402321.015 [NAL9602](INFO): Packets left to send: 0
2022-05-13T00:38:47.515Z,1652402327.515 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:38:53.569Z,1652402333.569 [NAL9602](INFO): SBD MO Status=1, MOMSN=5488, MT Status=0, MTMSN=0
2022-05-13T00:38:53.627Z,1652402333.627 [NAL9602](INFO): Sent 141 bytes from file Logs/20220512T234059/Express0032.lzma
2022-05-13T00:38:53.627Z,1652402333.627 [NAL9602](INFO): Packets left to send: 0
2022-05-13T00:39:06.955Z,1652402346.955 [NAL9602](INFO): SBD MO Status=2, MOMSN=5489, MT Status=2, MTMSN=0
2022-05-13T00:39:06.955Z,1652402346.955 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:39:11.852Z,1652402351.852 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2022-05-13T00:39:15.090Z,1652402355.090 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2022-05-13T00:39:17.149Z,1652402357.149 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0
2022-05-13T00:39:22.659Z,1652402362.659 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:39:25.146Z,1652402365.146 [NAL9602](INFO): SBD MO Status=0, MOMSN=5489, MT Status=0, MTMSN=0
2022-05-13T00:39:25.394Z,1652402365.394 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:39:25.394Z,1652402365.394 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:39:25.395Z,1652402365.395 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:39:55.769Z,1652402395.769 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:39:57.807Z,1652402397.807 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:40:32.947Z,1652402432.947 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:41:08.095Z,1652402468.095 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:41:35.567Z,1652402495.567 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003019
2022-05-13T00:44:19.993Z,1652402659.993 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T00:44:19.993Z,1652402659.993 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+9999.999
2022-05-13T00:44:25.658Z,1652402665.658 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:44:25.658Z,1652402665.658 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:44:25.658Z,1652402665.658 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:44:25.658Z,1652402665.658 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:44:26.072Z,1652402666.072 [Default:CheckIn:D] Stopped
2022-05-13T00:44:26.072Z,1652402666.072 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:44:26.462Z,1652402666.462 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.835189 min 
2022-05-13T00:44:26.462Z,1652402666.462 [Default:CheckIn:E] Stopped
2022-05-13T00:44:26.462Z,1652402666.462 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:44:26.462Z,1652402666.462 [Default:CheckIn] Stopped
2022-05-13T00:44:26.463Z,1652402666.463 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:44:26.463Z,1652402666.463 [Default:CheckIn](INFO): Running loop #11
2022-05-13T00:44:26.463Z,1652402666.463 [Default:CheckIn] Running Loop=11
2022-05-13T00:44:26.463Z,1652402666.463 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:44:26.463Z,1652402666.463 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:44:28.493Z,1652402668.493 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004426.00,A,3648.13450,N,12147.22449,W,0.019,0.00,130522,,,D*70
2022-05-13T00:44:28.496Z,1652402668.496 [NAL9602](INFO): GPS fix at 20220513T004426: (36.802242, -121.787075)
2022-05-13T00:44:28.506Z,1652402668.506 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:44:28.506Z,1652402668.506 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:44:35.826Z,1652402675.826 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0034.lzma
2022-05-13T00:44:36.829Z,1652402676.829 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0034.lzma.bak
2022-05-13T00:44:36.829Z,1652402676.829 [DataOverHttps](INFO): SBD MOMSN=16776144
2022-05-13T00:44:46.250Z,1652402686.250 [NAL9602](INFO): SBD MO Status=2, MOMSN=5490, MT Status=2, MTMSN=0
2022-05-13T00:44:46.250Z,1652402686.250 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T00:44:52.822Z,1652402692.822 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20220512T234059/Express0035.lzma
2022-05-13T00:44:53.825Z,1652402693.825 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0035.lzma.bak
2022-05-13T00:44:53.826Z,1652402693.826 [DataOverHttps](INFO): SBD MOMSN=16776147
2022-05-13T00:44:55.153Z,1652402695.153 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:44:55.153Z,1652402695.153 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:44:55.154Z,1652402695.154 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:46:04.243Z,1652402764.243 [NAL9602](INFO): SBD MO Status=0, MOMSN=5490, MT Status=0, MTMSN=0
2022-05-13T00:46:04.244Z,1652402764.244 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:46:34.948Z,1652402794.948 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:46:36.099Z,1652402796.099 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:46:38.107Z,1652402798.107 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.243267
2022-05-13T00:47:11.239Z,1652402831.239 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:47:46.395Z,1652402866.395 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:48:19.169Z,1652402899.169 [DVL_micro](ERROR): Failed to parse:
61,-00393,+01013,+00000,I
2022-05-13T00:48:21.535Z,1652402901.535 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2022-05-13T00:48:33.999Z,1652402913.999 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003005
2022-05-13T00:49:55.749Z,1652402995.749 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:49:55.749Z,1652402995.749 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:49:55.749Z,1652402995.749 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:49:55.749Z,1652402995.749 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:49:56.171Z,1652402996.171 [Default:CheckIn:D] Stopped
2022-05-13T00:49:56.172Z,1652402996.172 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.336853 min 
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn:E] Stopped
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn] Stopped
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn](INFO): Running loop #12
2022-05-13T00:49:56.554Z,1652402996.554 [Default:CheckIn] Running Loop=12
2022-05-13T00:49:56.576Z,1652402996.576 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:49:56.576Z,1652402996.576 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:49:58.557Z,1652402998.557 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,004956.00,A,3648.13562,N,12147.22397,W,0.058,0.00,130522,,,D*7B
2022-05-13T00:49:58.560Z,1652402998.560 [NAL9602](INFO): GPS fix at 20220513T004956: (36.802260, -121.787066)
2022-05-13T00:49:58.570Z,1652402998.570 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:49:58.570Z,1652402998.570 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:50:05.558Z,1652403005.558 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0037.lzma
2022-05-13T00:50:06.561Z,1652403006.561 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0037.lzma.bak
2022-05-13T00:50:06.561Z,1652403006.561 [DataOverHttps](INFO): SBD MOMSN=16776184
2022-05-13T00:50:21.982Z,1652403021.982 [NAL9602](INFO): SBD MO Status=0, MOMSN=5491, MT Status=0, MTMSN=0
2022-05-13T00:50:21.982Z,1652403021.982 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:50:22.458Z,1652403022.458 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220512T234059/Express0038.lzma
2022-05-13T00:50:23.461Z,1652403023.461 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0038.lzma.bak
2022-05-13T00:50:23.461Z,1652403023.461 [DataOverHttps](INFO): SBD MOMSN=16776191
2022-05-13T00:50:24.827Z,1652403024.827 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:50:24.827Z,1652403024.827 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:50:24.828Z,1652403024.828 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:50:52.681Z,1652403052.681 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T00:53:27.033Z,1652403207.033 [DVL_micro](ERROR): Failed to parse:
:R99,+9999.99,+99999.99
2022-05-13T00:55:25.394Z,1652403325.394 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T00:55:25.394Z,1652403325.394 [Default:CheckIn:C.Wait] Stopped
2022-05-13T00:55:25.394Z,1652403325.394 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T00:55:25.394Z,1652403325.394 [Default:CheckIn:D] Running Loop=1
2022-05-13T00:55:25.801Z,1652403325.801 [Default:CheckIn:D] Stopped
2022-05-13T00:55:25.801Z,1652403325.801 [Default:CheckIn:E] Running Loop=1
2022-05-13T00:55:26.200Z,1652403326.200 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.830672 min 
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn:E] Stopped
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn] Stopped
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn](INFO): Running loop #13
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn] Running Loop=13
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T00:55:26.201Z,1652403326.201 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T00:55:28.215Z,1652403328.215 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,005526.00,A,3648.13291,N,12147.22411,W,0.058,0.00,130522,,,D*73
2022-05-13T00:55:28.217Z,1652403328.217 [NAL9602](INFO): GPS fix at 20220513T005526: (36.802215, -121.787069)
2022-05-13T00:55:28.228Z,1652403328.228 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T00:55:28.228Z,1652403328.228 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T00:55:35.978Z,1652403335.978 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0040.lzma
2022-05-13T00:55:36.981Z,1652403336.981 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0040.lzma.bak
2022-05-13T00:55:36.981Z,1652403336.981 [DataOverHttps](INFO): SBD MOMSN=16776239
2022-05-13T00:55:52.870Z,1652403352.870 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20220512T234059/Express0041.lzma
2022-05-13T00:55:53.873Z,1652403353.873 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0041.lzma.bak
2022-05-13T00:55:53.873Z,1652403353.873 [DataOverHttps](INFO): SBD MOMSN=16776244
2022-05-13T00:55:55.299Z,1652403355.299 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T00:55:55.299Z,1652403355.299 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T00:55:55.300Z,1652403355.300 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T00:58:07.399Z,1652403487.399 [NAL9602](INFO): SBD MO Status=0, MOMSN=5492, MT Status=0, MTMSN=0
2022-05-13T00:58:07.399Z,1652403487.399 [NAL9602](INFO): No messages in MT queue
2022-05-13T00:58:29.609Z,1652403509.609 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T00:58:29.609Z,1652403509.609 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.5,0000.0,1489.0,,+01125,-00132,+01122,+00000,A
2022-05-13T00:58:38.129Z,1652403518.129 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:00:55.870Z,1652403655.870 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:00:55.870Z,1652403655.870 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:00:55.870Z,1652403655.870 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:00:55.870Z,1652403655.870 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:00:56.277Z,1652403656.277 [Default:CheckIn:D] Stopped
2022-05-13T01:00:56.277Z,1652403656.277 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:00:56.676Z,1652403656.676 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.338615 min 
2022-05-13T01:00:56.676Z,1652403656.676 [Default:CheckIn:E] Stopped
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn] Stopped
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn](INFO): Running loop #14
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn] Running Loop=14
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:00:56.677Z,1652403656.677 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:00:58.692Z,1652403658.692 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,010057.00,A,3648.13723,N,12147.22330,W,0.019,0.00,130522,,,D*79
2022-05-13T01:00:58.695Z,1652403658.695 [NAL9602](INFO): GPS fix at 20220513T010057: (36.802287, -121.787055)
2022-05-13T01:00:58.705Z,1652403658.705 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:00:58.705Z,1652403658.705 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:01:00.031Z,1652403660.031 [DVL_micro](ERROR): DVL uart error: serial timeout
2022-05-13T01:01:00.031Z,1652403660.031 [DVL_micro] Communications Fault, FailCount= 1
2022-05-13T01:01:00.031Z,1652403660.031 [DVL_micro](ERROR): Communications Fault
2022-05-13T01:01:00.031Z,1652403660.031 [DVL_micro](ERROR): Failed to parse:
2022-05-13T01:01:00.083Z,1652403660.083 [CBIT](ERROR): Communications Fault in component: DVL_micro
2022-05-13T01:01:00.391Z,1652403660.391 [DVL_micro](INFO): Powering down
2022-05-13T01:01:01.147Z,1652403661.147 [CBIT](INFO): Clearing failed state for component DVL_micro
2022-05-13T01:01:01.147Z,1652403661.147 [DVL_micro] No Fault, FailCount= 1
2022-05-13T01:01:06.430Z,1652403666.430 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0043.lzma
2022-05-13T01:01:07.433Z,1652403667.433 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0043.lzma.bak
2022-05-13T01:01:07.433Z,1652403667.433 [DataOverHttps](INFO): SBD MOMSN=16776263
2022-05-13T01:01:18.096Z,1652403678.096 [NAL9602](INFO): SBD MO Status=0, MOMSN=5493, MT Status=0, MTMSN=0
2022-05-13T01:01:18.096Z,1652403678.096 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:01:23.350Z,1652403683.350 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220512T234059/Express0044.lzma
2022-05-13T01:01:24.353Z,1652403684.353 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0044.lzma.bak
2022-05-13T01:01:24.353Z,1652403684.353 [DataOverHttps](INFO): SBD MOMSN=16776287
2022-05-13T01:01:25.808Z,1652403685.808 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:01:25.808Z,1652403685.808 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:01:25.808Z,1652403685.808 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:01:48.800Z,1652403708.800 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:06:26.362Z,1652403986.362 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:06:26.362Z,1652403986.362 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:06:26.362Z,1652403986.362 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:06:26.362Z,1652403986.362 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:06:26.788Z,1652403986.788 [Default:CheckIn:D] Stopped
2022-05-13T01:06:26.788Z,1652403986.788 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:06:27.170Z,1652403987.170 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 82.847127 min 
2022-05-13T01:06:27.170Z,1652403987.170 [Default:CheckIn:E] Stopped
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn] Stopped
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn](INFO): Running loop #15
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn] Running Loop=15
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:06:27.187Z,1652403987.187 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:06:29.182Z,1652403989.182 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,010627.00,A,3648.13345,N,12147.22347,W,0.039,0.00,130522,,,D*7E
2022-05-13T01:06:29.184Z,1652403989.184 [NAL9602](INFO): GPS fix at 20220513T010627: (36.802224, -121.787058)
2022-05-13T01:06:29.195Z,1652403989.195 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:06:29.195Z,1652403989.195 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:06:37.150Z,1652403997.150 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0046.lzma
2022-05-13T01:06:38.153Z,1652403998.153 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0046.lzma.bak
2022-05-13T01:06:38.153Z,1652403998.153 [DataOverHttps](INFO): SBD MOMSN=16776302
2022-05-13T01:06:54.190Z,1652404014.190 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20220512T234059/Express0047.lzma
2022-05-13T01:06:55.193Z,1652404015.193 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0047.lzma.bak
2022-05-13T01:06:55.193Z,1652404015.193 [DataOverHttps](INFO): SBD MOMSN=16776313
2022-05-13T01:06:56.650Z,1652404016.650 [NAL9602](INFO): SBD MO Status=2, MOMSN=5494, MT Status=2, MTMSN=0
2022-05-13T01:06:56.650Z,1652404016.650 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:06:56.688Z,1652404016.688 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:06:56.688Z,1652404016.688 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:06:56.688Z,1652404016.688 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:07:12.818Z,1652404032.818 [DVL_micro](ERROR): Failed to parse:
:BI,+02171,+00149,+01418,+00000,I
2022-05-13T01:09:40.289Z,1652404180.289 [DVL_micro](ERROR): Failed to parse:
:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00
2022-05-13T01:10:20.674Z,1652404220.674 [NAL9602](INFO): SBD MO Status=2, MOMSN=5494, MT Status=2, MTMSN=0
2022-05-13T01:10:20.674Z,1652404220.674 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:10:46.934Z,1652404246.934 [NAL9602](INFO): SBD MO Status=0, MOMSN=5494, MT Status=0, MTMSN=0
2022-05-13T01:10:46.934Z,1652404246.934 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:11:17.636Z,1652404277.636 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:11:57.251Z,1652404317.251 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:11:57.251Z,1652404317.251 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:11:57.251Z,1652404317.251 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:11:57.251Z,1652404317.251 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:11:57.648Z,1652404317.648 [Default:CheckIn:D] Stopped
2022-05-13T01:11:57.648Z,1652404317.648 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:11:58.046Z,1652404318.046 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 88.361458 min 
2022-05-13T01:11:58.046Z,1652404318.046 [Default:CheckIn:E] Stopped
2022-05-13T01:11:58.046Z,1652404318.046 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:11:58.046Z,1652404318.046 [Default:CheckIn] Stopped
2022-05-13T01:11:58.047Z,1652404318.047 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:11:58.047Z,1652404318.047 [Default:CheckIn](INFO): Running loop #16
2022-05-13T01:11:58.047Z,1652404318.047 [Default:CheckIn] Running Loop=16
2022-05-13T01:11:58.047Z,1652404318.047 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:11:58.047Z,1652404318.047 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:12:00.074Z,1652404320.074 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,011158.00,A,3648.13360,N,12147.22481,W,0.019,0.00,130522,,,D*78
2022-05-13T01:12:00.076Z,1652404320.076 [NAL9602](INFO): GPS fix at 20220513T011158: (36.802227, -121.787080)
2022-05-13T01:12:00.087Z,1652404320.087 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:12:00.087Z,1652404320.087 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:12:07.810Z,1652404327.810 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0049.lzma
2022-05-13T01:12:08.813Z,1652404328.813 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0049.lzma.bak
2022-05-13T01:12:08.813Z,1652404328.813 [DataOverHttps](INFO): SBD MOMSN=16776339
2022-05-13T01:12:18.640Z,1652404338.640 [NAL9602](INFO): SBD MO Status=0, MOMSN=5495, MT Status=0, MTMSN=0
2022-05-13T01:12:18.640Z,1652404338.640 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:12:24.747Z,1652404344.747 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20220512T234059/Express0050.lzma
2022-05-13T01:12:25.749Z,1652404345.749 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0050.lzma.bak
2022-05-13T01:12:25.749Z,1652404345.749 [DataOverHttps](INFO): SBD MOMSN=16776346
2022-05-13T01:12:27.151Z,1652404347.151 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:12:27.151Z,1652404347.151 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:12:27.151Z,1652404347.151 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:12:49.342Z,1652404369.342 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:17:10.733Z,1652404630.733 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T01:17:10.733Z,1652404630.733 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.2,0000.0,10
2022-05-13T01:17:27.714Z,1652404647.714 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:17:27.714Z,1652404647.714 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:17:27.715Z,1652404647.715 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:17:27.715Z,1652404647.715 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:17:28.112Z,1652404648.112 [Default:CheckIn:D] Stopped
2022-05-13T01:17:28.112Z,1652404648.112 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:17:28.584Z,1652404648.584 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 93.869198 min 
2022-05-13T01:17:28.584Z,1652404648.584 [Default:CheckIn:E] Stopped
2022-05-13T01:17:28.584Z,1652404648.584 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:17:28.584Z,1652404648.584 [Default:CheckIn] Stopped
2022-05-13T01:17:28.585Z,1652404648.585 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:17:28.585Z,1652404648.585 [Default:CheckIn](INFO): Running loop #17
2022-05-13T01:17:28.585Z,1652404648.585 [Default:CheckIn] Running Loop=17
2022-05-13T01:17:28.585Z,1652404648.585 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:17:28.585Z,1652404648.585 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:17:30.534Z,1652404650.534 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,011728.00,A,3648.13414,N,12147.21908,W,0.039,0.00,130522,,,D*70
2022-05-13T01:17:30.547Z,1652404650.547 [NAL9602](INFO): GPS fix at 20220513T011728: (36.802236, -121.786985)
2022-05-13T01:17:30.558Z,1652404650.558 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:17:30.558Z,1652404650.558 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:17:38.374Z,1652404658.374 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0052.lzma
2022-05-13T01:17:39.377Z,1652404659.377 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0052.lzma.bak
2022-05-13T01:17:39.377Z,1652404659.377 [DataOverHttps](INFO): SBD MOMSN=16776375
2022-05-13T01:17:55.254Z,1652404675.254 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220512T234059/Express0053.lzma
2022-05-13T01:17:56.262Z,1652404676.262 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0053.lzma.bak
2022-05-13T01:17:56.263Z,1652404676.263 [DataOverHttps](INFO): SBD MOMSN=16776381
2022-05-13T01:17:57.618Z,1652404677.618 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:17:57.618Z,1652404677.618 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:17:57.618Z,1652404677.618 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:18:02.450Z,1652404682.450 [NAL9602](INFO): SBD MO Status=2, MOMSN=5496, MT Status=2, MTMSN=0
2022-05-13T01:18:02.450Z,1652404682.450 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:18:19.819Z,1652404699.819 [NAL9602](INFO): SBD MO Status=2, MOMSN=5496, MT Status=2, MTMSN=0
2022-05-13T01:18:19.819Z,1652404699.819 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:18:54.566Z,1652404734.566 [NAL9602](INFO): SBD MO Status=0, MOMSN=5496, MT Status=0, MTMSN=0
2022-05-13T01:18:54.566Z,1652404734.566 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:19:25.264Z,1652404765.264 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:22:58.196Z,1652404978.196 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:22:58.196Z,1652404978.196 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:22:58.196Z,1652404978.196 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:22:58.196Z,1652404978.196 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:22:58.626Z,1652404978.626 [Default:CheckIn:D] Stopped
2022-05-13T01:22:58.626Z,1652404978.626 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:22:59.039Z,1652404979.039 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 99.377759 min 
2022-05-13T01:22:59.039Z,1652404979.039 [Default:CheckIn:E] Stopped
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn] Stopped
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn](INFO): Running loop #18
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn] Running Loop=18
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:22:59.040Z,1652404979.040 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:23:01.006Z,1652404981.006 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012259.00,A,3648.13416,N,12147.22246,W,0.039,0.00,130522,,,D*70
2022-05-13T01:23:01.009Z,1652404981.009 [NAL9602](INFO): GPS fix at 20220513T012259: (36.802236, -121.787041)
2022-05-13T01:23:01.040Z,1652404981.040 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:23:01.040Z,1652404981.040 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:23:08.774Z,1652404988.774 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0055.lzma
2022-05-13T01:23:09.777Z,1652404989.777 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0055.lzma.bak
2022-05-13T01:23:09.777Z,1652404989.777 [DataOverHttps](INFO): SBD MOMSN=16776416
2022-05-13T01:23:25.678Z,1652405005.678 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20220512T234059/Express0056.lzma
2022-05-13T01:23:26.681Z,1652405006.681 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0056.lzma.bak
2022-05-13T01:23:26.681Z,1652405006.681 [DataOverHttps](INFO): SBD MOMSN=16776422
2022-05-13T01:23:28.075Z,1652405008.075 [NAL9602](INFO): SBD MO Status=2, MOMSN=5497, MT Status=2, MTMSN=0
2022-05-13T01:23:28.075Z,1652405008.075 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:23:28.092Z,1652405008.092 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:23:28.092Z,1652405008.092 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:23:28.092Z,1652405008.092 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:25:03.014Z,1652405103.014 [NAL9602](INFO): SBD MO Status=0, MOMSN=5497, MT Status=0, MTMSN=0
2022-05-13T01:25:03.014Z,1652405103.014 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:25:33.720Z,1652405133.720 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:28:28.666Z,1652405308.666 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:28:28.666Z,1652405308.666 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:28:28.666Z,1652405308.666 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:28:28.666Z,1652405308.666 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:28:29.070Z,1652405309.070 [Default:CheckIn:D] Stopped
2022-05-13T01:28:29.070Z,1652405309.070 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:28:29.481Z,1652405309.481 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 104.885164 min 
2022-05-13T01:28:29.481Z,1652405309.481 [Default:CheckIn:E] Stopped
2022-05-13T01:28:29.481Z,1652405309.481 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn] Stopped
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn](INFO): Running loop #19
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn] Running Loop=19
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:28:29.482Z,1652405309.482 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:28:31.485Z,1652405311.485 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,012829.00,A,3648.13277,N,12147.22334,W,0.000,0.00,130522,,,D*72
2022-05-13T01:28:31.488Z,1652405311.488 [NAL9602](INFO): GPS fix at 20220513T012829: (36.802213, -121.787056)
2022-05-13T01:28:31.523Z,1652405311.523 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:28:31.523Z,1652405311.523 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:28:39.286Z,1652405319.286 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0058.lzma
2022-05-13T01:28:40.289Z,1652405320.289 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0058.lzma.bak
2022-05-13T01:28:40.289Z,1652405320.289 [DataOverHttps](INFO): SBD MOMSN=16776455
2022-05-13T01:28:56.146Z,1652405336.146 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220512T234059/Express0059.lzma
2022-05-13T01:28:57.149Z,1652405337.149 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0059.lzma.bak
2022-05-13T01:28:57.149Z,1652405337.149 [DataOverHttps](INFO): SBD MOMSN=16776461
2022-05-13T01:28:58.563Z,1652405338.563 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:28:58.563Z,1652405338.563 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:28:58.563Z,1652405338.563 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:28:59.350Z,1652405339.350 [NAL9602](INFO): SBD MO Status=0, MOMSN=5498, MT Status=0, MTMSN=0
2022-05-13T01:28:59.350Z,1652405339.350 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:29:30.050Z,1652405370.050 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:29:51.472Z,1652405391.472 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+99999.99,+9999.99
2022-05-13T01:32:21.374Z,1652405541.374 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-05-13T01:32:21.374Z,1652405541.374 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+19.9,00000,000
2022-05-13T01:33:59.130Z,1652405639.130 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:33:59.130Z,1652405639.130 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:33:59.130Z,1652405639.130 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:33:59.130Z,1652405639.130 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:33:59.542Z,1652405639.542 [Default:CheckIn:D] Stopped
2022-05-13T01:33:59.542Z,1652405639.542 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:33:59.938Z,1652405639.938 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.393034 min 
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn:E] Stopped
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn] Stopped
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn](INFO): Running loop #20
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn] Running Loop=20
2022-05-13T01:33:59.939Z,1652405639.939 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:33:59.940Z,1652405639.940 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:34:01.945Z,1652405641.945 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013400.00,A,3648.13558,N,12147.22361,W,3.654,297.34,130522,,,D*71
2022-05-13T01:34:01.947Z,1652405641.947 [NAL9602](INFO): GPS fix at 20220513T013400: (36.802260, -121.787060)
2022-05-13T01:34:01.958Z,1652405641.958 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:34:01.958Z,1652405641.958 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:34:09.794Z,1652405649.794 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220512T234059/Courier0061.lzma
2022-05-13T01:34:10.797Z,1652405650.797 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0061.lzma.bak
2022-05-13T01:34:10.797Z,1652405650.797 [DataOverHttps](INFO): SBD MOMSN=16776494
2022-05-13T01:34:21.358Z,1652405661.358 [NAL9602](INFO): SBD MO Status=2, MOMSN=5499, MT Status=2, MTMSN=0
2022-05-13T01:34:21.359Z,1652405661.359 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:34:26.692Z,1652405666.692 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20220512T234059/Express0062.lzma
2022-05-13T01:34:27.693Z,1652405667.693 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0062.lzma.bak
2022-05-13T01:34:27.693Z,1652405667.693 [DataOverHttps](INFO): SBD MOMSN=16776499
2022-05-13T01:34:29.030Z,1652405669.030 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:34:29.031Z,1652405669.031 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:34:29.031Z,1652405669.031 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:34:53.666Z,1652405693.666 [NAL9602](INFO): SBD MO Status=2, MOMSN=5499, MT Status=2, MTMSN=0
2022-05-13T01:34:53.666Z,1652405693.666 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2022-05-13T01:35:02.949Z,1652405702.949 [NAL9602](INFO): SBD MO Status=0, MOMSN=5499, MT Status=0, MTMSN=0
2022-05-13T01:35:02.949Z,1652405702.949 [NAL9602](INFO): No messages in MT queue
2022-05-13T01:35:33.660Z,1652405733.660 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:37:16.697Z,1652405836.697 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T01:37:16.697Z,1652405836.697 [DVL_micro](ERROR): Failed to parse:
:BI,+00178,-00596,+00704,+000D,+0000000000000.00,+000,9999.99,:RD,+9999.99,+9999.999,+9999.99
2022-05-13T01:39:29.606Z,1652405969.606 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:39:29.606Z,1652405969.606 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:39:29.606Z,1652405969.606 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:39:29.606Z,1652405969.606 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:39:30.010Z,1652405970.010 [Default:CheckIn:D] Stopped
2022-05-13T01:39:30.010Z,1652405970.010 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 115.900822 min 
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn:E] Stopped
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn] Stopped
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn](INFO): Running loop #21
2022-05-13T01:39:30.420Z,1652405970.420 [Default:CheckIn] Running Loop=21
2022-05-13T01:39:30.421Z,1652405970.421 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:39:30.421Z,1652405970.421 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:39:32.420Z,1652405972.420 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,013930.00,A,3648.17311,N,12147.28052,W,2.488,323.59,130522,,,D*7E
2022-05-13T01:39:32.422Z,1652405972.422 [NAL9602](INFO): GPS fix at 20220513T013930: (36.802885, -121.788009)
2022-05-13T01:39:32.446Z,1652405972.446 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:39:32.446Z,1652405972.446 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:39:40.514Z,1652405980.514 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0064.lzma
2022-05-13T01:39:41.517Z,1652405981.517 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0064.lzma.bak
2022-05-13T01:39:41.517Z,1652405981.517 [DataOverHttps](INFO): SBD MOMSN=16776545
2022-05-13T01:39:49.402Z,1652405989.402 [DVL_micro](ERROR): Failed to parse:
:SA,-01.25,+00.03,250.0
2022-05-13T01:39:57.454Z,1652405997.454 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220512T234059/Express0065.lzma
2022-05-13T01:39:58.457Z,1652405998.457 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0065.lzma.bak
2022-05-13T01:39:58.457Z,1652405998.457 [DataOverHttps](INFO): SBD MOMSN=16776548
2022-05-13T01:39:59.919Z,1652405999.919 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:39:59.919Z,1652405999.919 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:39:59.920Z,1652405999.920 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:44:34.217Z,1652406274.217 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-05-13T01:45:00.487Z,1652406300.487 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-05-13T01:45:00.487Z,1652406300.487 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:45:00.488Z,1652406300.488 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:45:00.488Z,1652406300.488 [Default:CheckIn:D] Running Loop=1
2022-05-13T01:45:00.890Z,1652406300.890 [Default:CheckIn:D] Stopped
2022-05-13T01:45:00.890Z,1652406300.890 [Default:CheckIn:E] Running Loop=1
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.415495 min 
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn:E] Stopped
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn] Stopped
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn](INFO): Running loop #22
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn] Running Loop=22
2022-05-13T01:45:01.304Z,1652406301.304 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-05-13T01:45:01.305Z,1652406301.305 [Default:CheckIn:Read_GPS] Running Loop=1
2022-05-13T01:45:03.300Z,1652406303.300 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,014501.00,A,3648.15546,N,12147.27686,W,0.525,151.17,130522,,,A*7D
2022-05-13T01:45:03.303Z,1652406303.303 [NAL9602](INFO): GPS fix at 20220513T014501: (36.802591, -121.787948)
2022-05-13T01:45:03.334Z,1652406303.334 [Default:CheckIn:Read_GPS] Stopped
2022-05-13T01:45:03.334Z,1652406303.334 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-05-13T01:45:10.502Z,1652406310.502 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220512T234059/Courier0067.lzma
2022-05-13T01:45:11.505Z,1652406311.505 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Courier0067.lzma.bak
2022-05-13T01:45:11.505Z,1652406311.505 [DataOverHttps](INFO): SBD MOMSN=16776587
2022-05-13T01:45:27.451Z,1652406327.451 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20220512T234059/Express0068.lzma
2022-05-13T01:45:28.455Z,1652406328.455 [DataOverHttps](INFO): Moved sent file to Logs/20220512T234059/Express0068.lzma.bak
2022-05-13T01:45:28.455Z,1652406328.455 [DataOverHttps](INFO): SBD MOMSN=16776592
2022-05-13T01:45:29.983Z,1652406329.983 [Default:CheckIn:Read_Iridium] Stopped
2022-05-13T01:45:29.983Z,1652406329.983 [Default:CheckIn:C.Wait] Running Loop=1
2022-05-13T01:45:29.983Z,1652406329.983 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-05-13T01:45:35.631Z,1652406335.631 [NAL9602](INFO): Not Powering down - fast GPS
2022-05-13T01:47:07.335Z,1652406427.335 [DVL_micro](ERROR): only read 2 of 4 data items
2022-05-13T01:47:07.335Z,1652406427.335 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.999
2022-05-13T01:48:16.021Z,1652406496.021 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T01:48:16.021Z,1652406496.021 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.999,+9999.99,+9999.99
2022-05-13T01:49:39.657Z,1652406579.657 [DVL_micro](ERROR): only read 3 of 4 data items
2022-05-13T01:49:39.658Z,1652406579.658 [DVL_micro](ERROR): Failed to parse:
:BI,+00066,-00217,+00702,+000D,+0000000000000.00,+00000000.00,9999.99,000.00
2022-05-13T01:49:53.596Z,1652406593.596 [CommandExec](IMPORTANT): got command quit
2022-05-13T01:49:54.599Z,1652406594.599 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2022-05-13T01:49:54.599Z,1652406594.599 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:54.599Z,1652406594.599 [CommandExec](INFO): Uninitializing the command executive.
2022-05-13T01:49:54.599Z,1652406594.599 [CommandExec](INFO): Uninitializing the command scheduler.
2022-05-13T01:49:54.600Z,1652406594.600 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:54.763Z,1652406594.763 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2022-05-13T01:49:54.763Z,1652406594.763 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2022-05-13T01:49:54.763Z,1652406594.763 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:54.764Z,1652406594.764 [NavChartDb](INFO): Join timeout helper Thread ID is 967
2022-05-13T01:49:55.091Z,1652406595.091 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:55.091Z,1652406595.091 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:55.095Z,1652406595.095 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2022-05-13T01:49:55.095Z,1652406595.095 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:55.095Z,1652406595.095 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 968
2022-05-13T01:49:55.231Z,1652406595.231 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:55.231Z,1652406595.231 [WetLabsBB2FL](INFO): Powering down
2022-05-13T01:49:55.232Z,1652406595.232 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:55.243Z,1652406595.243 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2022-05-13T01:49:55.243Z,1652406595.243 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:55.243Z,1652406595.243 [CTD_Seabird](INFO): Join timeout helper Thread ID is 969
2022-05-13T01:49:56.203Z,1652406596.203 [CTD_Seabird](INFO): Powering down
2022-05-13T01:49:56.215Z,1652406596.215 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:56.215Z,1652406596.215 [CTD_Seabird](INFO): Powering down
2022-05-13T01:49:56.227Z,1652406596.227 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.235Z,1652406596.235 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2022-05-13T01:49:56.235Z,1652406596.235 [DAT ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.236Z,1652406596.236 [DAT](INFO): Join timeout helper Thread ID is 970
2022-05-13T01:49:56.467Z,1652406596.467 [DAT](INFO): Powering down
2022-05-13T01:49:56.543Z,1652406596.543 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:56.544Z,1652406596.544 [DAT](INFO): Powering down
2022-05-13T01:49:56.544Z,1652406596.544 [DAT ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.559Z,1652406596.559 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2022-05-13T01:49:56.559Z,1652406596.559 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.559Z,1652406596.559 [Radio_Surface](INFO): Join timeout helper Thread ID is 971
2022-05-13T01:49:56.751Z,1652406596.751 [Radio_Surface](INFO): Powering down
2022-05-13T01:49:56.752Z,1652406596.752 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:56.752Z,1652406596.752 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.764Z,1652406596.764 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2022-05-13T01:49:56.764Z,1652406596.764 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:56.764Z,1652406596.764 [Onboard](INFO): Join timeout helper Thread ID is 972
2022-05-13T01:49:57.011Z,1652406597.011 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2022-05-13T01:49:57.095Z,1652406597.095 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:57.095Z,1652406597.095 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:57.103Z,1652406597.103 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2022-05-13T01:49:57.104Z,1652406597.104 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:57.104Z,1652406597.104 [DataOverHttps](INFO): Join timeout helper Thread ID is 973
2022-05-13T01:49:58.015Z,1652406598.015 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:58.015Z,1652406598.015 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.020Z,1652406598.020 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2022-05-13T01:49:58.020Z,1652406598.020 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.020Z,1652406598.020 [BackseatComponent](INFO): Join timeout helper Thread ID is 974
2022-05-13T01:49:58.099Z,1652406598.099 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:58.099Z,1652406598.099 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.104Z,1652406598.104 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2022-05-13T01:49:58.104Z,1652406598.104 [logger ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.104Z,1652406598.104 [logger](INFO): Join timeout helper Thread ID is 975
2022-05-13T01:49:58.143Z,1652406598.143 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:58.143Z,1652406598.143 [logger ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.163Z,1652406598.163 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2022-05-13T01:49:58.164Z,1652406598.164 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.164Z,1652406598.164 [CommandLine](INFO): Join timeout helper Thread ID is 976
2022-05-13T01:49:58.219Z,1652406598.219 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:58.219Z,1652406598.219 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.228Z,1652406598.228 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2022-05-13T01:49:58.228Z,1652406598.228 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.228Z,1652406598.228 [CommandExec](INFO): Join timeout helper Thread ID is 977
2022-05-13T01:49:58.232Z,1652406598.232 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2022-05-13T01:49:58.232Z,1652406598.232 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.232Z,1652406598.232 [controlThread](INFO): Join timeout helper Thread ID is 978
2022-05-13T01:49:58.252Z,1652406598.252 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2022-05-13T01:49:58.253Z,1652406598.253 [controlThread](DEBUG): Uninitializing ControlThread
2022-05-13T01:49:58.253Z,1652406598.253 [AHRS_M2](INFO): Powering down
2022-05-13T01:49:58.395Z,1652406598.395 [DVL_micro](INFO): Powering down
2022-05-13T01:49:58.396Z,1652406598.396 [NAL9602](INFO): Powering down
2022-05-13T01:49:58.399Z,1652406598.399 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2022-05-13T01:49:58.400Z,1652406598.400 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2022-05-13T01:49:58.400Z,1652406598.400 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2022-05-13T01:49:58.401Z,1652406598.401 [MissionManager](INFO): Uninitializing Mission Default
2022-05-13T01:49:58.401Z,1652406598.401 [Default] Stopped
2022-05-13T01:49:58.401Z,1652406598.401 [Default](DEBUG): Aggregate::uninitialize Default
2022-05-13T01:49:58.401Z,1652406598.401 [Default:B.GoToSurface] Stopped
2022-05-13T01:49:58.401Z,1652406598.401 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-05-13T01:49:58.401Z,1652406598.401 [Default:CheckIn] Stopped
2022-05-13T01:49:58.401Z,1652406598.401 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-05-13T01:49:58.401Z,1652406598.401 [Default:CheckIn:C.Wait] Stopped
2022-05-13T01:49:58.401Z,1652406598.401 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-05-13T01:49:58.404Z,1652406598.404 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2022-05-13T01:49:58.404Z,1652406598.404 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2022-05-13T01:49:58.405Z,1652406598.405 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2022-05-13T01:49:58.405Z,1652406598.405 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2022-05-13T01:49:58.405Z,1652406598.405 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2022-05-13T01:49:58.405Z,1652406598.405 [BuoyancyServo](INFO): Powering down
2022-05-13T01:49:58.419Z,1652406598.419 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2022-05-13T01:49:58.419Z,1652406598.419 [ElevatorServo](INFO): Powering down
2022-05-13T01:49:58.420Z,1652406598.420 [MassServo](DEBUG): Uninitialize Mass Servo.
2022-05-13T01:49:58.420Z,1652406598.420 [MassServo](INFO): Powering down
2022-05-13T01:49:58.421Z,1652406598.421 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-05-13T01:49:58.421Z,1652406598.421 [RudderServo](INFO): Powering down
2022-05-13T01:49:58.422Z,1652406598.422 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2022-05-13T01:49:58.422Z,1652406598.422 [ThrusterHE](INFO): Powering down
2022-05-13T01:49:58.423Z,1652406598.423 [SBIT](DEBUG): Uninitialize SBIT Component.
2022-05-13T01:49:58.423Z,1652406598.423 [IBIT](DEBUG): Uninitialize IBIT Component.
2022-05-13T01:49:58.423Z,1652406598.423 [CBIT](DEBUG): Uninitialize CBIT Component.
2022-05-13T01:49:58.423Z,1652406598.423 [CBIT](DEBUG): Powering off loads.
2022-05-13T01:49:58.435Z,1652406598.435 [CBIT](DEBUG): Disabling WDT.
2022-05-13T01:49:58.447Z,1652406598.447 [CBIT](DEBUG): Opening all GF detection circuits.
2022-05-13T01:49:58.448Z,1652406598.448 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.489Z,1652406598.489 [DAT ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.495Z,1652406598.495 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.496Z,1652406598.496 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.504Z,1652406598.504 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.510Z,1652406598.510 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.559Z,1652406598.559 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.564Z,1652406598.564 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.585Z,1652406598.585 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-05-13T01:49:58.657Z,1652406598.657 [logger ThreadHandler](INFO): Thread cancelled.