2021-07-22T20:54:54.199Z,1626987294.199 [Supervisor](DEBUG): Initializing supervisor.
2021-07-22T20:54:54.203Z,1626987294.203 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-07-22T20:54:54.204Z,1626987294.204 [SyncHandler](INFO): Protected caller Thread ID is 7407
2021-07-22T20:54:54.204Z,1626987294.204 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-07-22T20:54:54.205Z,1626987294.205 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-07-22T20:54:54.206Z,1626987294.206 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7408
2021-07-22T20:54:54.210Z,1626987294.210 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-07-22T20:54:54.231Z,1626987294.231 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-07-22T20:54:54.232Z,1626987294.232 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-07-22T20:54:54.232Z,1626987294.232 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7409
2021-07-22T20:54:54.235Z,1626987294.235 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-07-22T20:54:54.236Z,1626987294.236 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-07-22T20:54:54.236Z,1626987294.236 [logger ThreadHandler](INFO): Protected caller Thread ID is 7410
2021-07-22T20:54:54.240Z,1626987294.240 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-07-22T20:54:54.241Z,1626987294.241 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-07-22T20:54:54.242Z,1626987294.242 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-07-22T20:54:54.685Z,1626987294.685 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-07-22T20:54:54.686Z,1626987294.686 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-07-22T20:54:54.910Z,1626987294.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-07-22T20:54:54.911Z,1626987294.911 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-07-22T20:54:55.112Z,1626987295.112 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-07-22T20:54:55.112Z,1626987295.112 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-07-22T20:54:55.223Z,1626987295.223 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-07-22T20:54:55.223Z,1626987295.223 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-07-22T20:54:55.614Z,1626987295.614 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-07-22T20:54:55.615Z,1626987295.615 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-07-22T20:54:55.969Z,1626987295.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-07-22T20:54:55.970Z,1626987295.970 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-07-22T20:54:56.069Z,1626987296.069 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-07-22T20:54:56.070Z,1626987296.070 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-07-22T20:54:56.226Z,1626987296.226 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-07-22T20:54:56.226Z,1626987296.226 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-07-22T20:54:56.795Z,1626987296.795 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-07-22T20:54:56.795Z,1626987296.795 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-07-22T20:54:57.266Z,1626987297.266 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-07-22T20:54:57.267Z,1626987297.267 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-07-22T20:54:57.463Z,1626987297.463 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-07-22T20:54:57.880Z,1626987297.880 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-07-22T20:54:57.881Z,1626987297.881 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-07-22T20:54:58.146Z,1626987298.146 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-07-22T20:54:58.147Z,1626987298.147 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-07-22T20:54:58.855Z,1626987298.855 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-07-22T20:54:58.856Z,1626987298.856 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-07-22T20:54:58.938Z,1626987298.938 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-07-22T20:54:59.200Z,1626987299.200 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-07-22T20:54:59.202Z,1626987299.202 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/
2021-07-22T20:54:59.203Z,1626987299.203 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/vehicle.cfg
2021-07-22T20:54:59.382Z,1626987299.382 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/logger.cfg
2021-07-22T20:54:59.479Z,1626987299.479 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Servo.cfg
2021-07-22T20:54:59.593Z,1626987299.593 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Control.cfg
2021-07-22T20:54:59.696Z,1626987299.696 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/secure.cfg
2021-07-22T20:54:59.781Z,1626987299.781 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Simulator.cfg
2021-07-22T20:54:59.869Z,1626987299.869 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Science.cfg
2021-07-22T20:54:59.986Z,1626987299.986 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/BIT.cfg
2021-07-22T20:55:00.087Z,1626987300.087 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Sensor.cfg
2021-07-22T20:55:00.236Z,1626987300.236 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Battery.cfg
2021-07-22T20:55:00.510Z,1626987300.510 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-07-22T20:55:00.511Z,1626987300.511 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Navigation.cfg
2021-07-22T20:55:00.607Z,1626987300.607 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-07-22T20:55:00.621Z,1626987300.621 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-07-22T20:55:00.991Z,1626987300.991 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-07-22T20:55:00.991Z,1626987300.991 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-07-22T20:55:01.078Z,1626987301.078 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-07-22T20:55:01.078Z,1626987301.078 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-07-22T20:55:01.114Z,1626987301.114 [DeadReckonUsingSpeedCalculator] Loaded
2021-07-22T20:55:01.115Z,1626987301.115 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2021-07-22T20:55:01.128Z,1626987301.128 [NavChart] Loaded
2021-07-22T20:55:01.128Z,1626987301.128 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-07-22T20:55:01.134Z,1626987301.134 [UniversalFixResidualReporter] Loaded
2021-07-22T20:55:01.135Z,1626987301.135 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-07-22T20:55:01.135Z,1626987301.135 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-07-22T20:55:01.136Z,1626987301.136 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-07-22T20:55:01.147Z,1626987301.147 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-07-22T20:55:01.148Z,1626987301.148 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-07-22T20:55:01.337Z,1626987301.337 [ESPComponent] Loaded
2021-07-22T20:55:01.337Z,1626987301.337 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2021-07-22T20:55:01.338Z,1626987301.338 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-07-22T20:55:01.339Z,1626987301.339 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-07-22T20:55:01.398Z,1626987301.398 [VerticalControl](DEBUG): Construct VerticalControl.
2021-07-22T20:55:01.460Z,1626987301.460 [VerticalControl] Loaded
2021-07-22T20:55:01.461Z,1626987301.461 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-07-22T20:55:01.463Z,1626987301.463 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-07-22T20:55:01.503Z,1626987301.503 [HorizontalControl] Loaded
2021-07-22T20:55:01.503Z,1626987301.503 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-07-22T20:55:01.506Z,1626987301.506 [SpeedControl](DEBUG): Construct SpeedControl.
2021-07-22T20:55:01.509Z,1626987301.509 [SpeedControl] Loaded
2021-07-22T20:55:01.510Z,1626987301.510 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-07-22T20:55:01.512Z,1626987301.512 [LoopControl](DEBUG): Construct LoopControl.
2021-07-22T20:55:01.513Z,1626987301.513 [LoopControl] Loaded
2021-07-22T20:55:01.513Z,1626987301.513 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-07-22T20:55:01.514Z,1626987301.514 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-07-22T20:55:01.514Z,1626987301.514 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-07-22T20:55:01.561Z,1626987301.561 [DepthRateCalculator] Loaded
2021-07-22T20:55:01.561Z,1626987301.561 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-07-22T20:55:01.566Z,1626987301.566 [PitchRateCalculator] Loaded
2021-07-22T20:55:01.566Z,1626987301.566 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-07-22T20:55:01.576Z,1626987301.576 [SpeedCalculator] Loaded
2021-07-22T20:55:01.576Z,1626987301.576 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-07-22T20:55:01.590Z,1626987301.590 [TempGradientCalculator] Loaded
2021-07-22T20:55:01.591Z,1626987301.591 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-07-22T20:55:01.595Z,1626987301.595 [YawRateCalculator] Loaded
2021-07-22T20:55:01.595Z,1626987301.595 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-07-22T20:55:01.613Z,1626987301.613 [ElevatorOffsetCalculator] Loaded
2021-07-22T20:55:01.614Z,1626987301.614 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-07-22T20:55:01.614Z,1626987301.614 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-07-22T20:55:01.615Z,1626987301.615 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-07-22T20:55:01.722Z,1626987301.722 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-07-22T20:55:01.723Z,1626987301.723 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-07-22T20:55:01.786Z,1626987301.786 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-07-22T20:55:01.787Z,1626987301.787 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-07-22T20:55:01.924Z,1626987301.924 [BuoyancyServo] Loaded
2021-07-22T20:55:01.924Z,1626987301.924 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-07-22T20:55:01.944Z,1626987301.944 [ElevatorServo] Loaded
2021-07-22T20:55:01.944Z,1626987301.944 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-07-22T20:55:01.964Z,1626987301.964 [RudderServo] Loaded
2021-07-22T20:55:01.964Z,1626987301.964 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-07-22T20:55:01.982Z,1626987301.982 [ThrusterServo] Loaded
2021-07-22T20:55:01.982Z,1626987301.982 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-07-22T20:55:01.983Z,1626987301.983 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-07-22T20:55:01.984Z,1626987301.984 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-07-22T20:55:02.103Z,1626987302.103 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-07-22T20:55:02.104Z,1626987302.104 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-07-22T20:55:03.645Z,1626987303.645 [BPC1] Loaded
2021-07-22T20:55:03.645Z,1626987303.645 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-07-22T20:55:03.720Z,1626987303.720 [DataOverHttps] Loaded
2021-07-22T20:55:03.720Z,1626987303.720 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-07-22T20:55:03.721Z,1626987303.721 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409B34E0
2021-07-22T20:55:03.722Z,1626987303.722 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 7492
2021-07-22T20:55:03.743Z,1626987303.743 [Depth_Keller] Loaded
2021-07-22T20:55:03.743Z,1626987303.743 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-07-22T20:55:03.807Z,1626987303.807 [NAL9602] Loaded
2021-07-22T20:55:03.807Z,1626987303.807 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-07-22T20:55:03.835Z,1626987303.835 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now
2021-07-22T20:55:03.836Z,1626987303.836 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now
2021-07-22T20:55:03.836Z,1626987303.836 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now
2021-07-22T20:55:03.837Z,1626987303.837 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full
2021-07-22T20:55:03.838Z,1626987303.838 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now
2021-07-22T20:55:03.838Z,1626987303.838 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now
2021-07-22T20:55:03.839Z,1626987303.839 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now
2021-07-22T20:55:03.839Z,1626987303.839 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full
2021-07-22T20:55:03.839Z,1626987303.839 [Onboard] Loaded
2021-07-22T20:55:03.840Z,1626987303.840 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-07-22T20:55:03.841Z,1626987303.841 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409E34E0
2021-07-22T20:55:03.841Z,1626987303.841 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 7493
2021-07-22T20:55:03.855Z,1626987303.855 [Power24vConverter] Loaded
2021-07-22T20:55:03.855Z,1626987303.855 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-07-22T20:55:03.869Z,1626987303.869 [Radio_Surface] Loaded
2021-07-22T20:55:03.870Z,1626987303.870 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-07-22T20:55:03.871Z,1626987303.871 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40A134E0
2021-07-22T20:55:03.871Z,1626987303.871 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7494
2021-07-22T20:55:03.957Z,1626987303.957 [DAT] Loaded
2021-07-22T20:55:03.958Z,1626987303.958 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-07-22T20:55:03.958Z,1626987303.958 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-07-22T20:55:03.959Z,1626987303.959 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-07-22T20:55:04.147Z,1626987304.147 [SBIT](DEBUG): Construct Startup Built In Test.
2021-07-22T20:55:04.172Z,1626987304.172 [SBIT] Loaded
2021-07-22T20:55:04.172Z,1626987304.172 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-07-22T20:55:04.175Z,1626987304.175 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-07-22T20:55:04.190Z,1626987304.190 [IBIT] Loaded
2021-07-22T20:55:04.191Z,1626987304.191 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-07-22T20:55:04.197Z,1626987304.197 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-07-22T20:55:04.358Z,1626987304.358 [CBIT] Loaded
2021-07-22T20:55:04.358Z,1626987304.358 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-07-22T20:55:04.359Z,1626987304.359 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-07-22T20:55:04.359Z,1626987304.359 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-07-22T20:55:04.389Z,1626987304.389 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-07-22T20:55:04.396Z,1626987304.396 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-07-22T20:55:04.399Z,1626987304.399 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-07-22T20:55:04.410Z,1626987304.410 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-07-22T20:55:04.411Z,1626987304.411 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A9E4E0
2021-07-22T20:55:04.411Z,1626987304.411 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7495
2021-07-22T20:55:04.416Z,1626987304.416 [Supervisor](INFO): Main Thread ID is 6160
2021-07-22T20:55:04.416Z,1626987304.416 [Supervisor](DEBUG): Running supervisor.
2021-07-22T20:55:04.417Z,1626987304.417 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7496
2021-07-22T20:55:04.419Z,1626987304.419 [controlThread ThreadHandler](INFO): Handler Thread ID is 7497
2021-07-22T20:55:04.419Z,1626987304.419 [controlThread](DEBUG): Initializing ControlThread
2021-07-22T20:55:04.421Z,1626987304.421 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T20:55:04.421Z,1626987304.421 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-07-22T20:55:04.422Z,1626987304.422 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-07-22T20:55:04.422Z,1626987304.422 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-07-22T20:55:04.424Z,1626987304.424 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-07-22T20:55:04.425Z,1626987304.425 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-07-22T20:55:04.426Z,1626987304.426 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-07-22T20:55:04.426Z,1626987304.426 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-07-22T20:55:04.426Z,1626987304.426 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-07-22T20:55:04.427Z,1626987304.427 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-07-22T20:55:04.427Z,1626987304.427 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-07-22T20:55:04.428Z,1626987304.428 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-07-22T20:55:04.428Z,1626987304.428 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-07-22T20:55:04.435Z,1626987304.435 [SBIT](INFO): Initialize SBIT Component.
2021-07-22T20:55:04.435Z,1626987304.435 [SBIT](IMPORTANT): git: 2021-06-24-7-gcba2ba184
2021-07-22T20:55:04.435Z,1626987304.435 [SBIT](INFO): git hash: cba2ba184a996ac72cd367cf95917907d16cfa04
2021-07-22T20:55:04.436Z,1626987304.436 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-07-22T20:55:04.437Z,1626987304.437 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2021-07-22T20:55:04.438Z,1626987304.438 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.
2021-07-22T20:55:04.439Z,1626987304.439 [IBIT](INFO): Initialize IBIT Component.
2021-07-22T20:55:04.440Z,1626987304.440 [CBIT](DEBUG): Initialize CBIT Component.
2021-07-22T20:55:04.441Z,1626987304.441 [logger ThreadHandler](INFO): Handler Thread ID is 7498
2021-07-22T20:55:04.454Z,1626987304.454 [CBIT](DEBUG): Initialized mux pins.
2021-07-22T20:55:04.454Z,1626987304.454 [CBIT](DEBUG): Initializing the watchdog timer.
2021-07-22T20:55:04.458Z,1626987304.458 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 7499
2021-07-22T20:55:04.459Z,1626987304.459 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-07-22T20:55:04.466Z,1626987304.466 [Onboard ThreadHandler](INFO): Handler Thread ID is 7500
2021-07-22T20:55:04.479Z,1626987304.479 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-07-22T20:55:04.479Z,1626987304.479 [CBIT](DEBUG): Initializing heartbeat.
2021-07-22T20:55:04.486Z,1626987304.486 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7501
2021-07-22T20:55:04.502Z,1626987304.502 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7502
2021-07-22T20:55:04.505Z,1626987304.505 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-07-22T20:55:04.505Z,1626987304.505 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-07-22T20:55:04.506Z,1626987304.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-07-22T20:55:04.506Z,1626987304.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-07-22T20:55:04.506Z,1626987304.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-07-22T20:55:04.506Z,1626987304.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-07-22T20:55:04.506Z,1626987304.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-07-22T20:55:04.507Z,1626987304.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-07-22T20:55:04.508Z,1626987304.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-07-22T20:55:04.508Z,1626987304.508 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-07-22T20:55:04.508Z,1626987304.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-07-22T20:55:04.549Z,1626987304.549 [CBIT](DEBUG): Deactivating GF circuits.
2021-07-22T20:55:04.550Z,1626987304.550 [CBIT](DEBUG): Deactivating emergency mode.
2021-07-22T20:55:04.586Z,1626987304.586 [CBIT](DEBUG): Backplane powered.
2021-07-22T20:55:04.587Z,1626987304.587 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-07-22T20:55:04.600Z,1626987304.600 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-07-22T20:55:04.628Z,1626987304.628 [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>


2021-07-22T20:55:04.628Z,1626987304.628 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-07-22T20:55:04.699Z,1626987304.699 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-07-22T20:55:04.700Z,1626987304.700 [Default:A.Wait](DEBUG): Construct Wait.
2021-07-22T20:55:04.718Z,1626987304.718 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-07-22T20:55:04.743Z,1626987304.743 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-07-22T20:55:04.786Z,1626987304.786 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-07-22T20:55:04.792Z,1626987304.792 [Default:E.Execute](DEBUG): Construct Execute.
2021-07-22T20:55:04.811Z,1626987304.811 [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>


2021-07-22T20:55:04.816Z,1626987304.816 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,BPC1,Depth_Keller,NAL9602,Power24vConverter,DAT,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2021-07-22T20:55:04.868Z,1626987304.868 [Depth_Keller](ERROR): Pressure reading out of range: 1628.471313 decibar
2021-07-22T20:55:04.869Z,1626987304.869 [Power24vConverter](INFO): Powering up.
2021-07-22T20:55:04.869Z,1626987304.869 [DAT](INFO): Powering up
2021-07-22T20:55:04.870Z,1626987304.870 [DAT](DEBUG): Initializing DAT.
2021-07-22T20:55:04.890Z,1626987304.890 [Radio_Surface](INFO): Powering up
2021-07-22T20:55:04.894Z,1626987304.894 [DepthRateCalculator](ERROR): Depth measurement is not active
2021-07-22T20:55:04.919Z,1626987304.919 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-07-22T20:55:04.926Z,1626987304.926 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-07-22T20:55:04.928Z,1626987304.928 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-07-22T20:55:04.934Z,1626987304.934 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-07-22T20:55:04.935Z,1626987304.935 [RudderServo](DEBUG): Initializing EZServoServo.
2021-07-22T20:55:04.942Z,1626987304.942 [RudderServo](DEBUG): Initializing RudderServo.
2021-07-22T20:55:04.943Z,1626987304.943 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-07-22T20:55:04.958Z,1626987304.958 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-07-22T20:55:25.056Z,1626987325.056 [SBIT](IMPORTANT): Beginning Startup BIT
2021-07-22T20:55:25.061Z,1626987325.061 [CBIT](IMPORTANT): Beginning ground fault scan
2021-07-22T20:55:33.911Z,1626987333.911 [NAL9602](INFO): Powering up NAL9602
2021-07-22T20:55:35.952Z,1626987335.952 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.008265
CHAN A1 (24V): 0.002088
CHAN A2 (12V): -0.005252
CHAN A3 (5V): -0.002336
CHAN B0 (3.3V): -0.001245
CHAN B1 (3.15aV): -0.001069
CHAN B2 (3.15bV): -0.001309
CHAN B3 (GND): -0.000507
OPEN: -0.001487
Full Scale Calc: 4.765 mA, -1.589 mA
2021-07-22T20:55:38.371Z,1626987338.371 [SBIT](ERROR): Could not read massPosReader_.
2021-07-22T20:55:44.819Z,1626987344.819 [NAL9602](INFO): NAL9602 initialized
2021-07-22T20:56:05.019Z,1626987365.019 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T20:56:05.019Z,1626987365.019 [DAT] Communications Fault, FailCount= 1
2021-07-22T20:56:05.019Z,1626987365.019 [DAT](ERROR): Communications Fault
2021-07-22T20:56:05.031Z,1626987365.031 [SBIT](ERROR): Could not read massPosReader_.
2021-07-22T20:56:05.031Z,1626987365.031 [SBIT](FAULT): Control surface position failure.
2021-07-22T20:56:05.055Z,1626987365.055 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T20:56:05.453Z,1626987365.453 [DAT](INFO): Powering down
2021-07-22T20:56:06.262Z,1626987366.262 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T20:56:06.262Z,1626987366.262 [DAT] No Fault, FailCount= 1
2021-07-22T20:56:08.674Z,1626987368.674 [DAT](INFO): Powering up
2021-07-22T20:56:08.674Z,1626987368.674 [DAT](DEBUG): Initializing DAT.
2021-07-22T20:56:18.800Z,1626987378.800 [SBIT](ERROR): Could not read massPosReader_.
2021-07-22T20:56:18.800Z,1626987378.800 [SBIT](FAULT): Control surface position failure.
2021-07-22T20:56:19.200Z,1626987379.200 [SBIT](CRITICAL): SBIT FAILED
2021-07-22T20:56:19.200Z,1626987379.200 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-07-22T20:56:19.202Z,1626987379.202 [SBIT](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2021-07-22T20:56:19.202Z,1626987379.202 [SBIT](IMPORTANT): CTD_NeilBrown.loadAtStartup=0 bool;

2021-07-22T20:56:19.204Z,1626987379.204 [SBIT](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2021-07-22T20:56:19.204Z,1626987379.204 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2021-07-22T20:56:19.204Z,1626987379.204 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2021-07-22T20:56:19.204Z,1626987379.204 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=1 bool;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): IBIT.batteryCapacityThreshold=5 ampere_hour;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=11 volt;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): MassServo.loadAtStartup=0 bool;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): MassServo.overloadTimeout=10 second;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=235 cubic_centimeter;

2021-07-22T20:56:19.205Z,1626987379.205 [SBIT](IMPORTANT): VerticalControl.massDefault=0 centimeter;

2021-07-22T20:56:19.206Z,1626987379.206 [SBIT](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool;

2021-07-22T20:56:19.209Z,1626987379.209 [CommandLine](FAULT): Scheduling is paused
2021-07-22T20:56:19.210Z,1626987379.210 [CBIT](INFO): Critical error at 20210722T205619
2021-07-22T20:56:19.210Z,1626987379.210 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-07-22T20:56:19.596Z,1626987379.596 [MissionManager](IMPORTANT): Started mission Startup
2021-07-22T20:56:19.596Z,1626987379.596 [Startup] Running Loop=1
2021-07-22T20:56:19.596Z,1626987379.596 [Startup](DEBUG): Aggregate::initialize Startup
2021-07-22T20:56:19.597Z,1626987379.597 [Startup:A.GoToSurface] Running Loop=1
2021-07-22T20:56:19.597Z,1626987379.597 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-07-22T20:56:19.597Z,1626987379.597 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-07-22T20:56:19.598Z,1626987379.598 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-07-22T20:56:19.598Z,1626987379.598 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-07-22T20:56:19.599Z,1626987379.599 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-07-22T20:56:19.599Z,1626987379.599 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-07-22T20:56:19.601Z,1626987379.601 [Startup:StartupSatComms] Running Loop=1
2021-07-22T20:56:19.601Z,1626987379.601 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-07-22T20:56:19.601Z,1626987379.601 [Startup:StartupSatComms:A] Running Loop=1
2021-07-22T20:56:19.999Z,1626987379.999 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-07-22T20:57:04.820Z,1626987424.820 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T20:57:04.820Z,1626987424.820 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-07-22T20:57:04.821Z,1626987424.821 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T20:57:04.822Z,1626987424.822 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T20:57:04.822Z,1626987424.822 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2021-07-22T20:57:04.822Z,1626987424.822 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T20:57:04.833Z,1626987424.833 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T20:57:04.834Z,1626987424.834 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T20:57:05.288Z,1626987425.288 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T20:57:05.288Z,1626987425.288 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-07-22T20:57:05.289Z,1626987425.289 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T20:57:05.289Z,1626987425.289 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2021-07-22T20:57:05.657Z,1626987425.657 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T20:57:08.852Z,1626987428.852 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T20:57:08.852Z,1626987428.852 [DAT] Communications Fault, FailCount= 2
2021-07-22T20:57:08.852Z,1626987428.852 [DAT](ERROR): Communications Fault
2021-07-22T20:57:08.887Z,1626987428.887 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T20:57:09.256Z,1626987429.256 [DAT](INFO): Powering down
2021-07-22T20:57:10.087Z,1626987430.087 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T20:57:10.087Z,1626987430.087 [DAT] No Fault, FailCount= 2
2021-07-22T20:57:12.518Z,1626987432.518 [DAT](INFO): Powering up
2021-07-22T20:57:12.518Z,1626987432.518 [DAT](DEBUG): Initializing DAT.
2021-07-22T20:57:19.782Z,1626987439.782 [Startup:StartupSatComms:A](INFO): Timed out from 2021-07-22T20:56:19.6Z
2021-07-22T20:57:19.782Z,1626987439.782 [Startup:StartupSatComms:A] Stopped
2021-07-22T20:57:19.782Z,1626987439.782 [Startup:StartupSatComms:B] Running Loop=1
2021-07-22T20:57:20.174Z,1626987440.174 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-07-22T20:57:25.469Z,1626987445.469 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T20:57:32.040Z,1626987452.040 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005151
2021-07-22T20:57:38.800Z,1626987458.800 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T20:57:39.018Z,1626987459.018 [DataOverHttps](INFO): Sending 263 bytes from file Logs/20210722T204442/Courier0007.lzma
2021-07-22T20:57:40.019Z,1626987460.019 [DataOverHttps](INFO): Moved sent file to Logs/20210722T204442/Courier0007.lzma.bak
2021-07-22T20:57:40.020Z,1626987460.020 [DataOverHttps](INFO): SBD MOMSN=15753950
2021-07-22T20:57:55.237Z,1626987475.237 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210722T205454/Courier0000.lzma
2021-07-22T20:57:56.239Z,1626987476.239 [DataOverHttps](INFO): Moved sent file to Logs/20210722T205454/Courier0000.lzma.bak
2021-07-22T20:57:56.239Z,1626987476.239 [DataOverHttps](INFO): SBD MOMSN=15753954
2021-07-22T20:58:12.287Z,1626987492.287 [DataOverHttps](INFO): Sending 1134 bytes from file Logs/20210722T204442/Express0008.lzma
2021-07-22T20:58:12.700Z,1626987492.700 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T20:58:12.700Z,1626987492.700 [DAT] Communications Fault, FailCount= 3
2021-07-22T20:58:12.701Z,1626987492.701 [DAT](ERROR): Communications Fault
2021-07-22T20:58:12.736Z,1626987492.736 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T20:58:13.104Z,1626987493.104 [DAT](INFO): Powering down
2021-07-22T20:58:13.287Z,1626987493.287 [DataOverHttps](INFO): Moved sent file to Logs/20210722T204442/Express0008.lzma.bak
2021-07-22T20:58:13.288Z,1626987493.288 [DataOverHttps](INFO): SBD MOMSN=15753958
2021-07-22T20:58:13.922Z,1626987493.922 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T20:58:13.922Z,1626987493.922 [DAT] No Fault, FailCount= 3
2021-07-22T20:58:16.348Z,1626987496.348 [DAT](INFO): Powering up
2021-07-22T20:58:16.348Z,1626987496.348 [DAT](DEBUG): Initializing DAT.
2021-07-22T20:58:20.019Z,1626987500.019 [Startup:StartupSatComms:B](INFO): Timed out from 2021-07-22T20:57:19.8Z
2021-07-22T20:58:20.019Z,1626987500.019 [Startup:StartupSatComms:B] Stopped
2021-07-22T20:58:20.020Z,1626987500.020 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-07-22T20:58:20.020Z,1626987500.020 [Startup:StartupSatComms] Stopped
2021-07-22T20:58:20.020Z,1626987500.020 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-07-22T20:58:20.021Z,1626987500.021 [Startup](INFO): Completed Startup
2021-07-22T20:58:20.021Z,1626987500.021 [MissionManager](INFO): Startup is completed.
2021-07-22T20:58:20.021Z,1626987500.021 [MissionManager](INFO): Uninitializing Mission Startup
2021-07-22T20:58:20.021Z,1626987500.021 [Startup] Stopped
2021-07-22T20:58:20.021Z,1626987500.021 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-07-22T20:58:20.021Z,1626987500.021 [Startup:A.GoToSurface] Stopped
2021-07-22T20:58:20.021Z,1626987500.021 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-07-22T20:58:20.426Z,1626987500.426 [MissionManager](IMPORTANT): Started mission Default
2021-07-22T20:58:20.427Z,1626987500.427 [Default] Running Loop=1
2021-07-22T20:58:20.427Z,1626987500.427 [Default](DEBUG): Aggregate::initialize Default
2021-07-22T20:58:20.427Z,1626987500.427 [Default:B.GoToSurface] Running Loop=1
2021-07-22T20:58:20.427Z,1626987500.427 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-07-22T20:58:20.427Z,1626987500.427 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-07-22T20:58:20.428Z,1626987500.428 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-07-22T20:58:20.428Z,1626987500.428 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-07-22T20:58:20.428Z,1626987500.428 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-07-22T20:58:20.429Z,1626987500.429 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-07-22T20:58:20.429Z,1626987500.429 [Default:A.Wait] Running Loop=1
2021-07-22T20:58:20.429Z,1626987500.429 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-07-22T20:58:28.524Z,1626987508.524 [DataOverHttps](INFO): Sending 1041 bytes from file Logs/20210722T205454/Express0001.lzma
2021-07-22T20:58:29.524Z,1626987509.524 [DataOverHttps](INFO): Moved sent file to Logs/20210722T205454/Express0001.lzma.bak
2021-07-22T20:58:29.524Z,1626987509.524 [DataOverHttps](INFO): SBD MOMSN=15754017
2021-07-22T20:58:33.745Z,1626987513.745 [Default:A.Wait](INFO): Done Waiting.
2021-07-22T20:58:33.745Z,1626987513.745 [Default:A.Wait] Stopped
2021-07-22T20:58:33.745Z,1626987513.745 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-07-22T20:58:34.128Z,1626987514.128 [Default:CheckIn] Running Loop=1
2021-07-22T20:58:34.128Z,1626987514.128 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-07-22T20:58:34.128Z,1626987514.128 [Default:CheckIn:Read_GPS] Running Loop=1
2021-07-22T20:58:34.531Z,1626987514.531 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-07-22T20:59:05.706Z,1626987545.706 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T20:59:05.707Z,1626987545.707 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-07-22T20:59:05.707Z,1626987545.707 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T20:59:05.708Z,1626987545.708 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T20:59:05.708Z,1626987545.708 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2021-07-22T20:59:05.708Z,1626987545.708 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T20:59:05.719Z,1626987545.719 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T20:59:05.719Z,1626987545.719 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T20:59:06.098Z,1626987546.098 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T20:59:06.098Z,1626987546.098 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-07-22T20:59:06.099Z,1626987546.099 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T20:59:06.099Z,1626987546.099 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2021-07-22T20:59:06.488Z,1626987546.488 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T20:59:16.545Z,1626987556.545 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T20:59:16.545Z,1626987556.545 [DAT] Communications Fault, FailCount= 4
2021-07-22T20:59:16.545Z,1626987556.545 [DAT](ERROR): Communications Fault
2021-07-22T20:59:16.561Z,1626987556.561 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T20:59:17.006Z,1626987557.006 [DAT](INFO): Powering down
2021-07-22T20:59:17.807Z,1626987557.807 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T20:59:17.807Z,1626987557.807 [DAT] No Fault, FailCount= 4
2021-07-22T20:59:20.195Z,1626987560.195 [DAT](INFO): Powering up
2021-07-22T20:59:20.196Z,1626987560.196 [DAT](DEBUG): Initializing DAT.
2021-07-22T20:59:54.170Z,1626987594.170 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T21:00:05.473Z,1626987605.473 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T21:00:08.132Z,1626987608.132 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree
2021-07-22T21:00:08.136Z,1626987608.136 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2021-07-22T21:00:08.137Z,1626987608.137 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -122.099998 degree
2021-07-22T21:00:08.141Z,1626987608.141 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2021-07-22T21:00:08.287Z,1626987608.287 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,BPC1,Depth_Keller,NAL9602,Power24vConverter,DAT,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2021-07-22T21:00:08.670Z,1626987608.670 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:08.670Z,1626987608.670 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-07-22T21:00:08.670Z,1626987608.670 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:08.671Z,1626987608.671 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:08.671Z,1626987608.671 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2021-07-22T21:00:08.671Z,1626987608.671 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:08.732Z,1626987608.732 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:08.732Z,1626987608.732 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:09.087Z,1626987609.087 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:09.087Z,1626987609.087 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-07-22T21:00:09.088Z,1626987609.088 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:09.088Z,1626987609.088 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2021-07-22T21:00:09.490Z,1626987609.490 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:09.890Z,1626987609.890 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:09.891Z,1626987609.891 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-07-22T21:00:09.891Z,1626987609.891 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:09.892Z,1626987609.892 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:09.892Z,1626987609.892 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2021-07-22T21:00:09.892Z,1626987609.892 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:09.971Z,1626987609.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:09.971Z,1626987609.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:10.315Z,1626987610.315 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:10.315Z,1626987610.315 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-07-22T21:00:10.316Z,1626987610.316 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:10.316Z,1626987610.316 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2021-07-22T21:00:10.698Z,1626987610.698 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:11.084Z,1626987611.084 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size.
2021-07-22T21:00:11.126Z,1626987611.126 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:11.126Z,1626987611.126 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-07-22T21:00:11.127Z,1626987611.127 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:11.128Z,1626987611.128 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:11.128Z,1626987611.128 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 5
2021-07-22T21:00:11.128Z,1626987611.128 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:11.215Z,1626987611.215 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:11.215Z,1626987611.215 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:11.543Z,1626987611.543 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:11.543Z,1626987611.543 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-07-22T21:00:11.543Z,1626987611.543 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:11.544Z,1626987611.544 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 5
2021-07-22T21:00:11.933Z,1626987611.933 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:12.302Z,1626987612.302 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:12.302Z,1626987612.302 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-07-22T21:00:12.302Z,1626987612.302 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:12.304Z,1626987612.304 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:12.304Z,1626987612.304 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 6
2021-07-22T21:00:12.304Z,1626987612.304 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:12.323Z,1626987612.323 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:12.323Z,1626987612.323 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:12.726Z,1626987612.726 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:12.726Z,1626987612.726 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-07-22T21:00:12.727Z,1626987612.727 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:12.727Z,1626987612.727 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 6
2021-07-22T21:00:13.114Z,1626987613.114 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:13.514Z,1626987613.514 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:13.514Z,1626987613.514 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-07-22T21:00:13.514Z,1626987613.514 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:13.516Z,1626987613.516 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:13.516Z,1626987613.516 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 7
2021-07-22T21:00:13.516Z,1626987613.516 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:13.539Z,1626987613.539 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:13.539Z,1626987613.539 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:13.943Z,1626987613.943 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:13.943Z,1626987613.943 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-07-22T21:00:13.944Z,1626987613.944 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:13.944Z,1626987613.944 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 7
2021-07-22T21:00:14.322Z,1626987614.322 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:14.758Z,1626987614.758 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:14.758Z,1626987614.758 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-07-22T21:00:14.758Z,1626987614.758 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:14.760Z,1626987614.760 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:14.760Z,1626987614.760 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 8
2021-07-22T21:00:14.760Z,1626987614.760 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:14.771Z,1626987614.771 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:14.771Z,1626987614.771 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:15.171Z,1626987615.171 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:15.171Z,1626987615.171 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-07-22T21:00:15.172Z,1626987615.172 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:15.172Z,1626987615.172 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 8
2021-07-22T21:00:15.558Z,1626987615.558 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:15.958Z,1626987615.958 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:15.958Z,1626987615.958 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-07-22T21:00:15.958Z,1626987615.958 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:15.960Z,1626987615.960 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:15.960Z,1626987615.960 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 9
2021-07-22T21:00:15.960Z,1626987615.960 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:15.971Z,1626987615.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:15.971Z,1626987615.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:16.354Z,1626987616.354 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:16.354Z,1626987616.354 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-07-22T21:00:16.355Z,1626987616.355 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:16.355Z,1626987616.355 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 9
2021-07-22T21:00:16.749Z,1626987616.749 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:17.154Z,1626987617.154 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:17.154Z,1626987617.154 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-07-22T21:00:17.154Z,1626987617.154 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:17.155Z,1626987617.155 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:17.155Z,1626987617.155 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 10
2021-07-22T21:00:17.155Z,1626987617.155 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:17.166Z,1626987617.166 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:17.166Z,1626987617.166 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:17.611Z,1626987617.611 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:17.611Z,1626987617.611 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-07-22T21:00:17.611Z,1626987617.611 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:17.612Z,1626987617.612 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 10
2021-07-22T21:00:17.978Z,1626987617.978 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:18.382Z,1626987618.382 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:18.382Z,1626987618.382 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-07-22T21:00:18.382Z,1626987618.382 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:18.383Z,1626987618.383 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:18.383Z,1626987618.383 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 11
2021-07-22T21:00:18.383Z,1626987618.383 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:18.394Z,1626987618.394 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:18.395Z,1626987618.395 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:18.806Z,1626987618.806 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:18.806Z,1626987618.806 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-07-22T21:00:18.806Z,1626987618.806 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:18.807Z,1626987618.807 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 11
2021-07-22T21:00:19.189Z,1626987619.189 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:19.574Z,1626987619.574 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:19.574Z,1626987619.574 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-07-22T21:00:19.574Z,1626987619.574 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:19.576Z,1626987619.576 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:19.576Z,1626987619.576 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 12
2021-07-22T21:00:19.576Z,1626987619.576 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:19.591Z,1626987619.591 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:19.591Z,1626987619.591 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:20.005Z,1626987620.005 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:20.005Z,1626987620.005 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-07-22T21:00:20.006Z,1626987620.006 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:20.006Z,1626987620.006 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 12
2021-07-22T21:00:20.386Z,1626987620.386 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:00:20.387Z,1626987620.386 [DAT] Communications Fault, FailCount= 5
2021-07-22T21:00:20.387Z,1626987620.387 [DAT](ERROR): Communications Fault
2021-07-22T21:00:20.398Z,1626987620.398 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:20.408Z,1626987620.408 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:00:20.794Z,1626987620.794 [DAT](INFO): Powering down
2021-07-22T21:00:20.922Z,1626987620.922 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:20.922Z,1626987620.922 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2021-07-22T21:00:20.922Z,1626987620.922 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:00:20.924Z,1626987620.924 [DeadReckonUsingSpeedCalculator](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-07-22T21:00:20.924Z,1626987620.924 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 13
2021-07-22T21:00:20.924Z,1626987620.924 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:00:20.935Z,1626987620.935 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:20.935Z,1626987620.935 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:00:20.968Z,1626987620.968 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1626987648.000000 second
2021-07-22T21:00:21.209Z,1626987621.209 [Default:CheckIn:Read_GPS] Stopped
2021-07-22T21:00:21.209Z,1626987621.209 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-07-22T21:00:21.218Z,1626987621.218 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:00:21.218Z,1626987621.218 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2021-07-22T21:00:21.219Z,1626987621.219 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:00:21.219Z,1626987621.219 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 13
2021-07-22T21:00:21.591Z,1626987621.591 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:00:21.593Z,1626987621.593 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-07-22T21:00:21.602Z,1626987621.602 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:00:21.602Z,1626987621.602 [DAT] No Fault, FailCount= 5
2021-07-22T21:00:24.017Z,1626987624.017 [DAT](INFO): Powering up
2021-07-22T21:00:24.017Z,1626987624.017 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:00:25.728Z,1626987625.728 [CommandLine](IMPORTANT): got command show stack
2021-07-22T21:00:25.728Z,1626987625.728 [CommandLine](IMPORTANT): Behavior Stack:

2021-07-22T21:00:25.728Z,1626987625.728 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2021-07-22T21:00:25.728Z,1626987625.728 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_Iridium
2021-07-22T21:00:28.453Z,1626987628.453 [DataOverHttps](INFO): Sending 145 bytes from file Logs/20210722T205454/Courier0004.lzma
2021-07-22T21:00:29.455Z,1626987629.455 [DataOverHttps](INFO): Moved sent file to Logs/20210722T205454/Courier0004.lzma.bak
2021-07-22T21:00:29.456Z,1626987629.456 [DataOverHttps](INFO): SBD MOMSN=15754050
2021-07-22T21:00:31.688Z,1626987631.688 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file).
2021-07-22T21:00:48.295Z,1626987648.295 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-07-22T21:00:49.494Z,1626987649.494 [DataOverHttps](INFO): Sending 334 bytes from file Logs/20210722T205454/Express0005.lzma
2021-07-22T21:00:50.496Z,1626987650.496 [DataOverHttps](INFO): Moved sent file to Logs/20210722T205454/Express0005.lzma.bak
2021-07-22T21:00:50.496Z,1626987650.496 [DataOverHttps](IMPORTANT): SBD MOMSN=15754053, MTMSN=20210722T210048
2021-07-22T21:00:53.153Z,1626987653.153 [Default:CheckIn:Read_Iridium] Stopped
2021-07-22T21:00:53.153Z,1626987653.153 [Default:CheckIn:C.Wait] Running Loop=1
2021-07-22T21:00:53.153Z,1626987653.153 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-07-22T21:00:54.828Z,1626987654.828 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T21:00:59.298Z,1626987659.298 [DataOverHttps](INFO): Received command:load Maintenance/sample_lab.xml;set sample_lab.CartridgeType -6 count;set sample_lab.NumberOfSamples 2 count;run
2021-07-22T21:00:59.316Z,1626987659.316 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:00:59.317Z,1626987659.317 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:00:59.367Z,1626987659.367 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2021-07-22T21:00:59.371Z,1626987659.371 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2021-07-22T21:00:59.373Z,1626987659.373 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2021-07-22T21:00:59.375Z,1626987659.375 [sample_lab:A.AbortSample](DEBUG): Construct.
2021-07-22T21:00:59.379Z,1626987659.379 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct.
2021-07-22T21:00:59.414Z,1626987659.414 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Science="Tethys/Science"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sample http://okeanids.mbari.org/tethys/Xml/Sample.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="sample_lab">

    <Description>
        This mission is designed to run in the lab only and triggers an ESP
        sample with specified type.
    </Description>

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

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4)
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Sample:AbortSample>
        <Parallel/>
    </Sample:AbortSample>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Syslog Severity="Important">Sampling ESP cartridge type <Arg Name="CartridgeType"/><Units:count/></Syslog>

        <Science:ESPCartridgeSelect>
            <Sequence/>
            <Timeout Duration="P1M"/>
            <Setting><Science:ESPCartridgeSelect.cartridgeType/><Arg Name="CartridgeType"/></Setting>
        </Science:ESPCartridgeSelect>

        <ReadDatum Id="TriggerESP">
            <Science:ESPComponent.sampling/>
        </ReadDatum>

        <ReadDatum Id="WaitForESP">
            <Science:ESPComponent.sample_number/>
        </ReadDatum>

    </Aggregate>

</Mission>


2021-07-22T21:00:59.415Z,1626987659.415 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:01:02.373Z,1626987662.373 [CommandLine](IMPORTANT): got command set sample_lab.CartridgeType -6.000000 count
2021-07-22T21:01:02.374Z,1626987662.374 [CommandLine](IMPORTANT): got command set sample_lab.NumberOfSamples 2.000000 count
2021-07-22T21:01:02.374Z,1626987662.374 [CommandLine](IMPORTANT): got command run
2021-07-22T21:01:02.376Z,1626987662.376 [CommandLine](IMPORTANT): Running 
2021-07-22T21:01:02.445Z,1626987662.445 [Default] Stopped
2021-07-22T21:01:02.445Z,1626987662.445 [Default](DEBUG): Aggregate::uninitialize Default
2021-07-22T21:01:02.445Z,1626987662.445 [Default:B.GoToSurface] Stopped
2021-07-22T21:01:02.445Z,1626987662.445 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-07-22T21:01:02.446Z,1626987662.446 [Default:CheckIn] Stopped
2021-07-22T21:01:02.446Z,1626987662.446 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-07-22T21:01:02.446Z,1626987662.446 [Default:CheckIn:C.Wait] Stopped
2021-07-22T21:01:02.446Z,1626987662.446 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-07-22T21:01:02.446Z,1626987662.446 [MissionManager](IMPORTANT): Started mission sample_lab
2021-07-22T21:01:02.446Z,1626987662.446 [sample_lab] Running Loop=1
2021-07-22T21:01:02.446Z,1626987662.446 [sample_lab](DEBUG): Aggregate::initialize sample_lab
2021-07-22T21:01:02.447Z,1626987662.447 [sample_lab:A.AbortSample] Running Loop=1
2021-07-22T21:01:02.447Z,1626987662.447 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2021-07-22T21:01:02.447Z,1626987662.447 [sample_lab:SampleRepeater] Running Loop=1
2021-07-22T21:01:02.447Z,1626987662.447 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2021-07-22T21:01:02.447Z,1626987662.447 [sample_lab:SampleRepeater:A] Running Loop=1
2021-07-22T21:01:02.448Z,1626987662.448 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -6.000000 count 
2021-07-22T21:01:02.448Z,1626987662.448 [sample_lab:SampleRepeater:A] Stopped
2021-07-22T21:01:02.448Z,1626987662.448 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2021-07-22T21:01:02.448Z,1626987662.448 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2021-07-22T21:01:02.449Z,1626987662.449 [sample_lab:A.AbortSample] Running Loop=1
2021-07-22T21:01:02.859Z,1626987662.859 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -6.
2021-07-22T21:01:02.859Z,1626987662.859 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2021-07-22T21:01:02.859Z,1626987662.859 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2021-07-22T21:01:02.859Z,1626987662.859 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2021-07-22T21:01:03.258Z,1626987663.258 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2021-07-22T21:01:04.050Z,1626987664.050 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2021-07-22T21:01:04.054Z,1626987664.054 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2021-07-22T21:01:04.055Z,1626987664.055 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:01:14.439Z,1626987674.439 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:01:14.442Z,1626987674.442 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:01:14.843Z,1626987674.843 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:01:18.890Z,1626987678.890 [NAL9602](INFO): Not Powering down - fast GPS
2021-07-22T21:01:24.198Z,1626987684.198 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:01:24.198Z,1626987684.198 [DAT] Communications Fault, FailCount= 6
2021-07-22T21:01:24.198Z,1626987684.198 [DAT](ERROR): Communications Fault
2021-07-22T21:01:24.253Z,1626987684.253 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:01:24.571Z,1626987684.571 [DAT](INFO): Powering down
2021-07-22T21:01:24.943Z,1626987684.943 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:01:24.944Z,1626987684.944 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:01:25.347Z,1626987685.347 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:01:25.400Z,1626987685.400 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:01:25.400Z,1626987685.400 [DAT] No Fault, FailCount= 6
2021-07-22T21:01:27.780Z,1626987687.780 [DAT](INFO): Powering up
2021-07-22T21:01:27.780Z,1626987687.780 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:01:35.447Z,1626987695.447 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:01:35.448Z,1626987695.448 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:01:35.851Z,1626987695.851 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:01:45.952Z,1626987705.952 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:01:45.954Z,1626987705.954 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:01:46.355Z,1626987706.355 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:01:56.456Z,1626987716.456 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:01:56.458Z,1626987716.458 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:01:56.859Z,1626987716.859 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:01.947Z,1626987721.947 [CommandLine](IMPORTANT): got command show stack
2021-07-22T21:02:01.947Z,1626987721.947 [CommandLine](IMPORTANT): Behavior Stack:

2021-07-22T21:02:01.947Z,1626987721.947 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample
2021-07-22T21:02:01.947Z,1626987721.947 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:TriggerESP
2021-07-22T21:02:06.959Z,1626987726.959 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:06.960Z,1626987726.960 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:07.363Z,1626987727.363 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:17.463Z,1626987737.463 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:17.464Z,1626987737.464 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:17.867Z,1626987737.867 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:21.923Z,1626987741.923 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:02:21.923Z,1626987741.923 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-07-22T21:02:21.924Z,1626987741.924 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:02:21.926Z,1626987741.926 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:02:21.926Z,1626987741.926 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2021-07-22T21:02:21.926Z,1626987741.926 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:02:21.937Z,1626987741.937 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:02:21.938Z,1626987741.938 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:02:22.340Z,1626987742.340 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:02:22.341Z,1626987742.341 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-07-22T21:02:22.341Z,1626987742.341 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:02:22.341Z,1626987742.341 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2021-07-22T21:02:22.724Z,1626987742.724 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:02:27.967Z,1626987747.967 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:27.968Z,1626987747.968 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:27.983Z,1626987747.983 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:02:27.983Z,1626987747.983 [DAT] Communications Fault, FailCount= 7
2021-07-22T21:02:27.983Z,1626987747.983 [DAT](ERROR): Communications Fault
2021-07-22T21:02:28.001Z,1626987748.001 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:02:28.371Z,1626987748.371 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:28.395Z,1626987748.395 [DAT](INFO): Powering down
2021-07-22T21:02:29.203Z,1626987749.203 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:02:29.203Z,1626987749.203 [DAT] No Fault, FailCount= 7
2021-07-22T21:02:31.627Z,1626987751.627 [DAT](INFO): Powering up
2021-07-22T21:02:31.627Z,1626987751.627 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:02:38.471Z,1626987758.471 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:38.472Z,1626987758.472 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:38.875Z,1626987758.875 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:43.623Z,1626987763.623 [CommandLine](IMPORTANT): got command failComponent
2021-07-22T21:02:43.623Z,1626987763.623 [CommandLine](IMPORTANT): Failed components:
2021-07-22T21:02:43.624Z,1626987763.624 [CommandLine](IMPORTANT): No failed Components.
2021-07-22T21:02:48.975Z,1626987768.975 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:48.976Z,1626987768.976 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:49.379Z,1626987769.379 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:02:54.727Z,1626987774.727 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T21:02:59.479Z,1626987779.479 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:02:59.480Z,1626987779.480 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:02:59.883Z,1626987779.883 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:03:00.782Z,1626987780.782 [CommandLine](IMPORTANT): got command get ESPComponent.loadAtStartup
2021-07-22T21:03:00.783Z,1626987780.783 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup 1 bool
2021-07-22T21:03:03.376Z,1626987783.376 [CommandLine](IMPORTANT): got command show stack
2021-07-22T21:03:03.376Z,1626987783.376 [CommandLine](IMPORTANT): Behavior Stack:

2021-07-22T21:03:03.377Z,1626987783.377 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample
2021-07-22T21:03:03.377Z,1626987783.377 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:TriggerESP
2021-07-22T21:03:06.802Z,1626987786.802 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size.
2021-07-22T21:03:09.983Z,1626987789.983 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:03:09.984Z,1626987789.984 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:03:10.387Z,1626987790.387 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:03:10.484Z,1626987790.484 [CommandLine](IMPORTANT): got command show stack
2021-07-22T21:03:10.484Z,1626987790.484 [CommandLine](IMPORTANT): Behavior Stack:

2021-07-22T21:03:10.484Z,1626987790.484 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample
2021-07-22T21:03:10.484Z,1626987790.484 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:TriggerESP
2021-07-22T21:03:13.358Z,1626987793.358 [CommandLine](IMPORTANT): got command stop
2021-07-22T21:03:13.358Z,1626987793.358 [CommandLine](IMPORTANT): Scheduling is paused
2021-07-22T21:03:13.358Z,1626987793.358 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2021-07-22T21:03:13.633Z,1626987793.633 [MissionManager](INFO): MissionManager is completed.
2021-07-22T21:03:13.634Z,1626987793.634 [MissionManager](INFO): Uninitializing Mission sample_lab
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab] Stopped
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab:A.AbortSample] Stopped
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample.
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab:SampleRepeater] Stopped
2021-07-22T21:03:13.634Z,1626987793.634 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater
2021-07-22T21:03:13.635Z,1626987793.635 [sample_lab:SampleRepeater:TriggerESP] Stopped
2021-07-22T21:03:14.035Z,1626987794.035 [MissionManager](IMPORTANT): Started mission Default
2021-07-22T21:03:14.036Z,1626987794.036 [Default] Running Loop=1
2021-07-22T21:03:14.036Z,1626987794.036 [Default](DEBUG): Aggregate::initialize Default
2021-07-22T21:03:14.036Z,1626987794.036 [Default:B.GoToSurface] Running Loop=1
2021-07-22T21:03:14.036Z,1626987794.036 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-07-22T21:03:14.036Z,1626987794.036 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-07-22T21:03:14.037Z,1626987794.037 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-07-22T21:03:14.037Z,1626987794.037 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-07-22T21:03:14.037Z,1626987794.037 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-07-22T21:03:14.038Z,1626987794.038 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-07-22T21:03:14.038Z,1626987794.038 [Default:A.Wait] Running Loop=1
2021-07-22T21:03:14.038Z,1626987794.038 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-07-22T21:03:20.487Z,1626987800.487 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:03:20.488Z,1626987800.488 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port: Could not bind socket to port due to error: Address already in use errno=98
2021-07-22T21:03:21.295Z,1626987801.295 [ESPComponent](INFO): powering down ESP
2021-07-22T21:03:21.296Z,1626987801.296 [ESPComponent](INFO): powering down ESP secondary power supply
2021-07-22T21:03:27.370Z,1626987807.370 [Default:A.Wait](INFO): Done Waiting.
2021-07-22T21:03:27.370Z,1626987807.370 [Default:A.Wait] Stopped
2021-07-22T21:03:27.370Z,1626987807.370 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-07-22T21:03:27.779Z,1626987807.779 [Default:CheckIn] Running Loop=1
2021-07-22T21:03:27.779Z,1626987807.779 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-07-22T21:03:27.779Z,1626987807.779 [Default:CheckIn:Read_GPS] Running Loop=1
2021-07-22T21:03:31.808Z,1626987811.808 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:03:31.808Z,1626987811.808 [DAT] Communications Fault, FailCount= 8
2021-07-22T21:03:31.808Z,1626987811.808 [DAT](ERROR): Communications Fault
2021-07-22T21:03:31.867Z,1626987811.867 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:03:31.868Z,1626987811.868 [CBIT](FAULT): Communications Fault in component: DAT
2021-07-22T21:03:32.257Z,1626987812.257 [DAT](INFO): Powering down
2021-07-22T21:03:47.975Z,1626987827.975 [BPC1](ERROR): Battery stick #33 (s/n: 01B6) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.976Z,1626987827.976 [BPC1](ERROR): Battery stick #35 (s/n: 01F9) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.976Z,1626987827.976 [BPC1](ERROR): Battery stick #39 (s/n: 01F7) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.977Z,1626987827.977 [BPC1](ERROR): Battery stick #40 (s/n: 01E9) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0BD0.
2021-07-22T21:03:47.978Z,1626987827.978 [BPC1](ERROR): Battery stick #41 (s/n: 024C) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.979Z,1626987827.979 [BPC1](ERROR): Battery stick #43 (s/n: 01F6) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.980Z,1626987827.980 [BPC1](ERROR): Battery stick #47 (s/n: 0255) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.981Z,1626987827.981 [BPC1](ERROR): Battery stick #48 (s/n: 021B) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.981Z,1626987827.981 [BPC1](ERROR): Battery stick #49 (s/n: 0283) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.982Z,1626987827.982 [BPC1](ERROR): Battery stick #51 (s/n: 0256) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.983Z,1626987827.983 [BPC1](ERROR): Battery stick #55 (s/n: 024B) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.984Z,1626987827.984 [BPC1](ERROR): Battery stick #56 (s/n: 01FB) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.985Z,1626987827.985 [BPC1](ERROR): Battery stick #57 (s/n: 0282) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0AD0.
2021-07-22T21:03:47.986Z,1626987827.986 [BPC1](ERROR): Battery stick #58 (s/n: 0286) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x0BD0.
2021-07-22T21:03:47.986Z,1626987827.986 [BPC1](INFO): Calculating totals. Valid battery stick count: 45. Valid reserve battery stick count: 3.
2021-07-22T21:03:47.990Z,1626987827.990 [BPC1](INFO): Received data from all battery sticks.
2021-07-22T21:04:00.491Z,1626987840.491 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-07-22T21:04:00.573Z,1626987840.573 [NAL9602](ERROR): received: 
+CSQ:0

OK
2021-07-22T21:04:07.191Z,1626987847.191 [DataOverHttps](IMPORTANT): SBD MTMSN=20210722T210405
2021-07-22T21:04:14.229Z,1626987854.229 [DataOverHttps](INFO): Received command:load Maintenance/sample_lab.xml;set sample_lab.CartridgeType -6 count;set sample_lab.NumberOfSamples 2 count;run
2021-07-22T21:04:14.249Z,1626987854.249 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:04:14.254Z,1626987854.254 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:04:14.335Z,1626987854.335 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2021-07-22T21:04:14.337Z,1626987854.337 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2021-07-22T21:04:14.355Z,1626987854.355 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2021-07-22T21:04:14.356Z,1626987854.356 [sample_lab:A.AbortSample](DEBUG): Construct.
2021-07-22T21:04:14.372Z,1626987854.372 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct.
2021-07-22T21:04:14.388Z,1626987854.388 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Science="Tethys/Science"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sample http://okeanids.mbari.org/tethys/Xml/Sample.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="sample_lab">

    <Description>
        This mission is designed to run in the lab only and triggers an ESP
        sample with specified type.
    </Description>

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

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4)
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Sample:AbortSample>
        <Parallel/>
    </Sample:AbortSample>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Syslog Severity="Important">Sampling ESP cartridge type <Arg Name="CartridgeType"/><Units:count/></Syslog>

        <Science:ESPCartridgeSelect>
            <Sequence/>
            <Timeout Duration="P1M"/>
            <Setting><Science:ESPCartridgeSelect.cartridgeType/><Arg Name="CartridgeType"/></Setting>
        </Science:ESPCartridgeSelect>

        <ReadDatum Id="TriggerESP">
            <Science:ESPComponent.sampling/>
        </ReadDatum>

        <ReadDatum Id="WaitForESP">
            <Science:ESPComponent.sample_number/>
        </ReadDatum>

    </Aggregate>

</Mission>


2021-07-22T21:04:14.388Z,1626987854.388 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml
2021-07-22T21:04:17.332Z,1626987857.332 [CommandLine](IMPORTANT): got command set sample_lab.CartridgeType -6.000000 count
2021-07-22T21:04:17.334Z,1626987857.334 [CommandLine](IMPORTANT): got command set sample_lab.NumberOfSamples 2.000000 count
2021-07-22T21:04:17.334Z,1626987857.334 [CommandLine](IMPORTANT): got command run
2021-07-22T21:04:17.394Z,1626987857.394 [CommandLine](IMPORTANT): Running 
2021-07-22T21:04:17.486Z,1626987857.486 [Default] Stopped
2021-07-22T21:04:17.486Z,1626987857.486 [Default](DEBUG): Aggregate::uninitialize Default
2021-07-22T21:04:17.486Z,1626987857.486 [Default:B.GoToSurface] Stopped
2021-07-22T21:04:17.486Z,1626987857.486 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-07-22T21:04:17.486Z,1626987857.486 [Default:CheckIn] Stopped
2021-07-22T21:04:17.486Z,1626987857.486 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-07-22T21:04:17.487Z,1626987857.487 [Default:CheckIn:Read_GPS] Stopped
2021-07-22T21:04:17.487Z,1626987857.487 [MissionManager](IMPORTANT): Started mission sample_lab
2021-07-22T21:04:17.487Z,1626987857.487 [sample_lab] Running Loop=1
2021-07-22T21:04:17.487Z,1626987857.487 [sample_lab](DEBUG): Aggregate::initialize sample_lab
2021-07-22T21:04:17.487Z,1626987857.487 [sample_lab:A.AbortSample] Running Loop=1
2021-07-22T21:04:17.487Z,1626987857.487 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2021-07-22T21:04:17.488Z,1626987857.488 [sample_lab:SampleRepeater] Running Loop=1
2021-07-22T21:04:17.488Z,1626987857.488 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2021-07-22T21:04:17.488Z,1626987857.488 [sample_lab:SampleRepeater:A] Running Loop=1
2021-07-22T21:04:17.489Z,1626987857.489 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -6.000000 count 
2021-07-22T21:04:17.489Z,1626987857.489 [sample_lab:SampleRepeater:A] Stopped
2021-07-22T21:04:17.489Z,1626987857.489 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2021-07-22T21:04:17.489Z,1626987857.489 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2021-07-22T21:04:17.489Z,1626987857.489 [sample_lab:A.AbortSample] Running Loop=1
2021-07-22T21:04:17.870Z,1626987857.870 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -6.
2021-07-22T21:04:17.870Z,1626987857.870 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2021-07-22T21:04:17.870Z,1626987857.870 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2021-07-22T21:04:17.870Z,1626987857.870 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2021-07-22T21:04:18.278Z,1626987858.278 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2021-07-22T21:04:19.067Z,1626987859.067 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:04:22.740Z,1626987862.740 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:04:22.740Z,1626987862.740 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-07-22T21:04:22.740Z,1626987862.740 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:04:22.743Z,1626987862.743 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:04:22.743Z,1626987862.743 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2021-07-22T21:04:22.743Z,1626987862.743 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:04:22.754Z,1626987862.754 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:04:22.755Z,1626987862.755 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:04:23.132Z,1626987863.132 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:04:23.133Z,1626987863.133 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-07-22T21:04:23.133Z,1626987863.133 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:04:23.133Z,1626987863.133 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2021-07-22T21:04:23.522Z,1626987863.522 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:04:29.167Z,1626987869.167 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:04:29.168Z,1626987869.168 [ESPComponent](INFO): powering up ESP
2021-07-22T21:04:29.185Z,1626987869.185 [ESPComponent](INFO): powering up ESP secondary power supply
2021-07-22T21:04:29.206Z,1626987869.206 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 134.89.10.51:134.89.10.60 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 134.89.10.32 ms-dns 134.89.10.10
2021-07-22T21:04:29.331Z,1626987869.331 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2021-07-22T21:04:30.380Z,1626987870.380 [ESPComponent](INFO): console:

2021-07-22T21:04:30.783Z,1626987870.783 [ESPComponent](INFO): console:NAND:  256 MiB
2021-07-22T21:04:31.187Z,1626987871.187 [ESPComponent](INFO): console:
BOOTMODE: SPI
2021-07-22T21:04:31.591Z,1626987871.591 [ESPComponent](INFO): console:
reading SPI NOR..Done
2021-07-22T21:04:31.995Z,1626987871.995 [ESPComponent](INFO): console:

2021-07-22T21:04:32.399Z,1626987872.399 [ESPComponent](INFO): console:

2021-07-22T21:04:32.804Z,1626987872.804 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51)
2021-07-22T21:04:33.207Z,1626987873.207 [ESPComponent](INFO): console:

2021-07-22T21:04:33.613Z,1626987873.613 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2021-07-22T21:04:34.016Z,1626987874.016 [ESPComponent](INFO): console:
flash params are already written into flash
2021-07-22T21:04:34.430Z,1626987874.430 [ESPComponent](INFO): console:
DRAM:  64 MB
2021-07-22T21:04:34.823Z,1626987874.823 [ESPComponent](INFO): console:
In:    serial
2021-07-22T21:04:35.228Z,1626987875.228 [ESPComponent](INFO): console:
Out:   serial
2021-07-22T21:04:35.631Z,1626987875.631 [ESPComponent](INFO): console:
Err:   serial
2021-07-22T21:04:36.035Z,1626987876.035 [ESPComponent](INFO): console:
Net:   ks8851_mll
2021-07-22T21:04:36.440Z,1626987876.440 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2021-07-22T21:04:36.845Z,1626987876.845 [ESPComponent](INFO): console:
4096 KiB S25FL032P at 0:0 is now current device
2021-07-22T21:04:37.248Z,1626987877.248 [ESPComponent](INFO): console:
Loading kernel from SPI flash...done
2021-07-22T21:04:37.652Z,1626987877.652 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2021-07-22T21:04:38.056Z,1626987878.056 [ESPComponent](INFO): console:
   Image Name:   Linux-3.18.140-lpc31-mbari3
2021-07-22T21:04:38.460Z,1626987878.460 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2021-07-22T21:04:38.865Z,1626987878.865 [ESPComponent](INFO): console:
   Data Size:    2331832 Bytes =  2.2 MB
2021-07-22T21:04:39.267Z,1626987879.267 [ESPComponent](INFO): console:
   Load Address: 30008000
2021-07-22T21:04:39.672Z,1626987879.672 [ESPComponent](INFO): console:
   Entry Point:  30008000
2021-07-22T21:04:40.076Z,1626987880.076 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2021-07-22T21:04:40.480Z,1626987880.480 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2021-07-22T21:04:40.883Z,1626987880.883 [ESPComponent](INFO): console:
OK
2021-07-22T21:04:41.288Z,1626987881.288 [ESPComponent](INFO): console:

2021-07-22T21:04:41.691Z,1626987881.691 [ESPComponent](INFO): console:
Starting kernel ...
2021-07-22T21:04:42.095Z,1626987882.095 [ESPComponent](INFO): console:

2021-07-22T21:04:42.500Z,1626987882.500 [ESPComponent](INFO): console:
Uncompressing Linux... Booting kernel...
2021-07-22T21:04:42.904Z,1626987882.904 [ESPComponent](INFO): console:
[    0.05] MBARI ESP 3G
2021-07-22T21:04:43.307Z,1626987883.307 [ESPComponent](INFO): console:

2021-07-22T21:04:43.712Z,1626987883.712 [ESPComponent](INFO): console:INIT: version 2.85 booting
2021-07-22T21:04:44.115Z,1626987884.115 [ESPComponent](INFO): console:

2021-07-22T21:04:44.521Z,1626987884.521 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2021-07-22T21:04:44.924Z,1626987884.924 [ESPComponent](INFO): console:
ESPlrauvSIM
2021-07-22T21:04:45.327Z,1626987885.327 [ESPComponent](INFO): console:

2021-07-22T21:04:45.732Z,1626987885.732 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2021-07-22T21:04:46.136Z,1626987886.136 [ESPComponent](INFO): console:

2021-07-22T21:04:46.539Z,1626987886.539 [ESPComponent](INFO): console:Loading kernel modules
2021-07-22T21:04:46.946Z,1626987886.946 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2021-07-22T21:04:47.348Z,1626987887.348 [ESPComponent](INFO): console:
Starting device events handler
2021-07-22T21:04:47.821Z,1626987887.821 [ESPComponent](INFO): console:

2021-07-22T21:04:53.469Z,1626987893.469 [ESPComponent](INFO): console:Set system clock to:  
2021-07-22T21:04:53.812Z,1626987893.812 [ESPComponent](INFO): console:Thu Jul 22 14:04:53 PDT 2021
2021-07-22T21:04:54.216Z,1626987894.216 [ESPComponent](INFO): console:
Starting syslogd klogd...
2021-07-22T21:04:54.620Z,1626987894.620 [ESPComponent](INFO): console:
stopped syslogd (pid 686)
2021-07-22T21:04:55.023Z,1626987895.023 [ESPComponent](INFO): console:
Bringing up lo ...
2021-07-22T21:04:55.427Z,1626987895.427 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2021-07-22T21:04:55.832Z,1626987895.832 [ESPComponent](INFO): console:
Packet forwarding enabled
2021-07-22T21:04:56.236Z,1626987896.236 [ESPComponent](INFO): console:
Bringing up platform ...
2021-07-22T21:04:56.639Z,1626987896.639 [ESPComponent](INFO): console:
Starting portmap...
2021-07-22T21:04:57.044Z,1626987897.044 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2021-07-22T21:04:57.448Z,1626987897.448 [ESPComponent](INFO): console:
Network unavailable:  Local time is Thu Jul 22 14:04:55 PDT 2021
2021-07-22T21:04:57.851Z,1626987897.851 [ESPComponent](INFO): console:
Starting chronyd...
2021-07-22T21:04:58.256Z,1626987898.256 [ESPComponent](INFO): console:
Starting thttpd...
2021-07-22T21:04:58.729Z,1626987898.729 [ESPComponent](INFO): console:

2021-07-22T21:04:59.468Z,1626987899.468 [ESPComponent](INFO): console:Starting dnsmasq...
2021-07-22T21:04:59.941Z,1626987899.941 [ESPComponent](INFO): console:

2021-07-22T21:05:03.507Z,1626987903.507 [ESPComponent](INFO): console:Bringing up wired ...
2021-07-22T21:05:03.911Z,1626987903.911 [ESPComponent](INFO): console:

2021-07-22T21:05:04.317Z,1626987904.317 [ESPComponent](INFO): console:

2021-07-22T21:05:04.720Z,1626987904.720 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.73 -- 6/17/21 brent@mbari.org
2021-07-22T21:05:05.123Z,1626987905.123 [ESPComponent](INFO): console:

2021-07-22T21:05:05.529Z,1626987905.529 [ESPComponent](INFO): console:ESPlrauvSIM login: Determining IP configuration for wired ...udhcpc (v1.11.2) started
2021-07-22T21:05:05.931Z,1626987905.931 [ESPComponent](INFO): console:
Sending discover...
2021-07-22T21:05:06.405Z,1626987906.405 [ESPComponent](INFO): console:

2021-07-22T21:05:08.759Z,1626987908.759 [ESPComponent](INFO): console:Sending discover...
2021-07-22T21:05:09.225Z,1626987909.225 [ESPComponent](INFO): console:

2021-07-22T21:05:11.991Z,1626987911.991 [ESPComponent](INFO): console:Sending discover...
2021-07-22T21:05:12.465Z,1626987912.465 [ESPComponent](INFO): console:

2021-07-22T21:05:14.820Z,1626987914.820 [ESPComponent](INFO): console:No lease, forking to background
2021-07-22T21:05:15.262Z,1626987915.262 [ESPComponent](INFO): console:
Bringing up direct ...
2021-07-22T21:05:15.627Z,1626987915.627 [ESPComponent](IMPORTANT): ESP has connected as client
2021-07-22T21:05:16.441Z,1626987916.441 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -6
2021-07-22T21:05:16.458Z,1626987916.458 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2021-07-22T21:05:16.458Z,1626987916.458 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2021-07-22T21:05:16.475Z,1626987916.475 [sample_lab:SampleRepeater:TriggerESP] Stopped
2021-07-22T21:05:16.475Z,1626987916.475 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1
2021-07-22T21:05:16.870Z,1626987916.870 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2021-07-22T21:05:17.648Z,1626987917.648 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2021-07-22T21:05:18.051Z,1626987918.051 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2021-07-22T21:05:19.669Z,1626987919.669 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2021-07-22T21:05:56.464Z,1626987956.464 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@45,archive_bac)
2021-07-22T21:05:58.079Z,1626987958.079 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@5.0)
2021-07-22T21:05:58.485Z,1626987958.485 [ESPComponent](DEBUG): ESPClient: got filtering timeoutMinutes=5.640000 issuedCmd_=Cmd.startFiltering
2021-07-22T21:05:58.888Z,1626987958.888 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2021-07-22T21:06:06.582Z,1626987966.582 [Power24vConverter](INFO): Powering down.
2021-07-22T21:06:23.566Z,1626987983.566 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:06:23.566Z,1626987983.566 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-07-22T21:06:23.566Z,1626987983.566 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:06:23.568Z,1626987983.568 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:06:23.569Z,1626987983.569 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2021-07-22T21:06:23.569Z,1626987983.569 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:06:23.580Z,1626987983.580 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:06:23.580Z,1626987983.580 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:06:23.954Z,1626987983.954 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:06:23.954Z,1626987983.954 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-07-22T21:06:23.955Z,1626987983.955 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:06:23.955Z,1626987983.955 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2021-07-22T21:06:24.355Z,1626987984.355 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:06:40.904Z,1626988000.904 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2021-07-22T21:06:41.308Z,1626988001.308 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2021-07-22T21:07:09.991Z,1626988029.991 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@10.0)
2021-07-22T21:07:09.992Z,1626988029.992 [ESPComponent](DEBUG): Writing sampleVolume=10.000000
2021-07-22T21:07:10.396Z,1626988030.396 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@10.0)
2021-07-22T21:07:12.417Z,1626988032.417 [ESPComponent](DEBUG): ESPClient: got processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing
2021-07-22T21:07:12.820Z,1626988032.820 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@45,archive_bac)
2021-07-22T21:08:24.744Z,1626988104.744 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:08:24.744Z,1626988104.744 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-07-22T21:08:24.744Z,1626988104.744 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:08:24.747Z,1626988104.747 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:08:24.747Z,1626988104.747 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2021-07-22T21:08:24.747Z,1626988104.747 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:08:24.758Z,1626988104.758 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:08:24.759Z,1626988104.759 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:08:25.155Z,1626988105.155 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:08:25.155Z,1626988105.155 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-07-22T21:08:25.155Z,1626988105.155 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:08:25.155Z,1626988105.155 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2021-07-22T21:08:25.556Z,1626988105.556 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:08:32.012Z,1626988112.012 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-07-22T21:08:32.030Z,1626988112.030 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:08:32.030Z,1626988112.030 [DAT] No Fault, FailCount= 8
2021-07-22T21:08:32.415Z,1626988112.415 [DAT](INFO): Powering up
2021-07-22T21:08:32.415Z,1626988112.415 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:08:32.819Z,1626988112.819 [Power24vConverter](INFO): Powering up.
2021-07-22T21:09:02.714Z,1626988142.714 [NAL9602](INFO): Not Powering down - fast GPS
2021-07-22T21:09:32.611Z,1626988172.611 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:09:32.612Z,1626988172.612 [DAT] Communications Fault, FailCount= 1
2021-07-22T21:09:32.612Z,1626988172.612 [DAT](ERROR): Communications Fault
2021-07-22T21:09:32.662Z,1626988172.662 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:09:33.018Z,1626988173.018 [DAT](INFO): Powering down
2021-07-22T21:09:33.850Z,1626988173.850 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:09:33.850Z,1626988173.850 [DAT] No Fault, FailCount= 1
2021-07-22T21:09:36.247Z,1626988176.247 [DAT](INFO): Powering up
2021-07-22T21:09:36.247Z,1626988176.247 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:10:03.307Z,1626988203.307 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@45,archive_bac)
2021-07-22T21:10:13.409Z,1626988213.409 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr' /LRAUV/ESPlogs &
2021-07-22T21:10:13.443Z,1626988213.443 [ESPComponent](INFO): closing pipe.
2021-07-22T21:10:13.812Z,1626988213.812 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2021-07-22T21:10:25.940Z,1626988225.940 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:10:25.940Z,1626988225.940 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-07-22T21:10:25.940Z,1626988225.940 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:10:25.943Z,1626988225.943 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:10:25.943Z,1626988225.943 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 5
2021-07-22T21:10:25.943Z,1626988225.943 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:10:25.963Z,1626988225.963 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:10:25.963Z,1626988225.963 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:10:26.355Z,1626988226.355 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:10:26.355Z,1626988226.355 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-07-22T21:10:26.355Z,1626988226.355 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:10:26.355Z,1626988226.355 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 5
2021-07-22T21:10:26.747Z,1626988226.747 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:10:36.438Z,1626988236.438 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:10:36.438Z,1626988236.438 [DAT] Communications Fault, FailCount= 2
2021-07-22T21:10:36.438Z,1626988236.438 [DAT](ERROR): Communications Fault
2021-07-22T21:10:36.456Z,1626988236.456 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:10:36.843Z,1626988236.843 [DAT](INFO): Powering down
2021-07-22T21:10:37.670Z,1626988237.670 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:10:37.670Z,1626988237.670 [DAT] No Fault, FailCount= 2
2021-07-22T21:10:40.074Z,1626988240.074 [DAT](INFO): Powering up
2021-07-22T21:10:40.075Z,1626988240.075 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:11:40.271Z,1626988300.271 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:11:40.271Z,1626988300.271 [DAT] Communications Fault, FailCount= 3
2021-07-22T21:11:40.271Z,1626988300.271 [DAT](ERROR): Communications Fault
2021-07-22T21:11:40.322Z,1626988300.322 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:11:40.673Z,1626988300.673 [DAT](INFO): Powering down
2021-07-22T21:11:41.505Z,1626988301.505 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:11:41.505Z,1626988301.505 [DAT] No Fault, FailCount= 3
2021-07-22T21:11:43.911Z,1626988303.911 [DAT](INFO): Powering up
2021-07-22T21:11:43.911Z,1626988303.911 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:12:27.144Z,1626988347.144 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:12:27.144Z,1626988347.144 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-07-22T21:12:27.144Z,1626988347.144 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:12:27.147Z,1626988347.147 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:12:27.147Z,1626988347.147 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 6
2021-07-22T21:12:27.147Z,1626988347.147 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:12:27.158Z,1626988347.158 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:12:27.159Z,1626988347.159 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:12:27.557Z,1626988347.557 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:12:27.557Z,1626988347.557 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-07-22T21:12:27.558Z,1626988347.558 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:12:27.558Z,1626988347.558 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 6
2021-07-22T21:12:27.953Z,1626988347.953 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:12:44.108Z,1626988364.108 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:12:44.108Z,1626988364.108 [DAT] Communications Fault, FailCount= 4
2021-07-22T21:12:44.109Z,1626988364.109 [DAT](ERROR): Communications Fault
2021-07-22T21:12:44.126Z,1626988364.126 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:12:44.511Z,1626988364.511 [DAT](INFO): Powering down
2021-07-22T21:12:45.336Z,1626988365.336 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:12:45.336Z,1626988365.336 [DAT] No Fault, FailCount= 4
2021-07-22T21:12:47.743Z,1626988367.743 [DAT](INFO): Powering up
2021-07-22T21:12:47.743Z,1626988367.743 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:13:47.939Z,1626988427.939 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:13:47.939Z,1626988427.939 [DAT] Communications Fault, FailCount= 5
2021-07-22T21:13:47.939Z,1626988427.939 [DAT](ERROR): Communications Fault
2021-07-22T21:13:47.984Z,1626988427.984 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:13:48.343Z,1626988428.343 [DAT](INFO): Powering down
2021-07-22T21:13:49.171Z,1626988429.171 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:13:49.171Z,1626988429.171 [DAT] No Fault, FailCount= 5
2021-07-22T21:13:51.575Z,1626988431.575 [DAT](INFO): Powering up
2021-07-22T21:13:51.575Z,1626988431.575 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:14:28.344Z,1626988468.344 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:14:28.344Z,1626988468.344 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-07-22T21:14:28.344Z,1626988468.344 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:14:28.347Z,1626988468.347 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:14:28.347Z,1626988468.347 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 7
2021-07-22T21:14:28.347Z,1626988468.347 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:14:28.402Z,1626988468.402 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:14:28.402Z,1626988468.402 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:14:28.758Z,1626988468.758 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:14:28.758Z,1626988468.758 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-07-22T21:14:28.759Z,1626988468.759 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:14:28.759Z,1626988468.759 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 7
2021-07-22T21:14:29.153Z,1626988469.153 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:14:51.799Z,1626988491.799 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:14:51.799Z,1626988491.799 [DAT] Communications Fault, FailCount= 6
2021-07-22T21:14:51.799Z,1626988491.799 [DAT](ERROR): Communications Fault
2021-07-22T21:14:51.817Z,1626988491.817 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:14:52.199Z,1626988492.199 [DAT](INFO): Powering down
2021-07-22T21:14:53.038Z,1626988493.038 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:14:53.038Z,1626988493.038 [DAT] No Fault, FailCount= 6
2021-07-22T21:14:55.435Z,1626988495.435 [DAT](INFO): Powering up
2021-07-22T21:14:55.435Z,1626988495.435 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:15:13.607Z,1626988513.607 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2021-07-22T21:15:13.608Z,1626988513.608 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2021-07-22T21:15:13.623Z,1626988513.623 [sample_lab:SampleRepeater:WaitForESP] Stopped
2021-07-22T21:15:13.624Z,1626988513.624 [sample_lab:SampleRepeater](INFO): Completed sample_lab:SampleRepeater
2021-07-22T21:15:13.624Z,1626988513.624 [sample_lab:SampleRepeater] Stopped
2021-07-22T21:15:13.624Z,1626988513.624 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater
2021-07-22T21:15:13.624Z,1626988513.624 [sample_lab:SampleRepeater](INFO): Running loop #2
2021-07-22T21:15:13.624Z,1626988513.624 [sample_lab:SampleRepeater] Running Loop=2
2021-07-22T21:15:13.625Z,1626988513.625 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2021-07-22T21:15:13.625Z,1626988513.625 [sample_lab:SampleRepeater:A] Running Loop=1
2021-07-22T21:15:14.012Z,1626988514.012 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@14:05:27.49 Selecting Cartridge 45
@14:07:08.23 Sampled  10.0ml

2021-07-22T21:15:14.012Z,1626988514.012 [ESPComponent](INFO): powering down ESP
2021-07-22T21:15:14.013Z,1626988514.013 [ESPComponent](INFO): powering down ESP secondary power supply
2021-07-22T21:15:14.167Z,1626988514.167 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -6.000000 count 
2021-07-22T21:15:14.167Z,1626988514.167 [sample_lab:SampleRepeater:A] Stopped
2021-07-22T21:15:14.167Z,1626988514.167 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2021-07-22T21:15:14.167Z,1626988514.167 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2021-07-22T21:15:14.433Z,1626988514.433 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -6.
2021-07-22T21:15:14.433Z,1626988514.433 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2021-07-22T21:15:14.433Z,1626988514.433 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2021-07-22T21:15:14.434Z,1626988514.434 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2021-07-22T21:15:15.627Z,1626988515.627 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2021-07-22T21:15:25.727Z,1626988525.727 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2021-07-22T21:15:25.798Z,1626988525.798 [ESPComponent](INFO): powering up ESP
2021-07-22T21:15:25.817Z,1626988525.817 [ESPComponent](INFO): powering up ESP secondary power supply
2021-07-22T21:15:25.834Z,1626988525.834 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 134.89.10.51:134.89.10.60 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 134.89.10.32 ms-dns 134.89.10.10
2021-07-22T21:15:25.932Z,1626988525.932 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2021-07-22T21:15:26.939Z,1626988526.939 [ESPComponent](INFO): console:

2021-07-22T21:15:27.343Z,1626988527.343 [ESPComponent](INFO): console:NAND:  256 MiB
2021-07-22T21:15:27.747Z,1626988527.747 [ESPComponent](INFO): console:
BOOTMODE: SPI
2021-07-22T21:15:28.151Z,1626988528.151 [ESPComponent](INFO): console:
reading SPI NOR..Done
2021-07-22T21:15:28.555Z,1626988528.555 [ESPComponent](INFO): console:

2021-07-22T21:15:28.959Z,1626988528.959 [ESPComponent](INFO): console:

2021-07-22T21:15:29.365Z,1626988529.365 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51)
2021-07-22T21:15:29.767Z,1626988529.767 [ESPComponent](INFO): console:

2021-07-22T21:15:30.171Z,1626988530.171 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2021-07-22T21:15:30.576Z,1626988530.576 [ESPComponent](INFO): console:
flash params are already written into flash
2021-07-22T21:15:30.979Z,1626988530.979 [ESPComponent](INFO): console:
DRAM:  64 MB
2021-07-22T21:15:31.383Z,1626988531.383 [ESPComponent](INFO): console:
In:    serial
2021-07-22T21:15:31.788Z,1626988531.788 [ESPComponent](INFO): console:
Out:   serial
2021-07-22T21:15:32.192Z,1626988532.192 [ESPComponent](INFO): console:
Err:   serial
2021-07-22T21:15:32.595Z,1626988532.595 [ESPComponent](INFO): console:
Net:   ks8851_mll
2021-07-22T21:15:33.000Z,1626988533.000 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2021-07-22T21:15:33.404Z,1626988533.404 [ESPComponent](INFO): console:
4096 KiB S25FL032P at 0:0 is now current device
2021-07-22T21:15:33.808Z,1626988533.808 [ESPComponent](INFO): console:
Loading kernel from SPI flash...done
2021-07-22T21:15:34.212Z,1626988534.212 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2021-07-22T21:15:34.617Z,1626988534.617 [ESPComponent](INFO): console:
   Image Name:   Linux-3.18.140-lpc31-mbari3
2021-07-22T21:15:35.021Z,1626988535.021 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2021-07-22T21:15:35.424Z,1626988535.424 [ESPComponent](INFO): console:
   Data Size:    2331832 Bytes =  2.2 MB
2021-07-22T21:15:35.828Z,1626988535.828 [ESPComponent](INFO): console:
   Load Address: 30008000
2021-07-22T21:15:36.232Z,1626988536.232 [ESPComponent](INFO): console:
   Entry Point:  30008000
2021-07-22T21:15:36.636Z,1626988536.636 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2021-07-22T21:15:37.040Z,1626988537.040 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2021-07-22T21:15:37.443Z,1626988537.443 [ESPComponent](INFO): console:
OK
2021-07-22T21:15:37.847Z,1626988537.847 [ESPComponent](INFO): console:

2021-07-22T21:15:38.249Z,1626988538.249 [ESPComponent](INFO): console:
Starting kernel ...
2021-07-22T21:15:38.652Z,1626988538.652 [ESPComponent](INFO): console:

2021-07-22T21:15:39.057Z,1626988539.057 [ESPComponent](INFO): console:
Uncompressing Linux... Booting kernel...
2021-07-22T21:15:39.461Z,1626988539.461 [ESPComponent](INFO): console:
[    0.03] MBARI ESP 3G
2021-07-22T21:15:39.864Z,1626988539.864 [ESPComponent](INFO): console:

2021-07-22T21:15:40.269Z,1626988540.269 [ESPComponent](INFO): console:INIT: version 2.85 booting
2021-07-22T21:15:40.672Z,1626988540.672 [ESPComponent](INFO): console:

2021-07-22T21:15:41.077Z,1626988541.077 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2021-07-22T21:15:41.481Z,1626988541.481 [ESPComponent](INFO): console:
ESPlrauvSIM
2021-07-22T21:15:41.884Z,1626988541.884 [ESPComponent](INFO): console:

2021-07-22T21:15:42.289Z,1626988542.289 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2021-07-22T21:15:42.693Z,1626988542.693 [ESPComponent](INFO): console:

2021-07-22T21:15:43.097Z,1626988543.097 [ESPComponent](INFO): console:Loading kernel modules
2021-07-22T21:15:43.501Z,1626988543.501 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2021-07-22T21:15:43.905Z,1626988543.905 [ESPComponent](INFO): console:
Starting device events handler
2021-07-22T21:15:44.371Z,1626988544.371 [ESPComponent](INFO): console:

2021-07-22T21:15:46.794Z,1626988546.794 [ESPComponent](INFO): console:Set system clock to:  
2021-07-22T21:15:47.945Z,1626988547.945 [ESPComponent](INFO): console:Thu Jul 22 14:15:47 PDT 2021
2021-07-22T21:15:48.349Z,1626988548.349 [ESPComponent](INFO): console:
Starting syslogd klogd...
2021-07-22T21:15:48.753Z,1626988548.753 [ESPComponent](INFO): console:
stopped syslogd (pid 691)
2021-07-22T21:15:49.157Z,1626988549.157 [ESPComponent](INFO): console:
Bringing up lo ...
2021-07-22T21:15:49.570Z,1626988549.570 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2021-07-22T21:15:49.965Z,1626988549.965 [ESPComponent](INFO): console:
Packet forwarding enabled
2021-07-22T21:15:50.369Z,1626988550.369 [ESPComponent](INFO): console:
Bringing up platform ...
2021-07-22T21:15:50.772Z,1626988550.772 [ESPComponent](INFO): console:
Starting portmap...
2021-07-22T21:15:51.177Z,1626988551.177 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2021-07-22T21:15:51.582Z,1626988551.582 [ESPComponent](INFO): console:
Network unavailable:  Local time is Thu Jul 22 14:15:49 PDT 2021
2021-07-22T21:15:51.984Z,1626988551.984 [ESPComponent](INFO): console:
Starting chronyd...
2021-07-22T21:15:52.389Z,1626988552.389 [ESPComponent](INFO): console:
Starting thttpd...
2021-07-22T21:15:52.862Z,1626988552.862 [ESPComponent](INFO): console:

2021-07-22T21:15:53.603Z,1626988553.603 [ESPComponent](INFO): console:Starting dnsmasq...
2021-07-22T21:15:54.067Z,1626988554.067 [ESPComponent](INFO): console:

2021-07-22T21:15:55.632Z,1626988555.632 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:15:55.632Z,1626988555.632 [DAT] Communications Fault, FailCount= 7
2021-07-22T21:15:55.632Z,1626988555.632 [DAT](ERROR): Communications Fault
2021-07-22T21:15:55.659Z,1626988555.659 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:15:56.028Z,1626988556.028 [DAT](INFO): Powering down
2021-07-22T21:15:56.855Z,1626988556.855 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:15:56.855Z,1626988556.855 [DAT] No Fault, FailCount= 7
2021-07-22T21:15:57.641Z,1626988557.641 [ESPComponent](INFO): console:Bringing up wired ...
2021-07-22T21:15:58.044Z,1626988558.044 [ESPComponent](INFO): console:

2021-07-22T21:15:58.449Z,1626988558.449 [ESPComponent](INFO): console:

2021-07-22T21:15:58.855Z,1626988558.855 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.73 -- 6/17/21 brent@mbari.org
2021-07-22T21:15:59.256Z,1626988559.256 [ESPComponent](INFO): console:

2021-07-22T21:15:59.264Z,1626988559.264 [DAT](INFO): Powering up
2021-07-22T21:15:59.264Z,1626988559.264 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:15:59.662Z,1626988559.662 [ESPComponent](INFO): console:ESPlrauvSIM login: Determining IP configuration for wired ...udhcpc (v1.11.2) started
2021-07-22T21:16:00.064Z,1626988560.064 [ESPComponent](INFO): console:
Sending discover...
2021-07-22T21:16:00.530Z,1626988560.530 [ESPComponent](INFO): console:

2021-07-22T21:16:02.892Z,1626988562.892 [ESPComponent](INFO): console:Sending discover...
2021-07-22T21:16:03.358Z,1626988563.358 [ESPComponent](INFO): console:

2021-07-22T21:16:06.125Z,1626988566.125 [ESPComponent](INFO): console:Sending discover...
2021-07-22T21:16:06.598Z,1626988566.598 [ESPComponent](INFO): console:

2021-07-22T21:16:08.953Z,1626988568.953 [ESPComponent](IMPORTANT): ESP has connected as client
2021-07-22T21:16:09.764Z,1626988569.764 [ESPComponent](IMPORTANT): [sample #2] Setting cartridge argument to -6
2021-07-22T21:16:09.765Z,1626988569.765 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2021-07-22T21:16:09.765Z,1626988569.765 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2
2021-07-22T21:16:09.810Z,1626988569.810 [sample_lab:SampleRepeater:TriggerESP] Stopped
2021-07-22T21:16:09.810Z,1626988569.810 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1
2021-07-22T21:16:10.569Z,1626988570.569 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG
2021-07-22T21:16:10.972Z,1626988570.972 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS
2021-07-22T21:16:12.993Z,1626988572.993 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE
2021-07-22T21:16:29.169Z,1626988589.169 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:16:29.169Z,1626988589.169 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-07-22T21:16:29.169Z,1626988589.169 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:16:29.172Z,1626988589.172 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:16:29.172Z,1626988589.172 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 8
2021-07-22T21:16:29.172Z,1626988589.172 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:16:29.183Z,1626988589.183 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:16:29.184Z,1626988589.184 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:16:29.589Z,1626988589.589 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:16:29.590Z,1626988589.590 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-07-22T21:16:29.595Z,1626988589.595 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:16:29.597Z,1626988589.597 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 8
2021-07-22T21:16:29.990Z,1626988589.990 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:16:49.757Z,1626988609.757 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PRIMING (@44,archive_bac)
2021-07-22T21:16:51.373Z,1626988611.373 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PRIMING (@5.0)
2021-07-22T21:16:51.778Z,1626988611.778 [ESPComponent](DEBUG): ESPClient: got filtering timeoutMinutes=5.640000 issuedCmd_=Cmd.startFiltering
2021-07-22T21:16:52.181Z,1626988612.181 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2021-07-22T21:16:59.458Z,1626988619.458 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:16:59.458Z,1626988619.458 [DAT] Communications Fault, FailCount= 8
2021-07-22T21:16:59.458Z,1626988619.458 [DAT](ERROR): Communications Fault
2021-07-22T21:16:59.476Z,1626988619.476 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:16:59.476Z,1626988619.476 [CBIT](FAULT): Communications Fault in component: DAT
2021-07-22T21:16:59.864Z,1626988619.864 [DAT](INFO): Powering down
2021-07-22T21:17:34.197Z,1626988654.197 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_FILTERING (@0.0)
2021-07-22T21:17:34.600Z,1626988654.600 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2021-07-22T21:18:03.285Z,1626988683.285 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PAUSED (@10.0)
2021-07-22T21:18:03.285Z,1626988683.285 [ESPComponent](DEBUG): Writing sampleVolume=10.000000
2021-07-22T21:18:03.689Z,1626988683.689 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PROCESSING (@10.0)
2021-07-22T21:18:05.710Z,1626988685.710 [ESPComponent](DEBUG): ESPClient: got processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing
2021-07-22T21:18:06.113Z,1626988686.113 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PROCESSED (@44,archive_bac)
2021-07-22T21:18:30.359Z,1626988710.359 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:18:30.359Z,1626988710.359 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-07-22T21:18:30.359Z,1626988710.359 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:18:30.362Z,1626988710.362 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:18:30.362Z,1626988710.362 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 9
2021-07-22T21:18:30.362Z,1626988710.362 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:18:30.374Z,1626988710.374 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:18:30.375Z,1626988710.375 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:18:30.788Z,1626988710.788 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:18:30.788Z,1626988710.788 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-07-22T21:18:30.788Z,1626988710.788 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:18:30.789Z,1626988710.789 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 9
2021-07-22T21:18:31.178Z,1626988711.178 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:19:34.195Z,1626988774.195 [Power24vConverter](INFO): Powering down.
2021-07-22T21:20:31.562Z,1626988831.562 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:20:31.562Z,1626988831.562 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-07-22T21:20:31.562Z,1626988831.562 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:20:31.565Z,1626988831.565 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:20:31.565Z,1626988831.565 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 10
2021-07-22T21:20:31.565Z,1626988831.565 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:20:31.576Z,1626988831.576 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:20:31.577Z,1626988831.577 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:20:31.996Z,1626988831.996 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:20:31.996Z,1626988831.996 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-07-22T21:20:31.997Z,1626988831.997 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:20:31.997Z,1626988831.997 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 10
2021-07-22T21:20:32.370Z,1626988832.370 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:20:56.601Z,1626988856.601 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPING (@44,archive_bac)
2021-07-22T21:21:06.701Z,1626988866.701 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr' /LRAUV/ESPlogs &
2021-07-22T21:21:06.729Z,1626988866.729 [ESPComponent](INFO): closing pipe.
2021-07-22T21:21:07.105Z,1626988867.105 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPED
2021-07-22T21:21:59.648Z,1626988919.648 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:21:59.649Z,1626988919.649 [DAT] No Fault, FailCount= 8
2021-07-22T21:22:00.030Z,1626988920.030 [DAT](INFO): Powering up
2021-07-22T21:22:00.031Z,1626988920.031 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:22:00.436Z,1626988920.436 [Power24vConverter](INFO): Powering up.
2021-07-22T21:22:32.765Z,1626988952.765 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:22:32.765Z,1626988952.765 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-07-22T21:22:32.765Z,1626988952.765 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:22:32.768Z,1626988952.768 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:22:32.768Z,1626988952.768 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 11
2021-07-22T21:22:32.768Z,1626988952.768 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:22:32.807Z,1626988952.807 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:22:32.808Z,1626988952.808 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:22:33.183Z,1626988953.183 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:22:33.184Z,1626988953.184 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-07-22T21:22:33.184Z,1626988953.184 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:22:33.184Z,1626988953.184 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 11
2021-07-22T21:22:33.574Z,1626988953.574 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:22:43.672Z,1626988963.672 [CommandLine](IMPORTANT): got command show stack
2021-07-22T21:22:43.672Z,1626988963.672 [CommandLine](IMPORTANT): Behavior Stack:

2021-07-22T21:22:43.673Z,1626988963.673 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample
2021-07-22T21:22:43.673Z,1626988963.673 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:WaitForESP
2021-07-22T21:23:00.228Z,1626988980.228 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:23:00.228Z,1626988980.228 [DAT] Communications Fault, FailCount= 1
2021-07-22T21:23:00.228Z,1626988980.228 [DAT](ERROR): Communications Fault
2021-07-22T21:23:00.247Z,1626988980.247 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:23:00.633Z,1626988980.633 [DAT](INFO): Powering down
2021-07-22T21:23:01.460Z,1626988981.460 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:23:01.460Z,1626988981.460 [DAT] No Fault, FailCount= 1
2021-07-22T21:23:03.868Z,1626988983.868 [DAT](INFO): Powering up
2021-07-22T21:23:03.868Z,1626988983.868 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:24:04.160Z,1626989044.160 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:24:04.160Z,1626989044.160 [DAT] Communications Fault, FailCount= 2
2021-07-22T21:24:04.160Z,1626989044.160 [DAT](ERROR): Communications Fault
2021-07-22T21:24:04.178Z,1626989044.178 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:24:04.561Z,1626989044.561 [DAT](INFO): Powering down
2021-07-22T21:24:05.389Z,1626989045.389 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:24:05.389Z,1626989045.389 [DAT] No Fault, FailCount= 2
2021-07-22T21:24:07.796Z,1626989047.796 [DAT](INFO): Powering up
2021-07-22T21:24:07.796Z,1626989047.796 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:24:33.654Z,1626989073.654 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:24:33.654Z,1626989073.654 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-07-22T21:24:33.654Z,1626989073.654 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-07-22T21:24:33.657Z,1626989073.657 [DeadReckonUsingSpeedCalculator](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2021-07-22T21:24:33.657Z,1626989073.657 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 12
2021-07-22T21:24:33.657Z,1626989073.657 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2021-07-22T21:24:33.669Z,1626989073.669 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-07-22T21:24:33.669Z,1626989073.669 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2021-07-22T21:24:34.079Z,1626989074.079 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-07-22T21:24:34.079Z,1626989074.079 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-07-22T21:24:34.079Z,1626989074.079 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2021-07-22T21:24:34.080Z,1626989074.080 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 12
2021-07-22T21:24:34.462Z,1626989074.462 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2021-07-22T21:25:07.992Z,1626989107.992 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:25:07.992Z,1626989107.992 [DAT] Communications Fault, FailCount= 3
2021-07-22T21:25:07.992Z,1626989107.992 [DAT](ERROR): Communications Fault
2021-07-22T21:25:08.010Z,1626989108.010 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:25:08.392Z,1626989108.392 [DAT](INFO): Powering down
2021-07-22T21:25:09.217Z,1626989109.217 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:25:09.217Z,1626989109.217 [DAT] No Fault, FailCount= 3
2021-07-22T21:25:11.628Z,1626989111.628 [DAT](INFO): Powering up
2021-07-22T21:25:11.628Z,1626989111.628 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:26:06.968Z,1626989166.968 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence completed normally.
2021-07-22T21:26:06.969Z,1626989166.969 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2
2021-07-22T21:26:06.981Z,1626989166.981 [sample_lab:SampleRepeater:WaitForESP] Stopped
2021-07-22T21:26:06.981Z,1626989166.981 [sample_lab:SampleRepeater](INFO): Completed sample_lab:SampleRepeater
2021-07-22T21:26:06.981Z,1626989166.981 [sample_lab:SampleRepeater] Stopped
2021-07-22T21:26:06.981Z,1626989166.981 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater
2021-07-22T21:26:06.982Z,1626989166.982 [sample_lab](INFO): Completed sample_lab
2021-07-22T21:26:06.982Z,1626989166.982 [MissionManager](INFO): sample_lab is completed.
2021-07-22T21:26:06.982Z,1626989166.982 [MissionManager](INFO): Uninitializing Mission sample_lab
2021-07-22T21:26:06.982Z,1626989166.982 [sample_lab] Stopped
2021-07-22T21:26:06.983Z,1626989166.983 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab
2021-07-22T21:26:06.983Z,1626989166.983 [sample_lab:A.AbortSample] Stopped
2021-07-22T21:26:06.983Z,1626989166.983 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample.
2021-07-22T21:26:07.373Z,1626989167.373 [ESPComponent](IMPORTANT): [sample #2] ESP log summary report (2 messages):
@14:16:20.44 Selecting Cartridge 44
@14:18:01.05 Sampled  10.0ml

2021-07-22T21:26:07.373Z,1626989167.373 [ESPComponent](INFO): powering down ESP
2021-07-22T21:26:07.374Z,1626989167.374 [ESPComponent](INFO): powering down ESP secondary power supply
2021-07-22T21:26:07.528Z,1626989167.528 [MissionManager](IMPORTANT): Started mission Default
2021-07-22T21:26:07.528Z,1626989167.528 [Default] Running Loop=1
2021-07-22T21:26:07.528Z,1626989167.528 [Default](DEBUG): Aggregate::initialize Default
2021-07-22T21:26:07.528Z,1626989167.528 [Default:B.GoToSurface] Running Loop=1
2021-07-22T21:26:07.529Z,1626989167.529 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-07-22T21:26:07.529Z,1626989167.529 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-07-22T21:26:07.529Z,1626989167.529 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-07-22T21:26:07.530Z,1626989167.530 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-07-22T21:26:07.530Z,1626989167.530 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-07-22T21:26:07.531Z,1626989167.531 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-07-22T21:26:07.531Z,1626989167.531 [Default:A.Wait] Running Loop=1
2021-07-22T21:26:07.531Z,1626989167.531 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-07-22T21:26:11.818Z,1626989171.818 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2021-07-22T21:26:11.818Z,1626989171.818 [DAT] Communications Fault, FailCount= 4
2021-07-22T21:26:11.819Z,1626989171.819 [DAT](ERROR): Communications Fault
2021-07-22T21:26:11.837Z,1626989171.837 [CBIT](ERROR): Communications Fault in component: DAT
2021-07-22T21:26:12.225Z,1626989172.225 [DAT](INFO): Powering down
2021-07-22T21:26:13.048Z,1626989173.048 [CBIT](INFO): Clearing failed state for component DAT
2021-07-22T21:26:13.048Z,1626989173.048 [DAT] No Fault, FailCount= 4
2021-07-22T21:26:15.457Z,1626989175.457 [DAT](INFO): Powering up
2021-07-22T21:26:15.458Z,1626989175.457 [DAT](DEBUG): Initializing DAT.
2021-07-22T21:26:20.723Z,1626989180.723 [Default:A.Wait](INFO): Done Waiting.
2021-07-22T21:26:20.723Z,1626989180.723 [Default:A.Wait] Stopped
2021-07-22T21:26:20.723Z,1626989180.723 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-07-22T21:26:21.120Z,1626989181.120 [Default:CheckIn] Running Loop=1
2021-07-22T21:26:21.120Z,1626989181.120 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-07-22T21:26:21.120Z,1626989181.120 [Default:CheckIn:Read_GPS] Running Loop=1
2021-07-22T21:26:22.731Z,1626989182.731 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-07-22T21:26:22.732Z,1626989182.732 [NAL9602] Data Fault, FailCount= 1
2021-07-22T21:26:22.732Z,1626989182.732 [NAL9602](ERROR): Data Fault
2021-07-22T21:26:22.786Z,1626989182.786 [CBIT](ERROR): Data Fault in component: NAL9602
2021-07-22T21:26:23.131Z,1626989183.131 [NAL9602](INFO): Powering down
2021-07-22T21:26:23.959Z,1626989183.959 [CBIT](INFO): Clearing failed state for component NAL9602
2021-07-22T21:26:23.959Z,1626989183.959 [NAL9602] No Fault, FailCount= 1