Skip to content

TETHYS-625

Jira: https://mbari1.atlassian.net/browse/TETHYS-625

PR: https://bitbucket.org/mbari/lrauv-application/pull-requests/303/

On bufflehead:

$ cd esp2
$ git pull origin master
$ . ESPenv auv honu
$ ESPmode=simrapid
$ esp

-> slot All=>[::archiveHiBiomass_bac]
-> exit

archiveHiBiomass_bac corresponds to -4 at LRAUV mission level.

Using bin/LRAUV

That is, using the regular LRAUV framework.

On bufflehead

I prepare the following command for when the LRAUV indicates that it started waiting for the ESP to connect:

$ ESPclient=tethyshub:9998 ESPcmdPort=7777 esp

On tethyshub

Under ~carueda/lrauv-application I have a clone with the branch associated with the PR.

I prepare the usual local config file:

Config/sim/carueda/Science.cfg 
ESPComponent.loadAtStartup          = 1 bool;
ESPComponent.simulateHardware       = 0 bool;
ESPComponent.socketServerPort       = 9998 count;

Note

simulateHardware is set to false because the LRAUV will be interacting with the ESP as it were a real instrument.

I also set the ESPCOMPONENT_MANUAL_ESP env var: 

$ export ESPCOMPONENT_MANUAL_ESP=1
to avoid unnecessary operations (powering up/down the ESP, consoleUart, uart, etc.). Otherwise, the associated triggered errors would prevent the simulated exercise from proceeding.

__FASTSIM

Per a diagnosing session with Ben, I learned that simulateHardware() was recently forced to always return true when building the LRAUV application for the host. So, that setting above ESPComponent.simulateHardware = 0 bool was not having any effect. After adjusting the corresponding conditional section in Component.cpp, I was then able to proceed with the usual testing scheme.

Then:

$ bin/LRAUV -r -x "load Maintenance/sample_lab.xml;run"
Here is the LRAUV side output 
Writer for level Courier will be LZMA encoded.
Writer for level Express will be LZMA encoded.
Writer for level Priority will not be LZMA encoded.
Writer for level Normal will not be LZMA encoded.
tethyshub>load Maintenance/samp2021-07-23T01:31:23.040Z,1627003883.040 [SyncHandler](INFO): Protected caller Thread ID is 1094543
2021-07-23T01:31:23.040Z,1627003883.040 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1094544
2021-07-23T01:31:23.041Z,1627003883.041 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1094545
2021-07-23T01:31:23.041Z,1627003883.041 [logger ThreadHandler](INFO): Protected caller Thread ID is 1094546
2021-07-23T01:31:23.041Z,1627003883.041 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-07-23T01:31:23.041Z,1627003883.041 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-07-23T01:31:23.045Z,1627003883.045 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-07-23T01:31:23.051Z,1627003883.051 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-07-23T01:31:23.055Z,1627003883.055 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-07-23T01:31:23.059Z,1627003883.059 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-07-23T01:31:23.063Z,1627003883.063 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-07-23T01:31:23.066Z,1627003883.066 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-07-23T01:31:23.069Z,1627003883.069 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-07-23T01:31:23.072Z,1627003883.072 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-07-23T01:31:23.077Z,1627003883.077 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-07-23T01:31:23.083Z,1627003883.083 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-07-23T01:31:23.088Z,1627003883.088 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-07-23T01:31:23.094Z,1627003883.094 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-07-23T01:31:23.098Z,1627003883.098 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-07-23T01:31:23.101Z,1627003883.101 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-07-23T01:31:23.107Z,1627003883.107 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-07-23T01:31:23.110Z,1627003883.110 [Supervisor](INFO): Looking for Config files in directory: Config/tethyshub/
2021-07-23T01:31:23.110Z,1627003883.110 [Supervisor](INFO): Looking for Config files in directory: Config/tethyshub/carueda/
2021-07-23T01:31:23.110Z,1627003883.110 [Supervisor](INFO): Looking for Config files in directory: Config/sim/
2021-07-23T01:31:23.110Z,1627003883.110 [Supervisor](INFO): Opening Config file at: Config/sim/Derivation.cfg
2021-07-23T01:31:23.113Z,1627003883.113 [Supervisor](INFO): Opening Config file at: Config/sim/Navigation.cfg
2021-07-23T01:31:23.116Z,1627003883.116 [Supervisor](INFO): Opening Config file at: Config/sim/Science.cfg
2021-07-23T01:31:23.119Z,1627003883.119 [Supervisor](INFO): Opening Config file at: Config/sim/Sensor.cfg
2021-07-23T01:31:23.122Z,1627003883.122 [Supervisor](INFO): Opening Config file at: Config/sim/Servo.cfg
2021-07-23T01:31:23.125Z,1627003883.125 [Supervisor](INFO): Opening Config file at: Config/sim/Simulator.cfg
2021-07-23T01:31:23.128Z,1627003883.128 [Supervisor](INFO): Opening Config file at: Config/sim/secure.cfg
2021-07-23T01:31:23.131Z,1627003883.131 [Supervisor](INFO): Opening Config file at: Config/sim/vehicle.cfg
2021-07-23T01:31:23.134Z,1627003883.134 [Supervisor](INFO): Looking for Config files in directory: Config/sim/carueda/
2021-07-23T01:31:23.134Z,1627003883.134 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/secure.cfg
2021-07-23T01:31:23.137Z,1627003883.137 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Sensor.cfg
2021-07-23T01:31:23.140Z,1627003883.140 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Science.cfg
2021-07-23T01:31:23.140Z,1627003883.140 [Config/Science](ERROR): Could not parse value: As
2021-07-23T01:31:23.140Z,1627003883.140 [Config/Science](ERROR): Could not parse value: we
2021-07-23T01:31:23.140Z,1627003883.140 [Config/Science](ERROR): Could not parse value: (1)
2021-07-23T01:31:23.140Z,1627003883.140 [Config/Science](ERROR): Could not parse value: (2)
2021-07-23T01:31:23.141Z,1627003883.141 [Config/Science](ERROR): Could not parse value: (Keep
2021-07-23T01:31:23.144Z,1627003883.144 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-07-23T01:31:23.155Z,1627003883.155 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 1094637
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full
2021-07-23T01:31:23.156Z,1627003883.156 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 1094638
2021-07-23T01:31:23.156Z,1627003883.156 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1094639
2021-07-23T01:31:23.160Z,1627003883.160 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1094640
2021-07-23T01:31:23.161Z,1627003883.161 [ESPComponent](ERROR): Could not open device '/dev/loadA6' at ESPComponent.loadControl
2021-07-23T01:31:23.181Z,1627003883.181 [ESPComponent](ERROR): Could not open device '/dev/loadA7' at ESPComponent.loadControl2
2021-07-23T01:31:23.202Z,1627003883.202 [ESPComponent](IMPORTANT): ESPCOMPONENT_MANUAL_ESP INDICATED.
2021-07-23T01:31:23.204Z,1627003883.204 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1094641
2021-07-23T01:31:23.204Z,1627003883.204 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1094642
2021-07-23T01:31:23.205Z,1627003883.205 [Supervisor](INFO): Main Thread ID is 1094542
2021-07-23T01:31:23.205Z,1627003883.205 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1094643
2021-07-23T01:31:23.205Z,1627003883.205 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1094645
2021-07-23T01:31:23.206Z,1627003883.206 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 1094647
2021-07-23T01:31:23.206Z,1627003883.206 [controlThread ThreadHandler](INFO): Handler Thread ID is 1094644
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](INFO): Initialize SBIT Component.
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](IMPORTANT): git: 2021-06-24-6-gba3a55f22
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](INFO): git hash: ba3a55f2224e7c70e8e462f655364809e4684817
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](INFO): Kernel Reporting Different Release From Configuration.
Kernel Expected: 2.6.32-45-generic-pae
Kernel Reported: 4.18.0-240.22.1.el8_3.x86_64
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #102-Ubuntu SMP Wed Jan 2 22:10:16 UTC 2013
Kernel Reported: #1 SMP Thu Apr 8 19:01:30 UTC 2021
2021-07-23T01:31:23.206Z,1627003883.206 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.
2021-07-23T01:31:23.206Z,1627003883.206 [IBIT](INFO): Initialize IBIT Component.
2021-07-23T01:31:23.206Z,1627003883.206 [logger ThreadHandler](INFO): Handler Thread ID is 1094646
2021-07-23T01:31:23.207Z,1627003883.207 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml
2021-07-23T01:31:23.207Z,1627003883.207 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample_lab.xml
2021-07-23T01:31:23.207Z,1627003883.207 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2021-07-23T01:31:23.207Z,1627003883.207 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2021-07-23T01:31:23.207Z,1627003883.207 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2021-07-23T01:31:23.208Z,1627003883.208 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml
2021-07-23T01:31:23.208Z,1627003883.208 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1094649
2021-07-23T01:31:23.208Z,1627003883.208 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1094651
2021-07-23T01:31:23.208Z,1627003883.208 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1094652
2021-07-23T01:31:23.208Z,1627003883.208 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1094650
2021-07-23T01:31:23.209Z,1627003883.209 [Onboard ThreadHandler](INFO): Handler Thread ID is 1094648
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-07-23T01:31:23.220Z,1627003883.220 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-07-23T01:31:23.238Z,1627003883.238 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-07-23T01:31:23.240Z,1627003883.240 [ExternalSim](INFO): ExternalSim initializing...
2021-07-23T01:31:23.248Z,1627003883.248 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-07-23T01:31:23.248Z,1627003883.248 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-07-23T01:31:23.248Z,1627003883.248 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-07-23T01:31:23.250Z,1627003883.250 [Power24vConverter](INFO): Powering up.
tethyshub>run
2021-07-23T01:31:23.305Z,1627003883.305 [CommandLine](IMPORTANT): got command run
2021-07-23T01:31:23.305Z,1627003883.305 [CommandLine](IMPORTANT): Running
2021-07-23T01:31:43.656Z,1627003903.656 [SBIT](IMPORTANT): Beginning Startup BIT
2021-07-23T01:31:57.658Z,1627003917.658 [NAL9602](INFO): GPS fix at 20210723T013157: (36.803404, -121.822207)
2021-07-23T01:31:58.858Z,1627003918.858 [NAL9602](INFO): No messages in MT queue
2021-07-23T01:32:29.267Z,1627003949.267 [NAL9602](INFO): Not Powering down - fast GPS
2021-07-23T01:32:37.269Z,1627003957.269 [SBIT](IMPORTANT): SBIT PASSED
2021-07-23T01:32:37.269Z,1627003957.269 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-07-23T01:32:37.269Z,1627003957.269 [SBIT](IMPORTANT): No configSet variables persisted
2021-07-23T01:32:37.669Z,1627003957.669 [MissionManager](IMPORTANT): Started mission Startup
2021-07-23T01:32:37.669Z,1627003957.669 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-07-23T01:32:42.469Z,1627003962.469 [NAL9602](INFO): GPS fix at 20210723T013242: (36.803409, -121.822216)
2021-07-23T01:32:43.670Z,1627003963.670 [NAL9602](INFO): No messages in MT queue
2021-07-23T01:33:15.678Z,1627003995.678 [NAL9602](INFO): Sent 65 bytes from file Logs/20210722T163207/Courier0004.lzma
2021-07-23T01:33:15.678Z,1627003995.678 [NAL9602](INFO): Packets left to send: 0
2021-07-23T01:33:42.485Z,1627004022.485 [Startup:StartupSatComms:B](INFO): Timed out from 2021-07-23T01:32:42.5Z
2021-07-23T01:33:42.485Z,1627004022.485 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-07-23T01:33:42.485Z,1627004022.485 [Startup](INFO): Completed Startup
2021-07-23T01:33:42.485Z,1627004022.485 [MissionManager](INFO): Startup is completed.
2021-07-23T01:33:42.485Z,1627004022.485 [MissionManager](INFO): Uninitializing Mission Startup
2021-07-23T01:33:42.886Z,1627004022.886 [MissionManager](IMPORTANT): Started mission sample_lab
2021-07-23T01:33:42.886Z,1627004022.886 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2021-07-23T01:33:42.886Z,1627004022.886 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -4.000000 count
2021-07-23T01:33:42.886Z,1627004022.886 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2021-07-23T01:33:43.285Z,1627004023.285 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4.
2021-07-23T01:33:43.285Z,1627004023.285 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2021-07-23T01:33:44.485Z,1627004024.485 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2021-07-23T01:33:44.485Z,1627004024.485 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2021-07-23T01:33:46.486Z,1627004026.486 [NAL9602](INFO): Sent 216 bytes from file Logs/20210723T013123/Courier0000.lzma
2021-07-23T01:33:46.486Z,1627004026.486 [NAL9602](INFO): Packets left to send: 0
2021-07-23T01:33:54.487Z,1627004034.487 [ESPComponent](IMPORTANT): powerUpESP IGNORED because manualEsp_
2021-07-23T01:33:54.487Z,1627004034.487 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)
2021-07-23T01:33:59.688Z,1627004039.688 [ESPComponent](IMPORTANT): ESP has connected as client
2021-07-23T01:34:00.489Z,1627004040.489 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4
2021-07-23T01:34:00.489Z,1627004040.489 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2021-07-23T01:34:01.691Z,1627004041.691 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2021-07-23T01:34:02.091Z,1627004042.091 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2021-07-23T01:34:03.690Z,1627004043.690 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2021-07-23T01:34:16.894Z,1627004056.894 [NAL9602](INFO): Not Powering down - fast GPS
2021-07-23T01:34:40.104Z,1627004080.104 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@59,archiveHiBiomass_bac)
2021-07-23T01:34:41.705Z,1627004081.705 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@5.0)
2021-07-23T01:34:42.105Z,1627004082.105 [ESPComponent](IMPORTANT): Filtering timeoutMinutes=5.640000 issuedCmd_=Cmd.startFiltering
2021-07-23T01:34:42.505Z,1627004082.505 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2021-07-23T01:35:22.520Z,1627004122.520 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2021-07-23T01:35:22.921Z,1627004122.921 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2021-07-23T01:35:50.929Z,1627004150.929 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@10.0)
2021-07-23T01:35:51.330Z,1627004151.330 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@10.0)
2021-07-23T01:35:53.330Z,1627004153.330 [ESPComponent](IMPORTANT): Processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing
2021-07-23T01:35:53.731Z,1627004153.731 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@59,archiveHiBiomass_bac)
2021-07-23T01:39:25.811Z,1627004365.811 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@59,archiveHiBiomass_bac)
2021-07-23T01:39:34.614Z,1627004374.614 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 carueda@bufflehead:'/var/log/carueda/simrapid.* /var/log/carueda/*.spr' /home/carueda/lrauv-application/ESPlogs &
2021-07-23T01:39:34.619Z,1627004374.619 [ESPComponent](INFO): closing pipe.
The authenticity of host 'bufflehead (134.89.11.120)' can't be established.
ECDSA key fingerprint is SHA256:TkMlwTouzQ7mpkqf5SWluSimQ8s5ikWPMetBRKMubvI.
Are you sure you want to continue connecting (yes/no/[fing2021-07-23T01:39:35.014Z,1627004375.014 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2021-07-23T01:39:45.016Z,1627004385.016 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2021-07-23T01:39:45.017Z,1627004385.017 [sample_lab:SampleRepeater](INFO): Completed sample_lab:SampleRepeater
2021-07-23T01:39:45.017Z,1627004385.017 [sample_lab](INFO): Completed sample_lab
2021-07-23T01:39:45.017Z,1627004385.017 [MissionManager](INFO): sample_lab is completed.
2021-07-23T01:39:45.017Z,1627004385.017 [MissionManager](INFO): Uninitializing Mission sample_lab
2021-07-23T01:39:45.017Z,1627004385.017 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample.
2021-07-23T01:39:45.417Z,1627004385.417 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@18:34:06.42 Selecting Cartridge 59
@18:35:49.35 Sampled  10.0ml

2021-07-23T01:39:45.417Z,1627004385.417 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_
2021-07-23T01:39:45.417Z,1627004385.417 [MissionManager](IMPORTANT): Started mission Default

A soon as "Waiting for ESP to connect" is displayed above, I launch the ESP command on bufflehead:

$ ESPclient=tethyshub:9998 ESPcmdPort=7777 esp
Here is the ESP output 
$ ESPclient=tethyshub:9998 ESPcmdPort=7777 esp
@18:33:58.67PDT22-Jul-21 <simrapid> Simulated gateway v3.24 for core bus
Simulated secondary gateway v3.24 for cartridge bus
@18:33:58.79
Configuration for honu by brent@mbari.org 7/1/21
/home/carueda/esp2/type/auv/honu/configure.rb
@18:33:58.96 Polling Can every 2:00
Clients may connect on TCP port 7777
Connecting to tethyshub:9998
@18:33:59.29 <LRAUV> Session Begun
@18:34:01.69 -> showStatus
@18:34:03.29 -> Cmd.loadCartridge -4
Gate.power :main,:ON
Gate.power :analytic1,:ON
Gate.power :analytic2,:ON
Gate.power :analytic3,:ON
Gate.power :core,:ON
@18:34:03.30 Archive.configure :default
@18:34:03.31 Air.configure :default
Lysis1.configure :default
Lysis2.configure :default
@18:34:03.32 Plunge.configure :default
SamplePump.configure :default
@18:34:03.33 ExtraPump.configure :default
Toroid.configure :default
@18:34:03.34 Carousel.configure :default
Pressure.configure :default
@18:34:03.35 PinPort.configure :default
All elf controllers running firmware version 4.79
Gate.power :motor,:ON
@18:34:03.36 <Archive_home> Archive.in :default
@18:34:03.37 Archive.home.jog 0
@18:34:03.38 <Air_home> Air.in :default
Air.home.jog 0
@18:34:03.39 <Lysis1_home> Lysis1.in :default
<Lysis2_home> Lysis2.in :default
<Lysis1_home> Lysis1.home.jog 0
@18:34:03.40 <Plunge_home> Plunge.in :default
<Lysis2_home> Lysis2.home.jog 0
<PinPort_home> PinPort.in :default
<Plunge_home> Plunge.home.jog 0
@18:34:03.41 <Toroid_home> Toroid.in :default
<PinPort_home> PinPort.home.jog 0
@18:34:03.45 <Toroid_home> Toroid.home.jog 0
@18:34:03.47 <Archive_home> Archive.setRawPosition! 50
@18:34:03.48 Archive.in :homing
Archive.seek :home
<Air_home> Air.setRawPosition! 50
@18:34:03.49 Air.in :homing
Air.seek :home
@18:34:03.52 <Plunge_home> Plunge.setRawPosition! 50
Plunge.in :homing
@18:34:03.53 Plunge.seek :home
<PinPort_home> PinPort.setRawPosition! 0
PinPort.in :homing
@18:34:03.54 PinPort.seek :home
@18:34:03.55 <Lysis1_home> Lysis1.setRawPosition! 50
Lysis1.in :homing
Lysis1.seek :home
@18:34:03.56 <Lysis2_home> Lysis2.setRawPosition! 50
Lysis2.in :homing
Lysis2.seek :home
@18:34:03.57 <Toroid_home> Toroid.setRawPosition! 0
@18:34:03.58 Toroid.in :homing
Toroid.seek :home
@18:34:03.61 <PinPort_home> PinPort.in :default
@18:34:03.65 <Toroid_home> Toroid.in :default
@18:34:03.75 <Archive_home> Archive.in :default
@18:34:03.77 <Air_home> Air.in :default
@18:34:03.80 <Plunge_home> Plunge.in :default
@18:34:03.83 <Lysis1_home> Lysis1.in :default
@18:34:03.84 <Lysis2_home> Lysis2.in :default
@18:34:04.10 <LRAUV> Toroid.seek :clear
@18:34:05.71 Carousel.in :default
Carousel.home.jog 0
@18:34:05.79 Carousel.setRawPosition! -53
Carousel.in :homing
Carousel.seek :home
@18:34:06.09 Carousel.in :default
@18:34:06.35 Carousel.seek 1
@18:34:06.42 Selecting Cartridge 59
@18:34:06.43 Carousel.seek 59
@18:34:18.49 Lysis1.in :fast
Lysis1.seek :locked
@18:34:21.02 <Plunge> Plunge.seek :locked
@18:34:21.03 <Air> Air.in :fast
Air.seek :locked
@18:34:23.56 <LRAUV> Gate.power :cartridge,:ON
@18:34:23.57 Gate.power :cartridge,:OFF
@18:34:24.07 Mounted archive Cartridge
@18:34:39.70 -> Cmd.startFiltering
@18:34:39.72 <FILTERING> Priming sample loop w/5ml, bypass w/1.5ml
SamplePump.setPosition! 0ml
Bypass.open
@18:34:40.43 Intake.open
@18:34:41.93 Sea 127.8m deep (203.5psia)
Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
@18:34:44.43 Vacuum tare is 37% of full scale
@18:34:44.44 <closeIntake> Intake.close
<closeBypass> Bypass.close
@18:34:45.94 <FILTERING> Verifying toroid holds at least 0.6..0.85 of 203.5psia
Waiting up to 40 seconds for toroid pressure to stabilize +/-1.50psi
@18:34:50.44 Bypass.open
@18:34:51.94 Intake.open
@18:34:54.14 Pressure.in :default
@18:34:54.15 Pressure.hold
@18:34:54.22 SamplePump.in :prime
SamplePump.seek 1.5ml,35 seconds
@18:34:55.85 Pressure.stop
SamplePump.setPosition! 0ml
Exhaust.open
@18:34:58.05 <closeBypass> Bypass.close
@18:35:00.26 <FILTERING> Pressure.hold
@18:35:00.33 Sea 127.8m deep (203.5psia)
SamplePump.in :prime
SamplePump.seek 5ml,45 seconds
@18:35:05.07 Pressure.stop
Bypass.open
@18:35:06.57 Intake.close
@18:35:08.07 Toroid.in :hold
@18:35:08.08 Toroid.seek :crack
@18:35:09.57 Toroid.seek :cartridge
@18:35:10.67 Toroid.in :default
Toroid.seek :clear
@18:35:12.49 <closeExhaust> Exhaust.close
<closeBypass> Bypass.close
@18:35:13.98 <FILTERING> Verifying cartridge holds at least 0.75..0.85 of 203.5psia
Waiting up to 40 seconds for cartridge pressure to stabilize +/-1.50psi
@18:35:18.49 Sampling 10.0ml
SamplePump.setPosition! 0ml
Exhaust.open
@18:35:19.99 Intake.open
@18:35:21.49 Pressure.hold
@18:35:21.56 Sea 127.8m deep (203.5psia)
@18:35:21.57 SamplePump.in :sample
SamplePump.seek 10ml,1:21
@18:35:24.50 <sampling> Cartridge 59 filtering 1/10ml at 0.42ml/s with 0.0psi vacuum 127.8m deep (203.5psia)
@18:35:46.10 <FILTERING> Pressure.stop
@18:35:46.11 <closeIntake> Intake.close
<closeExhaust> Exhaust.close
@18:35:46.12 <FILTERING> Toroid.in :hold
Toroid.seek :bypass
@18:35:47.73 Toroid.in :default
@18:35:47.74 Toroid.seek :clear
@18:35:49.35 Sampled  10.0ml
@18:35:50.93 <LRAUV> -> Cmd.startProcessing
@18:35:50.94 <PROCESSING> Plunge.seek :reagent
@18:35:51.78 Sample loop closed. Ready to Deliver Reagents
Archive.seek :sealed
@18:35:56.05 Archive.seek :evac
@18:36:10.03 delay 1:00
@18:37:10.04 Archive.seek :clear
@18:37:27.80 RNAlater soak for 45 seconds
@18:38:12.81 Archive.seek :tVent
@18:38:15.39 delay 1 second
@18:38:16.39 Archive.seek :evac
@18:38:32.06 delay 10 seconds
@18:38:42.07 Archive.seek :tVent
@18:38:57.73 delay 1 second
@18:38:58.74 Archive.seek :evac
@18:39:14.40 delay 10 seconds
@18:39:24.41 Sample preserved and evacuated
@18:39:25.41 <LRAUV> -> Cmd.stop
Carousel.seek 59
@18:39:25.49 Plunge.seek :locked
@18:39:26.33 <Archive> Archive.in :unlocking
@18:39:26.34 Archive.seek :clear
<Air> Air.in :unlocking
Air.seek :clear
@18:39:26.36 <Lysis1> Lysis1.in :unlocking
Lysis1.seek :clear
@18:39:30.43 <LRAUV> Gate.power :motor,:OFF
Gate.power :core,:OFF
Gate.power :analytic1,:OFF
Gate.power :analytic2,:OFF
@18:39:30.44 Gate.power :analytic3,:OFF
Gate.power :main,:OFF
Safely stopped and ready to power off
@18:41:04.67 Session Ended
ESPhonu:001:0->

In summary, all satisfactory testing.

Using ESPClientTest

Before the tests with the LRAUV execution framework scheme above, I did the following tests with the ESPClientTest program, which very conveniently (but still using the same supporting ESPClient class) also allows exercising interaction with an ESP outside the regular LRAUV execution framework.

On bufflehead

In this case, I immediately start the ESP with indication to accept clients on port 7777:

$ ESPcmdPort=7777 esp

On tethyshub

I initially had a flag debug_g in Source/scienceModule/ESPClient.cpp, which I set to true to help with the inspection directly from the ESPClientTest output on the console.

Run ESPClientTest:

$  bin/ESPClientTest --log esp.log --cartridge -4
Here is the output on the ESPClientTest side 
[root@cfd62e536f78 lrauv-application]# bin/ESPClientTest --log esp.log --cartridge -4
Connecting to bufflehead.shore.mbari.org:7777
Connected to bufflehead.shore.mbari.org:7777
ESPClient created
Sampling state transitions:
DEBUG: --ESPClient::startSampling cartridge='-4'--
DEBUG: startSampling complete; samplingState_=S_WAITING_INITIAL_PROMPT
0000.000    S_WAITING_INITIAL_PROMPT
DEBUG: :-<: unknown "LRAUV-ESPClientTest"
DEBUG: issueCommand: cmd='\tshowlog nil, true'
0001.437    S_PREPARING_SHOW_LOG
DEBUG: issueCommand: cmd='showStatus'
0002.155    S_PREPARING_SHOW_STATUS
DEBUG: :-<: log "@15:11:19.84 -> showStatus"
DEBUG: :-<: result "true"
DEBUG: In S_PREPARING_SHOW_STATUS, for cmd='showStatus', consuming result: <<true\n>> which took 2.8492
DEBUG: issueCommand: cmd='Cmd.loadCartridge -4'
0005.039    S_LOADING_CARTRIDGE
DEBUG: :-<: log "@15:11:22.72 -> Cmd.loadCartridge -4"
DEBUG: :-<: status "STOPPED-->IDLE"
DEBUG: :-<: log "Gate.power :main,:ON"
DEBUG: :-<: log "Gate.power :analytic1,:ON"
DEBUG: :-<: log "Gate.power :analytic2,:ON"
DEBUG: :-<: log "Gate.power :analytic3,:ON"
DEBUG: :-<: log "@15:11:22.73 Gate.power :core,:ON"
DEBUG: :-<: log "@15:11:22.74 Archive.configure :default"
DEBUG: :-<: log "Air.configure :default"
DEBUG: :-<: log "@15:11:22.75 Lysis1.configure :default"
DEBUG: :-<: log "Lysis2.configure :default"
DEBUG: :-<: log "@15:11:22.76 Plunge.configure :default"
DEBUG: :-<: log "SamplePump.configure :default"
DEBUG: :-<: log "@15:11:22.77 ExtraPump.configure :default"
DEBUG: :-<: log "Toroid.configure :default"
DEBUG: :-<: log "@15:11:22.78 Carousel.configure :default"
DEBUG: :-<: log "Pressure.configure :default"
DEBUG: :-<: log "@15:11:22.79 PinPort.configure :default"
DEBUG: :-<: log "All elf controllers running firmware version 4.79"
DEBUG: :-<: log "Gate.power :motor,:ON"
DEBUG: :-<: log "@15:11:22.80 <Archive_home> Archive.in :default"
DEBUG: :-<: log "@15:11:22.81 Archive.home.jog 0"
DEBUG: :-<: log "@15:11:22.82 <Air_home> Air.in :default"
DEBUG: :-<: log "Air.home.jog 0"
DEBUG: :-<: log "@15:11:22.83 <Lysis1_home> Lysis1.in :default"
DEBUG: :-<: log "<Lysis2_home> Lysis2.in :default"
DEBUG: :-<: log "<Lysis1_home> Lysis1.home.jog 0"
DEBUG: :-<: log "@15:11:22.84 <Plunge_home> Plunge.in :default"
DEBUG: :-<: log "<Lysis2_home> Lysis2.home.jog 0"
DEBUG: :-<: log "<PinPort_home> PinPort.in :default"
DEBUG: :-<: log "<Plunge_home> Plunge.home.jog 0"
DEBUG: :-<: log "@15:11:22.85 <Toroid_home> Toroid.in :default"
DEBUG: :-<: log "<PinPort_home> PinPort.home.jog 0"
DEBUG: :-<: log "<Toroid_home> Toroid.home.jog 0"
DEBUG: :-<: log "@15:11:22.89 <Archive_home> Archive.setRawPosition! 50"
DEBUG: :-<: log "@15:11:22.90 Archive.in :homing"
DEBUG: :-<: log "Archive.seek :home"
DEBUG: :-<: log "@15:11:22.91 <Air_home> Air.setRawPosition! 50"
DEBUG: :-<: log "Air.in :homing"
DEBUG: :-<: log "Air.seek :home"
DEBUG: :-<: log "@15:11:22.92 <Plunge_home> Plunge.setRawPosition! 50"
DEBUG: :-<: log "Plunge.in :homing"
DEBUG: :-<: log "@15:11:22.93 Plunge.seek :home"
DEBUG: :-<: log "@15:11:22.94 <PinPort_home> PinPort.setRawPosition! 0"
DEBUG: :-<: log "PinPort.in :homing"
DEBUG: :-<: log "PinPort.seek :home"
DEBUG: :-<: log "@15:11:22.95 <Lysis1_home> Lysis1.setRawPosition! 50"
DEBUG: :-<: log "Lysis1.in :homing"
DEBUG: :-<: log "@15:11:22.96 Lysis1.seek :home"
DEBUG: :-<: log "@15:11:22.97 <Lysis2_home> Lysis2.setRawPosition! 50"
DEBUG: :-<: log "Lysis2.in :homing"
DEBUG: :-<: log "Lysis2.seek :home"
DEBUG: :-<: log "@15:11:23.02 <Toroid_home> Toroid.setRawPosition! 0"
DEBUG: :-<: log "Toroid.in :homing"
DEBUG: :-<: log "@15:11:23.03 Toroid.seek :home"
DEBUG: :-<: log "@15:11:23.04 <PinPort_home> PinPort.in :default"
DEBUG: :-<: log "@15:11:23.10 <Toroid_home> Toroid.in :default"
DEBUG: :-<: log "@15:11:23.17 <Archive_home> Archive.in :default"
DEBUG: :-<: log "@15:11:23.19 <Air_home> Air.in :default"
DEBUG: :-<: log "@15:11:23.20 <Plunge_home> Plunge.in :default"
DEBUG: :-<: log "@15:11:23.23 <Lysis1_home> Lysis1.in :default"
DEBUG: :-<: log "@15:11:23.25 <Lysis2_home> Lysis2.in :default"
DEBUG: :-<: log "@15:11:23.50 <LRAUV-ESPClientTest> Toroid.seek :clear"
DEBUG: :-<: log "@15:11:25.12 Carousel.in :default"
DEBUG: :-<: log "Carousel.home.jog 0"
DEBUG: :-<: log "@15:11:25.20 Carousel.setRawPosition! -53"
DEBUG: :-<: log "Carousel.in :homing"
DEBUG: :-<: log "@15:11:25.21 Carousel.seek :home"
DEBUG: :-<: log "@15:11:25.51 Carousel.in :default"
DEBUG: :-<: log "@15:11:25.77 Carousel.seek 1"
DEBUG: :-<: status "IDLE-->LOADING"
DEBUG: :-<: status "LOADING-->LOADING@60,archiveHiBiomass_bac"
DEBUG: :-<: log "@15:11:25.84 Selecting Cartridge 60"
DEBUG: :-<: log "@15:11:25.86 Carousel.seek 60"
DEBUG: :-<: log "@15:11:38.13 Lysis1.in :fast"
DEBUG: :-<: log "Lysis1.seek :locked"
DEBUG: :-<: log "@15:11:40.66 <Plunge> Plunge.seek :locked"
DEBUG: :-<: log "@15:11:40.67 <Air> Air.in :fast"
DEBUG: :-<: log "Air.seek :locked"
DEBUG: :-<: log "@15:11:43.20 <LRAUV-ESPClientTest> Gate.power :cartridge,:ON"
DEBUG: :-<: log "Gate.power :cartridge,:OFF"
DEBUG: :-<: log "@15:11:43.71 Mounted archive Cartridge"
DEBUG: :-<: status "LOADING-->READY@60,archiveHiBiomass_bac"
DEBUG: :-<: result "60"
DEBUG: In S_LOADING_CARTRIDGE, for cmd='Cmd.loadCartridge -4', consuming result: <<60\n>> which took 65.4953
DEBUG: issueCommand: cmd='Cmd.startFiltering'
0070.602    S_WAITING_FOR_PRIMING
DEBUG: :-<: log "@15:12:28.20 -> Cmd.startFiltering"
DEBUG: :-<: status "READY-->PRIMING@5.0"
0073.487    S_PRIMING
DEBUG: :-<: result "5.64"
DEBUG: In S_PRIMING, for cmd='Cmd.startFiltering', consuming result: <<5.64\n>> which took 4.3252
DEBUG: got filtering timeoutMinutes=5.640000 issuedCmd_=Cmd.startFiltering
0074.927    S_WAITING_FOR_FILTERING
DEBUG: :-<: log "@15:12:28.22 <FILTERING> Priming sample loop w/5ml, bypass w/1.5ml"
DEBUG: :-<: log "SamplePump.setPosition! 0ml"
DEBUG: :-<: log "Bypass.open"
DEBUG: :-<: log "@15:12:28.93 Intake.open"
DEBUG: :-<: log "@15:12:30.43 Sea 127.8m deep (203.5psia)"
DEBUG: :-<: log "Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi"
DEBUG: :-<: log "@15:12:32.93 Vacuum tare is 37% of full scale"
DEBUG: :-<: log "@15:12:32.94 <closeIntake> Intake.close"
DEBUG: :-<: log "@15:12:32.95 <closeBypass> Bypass.close"
DEBUG: :-<: log "@15:12:34.43 <FILTERING> Verifying toroid holds at least 0.6..0.85 of 203.5psia"
DEBUG: :-<: log "Waiting up to 40 seconds for toroid pressure to stabilize +/-1.50psi"
DEBUG: :-<: log "@15:12:38.94 Bypass.open"
DEBUG: :-<: log "@15:12:40.44 Intake.open"
DEBUG: :-<: log "@15:12:42.64 Pressure.in :default"
DEBUG: :-<: log "Pressure.hold"
DEBUG: :-<: log "@15:12:42.71 SamplePump.in :prime"
DEBUG: :-<: log "@15:12:42.72 SamplePump.seek 1.5ml,35 seconds"
DEBUG: :-<: log "@15:12:44.34 Pressure.stop"
DEBUG: :-<: log "SamplePump.setPosition! 0ml"
DEBUG: :-<: log "@15:12:44.35 Exhaust.open"
DEBUG: :-<: log "@15:12:46.54 <closeBypass> Bypass.close"
DEBUG: :-<: log "@15:12:48.75 <FILTERING> Pressure.hold"
DEBUG: :-<: log "@15:12:48.82 Sea 127.8m deep (203.5psia)"
DEBUG: :-<: log "SamplePump.in :prime"
DEBUG: :-<: log "@15:12:48.83 SamplePump.seek 5ml,45 seconds"
DEBUG: :-<: log "@15:12:53.56 Pressure.stop"
DEBUG: :-<: log "@15:12:53.57 Bypass.open"
DEBUG: :-<: log "@15:12:55.06 Intake.close"
DEBUG: :-<: log "@15:12:56.57 Toroid.in :hold"
DEBUG: :-<: log "Toroid.seek :crack"
DEBUG: :-<: log "@15:12:58.07 Toroid.seek :cartridge"
DEBUG: :-<: log "@15:12:59.16 Toroid.in :default"
DEBUG: :-<: log "Toroid.seek :clear"
DEBUG: :-<: log "@15:13:00.98 <closeExhaust> Exhaust.close"
DEBUG: :-<: log "<closeBypass> Bypass.close"
DEBUG: :-<: log "@15:13:02.47 <FILTERING> Verifying cartridge holds at least 0.75..0.85 of 203.5psia"
DEBUG: :-<: log "Waiting up to 40 seconds for cartridge pressure to stabilize +/-1.50psi"
DEBUG: :-<: log "@15:13:06.98 Sampling 10.0ml"
DEBUG: :-<: log "SamplePump.setPosition! 0ml"
DEBUG: :-<: log "Exhaust.open"
DEBUG: :-<: log "@15:13:08.48 Intake.open"
DEBUG: :-<: status "PRIMING-->FILTERING@0.0"
0113.825    S_FILTERING
0114.543    S_WAITING_FOR_PAUSED
DEBUG: :-<: log "@15:13:09.98 Pressure.hold"
DEBUG: :-<: log "@15:13:10.05 Sea 127.8m deep (203.5psia)"
DEBUG: :-<: log "@15:13:10.06 SamplePump.in :sample"
DEBUG: :-<: log "SamplePump.seek 10ml,1:21"
DEBUG: :-<: log "@15:13:12.99 <sampling> Cartridge 60 filtering 1/10ml at 0.42ml/s with 0.0psi vacuum 127.8m deep (203.5psia)"
DEBUG: :-<: log "@15:13:34.59 <FILTERING> Pressure.stop"
DEBUG: :-<: log "@15:13:34.60 <closeIntake> Intake.close"
DEBUG: :-<: log "<closeExhaust> Exhaust.close"
DEBUG: :-<: log "@15:13:34.61 <FILTERING> Toroid.in :hold"
DEBUG: :-<: log "Toroid.seek :bypass"
DEBUG: :-<: log "@15:13:36.22 Toroid.in :default"
DEBUG: :-<: log "@15:13:36.23 Toroid.seek :clear"
DEBUG: :-<: log "@15:13:37.84 Sampled  10.0ml"
DEBUG: :-<: status "FILTERING-->PAUSED@10.0"
0144.056    S_PAUSED
DEBUG: issueCommand: cmd='Cmd.startProcessing'
0144.777    S_PROCESSING
DEBUG: :-<: log "@15:13:42.36 <LRAUV-ESPClientTest> -> Cmd.startProcessing"
DEBUG: :-<: status "PAUSED-->PROCESSING@60,archiveHiBiomass_bac"
DEBUG: :-<: result "30.0"
DEBUG: In S_PROCESSING, for cmd='Cmd.startProcessing', consuming result: <<30.0\n>> which took 4.3248
DEBUG: got processing timeoutMinutes=30.000000 issuedCmd_=Cmd.startProcessing
0149.102    S_WAITING_FOR_PROCESSED
DEBUG: :-<: log "@15:13:42.39 <PROCESSING> Plunge.seek :reagent"
DEBUG: :-<: log "@15:13:43.22 Sample loop closed. Ready to Deliver Reagents"
DEBUG: :-<: log "Archive.seek :sealed"
DEBUG: :-<: log "@15:13:47.49 Archive.seek :evac"
DEBUG: :-<: log "@15:14:01.47 delay 1:00"
DEBUG: :-<: log "@15:15:01.48 Archive.seek :clear"
DEBUG: :-<: log "@15:15:19.25 RNAlater soak for 45 seconds"
DEBUG: :-<: log "@15:16:04.25 Archive.seek :tVent"
DEBUG: :-<: log "@15:16:06.83 delay 1 second"
DEBUG: :-<: log "@15:16:07.83 Archive.seek :evac"
DEBUG: :-<: log "@15:16:23.50 delay 10 seconds"
DEBUG: :-<: log "@15:16:33.51 Archive.seek :tVent"
DEBUG: :-<: log "@15:16:49.18 delay 1 second"
DEBUG: :-<: log "@15:16:50.18 Archive.seek :evac"
DEBUG: :-<: log "@15:17:05.85 delay 10 seconds"
DEBUG: :-<: log "@15:17:15.86 Sample preserved and evacuated"
DEBUG: :-<: status "PROCESSING-->PROCESSED@60,archiveHiBiomass_bac"
DEBUG: issueCommand: cmd='Cmd.stop'
0360.471    S_STOPPING
DEBUG: :-<: log "@15:17:17.74 <LRAUV-ESPClientTest> -> Cmd.stop"
DEBUG: :-<: log "@15:17:17.75 Carousel.seek 60"
DEBUG: :-<: log "@15:17:17.82 Plunge.seek :locked"
DEBUG: :-<: log "@15:17:18.67 <Archive> Archive.in :unlocking"
DEBUG: :-<: log "Archive.seek :clear"
DEBUG: :-<: log "@15:17:18.68 <Air> Air.in :unlocking"
DEBUG: :-<: log "Air.seek :clear"
DEBUG: :-<: log "@15:17:18.70 <Lysis1> Lysis1.in :unlocking"
DEBUG: :-<: log "Lysis1.seek :clear"
DEBUG: :-<: log "@15:17:22.77 <LRAUV-ESPClientTest> Gate.power :motor,:OFF"
DEBUG: :-<: log "Gate.power :core,:OFF"
DEBUG: :-<: log "Gate.power :analytic1,:OFF"
DEBUG: :-<: log "Gate.power :analytic2,:OFF"
DEBUG: :-<: log "Gate.power :analytic3,:OFF"
DEBUG: :-<: log "@15:17:22.78 Gate.power :main,:OFF"
DEBUG: :-<: log "Safely stopped and ready to power off"
DEBUG: :-<: status "PROCESSED-->STOPPED"
DEBUG: :-<: result ":STOPPED"
DEBUG: In S_STOPPING, for cmd='Cmd.stop', consuming result: <<:STOPPED\n>> which took 15.1004
0375.605  OK: ESP sampling sequence completed normally
Here is the output on the ESP side 
carueda@bufflehead:~/esp2$ ESPcmdPort=7777 esp
@15:10:14.84PDT21-Jul-21 <simrapid> Simulated gateway v3.24 for core bus
Simulated secondary gateway v3.24 for cartridge bus
@15:10:14.96
Configuration for honu by brent@mbari.org 7/1/21
/home/carueda/esp2/type/auv/honu/configure.rb
@15:10:15.10 Polling Can every 2:00
Clients may connect on TCP port 7777
@15:11:17.66 <LRAUV-ESPClientTest> Session Begun
Session Ended
@15:11:17.69 <LRAUV-ESPClientTest> Session Begun
@15:11:19.84 -> showStatus
@15:11:22.72 -> Cmd.loadCartridge -4
Gate.power :main,:ON
Gate.power :analytic1,:ON
Gate.power :analytic2,:ON
Gate.power :analytic3,:ON
@15:11:22.73 Gate.power :core,:ON
@15:11:22.74 Archive.configure :default
Air.configure :default
@15:11:22.75 Lysis1.configure :default
Lysis2.configure :default
@15:11:22.76 Plunge.configure :default
SamplePump.configure :default
@15:11:22.77 ExtraPump.configure :default
Toroid.configure :default
@15:11:22.78 Carousel.configure :default
Pressure.configure :default
@15:11:22.79 PinPort.configure :default
All elf controllers running firmware version 4.79
Gate.power :motor,:ON
@15:11:22.80 <Archive_home> Archive.in :default
@15:11:22.81 Archive.home.jog 0
@15:11:22.82 <Air_home> Air.in :default
Air.home.jog 0
@15:11:22.83 <Lysis1_home> Lysis1.in :default
<Lysis2_home> Lysis2.in :default
<Lysis1_home> Lysis1.home.jog 0
@15:11:22.84 <Plunge_home> Plunge.in :default
<Lysis2_home> Lysis2.home.jog 0
<PinPort_home> PinPort.in :default
<Plunge_home> Plunge.home.jog 0
@15:11:22.85 <Toroid_home> Toroid.in :default
<PinPort_home> PinPort.home.jog 0
<Toroid_home> Toroid.home.jog 0
@15:11:22.89 <Archive_home> Archive.setRawPosition! 50
@15:11:22.90 Archive.in :homing
Archive.seek :home
@15:11:22.91 <Air_home> Air.setRawPosition! 50
Air.in :homing
Air.seek :home
@15:11:22.92 <Plunge_home> Plunge.setRawPosition! 50
Plunge.in :homing
@15:11:22.93 Plunge.seek :home
@15:11:22.94 <PinPort_home> PinPort.setRawPosition! 0
PinPort.in :homing
PinPort.seek :home
@15:11:22.95 <Lysis1_home> Lysis1.setRawPosition! 50
Lysis1.in :homing
@15:11:22.96 Lysis1.seek :home
@15:11:22.97 <Lysis2_home> Lysis2.setRawPosition! 50
Lysis2.in :homing
Lysis2.seek :home
@15:11:23.02 <Toroid_home> Toroid.setRawPosition! 0
Toroid.in :homing
@15:11:23.03 Toroid.seek :home
@15:11:23.04 <PinPort_home> PinPort.in :default
@15:11:23.10 <Toroid_home> Toroid.in :default
@15:11:23.17 <Archive_home> Archive.in :default
@15:11:23.19 <Air_home> Air.in :default
@15:11:23.20 <Plunge_home> Plunge.in :default
@15:11:23.23 <Lysis1_home> Lysis1.in :default
@15:11:23.25 <Lysis2_home> Lysis2.in :default
@15:11:23.50 <LRAUV-ESPClientTest> Toroid.seek :clear
@15:11:25.12 Carousel.in :default
Carousel.home.jog 0
@15:11:25.20 Carousel.setRawPosition! -53
Carousel.in :homing
@15:11:25.21 Carousel.seek :home
@15:11:25.51 Carousel.in :default
@15:11:25.77 Carousel.seek 1
@15:11:25.84 Selecting Cartridge 60
@15:11:25.86 Carousel.seek 60
@15:11:38.13 Lysis1.in :fast
Lysis1.seek :locked
@15:11:40.66 <Plunge> Plunge.seek :locked
@15:11:40.67 <Air> Air.in :fast
Air.seek :locked
@15:11:43.20 <LRAUV-ESPClientTest> Gate.power :cartridge,:ON
Gate.power :cartridge,:OFF
@15:11:43.71 Mounted archive Cartridge
@15:12:28.20 -> Cmd.startFiltering
@15:12:28.22 <FILTERING> Priming sample loop w/5ml, bypass w/1.5ml
SamplePump.setPosition! 0ml
Bypass.open
@15:12:28.93 Intake.open
@15:12:30.43 Sea 127.8m deep (203.5psia)
Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
@15:12:32.93 Vacuum tare is 37% of full scale
@15:12:32.94 <closeIntake> Intake.close
@15:12:32.95 <closeBypass> Bypass.close
@15:12:34.43 <FILTERING> Verifying toroid holds at least 0.6..0.85 of 203.5psia
Waiting up to 40 seconds for toroid pressure to stabilize +/-1.50psi
@15:12:38.94 Bypass.open
@15:12:40.44 Intake.open
@15:12:42.64 Pressure.in :default
Pressure.hold
@15:12:42.71 SamplePump.in :prime
@15:12:42.72 SamplePump.seek 1.5ml,35 seconds
@15:12:44.34 Pressure.stop
SamplePump.setPosition! 0ml
@15:12:44.35 Exhaust.open
@15:12:46.54 <closeBypass> Bypass.close
@15:12:48.75 <FILTERING> Pressure.hold
@15:12:48.82 Sea 127.8m deep (203.5psia)
SamplePump.in :prime
@15:12:48.83 SamplePump.seek 5ml,45 seconds
@15:12:53.56 Pressure.stop
@15:12:53.57 Bypass.open
@15:12:55.06 Intake.close
@15:12:56.57 Toroid.in :hold
Toroid.seek :crack
@15:12:58.07 Toroid.seek :cartridge
@15:12:59.16 Toroid.in :default
Toroid.seek :clear
@15:13:00.98 <closeExhaust> Exhaust.close
<closeBypass> Bypass.close
@15:13:02.47 <FILTERING> Verifying cartridge holds at least 0.75..0.85 of 203.5psia
Waiting up to 40 seconds for cartridge pressure to stabilize +/-1.50psi
@15:13:06.98 Sampling 10.0ml
SamplePump.setPosition! 0ml
Exhaust.open
@15:13:08.48 Intake.open
@15:13:09.98 Pressure.hold
@15:13:10.05 Sea 127.8m deep (203.5psia)
@15:13:10.06 SamplePump.in :sample
SamplePump.seek 10ml,1:21
@15:13:12.99 <sampling> Cartridge 60 filtering 1/10ml at 0.42ml/s with 0.0psi vacuum 127.8m deep (203.5psia)
@15:13:34.59 <FILTERING> Pressure.stop
@15:13:34.60 <closeIntake> Intake.close
<closeExhaust> Exhaust.close
@15:13:34.61 <FILTERING> Toroid.in :hold
Toroid.seek :bypass
@15:13:36.22 Toroid.in :default
@15:13:36.23 Toroid.seek :clear
@15:13:37.84 Sampled  10.0ml
@15:13:42.36 <LRAUV-ESPClientTest> -> Cmd.startProcessing
@15:13:42.39 <PROCESSING> Plunge.seek :reagent
@15:13:43.22 Sample loop closed. Ready to Deliver Reagents
Archive.seek :sealed
@15:13:47.49 Archive.seek :evac
@15:14:01.47 delay 1:00
@15:15:01.48 Archive.seek :clear
@15:15:19.25 RNAlater soak for 45 seconds
@15:16:04.25 Archive.seek :tVent
@15:16:06.83 delay 1 second
@15:16:07.83 Archive.seek :evac
@15:16:23.50 delay 10 seconds
@15:16:33.51 Archive.seek :tVent
@15:16:49.18 delay 1 second
@15:16:50.18 Archive.seek :evac
@15:17:05.85 delay 10 seconds
@15:17:15.86 Sample preserved and evacuated
@15:17:17.74 <LRAUV-ESPClientTest> -> Cmd.stop
@15:17:17.75 Carousel.seek 60
@15:17:17.82 Plunge.seek :locked
@15:17:18.67 <Archive> Archive.in :unlocking
Archive.seek :clear
@15:17:18.68 <Air> Air.in :unlocking
Air.seek :clear
@15:17:18.70 <Lysis1> Lysis1.in :unlocking
Lysis1.seek :clear
@15:17:22.77 <LRAUV-ESPClientTest> Gate.power :motor,:OFF
Gate.power :core,:OFF
Gate.power :analytic1,:OFF
Gate.power :analytic2,:OFF
Gate.power :analytic3,:OFF
@15:17:22.78 Gate.power :main,:OFF
Safely stopped and ready to power off
@15:17:32.86 Session Ended
ESPhonu:001:0->