2025-08-07T16:08:47.513Z,1754582927.513 [Supervisor](DEBUG): Initializing supervisor. 2025-08-07T16:08:47.528Z,1754582927.528 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2025-08-07T16:08:47.528Z,1754582927.528 [SyncHandler](INFO): Protected caller Thread ID is 832 2025-08-07T16:08:47.529Z,1754582927.529 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2025-08-07T16:08:47.540Z,1754582927.540 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2025-08-07T16:08:47.540Z,1754582927.540 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 833 2025-08-07T16:08:47.544Z,1754582927.544 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2025-08-07T16:08:47.589Z,1754582927.589 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2025-08-07T16:08:47.600Z,1754582927.600 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2025-08-07T16:08:47.600Z,1754582927.600 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 834 2025-08-07T16:08:47.605Z,1754582927.605 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2025-08-07T16:08:47.616Z,1754582927.616 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2025-08-07T16:08:47.616Z,1754582927.616 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 835 2025-08-07T16:08:47.618Z,1754582927.618 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2025-08-07T16:08:47.628Z,1754582927.628 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2025-08-07T16:08:47.628Z,1754582927.628 [logger ThreadHandler](INFO): Protected caller Thread ID is 836 2025-08-07T16:08:47.632Z,1754582927.632 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2025-08-07T16:08:47.633Z,1754582927.633 [Supervisor](INFO): Looking for Config files in directory: Config/ 2025-08-07T16:08:47.646Z,1754582927.646 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2025-08-07T16:08:48.337Z,1754582928.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2025-08-07T16:08:48.338Z,1754582928.338 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2025-08-07T16:08:49.420Z,1754582929.420 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2025-08-07T16:08:49.422Z,1754582929.422 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2025-08-07T16:08:49.540Z,1754582929.540 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2025-08-07T16:08:49.541Z,1754582929.541 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2025-08-07T16:08:50.108Z,1754582930.108 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2025-08-07T16:08:50.110Z,1754582930.110 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2025-08-07T16:08:50.217Z,1754582930.217 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2025-08-07T16:08:50.217Z,1754582930.217 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2025-08-07T16:08:50.319Z,1754582930.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Guidance 2025-08-07T16:08:50.320Z,1754582930.320 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2025-08-07T16:08:50.825Z,1754582930.825 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2025-08-07T16:08:50.825Z,1754582930.825 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2025-08-07T16:08:51.349Z,1754582931.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2025-08-07T16:08:51.350Z,1754582931.350 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2025-08-07T16:08:51.499Z,1754582931.499 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2025-08-07T16:08:51.501Z,1754582931.501 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2025-08-07T16:08:51.763Z,1754582931.763 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2025-08-07T16:08:51.764Z,1754582931.764 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2025-08-07T16:08:52.344Z,1754582932.344 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2025-08-07T16:08:52.345Z,1754582932.345 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2025-08-07T16:08:52.766Z,1754582932.766 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2025-08-07T16:08:52.767Z,1754582932.767 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2025-08-07T16:08:52.857Z,1754582932.857 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2025-08-07T16:08:53.054Z,1754582933.054 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2025-08-07T16:08:53.055Z,1754582933.055 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2025-08-07T16:08:53.319Z,1754582933.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2025-08-07T16:08:53.320Z,1754582933.320 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2025-08-07T16:08:53.641Z,1754582933.641 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2025-08-07T16:08:53.643Z,1754582933.643 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/ 2025-08-07T16:08:53.648Z,1754582933.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg 2025-08-07T16:08:53.758Z,1754582933.758 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg 2025-08-07T16:08:53.926Z,1754582933.926 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg 2025-08-07T16:08:54.025Z,1754582934.025 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg 2025-08-07T16:08:54.120Z,1754582934.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg 2025-08-07T16:08:54.246Z,1754582934.246 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/workSite.cfg 2025-08-07T16:08:54.351Z,1754582934.351 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Dock.cfg 2025-08-07T16:08:54.471Z,1754582934.471 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg 2025-08-07T16:08:54.586Z,1754582934.586 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg 2025-08-07T16:08:54.869Z,1754582934.869 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2025-08-07T16:08:54.870Z,1754582934.870 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg 2025-08-07T16:08:55.015Z,1754582935.015 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg 2025-08-07T16:08:55.120Z,1754582935.120 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg 2025-08-07T16:08:55.223Z,1754582935.223 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg 2025-08-07T16:08:55.318Z,1754582935.318 [Supervisor](IMPORTANT): Reloading configuration overrides from Data/persisted.cfg 2025-08-07T16:08:55.330Z,1754582935.330 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2025-08-07T16:08:55.504Z,1754582935.504 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2025-08-07T16:08:55.505Z,1754582935.505 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2025-08-07T16:08:55.521Z,1754582935.521 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2025-08-07T16:08:55.521Z,1754582935.521 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2025-08-07T16:08:55.594Z,1754582935.594 [DepthRateCalculator] Loaded 2025-08-07T16:08:55.594Z,1754582935.594 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2025-08-07T16:08:55.600Z,1754582935.600 [PitchRateCalculator] Loaded 2025-08-07T16:08:55.600Z,1754582935.600 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2025-08-07T16:08:55.611Z,1754582935.611 [SpeedCalculator] Loaded 2025-08-07T16:08:55.611Z,1754582935.611 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2025-08-07T16:08:55.617Z,1754582935.617 [YawRateCalculator] Loaded 2025-08-07T16:08:55.617Z,1754582935.617 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2025-08-07T16:08:55.639Z,1754582935.639 [ElevatorOffsetCalculator] Loaded 2025-08-07T16:08:55.639Z,1754582935.639 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2025-08-07T16:08:55.640Z,1754582935.640 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2025-08-07T16:08:55.640Z,1754582935.640 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2025-08-07T16:08:55.714Z,1754582935.714 [VerticalControl](DEBUG): Construct VerticalControl. 2025-08-07T16:08:55.772Z,1754582935.772 [VerticalControl] Loaded 2025-08-07T16:08:55.772Z,1754582935.772 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2025-08-07T16:08:55.775Z,1754582935.775 [HorizontalControl](DEBUG): Construct HorizontalControl. 2025-08-07T16:08:55.824Z,1754582935.824 [HorizontalControl] Loaded 2025-08-07T16:08:55.824Z,1754582935.824 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2025-08-07T16:08:55.826Z,1754582935.826 [SpeedControl](DEBUG): Construct SpeedControl. 2025-08-07T16:08:55.829Z,1754582935.829 [SpeedControl] Loaded 2025-08-07T16:08:55.829Z,1754582935.829 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2025-08-07T16:08:55.832Z,1754582935.832 [LoopControl](DEBUG): Construct LoopControl. 2025-08-07T16:08:55.833Z,1754582935.833 [LoopControl] Loaded 2025-08-07T16:08:55.833Z,1754582935.833 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2025-08-07T16:08:55.833Z,1754582935.833 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2025-08-07T16:08:55.834Z,1754582935.834 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2025-08-07T16:08:56.676Z,1754582936.676 [DeadReckonUsingMultipleVelocitySources] Loaded 2025-08-07T16:08:56.676Z,1754582936.676 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2025-08-07T16:08:56.690Z,1754582936.690 [NavChart] Loaded 2025-08-07T16:08:56.691Z,1754582936.691 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2025-08-07T16:08:56.696Z,1754582936.696 [UniversalFixResidualReporter] Loaded 2025-08-07T16:08:56.697Z,1754582936.697 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2025-08-07T16:08:56.697Z,1754582936.697 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2025-08-07T16:08:56.698Z,1754582936.698 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2025-08-07T16:08:56.917Z,1754582936.917 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2025-08-07T16:08:56.917Z,1754582936.917 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2025-08-07T16:08:57.768Z,1754582937.768 [AHRS_M2] Loaded 2025-08-07T16:08:57.768Z,1754582937.768 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2025-08-07T16:08:58.022Z,1754582938.022 [BackseatComponent] Loaded 2025-08-07T16:08:58.023Z,1754582938.023 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2025-08-07T16:08:58.024Z,1754582938.024 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 4093E4E0 2025-08-07T16:08:58.024Z,1754582938.024 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 924 2025-08-07T16:08:58.027Z,1754582938.027 [LcmUniversalReporter] Loaded 2025-08-07T16:08:58.027Z,1754582938.027 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2025-08-07T16:08:58.896Z,1754582938.896 [BPC1] Loaded 2025-08-07T16:08:58.896Z,1754582938.896 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2025-08-07T16:08:59.001Z,1754582939.001 [DAT] Loaded 2025-08-07T16:08:59.001Z,1754582939.001 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2025-08-07T16:08:59.002Z,1754582939.002 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 4096E4E0 2025-08-07T16:08:59.002Z,1754582939.002 [DAT ThreadHandler](INFO): Protected caller Thread ID is 925 2025-08-07T16:08:59.148Z,1754582939.148 [DataOverHttps] Loaded 2025-08-07T16:08:59.148Z,1754582939.148 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2025-08-07T16:08:59.149Z,1754582939.149 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4099E4E0 2025-08-07T16:08:59.150Z,1754582939.150 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 926 2025-08-07T16:08:59.174Z,1754582939.174 [Depth_Keller] Loaded 2025-08-07T16:08:59.174Z,1754582939.174 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2025-08-07T16:08:59.242Z,1754582939.242 [NAL9602] Loaded 2025-08-07T16:08:59.242Z,1754582939.242 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2025-08-07T16:08:59.273Z,1754582939.273 [Onboard] Loaded 2025-08-07T16:08:59.273Z,1754582939.273 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2025-08-07T16:08:59.274Z,1754582939.274 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409CE4E0 2025-08-07T16:08:59.275Z,1754582939.275 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 927 2025-08-07T16:08:59.289Z,1754582939.289 [Power24vConverter] Loaded 2025-08-07T16:08:59.290Z,1754582939.290 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2025-08-07T16:08:59.306Z,1754582939.306 [Radio_Surface] Loaded 2025-08-07T16:08:59.306Z,1754582939.306 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2025-08-07T16:08:59.307Z,1754582939.307 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409FE4E0 2025-08-07T16:08:59.308Z,1754582939.308 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 928 2025-08-07T16:08:59.357Z,1754582939.357 [RDI_Pathfinder] Loaded 2025-08-07T16:08:59.357Z,1754582939.357 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2025-08-07T16:08:59.373Z,1754582939.373 [Sonardyne_Nano] Loaded 2025-08-07T16:08:59.373Z,1754582939.373 [ComponentRegistry](DEBUG): SyncComponent "Sonardyne_Nano" handled in the control thread. 2025-08-07T16:08:59.374Z,1754582939.374 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2025-08-07T16:08:59.374Z,1754582939.374 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2025-08-07T16:08:59.547Z,1754582939.547 [BuoyancyServo] Loaded 2025-08-07T16:08:59.547Z,1754582939.547 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2025-08-07T16:08:59.571Z,1754582939.571 [ElevatorServo] Loaded 2025-08-07T16:08:59.571Z,1754582939.571 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2025-08-07T16:08:59.603Z,1754582939.603 [DockingStepper] Loaded 2025-08-07T16:08:59.603Z,1754582939.603 [ComponentRegistry](DEBUG): SyncComponent "DockingStepper" handled in the control thread. 2025-08-07T16:08:59.627Z,1754582939.627 [MassServo] Loaded 2025-08-07T16:08:59.627Z,1754582939.627 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2025-08-07T16:08:59.649Z,1754582939.649 [RudderServo] Loaded 2025-08-07T16:08:59.649Z,1754582939.649 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2025-08-07T16:08:59.666Z,1754582939.666 [ThrusterHE] Loaded 2025-08-07T16:08:59.667Z,1754582939.667 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread. 2025-08-07T16:08:59.667Z,1754582939.667 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2025-08-07T16:08:59.668Z,1754582939.668 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2025-08-07T16:08:59.756Z,1754582939.756 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2025-08-07T16:08:59.756Z,1754582939.756 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2025-08-07T16:08:59.805Z,1754582939.805 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2025-08-07T16:08:59.805Z,1754582939.805 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2025-08-07T16:09:00.222Z,1754582940.222 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2025-08-07T16:09:00.223Z,1754582940.223 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2025-08-07T16:09:00.789Z,1754582940.789 [CTD_Seabird] Loaded 2025-08-07T16:09:00.789Z,1754582940.789 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2025-08-07T16:09:00.790Z,1754582940.790 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40BBE4E0 2025-08-07T16:09:00.791Z,1754582940.791 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 929 2025-08-07T16:09:00.932Z,1754582940.932 [ESPComponent] Loaded 2025-08-07T16:09:00.932Z,1754582940.932 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2025-08-07T16:09:01.156Z,1754582941.156 [PAR_Licor] Loaded 2025-08-07T16:09:01.156Z,1754582941.156 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2025-08-07T16:09:01.347Z,1754582941.347 [WetLabsBB2FL] Loaded 2025-08-07T16:09:01.347Z,1754582941.347 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2025-08-07T16:09:01.365Z,1754582941.365 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40BEE4E0 2025-08-07T16:09:01.365Z,1754582941.365 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 930 2025-08-07T16:09:01.366Z,1754582941.366 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2025-08-07T16:09:01.366Z,1754582941.366 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2025-08-07T16:09:01.659Z,1754582941.659 [SBIT](DEBUG): Construct Startup Built In Test. 2025-08-07T16:09:01.668Z,1754582941.668 [SBIT] Loaded 2025-08-07T16:09:01.669Z,1754582941.669 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2025-08-07T16:09:01.672Z,1754582941.672 [IBIT](DEBUG): Construct Initiated Built In Test. 2025-08-07T16:09:01.685Z,1754582941.685 [IBIT] Loaded 2025-08-07T16:09:01.685Z,1754582941.685 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2025-08-07T16:09:01.691Z,1754582941.691 [CBIT](DEBUG): Construct Continuous Built In Test. 2025-08-07T16:09:01.801Z,1754582941.801 [CBIT] Loaded 2025-08-07T16:09:01.801Z,1754582941.801 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2025-08-07T16:09:01.835Z,1754582941.835 [GFScanner] Loaded 2025-08-07T16:09:01.836Z,1754582941.836 [ComponentRegistry](DEBUG): SyncComponent "GFScanner" handled in the control thread. 2025-08-07T16:09:01.836Z,1754582941.836 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2025-08-07T16:09:01.843Z,1754582941.843 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2025-08-07T16:09:01.846Z,1754582941.846 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2025-08-07T16:09:01.857Z,1754582941.857 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2025-08-07T16:09:01.858Z,1754582941.858 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C694E0 2025-08-07T16:09:01.859Z,1754582941.859 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 931 2025-08-07T16:09:01.863Z,1754582941.863 [Supervisor](INFO): Main Thread ID is 825 2025-08-07T16:09:01.863Z,1754582941.863 [Supervisor](DEBUG): Running supervisor. 2025-08-07T16:09:01.864Z,1754582941.864 [CommandExec ThreadHandler](INFO): Handler Thread ID is 932 2025-08-07T16:09:01.864Z,1754582941.864 [CommandExec](INFO): Initializing the command executive. 2025-08-07T16:09:01.866Z,1754582941.866 [CommandLine ThreadHandler](INFO): Handler Thread ID is 933 2025-08-07T16:09:01.868Z,1754582941.868 [controlThread ThreadHandler](INFO): Handler Thread ID is 934 2025-08-07T16:09:01.869Z,1754582941.869 [controlThread](DEBUG): Initializing ControlThread 2025-08-07T16:09:01.869Z,1754582941.869 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2025-08-07T16:09:01.870Z,1754582941.870 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2025-08-07T16:09:01.870Z,1754582941.870 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2025-08-07T16:09:01.870Z,1754582941.870 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2025-08-07T16:09:01.871Z,1754582941.871 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2025-08-07T16:09:01.871Z,1754582941.871 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2025-08-07T16:09:01.873Z,1754582941.873 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2025-08-07T16:09:01.874Z,1754582941.874 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2025-08-07T16:09:01.874Z,1754582941.874 [LoopControl](DEBUG): Initialize LoopControlComponent. 2025-08-07T16:09:01.875Z,1754582941.875 [NavChart](DEBUG): Initialize NavChart Navigation. 2025-08-07T16:09:01.876Z,1754582941.876 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2025-08-07T16:09:01.880Z,1754582941.880 [SBIT](INFO): Initialize SBIT Component. 2025-08-07T16:09:01.881Z,1754582941.881 [SBIT](IMPORTANT): git: 2025-05-06A 2025-08-07T16:09:01.881Z,1754582941.881 [SBIT](INFO): git hash: 35bdf637df5168d7c8016b5753c9843f2e4eccbc 2025-08-07T16:09:01.881Z,1754582941.881 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2025-08-07T16:09:01.882Z,1754582941.882 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Tue Sep 24 11:12:27 PDT 2019 Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021 2025-08-07T16:09:01.883Z,1754582941.883 [SBIT](INFO): Beginning SBIT in 105.000000 seconds. 2025-08-07T16:09:01.884Z,1754582941.884 [IBIT](INFO): Initialize IBIT Component. 2025-08-07T16:09:01.885Z,1754582941.885 [CBIT](DEBUG): Initialize CBIT Component. 2025-08-07T16:09:01.886Z,1754582941.886 [logger ThreadHandler](INFO): Handler Thread ID is 935 2025-08-07T16:09:01.896Z,1754582941.896 [CBIT](DEBUG): Initialized mux pins. 2025-08-07T16:09:01.896Z,1754582941.896 [CBIT](DEBUG): Initializing the watchdog timer. 2025-08-07T16:09:01.904Z,1754582941.904 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 936 2025-08-07T16:09:01.916Z,1754582941.916 [DAT ThreadHandler](INFO): Handler Thread ID is 937 2025-08-07T16:09:01.917Z,1754582941.917 [DAT](INFO): Powering up 2025-08-07T16:09:01.917Z,1754582941.917 [DAT](DEBUG): Initializing DAT. 2025-08-07T16:09:01.920Z,1754582941.920 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2025-08-07T16:09:01.920Z,1754582941.920 [CBIT](DEBUG): Initializing heartbeat. 2025-08-07T16:09:01.922Z,1754582941.922 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 939 2025-08-07T16:09:01.924Z,1754582941.924 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2025-08-07T16:09:01.933Z,1754582941.933 [Onboard ThreadHandler](INFO): Handler Thread ID is 940 2025-08-07T16:09:01.953Z,1754582941.953 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 941 2025-08-07T16:09:01.969Z,1754582941.969 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 942 2025-08-07T16:09:01.969Z,1754582941.969 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2025-08-07T16:09:01.973Z,1754582941.973 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 944 2025-08-07T16:09:01.976Z,1754582941.976 [WetLabsBB2FL](INFO): Powering up 2025-08-07T16:09:01.977Z,1754582941.977 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 946 2025-08-07T16:09:01.986Z,1754582941.986 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2025-08-07T16:09:01.986Z,1754582941.986 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2025-08-07T16:09:01.986Z,1754582941.986 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2025-08-07T16:09:01.986Z,1754582941.986 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2025-08-07T16:09:01.986Z,1754582941.986 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2025-08-07T16:09:01.987Z,1754582941.987 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2025-08-07T16:09:01.987Z,1754582941.987 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2025-08-07T16:09:01.987Z,1754582941.987 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2025-08-07T16:09:01.992Z,1754582941.992 [CBIT](DEBUG): Deactivating emergency mode. 2025-08-07T16:09:02.032Z,1754582942.032 [CBIT](DEBUG): Backplane powered. 2025-08-07T16:09:02.032Z,1754582942.032 [GFScanner](DEBUG): Initializing GFScanner 2025-08-07T16:09:02.032Z,1754582942.032 [GFScanner](DEBUG): Deactivating GF circuits. 2025-08-07T16:09:02.037Z,1754582942.037 [MissionManager](IMPORTANT): Using TethysL tl-to-tx parser 2025-08-07T16:09:02.038Z,1754582942.038 [MissionManager](INFO): Loading Mission from file: Missions/underIce/StartupUnder.tl 2025-08-07T16:09:02.038Z,1754582942.038 [MissionManager](DEBUG): TethyslAPI: loading: Missions/underIce/StartupUnder.tl 2025-08-07T16:09:02.061Z,1754582942.061 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/underIce/StartupUnder.tl 2025-08-07T16:09:02.076Z,1754582942.076 [MissionManager](DEBUG): TethyslAPI: Missions/underIce/StartupUnder.tl translated into: 2025-08-07T16:09:02.077Z,1754582942.077 [MissionManager](ERROR): Top node has no child nodes: Mission 2025-08-07T16:09:02.077Z,1754582942.077 [MissionManager](ERROR): Could not load startup mission. 2025-08-07T16:09:02.077Z,1754582942.077 [MissionManager](INFO): Loading Mission from file: Missions/underIce/DefaultWithUndock.tl 2025-08-07T16:09:02.078Z,1754582942.078 [MissionManager](DEBUG): TethyslAPI: loading: Missions/underIce/DefaultWithUndock.tl 2025-08-07T16:09:02.084Z,1754582942.084 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/underIce/DefaultWithUndock.tl 2025-08-07T16:09:02.356Z,1754582942.356 [Radio_Surface](INFO): Powering up 2025-08-07T16:09:02.654Z,1754582942.654 [MissionManager](DEBUG): TethyslAPI: Missions/underIce/DefaultWithUndock.tl translated into: 0 6 10 1 3 30 Timed out while trying to detach from dock at current depth of . Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2025-08-07T16:09:02.678Z,1754582942.678 [MissionManager](INFO): DefineArg DefaultWithUndock.ElapsedSinceDefaultStarted = 0.000000 min 2025-08-07T16:09:02.690Z,1754582942.690 [MissionManager](INFO): DefineArg DefaultWithUndock.DetachTimeout = 6.000000 h 2025-08-07T16:09:02.695Z,1754582942.695 [MissionManager](INFO): DefineArg DefaultWithUndock.TransponderCode = 50 count 2025-08-07T16:09:02.724Z,1754582942.724 [MissionManager](INFO): DefineArg DefaultWithUndock.TrackingUpdatePeriod = 10.000000 s 2025-08-07T16:09:02.744Z,1754582942.744 [MissionManager](INFO): DefineArg DefaultWithUndock.NumberOfPings = 1.000000 count 2025-08-07T16:09:02.748Z,1754582942.748 [MissionManager](INFO): DefineArg DefaultWithUndock.DriftTimeout = 3.000000 min 2025-08-07T16:09:02.749Z,1754582942.749 [DefaultWithUndock:A.Wait](DEBUG): Construct Wait. 2025-08-07T16:09:02.910Z,1754582942.910 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Construct. 2025-08-07T16:09:02.910Z,1754582942.910 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:09:02.971Z,1754582942.971 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Construct GoToSurface. 2025-08-07T16:09:03.032Z,1754582943.032 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2025-08-07T16:09:03.035Z,1754582943.035 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Construct Wait. 2025-08-07T16:09:03.057Z,1754582943.057 [DefaultWithUndock:E.Execute](DEBUG): Construct Execute. 2025-08-07T16:09:03.077Z,1754582943.077 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. mission DefaultWithUndock { arguments { ElapsedSinceDefaultStarted = 0 minute DetachTimeout = 6 hour """ Maximum time duration for the vehicle to detach form the dock. """ TransponderCode = Dock:Dock.transponderCode """ Dock transponder address. """ TrackingUpdatePeriod = 10 second """ Time duration between acoustic range queries while the mission is detaching from the dock. """ NumberOfPings = 1 count """ Number of pings requested each time. """ DriftTimeout = 3 minute """ How long to allow vehicle to drift away from dock before retrying reverse """ } behavior Guidance:Wait { """ Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. """ run in sequence set duration = 30 second } aggregate LeaveDock { run in sequence timeout duration=DetachTimeout { syslog important "Timed out while trying to detach from dock at current depth of " + Universal:depth~meter + "." } # Acoustic tracking directives behavior Estimation:TrackAcousticContact { run while ( Universal:depth > Control:VerticalControl.surfaceThreshold ) set contactLabelSetting = TransponderCode set numberOfSamplesSetting = NumberOfPings set updatePeriodSetting = TrackingUpdatePeriod } # Leave the dock behavior Dock:Undock { run in sequence set driftTimeout = DriftTimeout } } aggregate SurfaceDefault { run in sequence # This mission assumes open water so from here on it's the same old default that's always used behavior Guidance:GoToSurface { run in progression } aggregate CheckIn { run in sequence repeat=288 readDatum id="Read_GPS" { timeout duration=P5M Universal:time_fix } readDatum id="Read_Iridium" { timeout duration=P2H { behavior Guidance:Execute { run in sequence set command = "Burn on" } syslog critical "Dropped weight due to communications timeout." } Universal:platform_communications } behavior Guidance:Wait { run in sequence set duration = 5 minute } assign in sequence ElapsedSinceDefaultStarted = elapsed ( Universal:mission_started ) syslog important "Default mission has been running for " + ElapsedSinceDefaultStarted~minute } } syslog important "Restarting logs and Default mission." behavior Guidance:Execute { run in sequence set command = "restart logs" } } 2025-08-07T16:09:03.082Z,1754582943.082 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,NAL9602,Power24vConverter,RDI_Pathfinder,Sonardyne_Nano,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,DockingStepper,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,GFScanner,LcmUniversalReporter,Reporter,LogSplitter, 2025-08-07T16:09:03.110Z,1754582943.110 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2025-08-07T16:09:03.248Z,1754582943.248 [Depth_Keller](INFO): Initializing. 2025-08-07T16:09:03.249Z,1754582943.249 [Power24vConverter](INFO): Powering up. 2025-08-07T16:09:03.250Z,1754582943.250 [RDI_Pathfinder](IMPORTANT): Expecting PD13 message format 2025-08-07T16:09:03.253Z,1754582943.253 [Sonardyne_Nano](INFO): Initializing. 2025-08-07T16:09:03.296Z,1754582943.296 [DepthRateCalculator](ERROR): Depth measurement is not active 2025-08-07T16:09:03.323Z,1754582943.323 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.328Z,1754582943.328 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2025-08-07T16:09:03.329Z,1754582943.329 [ElevatorServo](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.336Z,1754582943.336 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2025-08-07T16:09:03.337Z,1754582943.337 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.344Z,1754582943.344 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T16:09:03.345Z,1754582943.345 [MassServo](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.352Z,1754582943.352 [MassServo](DEBUG): Initializing MassServo. 2025-08-07T16:09:03.353Z,1754582943.353 [RudderServo](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.360Z,1754582943.360 [RudderServo](DEBUG): Initializing RudderServo. 2025-08-07T16:09:03.361Z,1754582943.361 [ThrusterHE](DEBUG): Initializing EZServoServo. 2025-08-07T16:09:03.368Z,1754582943.368 [ThrusterHE](DEBUG): Initializing ThrusterHE. 2025-08-07T16:09:04.116Z,1754582944.116 [WetLabsBB2FL](INFO): Powering down 2025-08-07T16:09:05.514Z,1754582945.514 [Sonardyne_Nano](ERROR): Failed to get valid response or reached max queue size, flushing UART 2025-08-07T16:09:06.756Z,1754582946.756 [Sonardyne_Nano](IMPORTANT): Found beacon with acoustic ID 2207 2025-08-07T16:09:08.869Z,1754582948.869 [ThrusterHE](ERROR): Zero Speed Commanded. 2025-08-07T16:09:13.764Z,1754582953.764 [DAT](INFO): DAT read: 2025-08-07T16:09:13.766Z,1754582953.766 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2025-08-07T16:09:15.529Z,1754582955.529 [DAT](INFO): DAT read: MF Frequency Band 2025-08-07T16:09:15.530Z,1754582955.530 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0 2025-08-07T16:09:15.530Z,1754582955.530 [DAT](INFO): DAT read: Aug 7 2025 16:09:11 2025-08-07T16:09:16.537Z,1754582956.537 [DAT](INFO): DAT read: Features enabled [Bearing] 2025-08-07T16:09:16.538Z,1754582956.538 [DAT](INFO): DAT read: CONNECT 00600 bits/sec 1 of 4, Rate 1/2 CC 25.00ms MGP 2025-08-07T16:09:16.539Z,1754582956.539 [DAT](INFO): commRate: 600 2025-08-07T16:09:18.604Z,1754582958.604 [DAT](INFO): entering command mode 2025-08-07T16:09:18.804Z,1754582958.804 [DAT](INFO): DAT read: 2025-08-07T16:09:18.805Z,1754582958.805 [DAT](INFO): DAT read: user:1> 2025-08-07T16:09:18.805Z,1754582958.805 [DAT](INFO): setting verbose to 3 2025-08-07T16:09:19.057Z,1754582959.057 [DAT](INFO): DAT read: user:1> 2025-08-07T16:09:19.058Z,1754582959.058 [DAT](INFO): DAT read: Verbose | 3 2025-08-07T16:09:19.058Z,1754582959.058 [DAT](INFO): set verbose to 3 2025-08-07T16:09:19.058Z,1754582959.058 [DAT](INFO): setting DatVerbose to 27440 2025-08-07T16:09:19.309Z,1754582959.309 [DAT](INFO): DAT read: user:2> 2025-08-07T16:09:19.310Z,1754582959.310 [DAT](INFO): DAT read: DatVerbose | 27440 2025-08-07T16:09:19.311Z,1754582959.311 [DAT](INFO): set DatVerbose to 27440 2025-08-07T16:09:19.311Z,1754582959.311 [DAT](INFO): setting transmit power to 8 2025-08-07T16:09:19.561Z,1754582959.561 [DAT](INFO): DAT read: user:3> 2025-08-07T16:09:19.561Z,1754582959.561 [DAT](INFO): DAT read: TxPower | 8 (Max) 2025-08-07T16:09:19.562Z,1754582959.562 [DAT](INFO): set transmit power to 8 2025-08-07T16:09:19.562Z,1754582959.562 [DAT](INFO): setting local address to 11 2025-08-07T16:09:19.813Z,1754582959.813 [DAT](INFO): DAT read: user:4> 2025-08-07T16:09:19.813Z,1754582959.813 [DAT](INFO): DAT read: LocalAddr | 11 2025-08-07T16:09:19.814Z,1754582959.814 [DAT](INFO): set local address to 11 2025-08-07T16:09:19.815Z,1754582959.815 [DAT](INFO): Setting time to: 16:9:19 And date to:8/7/2025 2025-08-07T16:09:20.065Z,1754582960.065 [DAT](INFO): DAT read: user:5> 2025-08-07T16:09:20.065Z,1754582960.065 [DAT](INFO): DAT read: Thu Aug 7, 2025 16:09:19 2025-08-07T16:09:20.066Z,1754582960.066 [DAT](INFO): Local DAT time set to Thu Aug 7, 2025 16:09:19 2025-08-07T16:09:29.353Z,1754582969.353 [NAL9602](INFO): Powering up NAL9602 2025-08-07T16:09:40.265Z,1754582980.265 [NAL9602](INFO): NAL9602 initialized 2025-08-07T16:10:13.854Z,1754583013.854 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:10:24.354Z,1754583024.354 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:10:35.267Z,1754583035.267 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:10:39.493Z,1754583039.493 [CommandExec](IMPORTANT): got command strobe off 2025-08-07T16:10:39.493Z,1754583039.493 [CommandExec](IMPORTANT): Deactivating strobe 2025-08-07T16:10:45.821Z,1754583045.821 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:10:47.352Z,1754583047.352 [SBIT](IMPORTANT): Beginning Startup BIT 2025-08-07T16:10:47.380Z,1754583047.380 [GFScanner](IMPORTANT): Beginning ground fault scan 2025-08-07T16:10:51.904Z,1754583051.904 [GFScanner](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.001126 CHAN A1 (24V): 0.000355 CHAN A2 (12V): -0.000167 CHAN A3 (5V): -0.000840 CHAN B0 (3.3V): -0.000237 CHAN B1 (3.15aV): 0.000719 CHAN B2 (3.15bV): -0.000097 CHAN B3 (GND): -0.000211 OPEN: -0.003669 Full Scale: +/- 1 mA 2025-08-07T16:10:56.696Z,1754583056.696 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:11:03.790Z,1754583063.790 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004715 2025-08-07T16:11:09.118Z,1754583069.118 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:11:41.399Z,1754583101.399 [SBIT](IMPORTANT): SBIT PASSED 2025-08-07T16:11:41.399Z,1754583101.399 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2025-08-07T16:11:41.427Z,1754583101.427 [SBIT](IMPORTANT): DockingStepper.closedValue=14700 count; 2025-08-07T16:11:41.427Z,1754583101.427 [SBIT](IMPORTANT): DockingStepper.slideValue=10000 count; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): ESPComponent.sampleTimeout=5 minute; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): ESPComponent.simulateHardware=0 bool; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): Express linearApproximation DAT.acoustic_contact_range 15.000000 meter; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): SpeedControl.rollOptimum=0.600000 meter_per_second; 2025-08-07T16:11:41.428Z,1754583101.428 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=362.232292 cubic_centimeter; 2025-08-07T16:11:41.429Z,1754583101.429 [SBIT](IMPORTANT): VerticalControl.massDefault=21.376612 millimeter; 2025-08-07T16:11:41.820Z,1754583101.820 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2025-08-07T16:11:41.821Z,1754583101.821 [DefaultWithUndock] Running Loop=1 2025-08-07T16:11:41.821Z,1754583101.821 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2025-08-07T16:11:41.822Z,1754583101.822 [DefaultWithUndock:A.Wait] Running Loop=1 2025-08-07T16:11:41.822Z,1754583101.822 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:12:01.997Z,1754583121.997 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2025-08-07T16:12:01.997Z,1754583121.997 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:12:02.027Z,1754583122.027 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:12:02.409Z,1754583122.409 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:12:02.409Z,1754583122.409 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2025-08-07T16:12:12.109Z,1754583132.109 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2025-08-07T16:12:12.109Z,1754583132.109 [DefaultWithUndock:A.Wait] Stopped 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock] Running Loop=1 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:12:12.110Z,1754583132.110 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:12:12.522Z,1754583132.522 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:12:12.522Z,1754583132.522 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:12:12.523Z,1754583132.523 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached from dock at depth -0.130842 m. 2025-08-07T16:12:12.528Z,1754583132.528 [DefaultWithUndock:LeaveDock:A.] Stopped 2025-08-07T16:12:12.528Z,1754583132.528 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-08-07T16:12:12.926Z,1754583132.926 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2025-08-07T16:12:13.313Z,1754583133.313 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T16:12:13.429Z,1754583133.429 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T16:12:33.107Z,1754583153.107 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning docking module to standby. 2025-08-07T16:12:33.563Z,1754583153.563 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:LeaveDock] Stopped 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2025-08-07T16:12:33.921Z,1754583153.921 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:12:33.922Z,1754583153.922 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2025-08-07T16:12:33.922Z,1754583153.922 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-08-07T16:12:33.922Z,1754583153.922 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-08-07T16:12:33.923Z,1754583153.923 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-08-07T16:12:33.923Z,1754583153.923 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-08-07T16:12:33.923Z,1754583153.923 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-08-07T16:12:33.924Z,1754583153.924 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-08-07T16:12:33.924Z,1754583153.924 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-08-07T16:12:34.322Z,1754583154.322 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2025-08-07T16:12:34.322Z,1754583154.322 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:12:34.322Z,1754583154.322 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:12:34.753Z,1754583154.753 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2025-08-07T16:13:38.558Z,1754583218.558 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:13:50.728Z,1754583230.728 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:14:02.448Z,1754583242.448 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:14:14.569Z,1754583254.569 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:14:24.656Z,1754583264.656 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:14:26.286Z,1754583266.286 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:14:37.120Z,1754583277.120 [BPC1](ERROR): BPC1B got IPBS message with 5 sticks (min is 7). 2025-08-07T16:14:37.123Z,1754583277.123 [BPC1](ERROR): BPC1B failed to parse battery stick message. 2025-08-07T16:14:42.781Z,1754583282.781 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2025-08-07T16:14:48.907Z,1754583288.907 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:01.030Z,1754583301.030 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:03.007Z,1754583303.007 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2025-08-07T16:15:03.007Z,1754583303.007 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:15:03.038Z,1754583303.038 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:15:03.427Z,1754583303.427 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:15:03.427Z,1754583303.427 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2025-08-07T16:15:12.748Z,1754583312.748 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:24.860Z,1754583324.860 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:36.563Z,1754583336.563 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:36.646Z,1754583336.646 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:40.154Z,1754583340.154 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:42.571Z,1754583342.571 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:44.994Z,1754583344.994 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:47.419Z,1754583347.419 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:48.701Z,1754583348.701 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:49.842Z,1754583349.842 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:52.271Z,1754583352.271 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:54.689Z,1754583354.689 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:57.114Z,1754583357.114 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:15:59.540Z,1754583359.540 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:00.432Z,1754583360.432 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:01.961Z,1754583361.961 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:04.388Z,1754583364.388 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:06.810Z,1754583366.810 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:09.236Z,1754583369.236 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:11.658Z,1754583371.658 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:12.546Z,1754583372.546 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:14.082Z,1754583374.082 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:16.506Z,1754583376.506 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:18.930Z,1754583378.930 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:21.354Z,1754583381.354 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:23.777Z,1754583383.777 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:26.201Z,1754583386.201 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:28.627Z,1754583388.627 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:31.050Z,1754583391.050 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:33.503Z,1754583393.503 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:35.901Z,1754583395.901 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:38.325Z,1754583398.325 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:40.746Z,1754583400.746 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:40.813Z,1754583400.813 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:43.170Z,1754583403.170 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:45.595Z,1754583405.595 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:46.977Z,1754583406.977 [CommandExec](IMPORTANT): got command failComponent 2025-08-07T16:16:46.977Z,1754583406.977 [CommandExec](IMPORTANT): Failed components: 2025-08-07T16:16:46.977Z,1754583406.977 [CommandExec](IMPORTANT): No failed Components. 2025-08-07T16:16:48.021Z,1754583408.021 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:50.442Z,1754583410.442 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:52.868Z,1754583412.868 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:55.290Z,1754583415.290 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:16:57.714Z,1754583417.714 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:00.138Z,1754583420.138 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:02.563Z,1754583422.563 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:04.986Z,1754583424.986 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:07.412Z,1754583427.412 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:09.833Z,1754583429.833 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:12.260Z,1754583432.260 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:14.682Z,1754583434.682 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:17.108Z,1754583437.108 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:19.531Z,1754583439.531 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:21.956Z,1754583441.956 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:24.377Z,1754583444.377 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:26.807Z,1754583446.807 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:29.225Z,1754583449.225 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:31.652Z,1754583451.652 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:34.073Z,1754583454.073 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:34.509Z,1754583454.509 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](INFO): Timed out from 2025-08-07T16:12:34.3Z 2025-08-07T16:17:34.509Z,1754583454.509 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T16:17:34.509Z,1754583454.509 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T16:17:34.926Z,1754583454.926 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2025-08-07T16:17:36.499Z,1754583456.499 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:38.922Z,1754583458.922 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:41.347Z,1754583461.347 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:42.840Z,1754583462.840 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20250807T160847/Courier0000.lzma 2025-08-07T16:17:43.770Z,1754583463.770 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:43.858Z,1754583463.858 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0000.lzma.bak 2025-08-07T16:17:43.858Z,1754583463.858 [DataOverHttps](INFO): SBD MOMSN=25803087 2025-08-07T16:17:46.196Z,1754583466.196 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:48.618Z,1754583468.618 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:51.043Z,1754583471.043 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:53.513Z,1754583473.513 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:55.891Z,1754583475.891 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:58.314Z,1754583478.314 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:17:59.914Z,1754583479.914 [DataOverHttps](INFO): Sending 1179 bytes from file Logs/20250807T160847/Express0001.lzma 2025-08-07T16:18:00.738Z,1754583480.738 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:18:00.914Z,1754583480.914 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0001.lzma.bak 2025-08-07T16:18:00.915Z,1754583480.915 [DataOverHttps](INFO): SBD MOMSN=25803090 2025-08-07T16:18:01.972Z,1754583481.972 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T16:18:01.972Z,1754583481.972 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T16:18:01.972Z,1754583481.972 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:18:03.985Z,1754583483.985 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2025-08-07T16:18:03.985Z,1754583483.985 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:18:04.028Z,1754583484.028 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:18:04.411Z,1754583484.411 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:18:04.411Z,1754583484.411 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2025-08-07T16:18:34.723Z,1754583514.723 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:18:45.237Z,1754583525.237 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:18:56.148Z,1754583536.148 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:19:06.649Z,1754583546.649 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:19:07.843Z,1754583547.843 [Sonardyne_Nano](ERROR): Failed to parse response: >VS:2207,HPR45,EXT,TILT 2025-08-07T16:19:17.634Z,1754583557.634 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:19:28.063Z,1754583568.063 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:19:38.970Z,1754583578.970 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:19:41.339Z,1754583581.339 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-08-07T16:19:41.339Z,1754583581.339 [NAL9602] Data Fault, FailCount= 1 2025-08-07T16:19:41.339Z,1754583581.339 [NAL9602](ERROR): Data Fault 2025-08-07T16:19:41.357Z,1754583581.357 [CBIT](ERROR): Data Fault in component: NAL9602 2025-08-07T16:19:41.737Z,1754583581.737 [NAL9602](INFO): Powering down 2025-08-07T16:19:42.570Z,1754583582.570 [CBIT](INFO): Clearing failed state for component NAL9602 2025-08-07T16:19:42.570Z,1754583582.570 [NAL9602] No Fault, FailCount= 1 2025-08-07T16:19:49.522Z,1754583589.522 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:00.377Z,1754583600.377 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:10.885Z,1754583610.885 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:12.045Z,1754583612.045 [NAL9602](INFO): Powering up NAL9602 2025-08-07T16:20:21.790Z,1754583621.790 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:22.949Z,1754583622.949 [NAL9602](INFO): NAL9602 initialized 2025-08-07T16:20:32.303Z,1754583632.303 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:35.567Z,1754583635.567 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude. Device response is::BD, +0.00, 5.99 2025-08-07T16:20:43.202Z,1754583643.202 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:20:53.708Z,1754583653.708 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:21:00.515Z,1754583660.515 [BPC1](ERROR): BPC1B got IPBS message with 2 sticks (min is 7). 2025-08-07T16:21:00.516Z,1754583660.516 [BPC1](ERROR): BPC1B failed to parse battery stick message. 2025-08-07T16:21:04.984Z,1754583664.984 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2025-08-07T16:21:04.984Z,1754583664.984 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:21:05.084Z,1754583665.084 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:21:05.402Z,1754583665.402 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:21:05.402Z,1754583665.402 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2025-08-07T16:22:57.716Z,1754583777.716 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:23:02.558Z,1754583782.558 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T16:23:02.558Z,1754583782.558 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T16:23:02.558Z,1754583782.558 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:23:02.558Z,1754583782.558 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T16:23:02.949Z,1754583782.949 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T16:23:02.949Z,1754583782.949 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T16:23:03.346Z,1754583783.346 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 11.352136 min 2025-08-07T16:23:03.346Z,1754583783.346 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T16:23:03.346Z,1754583783.346 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:23:03.346Z,1754583783.346 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T16:23:03.346Z,1754583783.346 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:23:03.347Z,1754583783.347 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2 2025-08-07T16:23:03.347Z,1754583783.347 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2 2025-08-07T16:23:03.347Z,1754583783.347 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:23:03.347Z,1754583783.347 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:23:34.920Z,1754583814.920 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:23:46.629Z,1754583826.629 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:23:58.753Z,1754583838.753 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:05.961Z,1754583845.961 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2025-08-07T16:24:05.961Z,1754583845.961 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:24:06.024Z,1754583846.024 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:24:06.389Z,1754583846.389 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:24:06.389Z,1754583846.389 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2025-08-07T16:24:10.527Z,1754583850.527 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:22.593Z,1754583862.593 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:23.381Z,1754583863.381 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:34.300Z,1754583874.300 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:46.424Z,1754583886.424 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:50.041Z,1754583890.041 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:24:58.137Z,1754583898.137 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:10.265Z,1754583910.265 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:21.972Z,1754583921.972 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:22.316Z,1754583922.316 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:31.598Z,1754583931.598 [BPC1](ERROR): BPC1A got IPBS message with 4 sticks (min is 7). 2025-08-07T16:25:31.598Z,1754583931.598 [BPC1](ERROR): BPC1A failed to parse battery stick message. 2025-08-07T16:25:34.031Z,1754583934.031 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:34.165Z,1754583934.165 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:35.920Z,1754583935.920 [CommandExec](IMPORTANT): got command get Sonardyne_Nano.chargePercent 2025-08-07T16:25:35.921Z,1754583935.921 [CommandExec](IMPORTANT): Sonardyne_Nano.chargePercent 98.000000 % 2025-08-07T16:25:36.450Z,1754583936.450 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:38.875Z,1754583938.875 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:41.298Z,1754583941.298 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:43.723Z,1754583943.723 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:45.809Z,1754583945.809 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:46.145Z,1754583946.145 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:48.571Z,1754583948.571 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:50.994Z,1754583950.994 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:53.418Z,1754583953.418 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:55.841Z,1754583955.841 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:57.940Z,1754583957.940 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:25:58.270Z,1754583958.270 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:00.689Z,1754583960.689 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:03.114Z,1754583963.114 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:05.537Z,1754583965.537 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:07.962Z,1754583967.962 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:10.386Z,1754583970.386 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:12.810Z,1754583972.810 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:15.234Z,1754583975.234 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:17.658Z,1754583977.658 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:20.081Z,1754583980.081 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:22.506Z,1754583982.506 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:24.930Z,1754583984.930 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:27.358Z,1754583987.358 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:29.777Z,1754583989.777 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:32.203Z,1754583992.203 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:34.626Z,1754583994.626 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:37.052Z,1754583997.052 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:39.508Z,1754583999.508 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:41.897Z,1754584001.897 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:44.322Z,1754584004.322 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:46.747Z,1754584006.747 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:49.169Z,1754584009.169 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:51.593Z,1754584011.593 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:54.018Z,1754584014.018 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:56.442Z,1754584016.442 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:26:58.866Z,1754584018.866 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:01.289Z,1754584021.289 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:03.713Z,1754584023.713 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:06.137Z,1754584026.137 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:06.973Z,1754584026.973 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2025-08-07T16:27:06.973Z,1754584026.973 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:27:06.984Z,1754584026.984 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:27:07.386Z,1754584027.386 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:27:07.386Z,1754584027.386 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2025-08-07T16:27:10.238Z,1754584030.238 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:15.430Z,1754584035.430 [BPC1](ERROR): BPC1A got IPBS message with 4 sticks (min is 7). 2025-08-07T16:27:15.430Z,1754584035.430 [BPC1](ERROR): BPC1A failed to parse battery stick message. 2025-08-07T16:27:17.857Z,1754584037.857 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:20.278Z,1754584040.278 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:22.703Z,1754584042.703 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:24.382Z,1754584044.382 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:27:25.125Z,1754584045.125 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2025-08-07T16:28:03.605Z,1754584083.605 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](INFO): Timed out from 2025-08-07T16:23:03.3Z 2025-08-07T16:28:03.605Z,1754584083.605 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T16:28:03.606Z,1754584083.606 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T16:28:11.490Z,1754584091.490 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250807T160847/Courier0004.lzma 2025-08-07T16:28:12.486Z,1754584092.486 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0004.lzma.bak 2025-08-07T16:28:12.486Z,1754584092.486 [DataOverHttps](INFO): SBD MOMSN=25803172 2025-08-07T16:28:28.440Z,1754584108.440 [DataOverHttps](INFO): Sending 258 bytes from file Logs/20250807T160847/Express0005.lzma 2025-08-07T16:28:29.445Z,1754584109.445 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0005.lzma.bak 2025-08-07T16:28:29.446Z,1754584109.446 [DataOverHttps](INFO): SBD MOMSN=25803174 2025-08-07T16:28:30.593Z,1754584110.593 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T16:28:30.593Z,1754584110.593 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T16:28:30.593Z,1754584110.593 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:30:07.954Z,1754584207.954 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2025-08-07T16:30:07.954Z,1754584207.954 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:30:07.966Z,1754584207.966 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:30:08.379Z,1754584208.379 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:30:08.379Z,1754584208.379 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2025-08-07T16:30:24.109Z,1754584224.109 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-08-07T16:30:24.109Z,1754584224.109 [NAL9602] Data Fault, FailCount= 2 2025-08-07T16:30:24.109Z,1754584224.109 [NAL9602](ERROR): Data Fault 2025-08-07T16:30:24.148Z,1754584224.148 [CBIT](ERROR): Data Fault in component: NAL9602 2025-08-07T16:30:24.513Z,1754584224.513 [NAL9602](INFO): Powering down 2025-08-07T16:30:25.337Z,1754584225.337 [CBIT](INFO): Clearing failed state for component NAL9602 2025-08-07T16:30:25.337Z,1754584225.337 [NAL9602] No Fault, FailCount= 2 2025-08-07T16:30:54.805Z,1754584254.805 [NAL9602](INFO): Powering up NAL9602 2025-08-07T16:31:05.709Z,1754584265.709 [NAL9602](INFO): NAL9602 initialized 2025-08-07T16:33:08.942Z,1754584388.942 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2025-08-07T16:33:08.942Z,1754584388.942 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:33:08.977Z,1754584388.977 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:33:09.355Z,1754584389.355 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:33:09.355Z,1754584389.355 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2025-08-07T16:33:31.162Z,1754584411.162 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T16:33:31.162Z,1754584411.162 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T16:33:31.162Z,1754584411.162 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:33:31.162Z,1754584411.162 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T16:33:31.593Z,1754584411.593 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T16:33:31.593Z,1754584411.593 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T16:33:31.974Z,1754584411.974 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 21.829533 min 2025-08-07T16:33:31.974Z,1754584411.974 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #3 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=3 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:33:31.975Z,1754584411.975 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:36:00.108Z,1754584560.108 [CommandExec](IMPORTANT): got command failComponent 2025-08-07T16:36:00.109Z,1754584560.109 [CommandExec](IMPORTANT): Failed components: 2025-08-07T16:36:00.109Z,1754584560.109 [CommandExec](IMPORTANT): No failed Components. 2025-08-07T16:36:09.935Z,1754584569.935 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9 2025-08-07T16:36:09.935Z,1754584569.935 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:36:09.946Z,1754584569.946 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:36:10.358Z,1754584570.358 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:36:10.358Z,1754584570.358 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9 2025-08-07T16:36:18.741Z,1754584578.741 [CommandExec](IMPORTANT): got command show stack 2025-08-07T16:36:18.741Z,1754584578.741 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T16:36:18.741Z,1754584578.741 [DefaultWithUndock:SurfaceDefault](IMPORTANT): Priority 0: DefaultWithUndock:SurfaceDefault:A.GoToSurface 2025-08-07T16:36:18.742Z,1754584578.742 [DefaultWithUndock:SurfaceDefault:CheckIn](IMPORTANT): Priority 1: DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS 2025-08-07T16:37:16.986Z,1754584636.986 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:37:16.986Z,1754584636.986 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:37:16.986Z,1754584636.986 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:37:16.989Z,1754584636.989 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:37:17.124Z,1754584637.124 [MissionManager](DEBUG): TethyslAPI: ./Missions/Maintenance/sample_lab.tl translated into: 90 -4 1 Sampling ESP cartridge type 2025-08-07T16:37:17.129Z,1754584637.129 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2025-08-07T16:37:17.132Z,1754584637.132 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2025-08-07T16:37:17.135Z,1754584637.135 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2025-08-07T16:37:17.136Z,1754584637.136 [sample_lab:A.AbortSample](DEBUG): Construct. 2025-08-07T16:37:17.140Z,1754584637.140 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2025-08-07T16:37:17.146Z,1754584637.146 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. # ==================== # Generated by TethysL # ==================== mission sample_lab { """ This mission is designed to run in the lab only and triggers an ESP sample with specified type. """ arguments { MissionTimeout = 90 minute """ How long to let the mission run. """ CartridgeType = -4 count """ Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) """ NumberOfSamples = 1 count """ Number of samples to take. """ } timeout duration=MissionTimeout behavior Sample:AbortSample { run in parallel } aggregate SampleRepeater { run in sequence repeat=NumberOfSamples syslog important "Sampling ESP cartridge type " + CartridgeType~count behavior Science:ESPCartridgeSelect { run in sequence timeout duration=P1M set cartridgeType = CartridgeType } readDatum id="TriggerESP" { Science:ESPComponent.sampling } readDatum id="WaitForESP" { Science:ESPComponent.sample_number } } } 2025-08-07T16:37:17.148Z,1754584637.148 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock] Stopped 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock:SurfaceDefault] Stopped 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-08-07T16:37:17.405Z,1754584637.405 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T16:37:17.406Z,1754584637.406 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:37:17.406Z,1754584637.406 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T16:37:17.406Z,1754584637.406 [MissionManager](IMPORTANT): Started mission sample_lab 2025-08-07T16:37:17.406Z,1754584637.406 [sample_lab] Running Loop=1 2025-08-07T16:37:17.406Z,1754584637.406 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2025-08-07T16:37:17.406Z,1754584637.406 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:37:17.406Z,1754584637.406 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2025-08-07T16:37:17.407Z,1754584637.407 [sample_lab:SampleRepeater] Running Loop=1 2025-08-07T16:37:17.407Z,1754584637.407 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2025-08-07T16:37:17.407Z,1754584637.407 [sample_lab:SampleRepeater:A] Running Loop=1 2025-08-07T16:37:17.407Z,1754584637.407 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -4.000000 count 2025-08-07T16:37:17.408Z,1754584637.408 [sample_lab:SampleRepeater:A] Stopped 2025-08-07T16:37:17.408Z,1754584637.408 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2025-08-07T16:37:17.408Z,1754584637.408 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2025-08-07T16:37:17.408Z,1754584637.408 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:37:17.845Z,1754584637.845 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4. 2025-08-07T16:37:17.846Z,1754584637.846 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2025-08-07T16:37:17.846Z,1754584637.846 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2025-08-07T16:37:17.846Z,1754584637.846 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2025-08-07T16:37:18.229Z,1754584638.229 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2025-08-07T16:37:19.012Z,1754584639.012 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:' 2025-08-07T16:37:19.014Z,1754584639.014 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:" 2025-08-07T16:37:19.015Z,1754584639.015 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence 2025-08-07T16:37:29.127Z,1754584649.127 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence 2025-08-07T16:37:29.129Z,1754584649.129 [ESPComponent](INFO): powering up ESP 2025-08-07T16:37:29.148Z,1754584649.148 [ESPComponent](INFO): powering up ESP secondary power supply 2025-08-07T16:37:29.164Z,1754584649.164 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.11.2:10.89.11.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2025-08-07T16:37:29.680Z,1754584649.680 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2025-08-07T16:37:30.605Z,1754584650.605 [ESPComponent](INFO): console: 2025-08-07T16:37:31.006Z,1754584651.006 [ESPComponent](INFO): console:NAND: 256 MiB 2025-08-07T16:37:31.406Z,1754584651.406 [ESPComponent](INFO): console: BOOTMODE: SPI 2025-08-07T16:37:31.826Z,1754584651.826 [ESPComponent](INFO): console: reading SPI NOR..Done 2025-08-07T16:37:32.200Z,1754584652.200 [ESPComponent](INFO): console: 2025-08-07T16:37:32.603Z,1754584652.603 [ESPComponent](INFO): console: 2025-08-07T16:37:33.019Z,1754584653.019 [ESPComponent](INFO): console: U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51) 2025-08-07T16:37:33.415Z,1754584653.415 [ESPComponent](INFO): console: 2025-08-07T16:37:33.854Z,1754584653.854 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2025-08-07T16:37:34.238Z,1754584654.238 [ESPComponent](INFO): console: flash params are already written into flash 2025-08-07T16:37:34.638Z,1754584654.638 [ESPComponent](INFO): console: DRAM: 64 MB 2025-08-07T16:37:35.031Z,1754584655.031 [ESPComponent](INFO): console: In: serial 2025-08-07T16:37:35.451Z,1754584655.451 [ESPComponent](INFO): console: Out: serial 2025-08-07T16:37:35.866Z,1754584655.866 [ESPComponent](INFO): console: Err: serial 2025-08-07T16:37:36.243Z,1754584656.243 [ESPComponent](INFO): console: Net: ks8851_mll 2025-08-07T16:37:36.662Z,1754584656.662 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2025-08-07T16:37:37.082Z,1754584657.082 [ESPComponent](INFO): console: 4096 KiB S25FL032P at 0:0 is now current device 2025-08-07T16:37:37.491Z,1754584657.491 [ESPComponent](INFO): console: Loading kernel from SPI flash...done 2025-08-07T16:37:37.887Z,1754584657.887 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2025-08-07T16:37:38.260Z,1754584658.260 [ESPComponent](INFO): console: Image Name: Linux-3.18.140-lpc31-mbari4 2025-08-07T16:37:38.665Z,1754584658.665 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2025-08-07T16:37:39.079Z,1754584659.079 [ESPComponent](INFO): console: Data Size: 2336368 Bytes = 2.2 MB 2025-08-07T16:37:39.538Z,1754584659.538 [ESPComponent](INFO): console: Load Address: 30008000 2025-08-07T16:37:39.894Z,1754584659.894 [ESPComponent](INFO): console: Entry Point: 30008000 2025-08-07T16:37:40.302Z,1754584660.302 [ESPComponent](INFO): console: Verifying Checksum ... OK 2025-08-07T16:37:40.693Z,1754584660.693 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2025-08-07T16:37:41.093Z,1754584661.093 [ESPComponent](INFO): console: OK 2025-08-07T16:37:41.546Z,1754584661.546 [ESPComponent](INFO): console: 2025-08-07T16:37:41.914Z,1754584661.914 [ESPComponent](INFO): console: Starting kernel ... 2025-08-07T16:37:42.382Z,1754584662.382 [ESPComponent](INFO): console: 2025-08-07T16:37:42.711Z,1754584662.711 [ESPComponent](INFO): console: Uncompressing Linux... Booting kernel... 2025-08-07T16:37:43.127Z,1754584663.127 [ESPComponent](INFO): console: [ 0.06] MBARI ESP 3G 2025-08-07T16:37:43.572Z,1754584663.572 [ESPComponent](INFO): console: 2025-08-07T16:37:43.927Z,1754584663.927 [ESPComponent](INFO): console:INIT: version 2.85 booting 2025-08-07T16:37:44.323Z,1754584664.323 [ESPComponent](INFO): console: 2025-08-07T16:37:44.739Z,1754584664.739 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2025-08-07T16:37:45.149Z,1754584665.149 [ESPComponent](INFO): console: ESPdummy 2025-08-07T16:37:45.567Z,1754584665.567 [ESPComponent](INFO): console: 2025-08-07T16:37:45.939Z,1754584665.939 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2025-08-07T16:37:46.343Z,1754584666.343 [ESPComponent](INFO): console: 2025-08-07T16:37:46.749Z,1754584666.749 [ESPComponent](INFO): console:Loading kernel modules 2025-08-07T16:37:47.152Z,1754584667.152 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2025-08-07T16:37:47.595Z,1754584667.595 [ESPComponent](INFO): console: [ 3.53] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support! 2025-08-07T16:37:47.974Z,1754584667.974 [ESPComponent](INFO): console: Starting device events handler 2025-08-07T16:37:48.440Z,1754584668.440 [ESPComponent](INFO): console: 2025-08-07T16:37:58.076Z,1754584678.076 [ESPComponent](INFO): console:Set system clock to: Thu Aug 7 09:38:28 PDT 2025 2025-08-07T16:37:58.471Z,1754584678.471 [ESPComponent](INFO): console: Starting syslogd klogd... 2025-08-07T16:37:58.869Z,1754584678.869 [ESPComponent](INFO): console: stopped syslogd (pid 714) 2025-08-07T16:37:59.271Z,1754584679.271 [ESPComponent](INFO): console: Bringing up lo ... 2025-08-07T16:37:59.706Z,1754584679.706 [ESPComponent](INFO): console: lo IP=127.0.0.1 2025-08-07T16:38:00.095Z,1754584680.095 [ESPComponent](INFO): console: Packet forwarding enabled 2025-08-07T16:38:00.494Z,1754584680.494 [ESPComponent](INFO): console: Bringing up platform ... 2025-08-07T16:38:00.948Z,1754584680.948 [ESPComponent](INFO): console: 2025-08-07T16:38:02.531Z,1754584682.531 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard 2025-08-07T16:38:03.008Z,1754584683.008 [ESPComponent](INFO): console: 2025-08-07T16:38:04.160Z,1754584684.160 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63 2025-08-07T16:38:04.531Z,1754584684.531 [ESPComponent](INFO): console: [#] ip -4 address add 192.168.5.39 dev wg2shore 2025-08-07T16:38:04.940Z,1754584684.940 [ESPComponent](INFO): console: [#] ip link set mtu 1376 up dev wg2shore 2025-08-07T16:38:05.340Z,1754584685.340 [ESPComponent](INFO): console: [#] ip -4 route add 192.168.4.0/23 dev wg2shore 2025-08-07T16:38:05.793Z,1754584685.793 [ESPComponent](INFO): console: Bringing up wg2shore ... 2025-08-07T16:38:06.171Z,1754584686.171 [ESPComponent](INFO): console: Starting netplugd... 2025-08-07T16:38:06.578Z,1754584686.578 [ESPComponent](INFO): console: Starting portmap... 2025-08-07T16:38:06.956Z,1754584686.956 [ESPComponent](INFO): console: Network unavailable: Local time is Thu Aug 7 09:38:35 PDT 2025 2025-08-07T16:38:07.359Z,1754584687.359 [ESPComponent](INFO): console: Starting chronyd... 2025-08-07T16:38:07.794Z,1754584687.794 [ESPComponent](INFO): console: Starting darkhttpd... 2025-08-07T16:38:08.169Z,1754584688.169 [ESPComponent](INFO): console: darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic. 2025-08-07T16:38:08.586Z,1754584688.586 [ESPComponent](INFO): console: listening on: http://0.0.0.0:80/ 2025-08-07T16:38:08.994Z,1754584688.994 [ESPComponent](INFO): console: set gid to 1 2025-08-07T16:38:09.398Z,1754584689.398 [ESPComponent](INFO): console: set uid to 65534 2025-08-07T16:38:09.836Z,1754584689.836 [ESPComponent](INFO): console: Starting dnsmasq... 2025-08-07T16:38:10.239Z,1754584690.239 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T16:38:10.243Z,1754584690.243 [ESPComponent](INFO): console: 2025-08-07T16:38:10.611Z,1754584690.611 [ESPComponent](INFO): console: 2025-08-07T16:38:11.017Z,1754584691.017 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.83 -- 4/24/24 brent@mbari.org 2025-08-07T16:38:11.398Z,1754584691.398 [ESPComponent](INFO): console: 2025-08-07T16:38:11.850Z,1754584691.850 [ESPComponent](INFO): console:ESPdummy login: Bringing up WiFi ... 2025-08-07T16:38:12.228Z,1754584692.228 [ESPComponent](INFO): console: Determining IP configuration for WiFi ...udhcpc (v1.11.2) started 2025-08-07T16:38:12.635Z,1754584692.635 [ESPComponent](INFO): console: Sending discover... 2025-08-07T16:38:13.088Z,1754584693.088 [ESPComponent](INFO): console: 2025-08-07T16:38:15.531Z,1754584695.531 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:15.936Z,1754584695.936 [ESPComponent](INFO): console: 2025-08-07T16:38:18.286Z,1754584698.286 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:18.748Z,1754584698.748 [ESPComponent](INFO): console: 2025-08-07T16:38:21.549Z,1754584701.549 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:21.992Z,1754584701.992 [ESPComponent](INFO): console: 2025-08-07T16:38:24.332Z,1754584704.332 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:24.804Z,1754584704.804 [ESPComponent](INFO): console: 2025-08-07T16:38:27.167Z,1754584707.167 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:27.676Z,1754584707.676 [ESPComponent](INFO): console: 2025-08-07T16:38:30.401Z,1754584710.401 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:30.864Z,1754584710.864 [ESPComponent](INFO): console: 2025-08-07T16:38:33.219Z,1754584713.219 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:33.724Z,1754584713.724 [ESPComponent](INFO): console: 2025-08-07T16:38:36.468Z,1754584716.468 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:36.940Z,1754584716.940 [ESPComponent](INFO): console: 2025-08-07T16:38:39.339Z,1754584719.339 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:38:39.715Z,1754584719.715 [ESPComponent](IMPORTANT): ESP has connected as client 2025-08-07T16:38:40.497Z,1754584720.497 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4 2025-08-07T16:38:40.497Z,1754584720.497 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2025-08-07T16:38:40.498Z,1754584720.498 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1 2025-08-07T16:38:40.555Z,1754584720.555 [sample_lab:SampleRepeater:TriggerESP] Stopped 2025-08-07T16:38:40.555Z,1754584720.555 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1 2025-08-07T16:38:41.016Z,1754584721.016 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2025-08-07T16:38:41.741Z,1754584721.741 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG 2025-08-07T16:38:42.135Z,1754584722.135 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS 2025-08-07T16:38:43.749Z,1754584723.749 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE 2025-08-07T16:38:45.358Z,1754584725.358 [ESPComponent](ERROR): In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<>. Elapsed time since command issued: 2.0235 2025-08-07T16:38:45.760Z,1754584725.760 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING 2025-08-07T16:38:48.183Z,1754584728.183 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq -e 'ssh -o StrictHostKeyChecking=no' --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs & 2025-08-07T16:38:48.196Z,1754584728.196 [ESPComponent](INFO): closing pipe. 2025-08-07T16:38:48.579Z,1754584728.579 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED 2025-08-07T16:39:10.820Z,1754584750.820 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10 2025-08-07T16:39:10.820Z,1754584750.820 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:39:10.831Z,1754584750.831 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:39:11.236Z,1754584751.236 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:39:11.236Z,1754584751.236 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10 2025-08-07T16:40:03.303Z,1754584803.303 [BPC1](ERROR): Battery stick #17 (s/n: 00C9) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x4AD0. 2025-08-07T16:40:03.304Z,1754584803.304 [BPC1](ERROR): Battery stick #18 (s/n: 0186) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x4AD0. 2025-08-07T16:40:03.305Z,1754584803.305 [BPC1](ERROR): Battery stick #26 (s/n: 0112) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2025-08-07T16:40:03.305Z,1754584803.305 [BPC1](ERROR): Battery stick #27 (s/n: 00AF) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x4AD0. 2025-08-07T16:40:03.306Z,1754584803.306 [BPC1](ERROR): Battery stick #44 (s/n: 00E4) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2025-08-07T16:40:03.307Z,1754584803.307 [BPC1](ERROR): Battery stick #58 (s/n: 00F3) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x4AD0. 2025-08-07T16:40:03.308Z,1754584803.308 [BPC1](INFO): Calculating totals. Valid battery stick count: 30. Valid reserve battery stick count: 3. 2025-08-07T16:40:03.311Z,1754584803.311 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2025-08-07T16:40:28.053Z,1754584828.053 [CommandExec](IMPORTANT): got command show stack 2025-08-07T16:40:28.053Z,1754584828.053 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T16:40:28.054Z,1754584828.054 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample 2025-08-07T16:40:28.054Z,1754584828.054 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:WaitForESP 2025-08-07T16:40:30.445Z,1754584830.445 [CommandExec](IMPORTANT): got command stop 2025-08-07T16:40:30.445Z,1754584830.445 [CommandExec](IMPORTANT): Scheduling is paused 2025-08-07T16:40:30.445Z,1754584830.445 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop 2025-08-07T16:40:30.791Z,1754584830.791 [MissionManager](INFO): MissionManager is completed. 2025-08-07T16:40:30.791Z,1754584830.791 [MissionManager](INFO): Uninitializing Mission sample_lab 2025-08-07T16:40:30.791Z,1754584830.791 [sample_lab] Stopped 2025-08-07T16:40:30.791Z,1754584830.791 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab 2025-08-07T16:40:30.791Z,1754584830.791 [sample_lab:A.AbortSample] Stopped 2025-08-07T16:40:30.791Z,1754584830.791 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample. 2025-08-07T16:40:30.791Z,1754584830.791 [sample_lab:SampleRepeater] Stopped 2025-08-07T16:40:30.792Z,1754584830.792 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater 2025-08-07T16:40:30.792Z,1754584830.792 [sample_lab:SampleRepeater:WaitForESP] Stopped 2025-08-07T16:40:31.194Z,1754584831.194 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2025-08-07T16:40:31.194Z,1754584831.194 [DefaultWithUndock] Running Loop=1 2025-08-07T16:40:31.194Z,1754584831.194 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2025-08-07T16:40:31.195Z,1754584831.195 [DefaultWithUndock:A.Wait] Running Loop=1 2025-08-07T16:40:31.195Z,1754584831.195 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:A.Wait] Stopped 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:LeaveDock] Running Loop=1 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2025-08-07T16:41:01.571Z,1754584861.571 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2025-08-07T16:41:01.572Z,1754584861.572 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2025-08-07T16:41:01.592Z,1754584861.592 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2025-08-07T16:41:01.592Z,1754584861.592 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:41:01.592Z,1754584861.592 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:41:01.910Z,1754584861.910 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:41:01.910Z,1754584861.910 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:41:01.910Z,1754584861.910 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached from dock at depth -0.138621 m. 2025-08-07T16:41:01.911Z,1754584861.911 [DefaultWithUndock:LeaveDock:A.] Stopped 2025-08-07T16:41:01.911Z,1754584861.911 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-08-07T16:41:02.322Z,1754584862.322 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2025-08-07T16:41:02.743Z,1754584862.743 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T16:41:02.861Z,1754584862.861 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T16:41:08.757Z,1754584868.757 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-08-07T16:41:08.757Z,1754584868.757 [NAL9602] Data Fault, FailCount= 3 2025-08-07T16:41:08.757Z,1754584868.757 [NAL9602](ERROR): Data Fault 2025-08-07T16:41:08.857Z,1754584868.857 [CBIT](ERROR): Data Fault in component: NAL9602 2025-08-07T16:41:09.161Z,1754584869.161 [NAL9602](INFO): Powering down 2025-08-07T16:41:09.577Z,1754584869.577 [NAL9602](FAULT): LCB fault: LCB Watchdog Reset. Current Limiter Activated. 2025-08-07T16:41:09.577Z,1754584869.577 [NAL9602] Hardware Fault, FailCount= 3 2025-08-07T16:41:09.577Z,1754584869.577 [NAL9602](ERROR): Hardware Fault 2025-08-07T16:41:10.073Z,1754584870.073 [CBIT](INFO): Clearing failed state for component NAL9602 2025-08-07T16:41:10.073Z,1754584870.073 [NAL9602] No Fault, FailCount= 3 2025-08-07T16:41:22.503Z,1754584882.503 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning docking module to standby. 2025-08-07T16:41:22.912Z,1754584882.912 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2025-08-07T16:41:23.309Z,1754584883.309 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2025-08-07T16:41:23.309Z,1754584883.309 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2025-08-07T16:41:23.310Z,1754584883.310 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2025-08-07T16:41:23.310Z,1754584883.310 [DefaultWithUndock:LeaveDock] Stopped 2025-08-07T16:41:23.310Z,1754584883.310 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2025-08-07T16:41:23.312Z,1754584883.312 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2025-08-07T16:41:23.312Z,1754584883.312 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:41:23.313Z,1754584883.313 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2025-08-07T16:41:23.313Z,1754584883.313 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-08-07T16:41:23.332Z,1754584883.332 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-08-07T16:41:23.332Z,1754584883.332 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-08-07T16:41:23.332Z,1754584883.332 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-08-07T16:41:23.333Z,1754584883.333 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-08-07T16:41:23.333Z,1754584883.333 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-08-07T16:41:23.333Z,1754584883.333 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-08-07T16:41:23.730Z,1754584883.730 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2025-08-07T16:41:23.731Z,1754584883.731 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:41:23.731Z,1754584883.731 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:41:39.499Z,1754584899.499 [NAL9602](INFO): Powering up NAL9602 2025-08-07T16:41:50.369Z,1754584910.369 [NAL9602](INFO): NAL9602 initialized 2025-08-07T16:42:11.882Z,1754584931.882 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11 2025-08-07T16:42:11.882Z,1754584931.882 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:42:11.947Z,1754584931.947 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:42:12.259Z,1754584932.259 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:42:12.259Z,1754584932.259 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11 2025-08-07T16:43:48.346Z,1754585028.346 [ESPComponent](CRITICAL): [sample #1] ESP sampling sequence terminated with error: In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<>. Elapsed time since command issued: 2.0235 2025-08-07T16:43:48.346Z,1754585028.346 [ESPComponent] Communications Fault, FailCount= 1 2025-08-07T16:43:48.346Z,1754585028.346 [ESPComponent](ERROR): Communications Fault 2025-08-07T16:43:48.361Z,1754585028.361 [CommandExec](FAULT): Scheduling is paused 2025-08-07T16:43:48.361Z,1754585028.361 [CBIT](INFO): Critical error at 20250807T164348 2025-08-07T16:43:48.364Z,1754585028.364 [CBIT](ERROR): Communications Fault in component: ESPComponent 2025-08-07T16:43:48.739Z,1754585028.739 [ESPComponent](IMPORTANT): [sample #1] No ESP summary messages. 2025-08-07T16:43:48.740Z,1754585028.740 [ESPComponent](INFO): powering down ESP 2025-08-07T16:43:48.741Z,1754585028.741 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T16:43:49.627Z,1754585029.627 [CBIT](INFO): Clearing failed state for component ESPComponent 2025-08-07T16:43:49.627Z,1754585029.627 [ESPComponent] No Fault, FailCount= 1 2025-08-07T16:43:50.356Z,1754585030.356 [ESPComponent](INFO): powering down ESP 2025-08-07T16:43:50.357Z,1754585030.357 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T16:44:55.825Z,1754585095.825 [RDI_Pathfinder](ERROR): only read 3 of 4 data items for bottom velocity. Device response is::BS,-32768,-32768,-3 2025-08-07T16:45:12.814Z,1754585112.814 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12 2025-08-07T16:45:12.814Z,1754585112.814 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:45:12.864Z,1754585112.864 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:45:13.282Z,1754585113.282 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:45:13.282Z,1754585113.282 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12 2025-08-07T16:45:25.757Z,1754585125.757 [RDI_Pathfinder](ERROR): only read 3 of 4 data items for bottom velocity. Device response is::BS,-32768,-32768,-3 2025-08-07T16:46:23.938Z,1754585183.938 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](INFO): Timed out from 2025-08-07T16:41:23.7Z 2025-08-07T16:46:23.938Z,1754585183.938 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T16:46:23.938Z,1754585183.938 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T16:46:32.861Z,1754585192.861 [DataOverHttps](INFO): Sending 437 bytes from file Logs/20250807T160847/Courier0007.lzma 2025-08-07T16:46:33.862Z,1754585193.862 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0007.lzma.bak 2025-08-07T16:46:33.862Z,1754585193.862 [DataOverHttps](INFO): SBD MOMSN=25803300 2025-08-07T16:46:49.867Z,1754585209.867 [DataOverHttps](INFO): Sending 1204 bytes from file Logs/20250807T160847/Express0008.lzma 2025-08-07T16:46:50.866Z,1754585210.866 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0008.lzma.bak 2025-08-07T16:46:50.866Z,1754585210.866 [DataOverHttps](INFO): SBD MOMSN=25803304 2025-08-07T16:46:52.210Z,1754585212.210 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T16:46:52.210Z,1754585212.210 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T16:46:52.210Z,1754585212.210 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:48:13.817Z,1754585293.817 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13 2025-08-07T16:48:13.817Z,1754585293.817 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:48:13.828Z,1754585293.828 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:48:14.227Z,1754585294.227 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:48:14.227Z,1754585294.227 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13 2025-08-07T16:50:02.785Z,1754585402.785 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:50:02.786Z,1754585402.786 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:50:02.786Z,1754585402.786 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:50:02.787Z,1754585402.787 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:50:03.062Z,1754585403.062 [MissionManager](DEBUG): TethyslAPI: ./Missions/Maintenance/sample_lab.tl translated into: 90 -4 1 Sampling ESP cartridge type 2025-08-07T16:50:03.070Z,1754585403.070 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2025-08-07T16:50:03.077Z,1754585403.077 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2025-08-07T16:50:03.079Z,1754585403.079 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2025-08-07T16:50:03.084Z,1754585403.084 [sample_lab:A.AbortSample](DEBUG): Construct. 2025-08-07T16:50:03.087Z,1754585403.087 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2025-08-07T16:50:03.137Z,1754585403.137 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. # ==================== # Generated by TethysL # ==================== mission sample_lab { """ This mission is designed to run in the lab only and triggers an ESP sample with specified type. """ arguments { MissionTimeout = 90 minute """ How long to let the mission run. """ CartridgeType = -4 count """ Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) """ NumberOfSamples = 1 count """ Number of samples to take. """ } timeout duration=MissionTimeout behavior Sample:AbortSample { run in parallel } aggregate SampleRepeater { run in sequence repeat=NumberOfSamples syslog important "Sampling ESP cartridge type " + CartridgeType~count behavior Science:ESPCartridgeSelect { run in sequence timeout duration=P1M set cartridgeType = CartridgeType } readDatum id="TriggerESP" { Science:ESPComponent.sampling } readDatum id="WaitForESP" { Science:ESPComponent.sample_number } } } 2025-08-07T16:50:03.138Z,1754585403.138 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock] Stopped 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault] Stopped 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T16:50:03.298Z,1754585403.298 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:50:03.299Z,1754585403.299 [MissionManager](IMPORTANT): Started mission sample_lab 2025-08-07T16:50:03.299Z,1754585403.299 [sample_lab] Running Loop=1 2025-08-07T16:50:03.299Z,1754585403.299 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2025-08-07T16:50:03.299Z,1754585403.299 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:50:03.299Z,1754585403.299 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2025-08-07T16:50:03.300Z,1754585403.300 [sample_lab:SampleRepeater] Running Loop=1 2025-08-07T16:50:03.320Z,1754585403.320 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2025-08-07T16:50:03.320Z,1754585403.320 [sample_lab:SampleRepeater:A] Running Loop=1 2025-08-07T16:50:03.321Z,1754585403.321 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -4.000000 count 2025-08-07T16:50:03.321Z,1754585403.321 [sample_lab:SampleRepeater:A] Stopped 2025-08-07T16:50:03.321Z,1754585403.321 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2025-08-07T16:50:03.321Z,1754585403.321 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2025-08-07T16:50:03.321Z,1754585403.321 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:50:03.744Z,1754585403.744 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4. 2025-08-07T16:50:03.745Z,1754585403.745 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2025-08-07T16:50:03.745Z,1754585403.745 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2025-08-07T16:50:03.745Z,1754585403.745 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2025-08-07T16:50:04.103Z,1754585404.103 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2025-08-07T16:50:04.891Z,1754585404.891 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence 2025-08-07T16:50:15.001Z,1754585415.001 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence 2025-08-07T16:50:15.073Z,1754585415.073 [ESPComponent](INFO): powering up ESP 2025-08-07T16:50:15.092Z,1754585415.092 [ESPComponent](INFO): powering up ESP secondary power supply 2025-08-07T16:50:15.108Z,1754585415.108 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.11.2:10.89.11.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2025-08-07T16:50:15.249Z,1754585415.249 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2025-08-07T16:50:16.622Z,1754585416.622 [ESPComponent](INFO): console: 2025-08-07T16:50:17.026Z,1754585417.026 [ESPComponent](INFO): console:NAND: 256 MiB 2025-08-07T16:50:17.425Z,1754585417.425 [ESPComponent](INFO): console: BOOTMODE: SPI 2025-08-07T16:50:17.849Z,1754585417.849 [ESPComponent](INFO): console: reading SPI NOR..Done 2025-08-07T16:50:18.224Z,1754585418.224 [ESPComponent](INFO): console: 2025-08-07T16:50:18.628Z,1754585418.628 [ESPComponent](INFO): console: 2025-08-07T16:50:19.028Z,1754585419.028 [ESPComponent](INFO): console: U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51) 2025-08-07T16:50:19.475Z,1754585419.475 [ESPComponent](INFO): console: 2025-08-07T16:50:19.878Z,1754585419.878 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2025-08-07T16:50:20.260Z,1754585420.260 [ESPComponent](INFO): console: flash params are already written into flash 2025-08-07T16:50:20.647Z,1754585420.647 [ESPComponent](INFO): console: DRAM: 64 MB 2025-08-07T16:50:21.051Z,1754585421.051 [ESPComponent](INFO): console: In: serial 2025-08-07T16:50:21.486Z,1754585421.486 [ESPComponent](INFO): console: Out: serial 2025-08-07T16:50:21.885Z,1754585421.885 [ESPComponent](INFO): console: Err: serial 2025-08-07T16:50:22.275Z,1754585422.275 [ESPComponent](INFO): console: Net: ks8851_mll 2025-08-07T16:50:22.683Z,1754585422.683 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2025-08-07T16:50:23.087Z,1754585423.087 [ESPComponent](INFO): console: 4096 KiB S25FL032P at 0:0 is now current device 2025-08-07T16:50:23.518Z,1754585423.518 [ESPComponent](INFO): console: Loading kernel from SPI flash...done 2025-08-07T16:50:23.880Z,1754585423.880 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2025-08-07T16:50:24.284Z,1754585424.284 [ESPComponent](INFO): console: Image Name: Linux-3.18.140-lpc31-mbari4 2025-08-07T16:50:24.689Z,1754585424.689 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2025-08-07T16:50:25.093Z,1754585425.093 [ESPComponent](INFO): console: Data Size: 2336368 Bytes = 2.2 MB 2025-08-07T16:50:25.539Z,1754585425.539 [ESPComponent](INFO): console: Load Address: 30008000 2025-08-07T16:50:25.914Z,1754585425.914 [ESPComponent](INFO): console: Entry Point: 30008000 2025-08-07T16:50:26.318Z,1754585426.318 [ESPComponent](INFO): console: Verifying Checksum ... OK 2025-08-07T16:50:26.707Z,1754585426.707 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2025-08-07T16:50:27.111Z,1754585427.111 [ESPComponent](INFO): console: OK 2025-08-07T16:50:27.561Z,1754585427.561 [ESPComponent](INFO): console: 2025-08-07T16:50:27.915Z,1754585427.915 [ESPComponent](INFO): console: Starting kernel ... 2025-08-07T16:50:28.330Z,1754585428.330 [ESPComponent](INFO): console: 2025-08-07T16:50:28.739Z,1754585428.739 [ESPComponent](INFO): console: Uncompressing Linux... Booting kernel... 2025-08-07T16:50:29.146Z,1754585429.146 [ESPComponent](INFO): console: [ 0.06] MBARI ESP 3G 2025-08-07T16:50:29.569Z,1754585429.569 [ESPComponent](INFO): console: 2025-08-07T16:50:29.936Z,1754585429.936 [ESPComponent](INFO): console:INIT: version 2.85 booting 2025-08-07T16:50:30.339Z,1754585430.339 [ESPComponent](INFO): console: 2025-08-07T16:50:30.745Z,1754585430.745 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2025-08-07T16:50:31.162Z,1754585431.162 [ESPComponent](INFO): console: ESPdummy 2025-08-07T16:50:31.590Z,1754585431.590 [ESPComponent](INFO): console: 2025-08-07T16:50:31.974Z,1754585431.974 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2025-08-07T16:50:32.424Z,1754585432.424 [ESPComponent](INFO): console: 2025-08-07T16:50:32.763Z,1754585432.763 [ESPComponent](INFO): console:Loading kernel modules 2025-08-07T16:50:33.183Z,1754585433.183 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2025-08-07T16:50:33.614Z,1754585433.614 [ESPComponent](INFO): console: [ 3.51] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support! 2025-08-07T16:50:33.986Z,1754585433.986 [ESPComponent](INFO): console: Starting device events handler 2025-08-07T16:50:34.444Z,1754585434.444 [ESPComponent](INFO): console: 2025-08-07T16:50:44.095Z,1754585444.095 [ESPComponent](INFO): console:Set system clock to: Thu Aug 7 09:51:14 PDT 2025 2025-08-07T16:50:44.480Z,1754585444.480 [ESPComponent](INFO): console: Starting syslogd klogd... 2025-08-07T16:50:44.887Z,1754585444.887 [ESPComponent](INFO): console: stopped syslogd (pid 719) 2025-08-07T16:50:45.292Z,1754585445.292 [ESPComponent](INFO): console: Bringing up lo ... 2025-08-07T16:50:45.717Z,1754585445.717 [ESPComponent](INFO): console: lo IP=127.0.0.1 2025-08-07T16:50:46.095Z,1754585446.095 [ESPComponent](INFO): console: Packet forwarding enabled 2025-08-07T16:50:46.514Z,1754585446.514 [ESPComponent](INFO): console: Bringing up platform ... 2025-08-07T16:50:46.984Z,1754585446.984 [ESPComponent](INFO): console: 2025-08-07T16:50:48.524Z,1754585448.524 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard 2025-08-07T16:50:48.988Z,1754585448.988 [ESPComponent](INFO): console: 2025-08-07T16:50:50.154Z,1754585450.154 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63 2025-08-07T16:50:50.551Z,1754585450.551 [ESPComponent](INFO): console: [#] ip -4 address add 192.168.5.39 dev wg2shore 2025-08-07T16:50:50.948Z,1754585450.948 [ESPComponent](INFO): console: [#] ip link set mtu 1376 up dev wg2shore 2025-08-07T16:50:51.353Z,1754585451.353 [ESPComponent](INFO): console: [#] ip -4 route add 192.168.4.0/23 dev wg2shore 2025-08-07T16:50:51.776Z,1754585451.776 [ESPComponent](INFO): console: Bringing up wg2shore ... 2025-08-07T16:50:52.170Z,1754585452.170 [ESPComponent](INFO): console: Starting netplugd... 2025-08-07T16:50:52.584Z,1754585452.584 [ESPComponent](INFO): console: Starting portmap... 2025-08-07T16:50:52.979Z,1754585452.979 [ESPComponent](INFO): console: Network unavailable: Local time is Thu Aug 7 09:51:21 PDT 2025 2025-08-07T16:50:53.373Z,1754585453.373 [ESPComponent](INFO): console: Starting chronyd... 2025-08-07T16:50:53.802Z,1754585453.802 [ESPComponent](INFO): console: Starting darkhttpd... 2025-08-07T16:50:54.187Z,1754585454.187 [ESPComponent](INFO): console: darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic. 2025-08-07T16:50:54.598Z,1754585454.598 [ESPComponent](INFO): console: listening on: http://0.0.0.0:80/ 2025-08-07T16:50:54.998Z,1754585454.998 [ESPComponent](INFO): console: set gid to 1 2025-08-07T16:50:55.420Z,1754585455.420 [ESPComponent](INFO): console: set uid to 65534 2025-08-07T16:50:55.834Z,1754585455.834 [ESPComponent](INFO): console: Starting dnsmasq... 2025-08-07T16:50:56.213Z,1754585456.213 [ESPComponent](INFO): console: 2025-08-07T16:50:56.618Z,1754585456.618 [ESPComponent](INFO): console: 2025-08-07T16:50:57.020Z,1754585457.020 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.83 -- 4/24/24 brent@mbari.org 2025-08-07T16:50:57.416Z,1754585457.416 [ESPComponent](INFO): console: 2025-08-07T16:50:57.839Z,1754585457.839 [ESPComponent](INFO): console:ESPdummy login: Bringing up WiFi ... 2025-08-07T16:50:58.220Z,1754585458.220 [ESPComponent](INFO): console: Determining IP configuration for WiFi ...udhcpc (v1.11.2) started 2025-08-07T16:50:58.624Z,1754585458.624 [ESPComponent](INFO): console: Sending discover... 2025-08-07T16:50:59.084Z,1754585459.084 [ESPComponent](INFO): console: 2025-08-07T16:51:01.518Z,1754585461.518 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:01.928Z,1754585461.928 [ESPComponent](INFO): console: 2025-08-07T16:51:04.288Z,1754585464.288 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:04.740Z,1754585464.740 [ESPComponent](INFO): console: 2025-08-07T16:51:07.108Z,1754585467.108 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:07.612Z,1754585467.612 [ESPComponent](INFO): console: 2025-08-07T16:51:10.341Z,1754585470.341 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:10.805Z,1754585470.805 [ESPComponent](INFO): console: 2025-08-07T16:51:13.178Z,1754585473.178 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:13.668Z,1754585473.668 [ESPComponent](INFO): console: 2025-08-07T16:51:14.789Z,1754585474.789 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14 2025-08-07T16:51:14.789Z,1754585474.789 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:51:14.800Z,1754585474.800 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:51:15.218Z,1754585475.218 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:51:15.218Z,1754585475.218 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14 2025-08-07T16:51:16.400Z,1754585476.400 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:16.864Z,1754585476.864 [ESPComponent](INFO): console: 2025-08-07T16:51:19.228Z,1754585479.228 [ESPComponent](INFO): console:Sending discover... 2025-08-07T16:51:19.653Z,1754585479.653 [ESPComponent](INFO): console: Sending select for 134.89.112.137... 2025-08-07T16:51:20.031Z,1754585480.031 [ESPComponent](INFO): console: Lease of 134.89.112.137 obtained, lease time 14400 2025-08-07T16:51:20.512Z,1754585480.512 [ESPComponent](INFO): console: 2025-08-07T16:51:24.480Z,1754585484.480 [ESPComponent](INFO): console:Mounting nfs filesystems ... 2025-08-07T16:51:24.881Z,1754585484.881 [ESPComponent](INFO): console: mounting /tempbox 2025-08-07T16:51:25.348Z,1754585485.348 [ESPComponent](INFO): console: 2025-08-07T16:51:26.095Z,1754585486.095 [ESPComponent](INFO): console: mounting /engineering 2025-08-07T16:51:26.572Z,1754585486.572 [ESPComponent](INFO): console: 2025-08-07T16:51:26.918Z,1754585486.918 [ESPComponent](INFO): console: mounting /project 2025-08-07T16:51:27.380Z,1754585487.380 [ESPComponent](INFO): console: 2025-08-07T16:51:27.728Z,1754585487.728 [ESPComponent](INFO): console: mounting /ESP 2025-08-07T16:51:28.184Z,1754585488.184 [ESPComponent](INFO): console: mounting /ftp 2025-08-07T16:51:28.580Z,1754585488.580 [ESPComponent](INFO): console: 2025-08-07T16:51:29.766Z,1754585489.766 [ESPComponent](INFO): console: mounting /bufflehead/home 2025-08-07T16:51:30.208Z,1754585490.208 [ESPComponent](INFO): console: 2025-08-07T16:51:30.540Z,1754585490.540 [ESPComponent](INFO): console: mounting /raven/home 2025-08-07T16:51:30.000Z,1754585491.000 [ESPComponent](INFO): console: 2025-08-07T16:51:33.367Z,1754585493.367 [ESPComponent](IMPORTANT): ESP has connected as client 2025-08-07T16:51:34.194Z,1754585494.194 [ESPComponent](IMPORTANT): [sample #2] Setting cartridge argument to -4 2025-08-07T16:51:34.194Z,1754585494.194 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2025-08-07T16:51:34.194Z,1754585494.194 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2 2025-08-07T16:51:34.242Z,1754585494.242 [sample_lab:SampleRepeater:TriggerESP] Stopped 2025-08-07T16:51:34.243Z,1754585494.243 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1 2025-08-07T16:51:34.606Z,1754585494.606 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2025-08-07T16:51:34.991Z,1754585494.991 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG 2025-08-07T16:51:35.389Z,1754585495.389 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS 2025-08-07T16:51:37.407Z,1754585497.407 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE 2025-08-07T16:51:39.030Z,1754585499.030 [ESPComponent](ERROR): In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<>. Elapsed time since command issued: 2.0148 2025-08-07T16:51:39.470Z,1754585499.470 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPING 2025-08-07T16:51:41.848Z,1754585501.848 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq -e 'ssh -o StrictHostKeyChecking=no' --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs & 2025-08-07T16:51:41.872Z,1754585501.872 [ESPComponent](INFO): closing pipe. 2025-08-07T16:51:42.270Z,1754585502.270 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPED 2025-08-07T16:51:48.801Z,1754585508.801 [CommandExec](IMPORTANT): got command stop 2025-08-07T16:51:48.801Z,1754585508.801 [CommandExec](IMPORTANT): Scheduling is paused 2025-08-07T16:51:48.801Z,1754585508.801 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop 2025-08-07T16:51:49.154Z,1754585509.154 [MissionManager](INFO): MissionManager is completed. 2025-08-07T16:51:49.154Z,1754585509.154 [MissionManager](INFO): Uninitializing Mission sample_lab 2025-08-07T16:51:49.154Z,1754585509.154 [sample_lab] Stopped 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab:A.AbortSample] Stopped 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample. 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab:SampleRepeater] Stopped 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater 2025-08-07T16:51:49.155Z,1754585509.155 [sample_lab:SampleRepeater:WaitForESP] Stopped 2025-08-07T16:51:49.568Z,1754585509.568 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2025-08-07T16:51:49.568Z,1754585509.568 [DefaultWithUndock] Running Loop=1 2025-08-07T16:51:49.568Z,1754585509.568 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2025-08-07T16:51:49.568Z,1754585509.568 [DefaultWithUndock:A.Wait] Running Loop=1 2025-08-07T16:51:49.568Z,1754585509.568 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:51:51.545Z,1754585511.545 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-08-07T16:51:51.545Z,1754585511.545 [NAL9602] Data Fault, FailCount= 4 2025-08-07T16:51:51.545Z,1754585511.545 [NAL9602](ERROR): Data Fault 2025-08-07T16:51:51.615Z,1754585511.615 [CBIT](ERROR): Data Fault in component: NAL9602 2025-08-07T16:51:51.949Z,1754585511.949 [NAL9602](INFO): Powering down 2025-08-07T16:51:52.769Z,1754585512.769 [CBIT](INFO): Clearing failed state for component NAL9602 2025-08-07T16:51:52.769Z,1754585512.769 [NAL9602] No Fault, FailCount= 4 2025-08-07T16:52:19.851Z,1754585539.851 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2025-08-07T16:52:19.851Z,1754585539.851 [DefaultWithUndock:A.Wait] Stopped 2025-08-07T16:52:19.851Z,1754585539.851 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:52:19.851Z,1754585539.851 [DefaultWithUndock:LeaveDock] Running Loop=1 2025-08-07T16:52:19.851Z,1754585539.851 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2025-08-07T16:52:19.852Z,1754585539.852 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2025-08-07T16:52:19.852Z,1754585539.852 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2025-08-07T16:52:19.852Z,1754585539.852 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2025-08-07T16:52:19.852Z,1754585539.852 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:52:19.852Z,1754585539.852 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:52:20.245Z,1754585540.245 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:52:20.245Z,1754585540.245 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:52:20.246Z,1754585540.246 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached from dock at depth -0.130410 m. 2025-08-07T16:52:20.247Z,1754585540.247 [DefaultWithUndock:LeaveDock:A.] Stopped 2025-08-07T16:52:20.247Z,1754585540.247 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-08-07T16:52:20.643Z,1754585540.643 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2025-08-07T16:52:21.051Z,1754585541.051 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T16:52:21.165Z,1754585541.165 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T16:52:22.249Z,1754585542.249 [NAL9602](INFO): Powering up NAL9602 2025-08-07T16:52:33.157Z,1754585553.157 [NAL9602](INFO): NAL9602 initialized 2025-08-07T16:52:40.844Z,1754585560.844 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning docking module to standby. 2025-08-07T16:52:41.253Z,1754585561.253 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:LeaveDock] Stopped 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2025-08-07T16:52:41.677Z,1754585561.677 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:52:41.678Z,1754585561.678 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2025-08-07T16:52:41.678Z,1754585561.678 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-08-07T16:52:41.678Z,1754585561.678 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-08-07T16:52:41.678Z,1754585561.678 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-08-07T16:52:41.678Z,1754585561.678 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-08-07T16:52:41.679Z,1754585561.679 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-08-07T16:52:41.679Z,1754585561.679 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-08-07T16:52:41.679Z,1754585561.679 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-08-07T16:52:42.085Z,1754585562.085 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2025-08-07T16:52:42.085Z,1754585562.085 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:52:42.085Z,1754585562.085 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:52:47.674Z,1754585567.674 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:52:47.675Z,1754585567.675 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:52:47.675Z,1754585567.675 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:52:47.676Z,1754585567.676 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Maintenance/sample_lab.tl 2025-08-07T16:52:47.850Z,1754585567.850 [MissionManager](DEBUG): TethyslAPI: ./Missions/Maintenance/sample_lab.tl translated into: 90 -4 1 Sampling ESP cartridge type 2025-08-07T16:52:47.854Z,1754585567.854 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2025-08-07T16:52:47.856Z,1754585567.856 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2025-08-07T16:52:47.858Z,1754585567.858 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2025-08-07T16:52:47.859Z,1754585567.859 [sample_lab:A.AbortSample](DEBUG): Construct. 2025-08-07T16:52:47.901Z,1754585567.901 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2025-08-07T16:52:47.909Z,1754585567.909 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. # ==================== # Generated by TethysL # ==================== mission sample_lab { """ This mission is designed to run in the lab only and triggers an ESP sample with specified type. """ arguments { MissionTimeout = 90 minute """ How long to let the mission run. """ CartridgeType = -4 count """ Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) """ NumberOfSamples = 1 count """ Number of samples to take. """ } timeout duration=MissionTimeout behavior Sample:AbortSample { run in parallel } aggregate SampleRepeater { run in sequence repeat=NumberOfSamples syslog important "Sampling ESP cartridge type " + CartridgeType~count behavior Science:ESPCartridgeSelect { run in sequence timeout duration=P1M set cartridgeType = CartridgeType } readDatum id="TriggerESP" { Science:ESPComponent.sampling } readDatum id="WaitForESP" { Science:ESPComponent.sample_number } } } 2025-08-07T16:52:47.910Z,1754585567.910 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.tl id=sample_lab 2025-08-07T16:53:05.719Z,1754585585.719 [CommandExec](IMPORTANT): got command set sample_lab.CartridgeType -15 count 2025-08-07T16:53:07.701Z,1754585587.701 [CommandExec](IMPORTANT): got command run 2025-08-07T16:53:07.702Z,1754585587.702 [CommandExec](IMPORTANT): Running 2025-08-07T16:53:07.939Z,1754585587.939 [DefaultWithUndock] Stopped 2025-08-07T16:53:07.940Z,1754585587.940 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault] Stopped 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:53:07.944Z,1754585587.944 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T16:53:07.945Z,1754585587.945 [MissionManager](IMPORTANT): Started mission sample_lab 2025-08-07T16:53:07.945Z,1754585587.945 [sample_lab] Running Loop=1 2025-08-07T16:53:07.945Z,1754585587.945 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2025-08-07T16:53:07.945Z,1754585587.945 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:53:07.945Z,1754585587.945 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2025-08-07T16:53:07.945Z,1754585587.945 [sample_lab:SampleRepeater] Running Loop=1 2025-08-07T16:53:07.946Z,1754585587.946 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2025-08-07T16:53:07.946Z,1754585587.946 [sample_lab:SampleRepeater:A] Running Loop=1 2025-08-07T16:53:07.946Z,1754585587.946 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -15.000000 count 2025-08-07T16:53:07.946Z,1754585587.946 [sample_lab:SampleRepeater:A] Stopped 2025-08-07T16:53:07.947Z,1754585587.947 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2025-08-07T16:53:07.947Z,1754585587.947 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2025-08-07T16:53:07.947Z,1754585587.947 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T16:53:08.339Z,1754585588.339 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -15. 2025-08-07T16:53:08.339Z,1754585588.339 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2025-08-07T16:53:08.339Z,1754585588.339 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2025-08-07T16:53:08.339Z,1754585588.339 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2025-08-07T16:53:08.733Z,1754585588.733 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2025-08-07T16:54:07.189Z,1754585647.189 [CommandExec](IMPORTANT): got command show stack 2025-08-07T16:54:07.189Z,1754585647.189 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T16:54:07.190Z,1754585647.190 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample 2025-08-07T16:54:07.190Z,1754585647.190 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:TriggerESP 2025-08-07T16:54:12.293Z,1754585652.293 [CommandExec](IMPORTANT): got command stop 2025-08-07T16:54:12.293Z,1754585652.293 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop 2025-08-07T16:54:12.574Z,1754585652.574 [MissionManager](INFO): MissionManager is completed. 2025-08-07T16:54:12.574Z,1754585652.574 [MissionManager](INFO): Uninitializing Mission sample_lab 2025-08-07T16:54:12.574Z,1754585652.574 [sample_lab] Stopped 2025-08-07T16:54:12.574Z,1754585652.574 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab 2025-08-07T16:54:12.574Z,1754585652.574 [sample_lab:A.AbortSample] Stopped 2025-08-07T16:54:12.574Z,1754585652.574 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample. 2025-08-07T16:54:12.575Z,1754585652.575 [sample_lab:SampleRepeater] Stopped 2025-08-07T16:54:12.575Z,1754585652.575 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater 2025-08-07T16:54:12.575Z,1754585652.575 [sample_lab:SampleRepeater:TriggerESP] Stopped 2025-08-07T16:54:12.985Z,1754585652.985 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2025-08-07T16:54:12.985Z,1754585652.985 [DefaultWithUndock] Running Loop=1 2025-08-07T16:54:12.985Z,1754585652.985 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2025-08-07T16:54:12.986Z,1754585652.986 [DefaultWithUndock:A.Wait] Running Loop=1 2025-08-07T16:54:12.986Z,1754585652.986 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2025-08-07T16:54:15.841Z,1754585655.841 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15 2025-08-07T16:54:15.841Z,1754585655.841 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:54:15.859Z,1754585655.859 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:54:16.219Z,1754585656.219 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:54:16.219Z,1754585656.219 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:A.Wait] Stopped 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:LeaveDock] Running Loop=1 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2025-08-07T16:54:43.278Z,1754585683.278 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2025-08-07T16:54:43.279Z,1754585683.279 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2025-08-07T16:54:43.279Z,1754585683.279 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2025-08-07T16:54:43.279Z,1754585683.279 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:54:43.279Z,1754585683.279 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:54:43.702Z,1754585683.702 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T16:54:43.702Z,1754585683.702 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T16:54:43.703Z,1754585683.703 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached from dock at depth -0.116147 m. 2025-08-07T16:54:43.704Z,1754585683.704 [DefaultWithUndock:LeaveDock:A.] Stopped 2025-08-07T16:54:43.704Z,1754585683.704 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-08-07T16:54:44.098Z,1754585684.098 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2025-08-07T16:54:44.496Z,1754585684.496 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T16:54:44.617Z,1754585684.617 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T16:55:04.286Z,1754585704.286 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning docking module to standby. 2025-08-07T16:55:04.690Z,1754585704.690 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2025-08-07T16:55:05.126Z,1754585705.126 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2025-08-07T16:55:05.126Z,1754585705.126 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:LeaveDock] Stopped 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2025-08-07T16:55:05.127Z,1754585705.127 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-08-07T16:55:05.128Z,1754585705.128 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-08-07T16:55:05.128Z,1754585705.128 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-08-07T16:55:05.128Z,1754585705.128 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-08-07T16:55:05.129Z,1754585705.129 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-08-07T16:55:05.129Z,1754585705.129 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-08-07T16:55:05.129Z,1754585705.129 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-08-07T16:55:05.532Z,1754585705.532 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2025-08-07T16:55:05.532Z,1754585705.532 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T16:55:05.533Z,1754585705.533 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T16:56:42.066Z,1754585802.066 [ESPComponent](CRITICAL): [sample #2] ESP sampling sequence terminated with error: In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<>. Elapsed time since command issued: 2.0148 2025-08-07T16:56:42.066Z,1754585802.066 [ESPComponent] Communications Fault, FailCount= 2 2025-08-07T16:56:42.066Z,1754585802.066 [ESPComponent](ERROR): Communications Fault 2025-08-07T16:56:42.085Z,1754585802.085 [CommandExec](FAULT): Scheduling is paused 2025-08-07T16:56:42.086Z,1754585802.086 [CBIT](INFO): Critical error at 20250807T165642 2025-08-07T16:56:42.088Z,1754585802.088 [CBIT](ERROR): Communications Fault in component: ESPComponent 2025-08-07T16:56:42.447Z,1754585802.447 [ESPComponent](IMPORTANT): [sample #2] No ESP summary messages. 2025-08-07T16:56:42.448Z,1754585802.448 [ESPComponent](INFO): powering down ESP 2025-08-07T16:56:42.448Z,1754585802.448 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T16:56:43.279Z,1754585803.279 [CBIT](INFO): Clearing failed state for component ESPComponent 2025-08-07T16:56:43.279Z,1754585803.279 [ESPComponent] No Fault, FailCount= 2 2025-08-07T16:56:44.073Z,1754585804.073 [ESPComponent](INFO): powering down ESP 2025-08-07T16:56:44.074Z,1754585804.074 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T16:57:16.797Z,1754585836.797 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16 2025-08-07T16:57:16.797Z,1754585836.797 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T16:57:16.808Z,1754585836.808 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T16:57:17.212Z,1754585837.212 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T16:57:17.212Z,1754585837.212 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16 2025-08-07T17:00:05.707Z,1754586005.707 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](INFO): Timed out from 2025-08-07T16:55:05.5Z 2025-08-07T17:00:05.707Z,1754586005.707 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:00:05.707Z,1754586005.707 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:00:13.352Z,1754586013.352 [DataOverHttps](INFO): Sending 306 bytes from file Logs/20250807T160847/Courier0010.lzma 2025-08-07T17:00:14.354Z,1754586014.354 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0010.lzma.bak 2025-08-07T17:00:14.355Z,1754586014.355 [DataOverHttps](INFO): SBD MOMSN=25803388 2025-08-07T17:00:17.838Z,1754586017.838 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17 2025-08-07T17:00:17.838Z,1754586017.838 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T17:00:17.881Z,1754586017.881 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T17:00:18.246Z,1754586018.246 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T17:00:18.246Z,1754586018.246 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17 2025-08-07T17:00:30.258Z,1754586030.258 [DataOverHttps](INFO): Sending 1001 bytes from file Logs/20250807T160847/Express0011.lzma 2025-08-07T17:00:31.258Z,1754586031.258 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0011.lzma.bak 2025-08-07T17:00:31.258Z,1754586031.258 [DataOverHttps](INFO): SBD MOMSN=25803392 2025-08-07T17:00:32.355Z,1754586032.355 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:00:32.355Z,1754586032.355 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:00:32.355Z,1754586032.355 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:02:34.337Z,1754586154.337 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-08-07T17:02:34.337Z,1754586154.337 [NAL9602] Data Fault, FailCount= 5 2025-08-07T17:02:34.337Z,1754586154.337 [NAL9602](ERROR): Data Fault 2025-08-07T17:02:34.355Z,1754586154.355 [CBIT](ERROR): Data Fault in component: NAL9602 2025-08-07T17:02:34.356Z,1754586154.356 [CBIT](CRITICAL): Data Fault in component: NAL9602 2025-08-07T17:02:34.741Z,1754586154.741 [NAL9602](INFO): Powering down 2025-08-07T17:02:34.758Z,1754586154.758 [CBIT](INFO): Critical error at 20250807T170234 2025-08-07T17:03:18.791Z,1754586198.791 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18 2025-08-07T17:03:18.791Z,1754586198.791 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T17:03:18.802Z,1754586198.802 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T17:03:19.213Z,1754586199.213 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T17:03:19.213Z,1754586199.213 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18 2025-08-07T17:04:01.614Z,1754586241.614 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude. Device response is::BD, +0.00, +0 +0.00, 0.00,3279.77 2025-08-07T17:04:34.346Z,1754586274.346 [CBIT](INFO): Clearing failed state for component NAL9602 2025-08-07T17:04:34.346Z,1754586274.346 [NAL9602] No Fault, FailCount= 5 2025-08-07T17:04:34.725Z,1754586274.725 [NAL9602](INFO): Powering up NAL9602 2025-08-07T17:04:45.633Z,1754586285.633 [NAL9602](INFO): NAL9602 initialized 2025-08-07T17:05:32.962Z,1754586332.962 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:05:32.962Z,1754586332.962 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:05:32.962Z,1754586332.962 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:05:32.962Z,1754586332.962 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:05:33.328Z,1754586333.328 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:05:33.328Z,1754586333.328 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 11.339047 min 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2 2025-08-07T17:05:33.748Z,1754586333.748 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2 2025-08-07T17:05:33.749Z,1754586333.749 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:05:33.749Z,1754586333.749 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:06:19.806Z,1754586379.806 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19 2025-08-07T17:06:19.806Z,1754586379.806 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T17:06:19.817Z,1754586379.817 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T17:06:20.212Z,1754586380.212 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T17:06:20.212Z,1754586380.212 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19 2025-08-07T17:09:20.787Z,1754586560.787 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20 2025-08-07T17:09:20.787Z,1754586560.787 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2025-08-07T17:09:20.798Z,1754586560.798 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2025-08-07T17:09:21.210Z,1754586561.210 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2025-08-07T17:09:21.210Z,1754586561.210 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 20 2025-08-07T17:10:33.910Z,1754586633.910 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](INFO): Timed out from 2025-08-07T17:05:33.7Z 2025-08-07T17:10:33.910Z,1754586633.910 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:10:33.911Z,1754586633.911 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:10:41.115Z,1754586641.115 [DataOverHttps](INFO): Sending 105 bytes from file Logs/20250807T160847/Courier0013.lzma 2025-08-07T17:10:42.118Z,1754586642.118 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0013.lzma.bak 2025-08-07T17:10:42.118Z,1754586642.118 [DataOverHttps](INFO): SBD MOMSN=25803486 2025-08-07T17:11:06.608Z,1754586666.608 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20250807T160847/Express0014.lzma 2025-08-07T17:11:07.610Z,1754586667.610 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0014.lzma.bak 2025-08-07T17:11:07.610Z,1754586667.610 [DataOverHttps](INFO): SBD MOMSN=25803489 2025-08-07T17:11:08.682Z,1754586668.682 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:11:08.682Z,1754586668.682 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:11:08.682Z,1754586668.682 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:12:19.763Z,1754586739.763 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171216.00,A,3648.13864,N,12147.24293,W,3.071,111.53,070825,,,A*7A 2025-08-07T17:12:19.767Z,1754586739.767 [NAL9602](INFO): GPS fix at 20250807T171216: (36.802311, -121.787382) 2025-08-07T17:12:52.497Z,1754586772.497 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:13:38.817Z,1754586818.817 [DataOverHttps](IMPORTANT): SBD MTMSN=20250807T171337 2025-08-07T17:13:46.540Z,1754586826.540 [DataOverHttps](INFO): Received command: failc 2025-08-07T17:13:46.577Z,1754586826.577 [CommandExec](IMPORTANT): got command failComponent 2025-08-07T17:13:46.577Z,1754586826.577 [CommandExec](IMPORTANT): Failed components: 2025-08-07T17:13:46.577Z,1754586826.577 [CommandExec](IMPORTANT): No failed Components. 2025-08-07T17:13:47.541Z,1754586827.541 [DataOverHttps](IMPORTANT): SBD MTMSN=20250807T171346 2025-08-07T17:13:55.240Z,1754586835.240 [DataOverHttps](INFO): Received command: ibit 2025-08-07T17:13:55.313Z,1754586835.313 [CommandExec](IMPORTANT): got command ibit 2025-08-07T17:13:55.549Z,1754586835.549 [IBIT](IMPORTANT): Beginning Initiated BIT 2025-08-07T17:13:55.549Z,1754586835.549 [IBIT](IMPORTANT): Beginning control surface checks. 2025-08-07T17:13:55.569Z,1754586835.569 [GFScanner](IMPORTANT): Beginning ground fault scan 2025-08-07T17:13:57.128Z,1754586837.128 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171353.00,A,3648.15125,N,12147.22481,W,0.078,140.37,070825,,,D*7A 2025-08-07T17:13:57.131Z,1754586837.131 [NAL9602](INFO): GPS fix at 20250807T171353: (36.802521, -121.787080) 2025-08-07T17:14:00.217Z,1754586840.217 [GFScanner](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.005315 CHAN A1 (24V): -0.002815 CHAN A2 (12V): -0.000522 CHAN A3 (5V): 0.000055 CHAN B0 (3.3V): 0.000590 CHAN B1 (3.15aV): 0.000294 CHAN B2 (3.15bV): -0.000014 CHAN B3 (GND): 0.001115 OPEN: 0.005036 Full Scale: +/- 1 mA 2025-08-07T17:14:20.209Z,1754586860.209 [NAL9602](INFO): SBD MO Status=2, MOMSN=450, MT Status=2, MTMSN=0 2025-08-07T17:14:20.209Z,1754586860.209 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-08-07T17:14:37.982Z,1754586877.982 [NAL9602](INFO): SBD MO Status=0, MOMSN=450, MT Status=0, MTMSN=0 2025-08-07T17:14:37.982Z,1754586877.982 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:14:37.982Z,1754586877.982 [NAL9602](INFO): Failure count cleared after critical for NAL9602 2025-08-07T17:14:39.199Z,1754586879.199 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171435.00,A,3648.14905,N,12147.22403,W,0.039,140.37,070825,,,D*79 2025-08-07T17:14:39.208Z,1754586879.208 [NAL9602](INFO): GPS fix at 20250807T171435: (36.802484, -121.787067) 2025-08-07T17:14:42.041Z,1754586882.041 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171438.00,A,3648.14926,N,12147.22448,W,0.078,140.37,070825,,,D*7F 2025-08-07T17:14:42.043Z,1754586882.043 [NAL9602](INFO): GPS fix at 20250807T171438: (36.802488, -121.787075) 2025-08-07T17:14:42.061Z,1754586882.061 [IBIT](IMPORTANT): Communications Status: Fix Status: 1 Iridium Signal Strength: 4 Latitude: 36.802486 Longitude: -121.787071 2025-08-07T17:14:42.466Z,1754586882.466 [IBIT](IMPORTANT): Battery Status: Battery Charge (AH): 0.000000 Voltage: 16.532000 2025-08-07T17:14:42.466Z,1754586882.466 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah 2025-08-07T17:14:42.467Z,1754586882.467 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V 2025-08-07T17:14:42.850Z,1754586882.850 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 % 2025-08-07T17:14:42.850Z,1754586882.850 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi 2025-08-07T17:14:42.851Z,1754586882.851 [IBIT](IMPORTANT): Pressure:10.485272 PSI 2025-08-07T17:14:42.851Z,1754586882.851 [IBIT](IMPORTANT): Humidity:10.432181 % 2025-08-07T17:14:43.257Z,1754586883.257 [IBIT](IMPORTANT): Vehicle Pitch:-0.982127 degrees 2025-08-07T17:14:43.258Z,1754586883.258 [IBIT](IMPORTANT): Vehicle Roll:1.127173 degrees 2025-08-07T17:14:43.258Z,1754586883.258 [IBIT](IMPORTANT): Vehicle Heading:11.417508 degrees 2025-08-07T17:14:43.693Z,1754586883.693 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m 2025-08-07T17:14:43.693Z,1754586883.693 [IBIT](IMPORTANT): buoyancyNeutral: 362.232300 cc 2025-08-07T17:14:43.693Z,1754586883.693 [IBIT](IMPORTANT): massDefault: 2.137661 cm 2025-08-07T17:14:43.694Z,1754586883.694 [IBIT](IMPORTANT): stopDepth: 275.000000 m 2025-08-07T17:14:43.694Z,1754586883.694 [IBIT](IMPORTANT): abortDepth: 300.000000 m 2025-08-07T17:14:43.694Z,1754586883.694 [IBIT](IMPORTANT): IBIT PASSED 2025-08-07T17:15:14.341Z,1754586914.341 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:15:40.102Z,1754586940.102 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:15:40.102Z,1754586940.102 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:15:40.102Z,1754586940.102 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:15:40.103Z,1754586940.103 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:15:40.351Z,1754586940.351 [MissionManager](DEBUG): TethyslAPI: ./Missions/Maintenance/sample_lab.tl translated into: 90 -4 1 Sampling ESP cartridge type 2025-08-07T17:15:40.359Z,1754586940.359 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2025-08-07T17:15:40.380Z,1754586940.380 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2025-08-07T17:15:40.382Z,1754586940.382 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2025-08-07T17:15:40.383Z,1754586940.383 [sample_lab:A.AbortSample](DEBUG): Construct. 2025-08-07T17:15:40.423Z,1754586940.423 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2025-08-07T17:15:40.431Z,1754586940.431 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. # ==================== # Generated by TethysL # ==================== mission sample_lab { """ This mission is designed to run in the lab only and triggers an ESP sample with specified type. """ arguments { MissionTimeout = 90 minute """ How long to let the mission run. """ CartridgeType = -4 count """ Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) """ NumberOfSamples = 1 count """ Number of samples to take. """ } timeout duration=MissionTimeout behavior Sample:AbortSample { run in parallel } aggregate SampleRepeater { run in sequence repeat=NumberOfSamples syslog important "Sampling ESP cartridge type " + CartridgeType~count behavior Science:ESPCartridgeSelect { run in sequence timeout duration=P1M set cartridgeType = CartridgeType } readDatum id="TriggerESP" { Science:ESPComponent.sampling } readDatum id="WaitForESP" { Science:ESPComponent.sample_number } } } 2025-08-07T17:15:40.441Z,1754586940.441 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.tl id=sample_lab 2025-08-07T17:15:55.593Z,1754586955.593 [CommandExec](IMPORTANT): got command set sample_lab.CartridgeType -15 count 2025-08-07T17:15:55.601Z,1754586955.601 [CommandExec](IMPORTANT): got command run 2025-08-07T17:15:55.602Z,1754586955.602 [CommandExec](IMPORTANT): Running 2025-08-07T17:15:55.637Z,1754586955.637 [DefaultWithUndock] Stopped 2025-08-07T17:15:55.637Z,1754586955.637 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2025-08-07T17:15:55.637Z,1754586955.637 [DefaultWithUndock:SurfaceDefault] Stopped 2025-08-07T17:15:55.637Z,1754586955.638 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:15:55.638Z,1754586955.638 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:15:55.638Z,1754586955.638 [MissionManager](IMPORTANT): Started mission sample_lab 2025-08-07T17:15:55.638Z,1754586955.638 [sample_lab] Running Loop=1 2025-08-07T17:15:55.638Z,1754586955.638 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2025-08-07T17:15:55.639Z,1754586955.639 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T17:15:55.639Z,1754586955.639 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2025-08-07T17:15:55.639Z,1754586955.639 [sample_lab:SampleRepeater] Running Loop=1 2025-08-07T17:15:55.639Z,1754586955.639 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2025-08-07T17:15:55.639Z,1754586955.639 [sample_lab:SampleRepeater:A] Running Loop=1 2025-08-07T17:15:55.652Z,1754586955.652 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -15.000000 count 2025-08-07T17:15:55.652Z,1754586955.652 [sample_lab:SampleRepeater:A] Stopped 2025-08-07T17:15:55.652Z,1754586955.652 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2025-08-07T17:15:55.652Z,1754586955.652 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2025-08-07T17:15:55.653Z,1754586955.653 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T17:15:55.973Z,1754586955.973 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -15. 2025-08-07T17:15:55.973Z,1754586955.973 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2025-08-07T17:15:55.973Z,1754586955.973 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2025-08-07T17:15:55.973Z,1754586955.973 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2025-08-07T17:15:56.370Z,1754586956.370 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2025-08-07T17:15:57.168Z,1754586957.168 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence 2025-08-07T17:16:07.275Z,1754586967.275 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence 2025-08-07T17:16:07.349Z,1754586967.349 [ESPComponent](INFO): powering up ESP 2025-08-07T17:16:07.368Z,1754586967.368 [ESPComponent](INFO): powering up ESP secondary power supply 2025-08-07T17:16:07.389Z,1754586967.389 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.11.2:10.89.11.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2025-08-07T17:16:07.580Z,1754586967.580 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2025-08-07T17:16:08.887Z,1754586968.887 [ESPComponent](INFO): console: 2025-08-07T17:16:09.291Z,1754586969.291 [ESPComponent](INFO): console:NAND: 256 MiB 2025-08-07T17:16:09.716Z,1754586969.716 [ESPComponent](INFO): console: BOOTMODE: SPI 2025-08-07T17:16:10.103Z,1754586970.103 [ESPComponent](INFO): console: reading SPI NOR..Done 2025-08-07T17:16:10.515Z,1754586970.515 [ESPComponent](INFO): console: 2025-08-07T17:16:10.911Z,1754586970.911 [ESPComponent](INFO): console: 2025-08-07T17:16:11.311Z,1754586971.311 [ESPComponent](INFO): console: U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51) 2025-08-07T17:16:11.743Z,1754586971.743 [ESPComponent](INFO): console: 2025-08-07T17:16:12.135Z,1754586972.135 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2025-08-07T17:16:12.527Z,1754586972.527 [ESPComponent](INFO): console: flash params are already written into flash 2025-08-07T17:16:12.927Z,1754586972.927 [ESPComponent](INFO): console: DRAM: 64 MB 2025-08-07T17:16:13.339Z,1754586973.339 [ESPComponent](INFO): console: In: serial 2025-08-07T17:16:13.772Z,1754586973.772 [ESPComponent](INFO): console: Out: serial 2025-08-07T17:16:14.138Z,1754586974.138 [ESPComponent](INFO): console: Err: serial 2025-08-07T17:16:14.547Z,1754586974.547 [ESPComponent](INFO): console: Net: ks8851_mll 2025-08-07T17:16:14.951Z,1754586974.951 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2025-08-07T17:16:15.351Z,1754586975.351 [ESPComponent](INFO): console: 4096 KiB S25FL032P at 0:0 is now current device 2025-08-07T17:16:15.793Z,1754586975.793 [ESPComponent](INFO): console: Loading kernel from SPI flash...done 2025-08-07T17:16:16.163Z,1754586976.163 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2025-08-07T17:16:16.567Z,1754586976.567 [ESPComponent](INFO): console: Image Name: Linux-3.18.140-lpc31-mbari4 2025-08-07T17:16:16.967Z,1754586976.967 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2025-08-07T17:16:17.372Z,1754586977.372 [ESPComponent](INFO): console: Data Size: 2336368 Bytes = 2.2 MB 2025-08-07T17:16:17.795Z,1754586977.795 [ESPComponent](INFO): console: Load Address: 30008000 2025-08-07T17:16:18.181Z,1754586978.181 [ESPComponent](INFO): console: Entry Point: 30008000 2025-08-07T17:16:18.592Z,1754586978.592 [ESPComponent](INFO): console: Verifying Checksum ... OK 2025-08-07T17:16:18.995Z,1754586978.995 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2025-08-07T17:16:19.391Z,1754586979.391 [ESPComponent](INFO): console: OK 2025-08-07T17:16:19.822Z,1754586979.822 [ESPComponent](INFO): console: 2025-08-07T17:16:20.199Z,1754586980.199 [ESPComponent](INFO): console: Starting kernel ... 2025-08-07T17:16:20.604Z,1754586980.604 [ESPComponent](INFO): console: 2025-08-07T17:16:21.007Z,1754586981.007 [ESPComponent](INFO): console: Uncompressing Linux... Booting kernel... 2025-08-07T17:16:21.415Z,1754586981.415 [ESPComponent](INFO): console: [ 0.06] MBARI ESP 3G 2025-08-07T17:16:21.840Z,1754586981.840 [ESPComponent](INFO): console: 2025-08-07T17:16:22.224Z,1754586982.224 [ESPComponent](INFO): console:INIT: version 2.85 booting 2025-08-07T17:16:22.624Z,1754586982.624 [ESPComponent](INFO): console: 2025-08-07T17:16:23.029Z,1754586983.029 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2025-08-07T17:16:23.465Z,1754586983.465 [ESPComponent](INFO): console: ESPdummy 2025-08-07T17:16:23.861Z,1754586983.861 [ESPComponent](INFO): console: 2025-08-07T17:16:24.239Z,1754586984.239 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2025-08-07T17:16:24.645Z,1754586984.645 [ESPComponent](INFO): console: 2025-08-07T17:16:25.054Z,1754586985.054 [ESPComponent](INFO): console:Loading kernel modules 2025-08-07T17:16:25.512Z,1754586985.512 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2025-08-07T17:16:25.873Z,1754586985.873 [ESPComponent](INFO): console: [ 3.52] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support! 2025-08-07T17:16:26.261Z,1754586986.261 [ESPComponent](INFO): console: Starting device events handler 2025-08-07T17:16:26.724Z,1754586986.724 [ESPComponent](INFO): console: 2025-08-07T17:16:36.361Z,1754586996.361 [ESPComponent](INFO): console:Set system clock to: Thu Aug 7 10:17:06 PDT 2025 2025-08-07T17:16:36.763Z,1754586996.763 [ESPComponent](INFO): console: Starting syslogd klogd... 2025-08-07T17:16:37.175Z,1754586997.175 [ESPComponent](INFO): console: stopped syslogd (pid 725) 2025-08-07T17:16:37.599Z,1754586997.599 [ESPComponent](INFO): console: Bringing up lo ... 2025-08-07T17:16:37.979Z,1754586997.979 [ESPComponent](INFO): console: lo IP=127.0.0.1 2025-08-07T17:16:38.381Z,1754586998.381 [ESPComponent](INFO): console: Packet forwarding enabled 2025-08-07T17:16:38.785Z,1754586998.785 [ESPComponent](INFO): console: Bringing up platform ... 2025-08-07T17:16:39.256Z,1754586999.256 [ESPComponent](INFO): console: 2025-08-07T17:16:40.402Z,1754587000.402 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard 2025-08-07T17:16:40.872Z,1754587000.872 [ESPComponent](INFO): console: 2025-08-07T17:16:42.020Z,1754587002.020 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63 2025-08-07T17:16:42.426Z,1754587002.426 [ESPComponent](INFO): console: [#] ip -4 address add 192.168.5.39 dev wg2shore 2025-08-07T17:16:42.827Z,1754587002.827 [ESPComponent](INFO): console: [#] ip link set mtu 1376 up dev wg2shore 2025-08-07T17:16:43.227Z,1754587003.227 [ESPComponent](INFO): console: [#] ip -4 route add 192.168.4.0/23 dev wg2shore 2025-08-07T17:16:43.652Z,1754587003.652 [ESPComponent](INFO): console: Bringing up wg2shore ... 2025-08-07T17:16:44.044Z,1754587004.044 [ESPComponent](INFO): console: Starting netplugd... 2025-08-07T17:16:44.441Z,1754587004.441 [ESPComponent](INFO): console: Starting portmap... 2025-08-07T17:16:44.844Z,1754587004.844 [ESPComponent](INFO): console: Network unavailable: Local time is Thu Aug 7 10:17:13 PDT 2025 2025-08-07T17:16:45.248Z,1754587005.248 [ESPComponent](INFO): console: Starting chronyd... 2025-08-07T17:16:45.680Z,1754587005.680 [ESPComponent](INFO): console: Starting darkhttpd... 2025-08-07T17:16:46.055Z,1754587006.055 [ESPComponent](INFO): console: darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic. 2025-08-07T17:16:46.460Z,1754587006.460 [ESPComponent](INFO): console: listening on: http://0.0.0.0:80/ 2025-08-07T17:16:46.864Z,1754587006.864 [ESPComponent](INFO): console: set gid to 1 2025-08-07T17:16:47.267Z,1754587007.267 [ESPComponent](INFO): console: set uid to 65534 2025-08-07T17:16:47.720Z,1754587007.720 [ESPComponent](INFO): console: Starting dnsmasq... 2025-08-07T17:16:48.082Z,1754587008.082 [ESPComponent](INFO): console: 2025-08-07T17:16:48.487Z,1754587008.487 [ESPComponent](INFO): console: 2025-08-07T17:16:48.884Z,1754587008.884 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.83 -- 4/24/24 brent@mbari.org 2025-08-07T17:16:49.287Z,1754587009.287 [ESPComponent](INFO): console: 2025-08-07T17:16:49.741Z,1754587009.741 [ESPComponent](INFO): console:ESPdummy login: Bringing up WiFi ... 2025-08-07T17:16:50.100Z,1754587010.100 [ESPComponent](INFO): console: Determining IP configuration for WiFi ...udhcpc (v1.11.2) started 2025-08-07T17:16:50.503Z,1754587010.503 [ESPComponent](INFO): console: Sending discover... 2025-08-07T17:16:50.968Z,1754587010.968 [ESPComponent](INFO): console: 2025-08-07T17:16:53.335Z,1754587013.335 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:16:53.820Z,1754587013.820 [ESPComponent](INFO): console: 2025-08-07T17:16:56.158Z,1754587016.158 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:16:56.628Z,1754587016.628 [ESPComponent](INFO): console: 2025-08-07T17:16:59.388Z,1754587019.388 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:16:59.817Z,1754587019.817 [ESPComponent](INFO): console: Sending select for 134.89.112.137... 2025-08-07T17:17:00.195Z,1754587020.195 [ESPComponent](INFO): console: Lease of 134.89.112.137 obtease time 14400 2025-08-07T17:17:00.660Z,1754587020.660 [ESPComponent](INFO): console: 2025-08-07T17:17:03.469Z,1754587023.469 [ESPComponent](INFO): console:Mounting nfs filesystems ... 2025-08-07T17:17:03.852Z,1754587023.852 [ESPComponent](INFO): console: mounting /tempbox 2025-08-07T17:17:04.308Z,1754587024.308 [ESPComponent](INFO): console: 2025-08-07T17:17:20.799Z,1754587040.799 [ESPComponent](INFO): console: mounting /engineering 2025-08-07T17:17:21.272Z,1754587041.272 [ESPComponent](INFO): console: 2025-08-07T17:17:22.822Z,1754587042.822 [ESPComponent](IMPORTANT): ESP has connected as client 2025-08-07T17:17:23.651Z,1754587043.651 [ESPComponent](IMPORTANT): [sample #3] Setting cartridge argument to -15 2025-08-07T17:17:23.652Z,1754587043.652 [ESPComponent](IMPORTANT): [sample #3] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2025-08-07T17:17:23.652Z,1754587043.652 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=3 2025-08-07T17:17:23.662Z,1754587043.662 [sample_lab:SampleRepeater:TriggerESP] Stopped 2025-08-07T17:17:23.662Z,1754587043.662 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1 2025-08-07T17:17:24.054Z,1754587044.054 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2025-08-07T17:17:24.435Z,1754587044.435 [ESPComponent](IMPORTANT): [sample #3] ESP sampling state: S_PREPARING_SHOW_LOG 2025-08-07T17:17:24.843Z,1754587044.843 [ESPComponent](IMPORTANT): [sample #3] ESP sampling state: S_PREPARING_SHOW_STATUS 2025-08-07T17:17:26.863Z,1754587046.863 [ESPComponent](IMPORTANT): [sample #3] ESP sampling state: S_LOADING_CARTRIDGE 2025-08-07T17:17:28.478Z,1754587048.478 [ESPComponent](ERROR): In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -15' exception=<>. Elapsed time since command issued: 2.0168 2025-08-07T17:17:28.883Z,1754587048.883 [ESPComponent](IMPORTANT): [sample #3] ESP sampling state: S_STOPPING 2025-08-07T17:17:31.310Z,1754587051.310 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq -e 'ssh -o StrictHostKeyChecking=no' --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs & 2025-08-07T17:17:31.324Z,1754587051.324 [ESPComponent](INFO): closing pipe. 2025-08-07T17:17:31.739Z,1754587051.739 [ESPComponent](IMPORTANT): [sample #3] ESP sampling state: S_STOPPED 2025-08-07T17:19:39.969Z,1754587179.969 [CommandExec](IMPORTANT): got command stop 2025-08-07T17:19:39.969Z,1754587179.969 [CommandExec](IMPORTANT): Scheduling is paused 2025-08-07T17:19:39.969Z,1754587179.969 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop 2025-08-07T17:19:40.227Z,1754587180.227 [MissionManager](INFO): MissionManager is completed. 2025-08-07T17:19:40.227Z,1754587180.227 [MissionManager](INFO): Uninitializing Mission sample_lab 2025-08-07T17:19:40.227Z,1754587180.227 [sample_lab] Stopped 2025-08-07T17:19:40.227Z,1754587180.227 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab 2025-08-07T17:19:40.227Z,1754587180.227 [sample_lab:A.AbortSample] Stopped 2025-08-07T17:19:40.227Z,1754587180.227 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample. 2025-08-07T17:19:40.227Z,1754587180.227 [sample_lab:SampleRepeater] Stopped 2025-08-07T17:19:40.228Z,1754587180.228 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater 2025-08-07T17:19:40.228Z,1754587180.228 [sample_lab:SampleRepeater:WaitForESP] Stopped 2025-08-07T17:19:40.636Z,1754587180.636 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2025-08-07T17:19:40.636Z,1754587180.636 [DefaultWithUndock] Running Loop=1 2025-08-07T17:19:40.637Z,1754587180.637 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2025-08-07T17:19:40.637Z,1754587180.637 [DefaultWithUndock:A.Wait] Running Loop=1 2025-08-07T17:19:40.637Z,1754587180.637 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:20:10.929Z,1754587210.929 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:A.Wait] Stopped 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:LeaveDock] Running Loop=1 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2025-08-07T17:20:10.930Z,1754587210.930 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2025-08-07T17:20:10.931Z,1754587210.931 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T17:20:10.931Z,1754587210.931 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T17:20:11.341Z,1754587211.341 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2025-08-07T17:20:11.341Z,1754587211.341 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2025-08-07T17:20:11.342Z,1754587211.342 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached from dock at depth -0.112689 m. 2025-08-07T17:20:11.342Z,1754587211.342 [DefaultWithUndock:LeaveDock:A.] Stopped 2025-08-07T17:20:11.342Z,1754587211.342 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-08-07T17:20:11.767Z,1754587211.767 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2025-08-07T17:20:12.149Z,1754587212.149 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-08-07T17:20:12.265Z,1754587212.265 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-08-07T17:20:31.939Z,1754587231.939 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning docking module to standby. 2025-08-07T17:20:32.354Z,1754587232.354 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2025-08-07T17:20:32.743Z,1754587232.743 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2025-08-07T17:20:32.744Z,1754587232.744 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2025-08-07T17:20:32.744Z,1754587232.744 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2025-08-07T17:20:32.744Z,1754587232.744 [DefaultWithUndock:LeaveDock] Stopped 2025-08-07T17:20:32.744Z,1754587232.744 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2025-08-07T17:20:32.744Z,1754587232.744 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2025-08-07T17:20:32.745Z,1754587232.745 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2025-08-07T17:20:32.745Z,1754587232.745 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2025-08-07T17:20:32.745Z,1754587232.745 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-08-07T17:20:32.745Z,1754587232.745 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-08-07T17:20:32.745Z,1754587232.745 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-08-07T17:20:32.746Z,1754587232.746 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-08-07T17:20:32.746Z,1754587232.746 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-08-07T17:20:32.746Z,1754587232.746 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-08-07T17:20:32.747Z,1754587232.747 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-08-07T17:20:33.148Z,1754587233.148 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2025-08-07T17:20:33.148Z,1754587233.148 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:20:33.149Z,1754587233.149 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:20:35.161Z,1754587235.161 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172034.00,A,3648.15272,N,12147.22088,W,0.019,90.34,070825,,,D*4F 2025-08-07T17:20:35.163Z,1754587235.163 [NAL9602](INFO): GPS fix at 20250807T172034: (36.802545, -121.787015) 2025-08-07T17:20:35.175Z,1754587235.175 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:20:35.175Z,1754587235.175 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:20:42.644Z,1754587242.644 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20250807T160847/Courier0016.lzma 2025-08-07T17:20:43.646Z,1754587243.646 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0016.lzma.bak 2025-08-07T17:20:43.646Z,1754587243.646 [DataOverHttps](INFO): SBD MOMSN=25803546 2025-08-07T17:21:00.103Z,1754587260.103 [DataOverHttps](INFO): Sending 1763 bytes from file Logs/20250807T160847/Express0017.lzma 2025-08-07T17:21:01.103Z,1754587261.103 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0017.lzma.bak 2025-08-07T17:21:01.103Z,1754587261.103 [DataOverHttps](INFO): SBD MOMSN=25803549 2025-08-07T17:21:02.386Z,1754587262.386 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:21:02.386Z,1754587262.386 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:21:02.387Z,1754587262.387 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:22:31.715Z,1754587351.715 [ESPComponent](CRITICAL): [sample #3] ESP sampling sequence terminated with error: In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -15' exception=<>. Elapsed time since command issued: 2.0168 2025-08-07T17:22:31.715Z,1754587351.715 [ESPComponent] Communications Fault, FailCount= 3 2025-08-07T17:22:31.715Z,1754587351.715 [ESPComponent](ERROR): Communications Fault 2025-08-07T17:22:31.731Z,1754587351.731 [CommandExec](FAULT): Scheduling is paused 2025-08-07T17:22:31.778Z,1754587351.778 [CBIT](INFO): Critical error at 20250807T172231 2025-08-07T17:22:31.780Z,1754587351.780 [CBIT](ERROR): Communications Fault in component: ESPComponent 2025-08-07T17:22:31.781Z,1754587351.781 [CBIT](CRITICAL): Communications Fault in component: ESPComponent 2025-08-07T17:22:32.075Z,1754587352.075 [ESPComponent](IMPORTANT): [sample #3] No ESP summary messages. 2025-08-07T17:22:32.075Z,1754587352.075 [ESPComponent](INFO): powering down ESP 2025-08-07T17:22:32.076Z,1754587352.076 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T17:22:32.274Z,1754587352.274 [CBIT](INFO): Critical error at 20250807T172231 2025-08-07T17:22:47.486Z,1754587367.486 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error. Device response is::TS,0002122109540+23.7, 0.0 0 2025-08-07T17:23:37.525Z,1754587417.525 [NAL9602](INFO): SBD MO Status=2, MOMSN=451, MT Status=2, MTMSN=0 2025-08-07T17:23:37.526Z,1754587417.526 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-08-07T17:24:22.790Z,1754587462.790 [NAL9602](INFO): SBD MO Status=0, MOMSN=451, MT Status=0, MTMSN=0 2025-08-07T17:24:22.790Z,1754587462.790 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:24:53.549Z,1754587493.549 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:26:03.094Z,1754587563.094 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:26:03.094Z,1754587563.094 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:26:03.094Z,1754587563.094 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:26:03.094Z,1754587563.094 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:26:03.569Z,1754587563.569 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:26:03.569Z,1754587563.569 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 6.382206 min 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2 2025-08-07T17:26:03.890Z,1754587563.890 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2 2025-08-07T17:26:03.891Z,1754587563.891 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:26:03.891Z,1754587563.891 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:26:05.895Z,1754587565.895 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172605.00,A,3648.14991,N,12147.21674,W,0.214,171.58,070825,,,A*74 2025-08-07T17:26:05.898Z,1754587565.898 [NAL9602](INFO): GPS fix at 20250807T172605: (36.802498, -121.786946) 2025-08-07T17:26:05.910Z,1754587565.910 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:26:05.910Z,1754587565.910 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:26:06.708Z,1754587566.708 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:26:06.708Z,1754587566.708 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:26:06.708Z,1754587566.708 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:26:17.204Z,1754587577.204 [NAL9602](INFO): SBD MO Status=0, MOMSN=452, MT Status=0, MTMSN=0 2025-08-07T17:26:17.205Z,1754587577.205 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:26:41.896Z,1754587601.896 [CBIT](INFO): Clearing failed state for component ESPComponent 2025-08-07T17:26:41.896Z,1754587601.896 [ESPComponent] No Fault, FailCount= 3 2025-08-07T17:26:42.670Z,1754587602.670 [ESPComponent](INFO): powering down ESP 2025-08-07T17:26:42.671Z,1754587602.671 [ESPComponent](INFO): powering down ESP secondary power supply 2025-08-07T17:26:47.917Z,1754587607.917 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:29:19.820Z,1754587759.820 [RDI_Pathfinder](ERROR): only read 2 of 4 data items for beam range. Device response is::RA, 0.002768,-32768,-32768,V 2025-08-07T17:31:07.289Z,1754587867.289 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:31:07.289Z,1754587867.289 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:31:07.289Z,1754587867.289 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:31:07.289Z,1754587867.289 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:31:07.720Z,1754587867.720 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:31:07.720Z,1754587867.720 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:31:08.111Z,1754587868.111 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 11.451396 min 2025-08-07T17:31:08.111Z,1754587868.111 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #3 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=3 2025-08-07T17:31:08.112Z,1754587868.112 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:31:08.113Z,1754587868.113 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:31:10.107Z,1754587870.107 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173109.00,A,3648.14962,N,12147.21674,W,0.039,171.58,070825,,,A*7F 2025-08-07T17:31:10.109Z,1754587870.109 [NAL9602](INFO): GPS fix at 20250807T173109: (36.802494, -121.786946) 2025-08-07T17:31:10.121Z,1754587870.121 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:31:10.121Z,1754587870.121 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:31:17.990Z,1754587877.990 [DataOverHttps](INFO): Sending 369 bytes from file Logs/20250807T160847/Courier0021.lzma 2025-08-07T17:31:18.990Z,1754587878.990 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0021.lzma.bak 2025-08-07T17:31:18.990Z,1754587878.990 [DataOverHttps](INFO): SBD MOMSN=25803659 2025-08-07T17:31:35.491Z,1754587895.491 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20250807T160847/Courier0025.lzma 2025-08-07T17:31:36.470Z,1754587896.470 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0025.lzma.bak 2025-08-07T17:31:36.470Z,1754587896.470 [DataOverHttps](INFO): SBD MOMSN=25803667 2025-08-07T17:31:51.330Z,1754587911.330 [NAL9602](INFO): SBD MO Status=2, MOMSN=453, MT Status=2, MTMSN=0 2025-08-07T17:31:51.330Z,1754587911.330 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-08-07T17:31:56.157Z,1754587916.157 [DataOverHttps](INFO): Sending 175 bytes from file Logs/20250807T160847/Express0020.lzma 2025-08-07T17:31:57.158Z,1754587917.158 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0020.lzma.bak 2025-08-07T17:31:57.158Z,1754587917.158 [DataOverHttps](INFO): SBD MOMSN=25803670 2025-08-07T17:32:09.540Z,1754587929.540 [NAL9602](INFO): SBD MO Status=2, MOMSN=453, MT Status=2, MTMSN=0 2025-08-07T17:32:09.540Z,1754587929.540 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-08-07T17:32:15.340Z,1754587935.340 [DataOverHttps](INFO): Sending 154 bytes from file Logs/20250807T160847/Express0026.lzma 2025-08-07T17:32:16.342Z,1754587936.342 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0026.lzma.bak 2025-08-07T17:32:16.342Z,1754587936.342 [DataOverHttps](INFO): SBD MOMSN=25803674 2025-08-07T17:32:17.642Z,1754587937.642 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:32:17.642Z,1754587937.642 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:32:17.643Z,1754587937.643 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:32:26.902Z,1754587946.902 [NAL9602](INFO): SBD MO Status=2, MOMSN=453, MT Status=2, MTMSN=0 2025-08-07T17:32:26.902Z,1754587946.902 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-08-07T17:32:46.296Z,1754587966.296 [NAL9602](INFO): SBD MO Status=0, MOMSN=453, MT Status=0, MTMSN=0 2025-08-07T17:32:46.296Z,1754587966.296 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:33:17.001Z,1754587997.001 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:37:18.205Z,1754588238.205 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:37:18.205Z,1754588238.205 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:37:18.205Z,1754588238.205 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:37:18.205Z,1754588238.205 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:37:18.607Z,1754588238.607 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:37:18.607Z,1754588238.607 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 17.632847 min 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #4 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=4 2025-08-07T17:37:19.026Z,1754588239.026 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:37:19.027Z,1754588239.027 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:37:21.015Z,1754588241.015 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173720.00,A,3648.15128,N,12147.22094,W,0.039,171.58,070825,,,D*7B 2025-08-07T17:37:21.018Z,1754588241.018 [NAL9602](INFO): GPS fix at 20250807T173720: (36.802521, -121.787016) 2025-08-07T17:37:21.030Z,1754588241.030 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:37:21.030Z,1754588241.030 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:37:28.840Z,1754588248.840 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20250807T160847/Courier0028.lzma 2025-08-07T17:37:29.842Z,1754588249.842 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0028.lzma.bak 2025-08-07T17:37:29.842Z,1754588249.842 [DataOverHttps](INFO): SBD MOMSN=25803760 2025-08-07T17:37:39.214Z,1754588259.214 [NAL9602](INFO): SBD MO Status=0, MOMSN=454, MT Status=0, MTMSN=0 2025-08-07T17:37:39.214Z,1754588259.214 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:37:48.560Z,1754588268.560 [DataOverHttps](INFO): Sending 149 bytes from file Logs/20250807T160847/Express0029.lzma 2025-08-07T17:37:49.562Z,1754588269.562 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0029.lzma.bak 2025-08-07T17:37:49.562Z,1754588269.562 [DataOverHttps](INFO): SBD MOMSN=25803763 2025-08-07T17:37:50.936Z,1754588270.936 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:37:50.936Z,1754588270.936 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:37:50.936Z,1754588270.936 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:38:09.917Z,1754588289.917 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:42:51.538Z,1754588571.538 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:42:51.538Z,1754588571.538 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:42:51.538Z,1754588571.538 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:42:51.538Z,1754588571.538 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:42:51.918Z,1754588571.918 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:42:51.918Z,1754588571.918 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 23.188025 min 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #5 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=5 2025-08-07T17:42:52.323Z,1754588572.323 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:42:52.324Z,1754588572.324 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:42:54.355Z,1754588574.355 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174253.00,A,3648.41330,N,12147.11606,W,4.354,3.05,070825,,,D*7A 2025-08-07T17:42:54.357Z,1754588574.357 [NAL9602](INFO): GPS fix at 20250807T174253: (36.806888, -121.785268) 2025-08-07T17:42:54.369Z,1754588574.369 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:42:54.369Z,1754588574.369 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:43:02.467Z,1754588582.467 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20250807T160847/Courier0031.lzma 2025-08-07T17:43:03.472Z,1754588583.472 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0031.lzma.bak 2025-08-07T17:43:03.472Z,1754588583.472 [DataOverHttps](INFO): SBD MOMSN=25803777 2025-08-07T17:43:09.282Z,1754588589.282 [NAL9602](INFO): SBD MO Status=0, MOMSN=455, MT Status=0, MTMSN=0 2025-08-07T17:43:09.282Z,1754588589.282 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:43:19.938Z,1754588599.938 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20250807T160847/Express0032.lzma 2025-08-07T17:43:20.938Z,1754588600.938 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0032.lzma.bak 2025-08-07T17:43:20.938Z,1754588600.938 [DataOverHttps](INFO): SBD MOMSN=25803781 2025-08-07T17:43:22.217Z,1754588602.217 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:43:22.217Z,1754588602.217 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:43:22.217Z,1754588602.217 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:43:39.989Z,1754588619.989 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:48:22.870Z,1754588902.870 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:48:22.870Z,1754588902.870 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:48:22.870Z,1754588902.870 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:48:22.871Z,1754588902.871 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:48:23.279Z,1754588903.279 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:48:23.279Z,1754588903.279 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:48:23.712Z,1754588903.712 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 28.710699 min 2025-08-07T17:48:23.712Z,1754588903.712 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:48:23.712Z,1754588903.712 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:48:23.712Z,1754588903.712 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:48:23.712Z,1754588903.712 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:48:23.713Z,1754588903.713 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #6 2025-08-07T17:48:23.713Z,1754588903.713 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=6 2025-08-07T17:48:23.713Z,1754588903.713 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:48:23.713Z,1754588903.713 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:48:25.688Z,1754588905.688 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174824.00,A,3648.08629,N,12148.21972,W,21.479,261.13,070825,,,D*4E 2025-08-07T17:48:25.691Z,1754588905.691 [NAL9602](INFO): GPS fix at 20250807T174824: (36.801438, -121.803662) 2025-08-07T17:48:25.750Z,1754588905.750 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:48:25.750Z,1754588905.750 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:48:33.731Z,1754588913.731 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20250807T160847/Courier0034.lzma 2025-08-07T17:48:34.735Z,1754588914.735 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0034.lzma.bak 2025-08-07T17:48:34.735Z,1754588914.735 [DataOverHttps](INFO): SBD MOMSN=25803840 2025-08-07T17:48:43.871Z,1754588923.871 [NAL9602](INFO): SBD MO Status=0, MOMSN=456, MT Status=0, MTMSN=0 2025-08-07T17:48:43.871Z,1754588923.871 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:48:50.896Z,1754588930.896 [DataOverHttps](INFO): Sending 169 bytes from file Logs/20250807T160847/Express0035.lzma 2025-08-07T17:48:51.898Z,1754588931.898 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0035.lzma.bak 2025-08-07T17:48:51.898Z,1754588931.898 [DataOverHttps](INFO): SBD MOMSN=25803847 2025-08-07T17:48:53.168Z,1754588933.168 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:48:53.168Z,1754588933.168 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:48:53.168Z,1754588933.168 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:49:14.577Z,1754588954.577 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:49:50.124Z,1754588990.124 [BPC1](ERROR): Failed to receive data from all battery packs. 2025-08-07T17:49:50.124Z,1754588990.124 [BPC1] Communications Fault, FailCount= 1 2025-08-07T17:49:50.124Z,1754588990.124 [BPC1](ERROR): Communications Fault 2025-08-07T17:49:50.153Z,1754588990.153 [CBIT](ERROR): Communications Fault in component: BPC1 2025-08-07T17:53:53.822Z,1754589233.822 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2025-08-07T17:53:53.822Z,1754589233.822 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:53:53.822Z,1754589233.822 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:53:53.823Z,1754589233.823 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2025-08-07T17:53:54.185Z,1754589234.185 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2025-08-07T17:53:54.185Z,1754589234.185 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2025-08-07T17:53:54.599Z,1754589234.599 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 34.225810 min 2025-08-07T17:53:54.599Z,1754589234.599 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2025-08-07T17:53:54.599Z,1754589234.599 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:53:54.599Z,1754589234.599 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:53:54.599Z,1754589234.599 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:53:54.600Z,1754589234.600 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #7 2025-08-07T17:53:54.600Z,1754589234.600 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=7 2025-08-07T17:53:54.600Z,1754589234.600 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:53:54.600Z,1754589234.600 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2025-08-07T17:53:56.594Z,1754589236.594 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175355.00,A,3647.86367,N,12150.27135,W,17.650,257.04,070825,,,A*4A 2025-08-07T17:53:56.597Z,1754589236.597 [NAL9602](INFO): GPS fix at 20250807T175355: (36.797728, -121.837856) 2025-08-07T17:53:56.608Z,1754589236.608 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2025-08-07T17:53:56.608Z,1754589236.608 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2025-08-07T17:54:04.816Z,1754589244.816 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20250807T160847/Courier0037.lzma 2025-08-07T17:54:05.818Z,1754589245.818 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Courier0037.lzma.bak 2025-08-07T17:54:05.818Z,1754589245.818 [DataOverHttps](INFO): SBD MOMSN=25803858 2025-08-07T17:54:13.968Z,1754589253.968 [NAL9602](INFO): SBD MO Status=0, MOMSN=457, MT Status=0, MTMSN=0 2025-08-07T17:54:13.968Z,1754589253.968 [NAL9602](INFO): No messages in MT queue 2025-08-07T17:54:22.055Z,1754589262.055 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20250807T160847/Express0038.lzma 2025-08-07T17:54:23.059Z,1754589263.059 [DataOverHttps](INFO): Moved sent file to Logs/20250807T160847/Express0038.lzma.bak 2025-08-07T17:54:23.059Z,1754589263.059 [DataOverHttps](INFO): SBD MOMSN=25803904 2025-08-07T17:54:24.119Z,1754589264.119 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2025-08-07T17:54:24.119Z,1754589264.119 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2025-08-07T17:54:24.119Z,1754589264.119 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-08-07T17:54:26.473Z,1754589266.473 [CommandExec](IMPORTANT): got command show stack 2025-08-07T17:54:26.473Z,1754589266.473 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T17:54:26.474Z,1754589266.474 [DefaultWithUndock:SurfaceDefault](IMPORTANT): Priority 0: DefaultWithUndock:SurfaceDefault:A.GoToSurface 2025-08-07T17:54:26.474Z,1754589266.474 [DefaultWithUndock:SurfaceDefault:CheckIn](IMPORTANT): Priority 1: DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait 2025-08-07T17:54:40.370Z,1754589280.370 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:54:40.371Z,1754589280.371 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:54:40.371Z,1754589280.371 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:54:40.374Z,1754589280.374 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Maintenance/sample_lab.tl 2025-08-07T17:54:40.465Z,1754589280.465 [MissionManager](DEBUG): TethyslAPI: ./Missions/Maintenance/sample_lab.tl translated into: 90 -4 1 Sampling ESP cartridge type 2025-08-07T17:54:40.469Z,1754589280.469 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2025-08-07T17:54:40.471Z,1754589280.471 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2025-08-07T17:54:40.473Z,1754589280.473 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2025-08-07T17:54:40.474Z,1754589280.474 [sample_lab:A.AbortSample](DEBUG): Construct. 2025-08-07T17:54:40.477Z,1754589280.477 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2025-08-07T17:54:40.482Z,1754589280.482 [MissionManager](DEBUG): # Copyright (c) 2024 MBARI # MBARI Proprietary Information. Confidential. All Rights Reserved # Unauthorized copying or distribution of this file via any medium is strictly # prohibited. # # WARNING - This file contains information whose export is restricted by the # Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as # amended. Violations of these export laws are subject to severe civil and/or # criminal penalties. # ==================== # Generated by TethysL # ==================== mission sample_lab { """ This mission is designed to run in the lab only and triggers an ESP sample with specified type. """ arguments { MissionTimeout = 90 minute """ How long to let the mission run. """ CartridgeType = -4 count """ Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) """ NumberOfSamples = 1 count """ Number of samples to take. """ } timeout duration=MissionTimeout behavior Sample:AbortSample { run in parallel } aggregate SampleRepeater { run in sequence repeat=NumberOfSamples syslog important "Sampling ESP cartridge type " + CartridgeType~count behavior Science:ESPCartridgeSelect { run in sequence timeout duration=P1M set cartridgeType = CartridgeType } readDatum id="TriggerESP" { Science:ESPComponent.sampling } readDatum id="WaitForESP" { Science:ESPComponent.sample_number } } } 2025-08-07T17:54:40.482Z,1754589280.482 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.tl id=sample_lab 2025-08-07T17:54:44.669Z,1754589284.669 [NAL9602](INFO): Not Powering down - fast GPS 2025-08-07T17:54:56.499Z,1754589296.499 [CommandExec](IMPORTANT): got command set sample_lab.CartridgeType -1 count 2025-08-07T17:54:56.501Z,1754589296.501 [CommandExec](IMPORTANT): got command run 2025-08-07T17:54:56.502Z,1754589296.502 [CommandExec](IMPORTANT): Running 2025-08-07T17:54:56.820Z,1754589296.820 [DefaultWithUndock] Stopped 2025-08-07T17:54:56.820Z,1754589296.820 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault] Stopped 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2025-08-07T17:54:56.821Z,1754589296.821 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-08-07T17:54:56.821Z,1754589296.821 [MissionManager](IMPORTANT): Started mission sample_lab 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab] Running Loop=1 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab:SampleRepeater] Running Loop=1 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2025-08-07T17:54:56.822Z,1754589296.822 [sample_lab:SampleRepeater:A] Running Loop=1 2025-08-07T17:54:56.823Z,1754589296.823 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -1.000000 count 2025-08-07T17:54:56.823Z,1754589296.823 [sample_lab:SampleRepeater:A] Stopped 2025-08-07T17:54:56.823Z,1754589296.823 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2025-08-07T17:54:56.823Z,1754589296.823 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2025-08-07T17:54:56.823Z,1754589296.823 [sample_lab:A.AbortSample] Running Loop=1 2025-08-07T17:54:57.217Z,1754589297.217 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -1. 2025-08-07T17:54:57.217Z,1754589297.217 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2025-08-07T17:54:57.217Z,1754589297.217 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2025-08-07T17:54:57.217Z,1754589297.217 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2025-08-07T17:54:57.636Z,1754589297.636 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2025-08-07T17:54:58.414Z,1754589298.414 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence 2025-08-07T17:55:08.511Z,1754589308.511 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence 2025-08-07T17:55:08.581Z,1754589308.581 [ESPComponent](INFO): powering up ESP 2025-08-07T17:55:08.600Z,1754589308.600 [ESPComponent](INFO): powering up ESP secondary power supply 2025-08-07T17:55:08.616Z,1754589308.616 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.11.2:10.89.11.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2025-08-07T17:55:08.796Z,1754589308.796 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2025-08-07T17:55:09.747Z,1754589309.747 [ESPComponent](INFO): console: 2025-08-07T17:55:10.123Z,1754589310.123 [ESPComponent](INFO): console:NAND: 256 MiB 2025-08-07T17:55:10.534Z,1754589310.534 [ESPComponent](INFO): console: BOOTMODE: SPI 2025-08-07T17:55:10.927Z,1754589310.927 [ESPComponent](INFO): console: reading SPI NOR..Done 2025-08-07T17:55:11.332Z,1754589311.332 [ESPComponent](INFO): console: 2025-08-07T17:55:11.764Z,1754589311.764 [ESPComponent](INFO): console: 2025-08-07T17:55:12.144Z,1754589312.144 [ESPComponent](INFO): console: U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51) 2025-08-07T17:55:12.543Z,1754589312.543 [ESPComponent](INFO): console: 2025-08-07T17:55:12.948Z,1754589312.948 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2025-08-07T17:55:13.364Z,1754589313.364 [ESPComponent](INFO): console: flash params are already written into flash 2025-08-07T17:55:13.786Z,1754589313.786 [ESPComponent](INFO): console: DRAM: 64 MB 2025-08-07T17:55:14.167Z,1754589314.167 [ESPComponent](INFO): console: In: serial 2025-08-07T17:55:14.570Z,1754589314.570 [ESPComponent](INFO): console: Out: serial 2025-08-07T17:55:14.975Z,1754589314.975 [ESPComponent](INFO): console: Err: serial 2025-08-07T17:55:15.376Z,1754589315.376 [ESPComponent](INFO): console: Net: ks8851_mll 2025-08-07T17:55:15.801Z,1754589315.801 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2025-08-07T17:55:16.186Z,1754589316.186 [ESPComponent](INFO): console: 4096 KiB S25FL032P at 0:0 is now current device 2025-08-07T17:55:16.593Z,1754589316.593 [ESPComponent](INFO): console: Loading kernel from SPI flash...done 2025-08-07T17:55:16.989Z,1754589316.989 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2025-08-07T17:55:17.396Z,1754589317.396 [ESPComponent](INFO): console: Image Name: Linux-3.18.140-lpc31-mbari4 2025-08-07T17:55:17.822Z,1754589317.822 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2025-08-07T17:55:18.200Z,1754589318.200 [ESPComponent](INFO): console: Data Size: 2336368 Bytes = 2.2 MB 2025-08-07T17:55:18.607Z,1754589318.607 [ESPComponent](INFO): console: Load Address: 30008000 2025-08-07T17:55:19.008Z,1754589319.008 [ESPComponent](INFO): console: Entry Point: 30008000 2025-08-07T17:55:19.448Z,1754589319.448 [ESPComponent](INFO): console: Verifying Checksum ... OK 2025-08-07T17:55:19.852Z,1754589319.852 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2025-08-07T17:55:20.226Z,1754589320.226 [ESPComponent](INFO): console: OK 2025-08-07T17:55:20.624Z,1754589320.624 [ESPComponent](INFO): console: 2025-08-07T17:55:21.029Z,1754589321.029 [ESPComponent](INFO): console: Starting kernel ... 2025-08-07T17:55:21.487Z,1754589321.487 [ESPComponent](INFO): console: 2025-08-07T17:55:21.840Z,1754589321.840 [ESPComponent](INFO): console: Uncompressing Linux... Booting kernel... 2025-08-07T17:55:22.243Z,1754589322.243 [ESPComponent](INFO): console: [ 0.06] MBARI ESP 3G 2025-08-07T17:55:22.646Z,1754589322.646 [ESPComponent](INFO): console: 2025-08-07T17:55:23.047Z,1754589323.047 [ESPComponent](INFO): console:INIT: version 2.85 booting 2025-08-07T17:55:23.493Z,1754589323.493 [ESPComponent](INFO): console: 2025-08-07T17:55:23.856Z,1754589323.856 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2025-08-07T17:55:24.260Z,1754589324.260 [ESPComponent](INFO): console: ESPdummy 2025-08-07T17:55:24.671Z,1754589324.671 [ESPComponent](INFO): console: 2025-08-07T17:55:25.068Z,1754589325.068 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2025-08-07T17:55:25.504Z,1754589325.504 [ESPComponent](INFO): console: 2025-08-07T17:55:25.879Z,1754589325.879 [ESPComponent](INFO): console:Loading kernel modules 2025-08-07T17:55:26.283Z,1754589326.283 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2025-08-07T17:55:26.686Z,1754589326.686 [ESPComponent](INFO): console: [ 3.50] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support! 2025-08-07T17:55:27.097Z,1754589327.097 [ESPComponent](INFO): console: Starting device events handler 2025-08-07T17:55:27.592Z,1754589327.592 [ESPComponent](INFO): console: 2025-08-07T17:55:37.195Z,1754589337.195 [ESPComponent](INFO): console:Set system clock to: Thu Aug 7 10:56:07 PDT 2025 2025-08-07T17:55:37.635Z,1754589337.635 [ESPComponent](INFO): console: Starting syslogd klogd... 2025-08-07T17:55:37.000Z,1754589338.000 [ESPComponent](INFO): console: stopped syslogd (pid 723) 2025-08-07T17:55:38.399Z,1754589338.399 [ESPComponent](INFO): console: Bringing up lo ... 2025-08-07T17:55:38.807Z,1754589338.807 [ESPComponent](INFO): console: lo IP=127.0.0.1 2025-08-07T17:55:39.207Z,1754589339.207 [ESPComponent](INFO): console: Packet forwarding enabled 2025-08-07T17:55:39.647Z,1754589339.647 [ESPComponent](INFO): console: Bringing up platform ... 2025-08-07T17:55:40.076Z,1754589340.076 [ESPComponent](INFO): console: 2025-08-07T17:55:41.661Z,1754589341.661 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard 2025-08-07T17:55:42.104Z,1754589342.104 [ESPComponent](INFO): console: 2025-08-07T17:55:42.846Z,1754589342.846 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63 2025-08-07T17:55:43.256Z,1754589343.256 [ESPComponent](INFO): console: [#] ip -4 address add 192.168.5.39 dev wg2shore 2025-08-07T17:55:43.678Z,1754589343.678 [ESPComponent](INFO): console: [#] ip link set mtu 1376 up dev wg2shore 2025-08-07T17:55:44.055Z,1754589344.055 [ESPComponent](INFO): console: [#] ip -4 route add 192.168.4.0/23 dev wg2shore 2025-08-07T17:55:44.460Z,1754589344.460 [ESPComponent](INFO): console: Bringing up wg2shore ... 2025-08-07T17:55:44.871Z,1754589344.871 [ESPComponent](INFO): console: Starting netplugd... 2025-08-07T17:55:45.267Z,1754589345.267 [ESPComponent](INFO): console: Starting portmap... 2025-08-07T17:55:45.691Z,1754589345.691 [ESPComponent](INFO): console: Network unavailable: Local time is Thu Aug 7 10:56:14 PDT 2025 2025-08-07T17:55:46.077Z,1754589346.077 [ESPComponent](INFO): console: Starting chronyd... 2025-08-07T17:55:46.520Z,1754589346.520 [ESPComponent](INFO): console: Starting darkhttpd... 2025-08-07T17:55:46.885Z,1754589346.885 [ESPComponent](INFO): console: darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic. 2025-08-07T17:55:47.288Z,1754589347.288 [ESPComponent](INFO): console: listening on: http://0.0.0.0:80/ 2025-08-07T17:55:47.716Z,1754589347.716 [ESPComponent](INFO): console: set gid to 1 2025-08-07T17:55:48.099Z,1754589348.099 [ESPComponent](INFO): console: set uid to 65534 2025-08-07T17:55:48.499Z,1754589348.499 [ESPComponent](INFO): console: Starting dnsmasq... 2025-08-07T17:55:48.928Z,1754589348.928 [ESPComponent](INFO): console: 2025-08-07T17:55:49.310Z,1754589349.310 [ESPComponent](INFO): console: 2025-08-07T17:55:49.731Z,1754589349.731 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.83 -- 4/24/24 brent@mbari.org 2025-08-07T17:55:50.119Z,1754589350.119 [ESPComponent](INFO): console: 2025-08-07T17:55:50.528Z,1754589350.528 [ESPComponent](INFO): console:ESPdummy login: Bringing up WiFi ... 2025-08-07T17:55:50.928Z,1754589350.928 [ESPComponent](INFO): console: Determining IP configuration for WiFi ...udhcpc (v1.11.2) started 2025-08-07T17:55:51.327Z,1754589351.327 [ESPComponent](INFO): console: Sending discover... 2025-08-07T17:55:51.824Z,1754589351.824 [ESPComponent](INFO): console: 2025-08-07T17:55:54.164Z,1754589354.164 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:55:54.628Z,1754589354.628 [ESPComponent](INFO): console: 2025-08-07T17:55:57.391Z,1754589357.391 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:55:57.880Z,1754589357.880 [ESPComponent](INFO): console: 2025-08-07T17:56:00.215Z,1754589360.215 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:00.680Z,1754589360.680 [ESPComponent](INFO): console: 2025-08-07T17:56:03.545Z,1754589363.545 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:03.920Z,1754589363.920 [ESPComponent](INFO): console: 2025-08-07T17:56:06.280Z,1754589366.280 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:06.752Z,1754589366.752 [ESPComponent](INFO): console: 2025-08-07T17:56:09.116Z,1754589369.116 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:09.604Z,1754589369.604 [ESPComponent](INFO): console: 2025-08-07T17:56:12.343Z,1754589372.343 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:12.812Z,1754589372.812 [ESPComponent](INFO): console: 2025-08-07T17:56:15.167Z,1754589375.167 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:15.676Z,1754589375.676 [ESPComponent](INFO): console: 2025-08-07T17:56:18.398Z,1754589378.398 [ESPComponent](INFO): console:Sending discover... 2025-08-07T17:56:18.876Z,1754589378.876 [ESPComponent](INFO): console: 2025-08-07T17:56:19.636Z,1754589379.636 [ESPComponent](IMPORTANT): ESP has connected as client 2025-08-07T17:56:20.454Z,1754589380.454 [ESPComponent](IMPORTANT): [sample #4] Setting cartridge argument to -1 2025-08-07T17:56:20.454Z,1754589380.454 [ESPComponent](IMPORTANT): [sample #4] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2025-08-07T17:56:20.455Z,1754589380.455 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=4 2025-08-07T17:56:20.473Z,1754589380.473 [sample_lab:SampleRepeater:TriggerESP] Stopped 2025-08-07T17:56:20.473Z,1754589380.473 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1 2025-08-07T17:56:20.866Z,1754589380.866 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2025-08-07T17:56:21.231Z,1754589381.231 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PREPARING_SHOW_LOG 2025-08-07T17:56:21.667Z,1754589381.667 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PREPARING_SHOW_STATUS 2025-08-07T17:56:23.683Z,1754589383.683 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_LOADING_CARTRIDGE 2025-08-07T17:56:34.430Z,1754589394.430 [CommandExec](IMPORTANT): got command show variable sampleVol 2025-08-07T17:56:34.627Z,1754589394.627 [CommandExec](IMPORTANT): ESPComponent.sampleVolume (milliliter) 2025-08-07T17:56:46.992Z,1754589406.992 [CommandExec](IMPORTANT): got command report touch ESPComponent.sampleVolume 2025-08-07T17:56:54.759Z,1754589414.759 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_PRIMING (@60,aRNAl_bac) 2025-08-07T17:56:57.613Z,1754589417.613 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PRIMING (@5.0) 2025-08-07T17:56:57.614Z,1754589417.614 [ESPComponent](IMPORTANT): Filtering timeoutMinutes=4.770000 issuedCmd_=Cmd.startFiltering 2025-08-07T17:56:57.000Z,1754589418.000 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0) 2025-08-07T17:57:41.219Z,1754589461.219 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_FILTERING (@0.0) 2025-08-07T17:57:41.643Z,1754589461.643 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0) 2025-08-07T17:57:58.999Z,1754589478.999 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PAUSED (@10.0) 2025-08-07T17:57:59.461Z,1754589479.461 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_PROCESSING (@10.0) 2025-08-07T17:57:59.462Z,1754589479.462 [ESPComponent](DEBUG): Writing sampleVolume=10.000000 2025-08-07T17:57:59.511Z,1754589479.511 [Reporter](INFO): ESPComponent.sampleVolume 10.000000 ml 2025-08-07T17:58:01.521Z,1754589481.521 [ESPComponent](IMPORTANT): Processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing 2025-08-07T17:58:01.827Z,1754589481.827 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_WAITING_FOR_PROCESSED (@60,aRNAl_bac) 2025-08-07T17:59:37.175Z,1754589577.175 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_STOPPING (@60,aRNAl_bac) 2025-08-07T17:59:44.449Z,1754589584.449 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq -e 'ssh -o StrictHostKeyChecking=no' --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs & 2025-08-07T17:59:44.468Z,1754589584.468 [ESPComponent](INFO): closing pipe. 2025-08-07T17:59:44.860Z,1754589584.860 [ESPComponent](IMPORTANT): [sample #4] ESP sampling state: S_STOPPED 2025-08-07T17:59:51.362Z,1754589591.362 [CBIT](INFO): Clearing failed state for component BPC1 2025-08-07T17:59:51.362Z,1754589591.362 [BPC1] No Fault, FailCount= 1 2025-08-07T18:01:01.361Z,1754589661.361 [CommandExec](IMPORTANT): got command show stack 2025-08-07T18:01:01.361Z,1754589661.361 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T18:01:01.362Z,1754589661.362 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample 2025-08-07T18:01:01.362Z,1754589661.362 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:WaitForESP 2025-08-07T18:01:39.465Z,1754589699.465 [DataOverHttps](IMPORTANT): SBD MTMSN=20250807T180138 2025-08-07T18:01:41.226Z,1754589701.226 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2025-08-07T18:01:44.910Z,1754589704.910 [CommandExec](IMPORTANT): got command show stack 2025-08-07T18:01:44.910Z,1754589704.910 [CommandExec](IMPORTANT): Behavior Stack: 2025-08-07T18:01:44.911Z,1754589704.911 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample 2025-08-07T18:01:44.911Z,1754589704.911 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:WaitForESP 2025-08-07T18:01:47.244Z,1754589707.244 [DataOverHttps](INFO): Received command: restart logs