Snippets

Carlos Rueda ESPComponent testing with LRAUV and ESP simulators

Created by Carlos Rueda last modified
snippet.markdown
Raw

ESPComponent<->ESP testing with simulators on tethyscode and bufflehead

Accounts and machines

  • tethysadmin @ tethyscode
  • carueda @ bufflehead

Preparations

On bufflehead

Using ESP master branch per Brent (2020-08-12).

As usual I have the code under carueda's account on bufflehead:

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

I created a special mode analogous to simreal called simrapid. If you replace simreal with simrapid in your existing instructions, you should get the accelerated sim. No more need to tweak the source code.

ESP simulator with available "dry" cartridges.

To make sure we have "dry" cartridges:

$ esp

-> slots spare: 10
-> slots All => [:dry, :archiveHiBiomass_bac]

Note:

  • archiveHiBiomass_bac is the default ESP cartridge type code in the the mission used below, Maintenance/sample.xml
  • An "archive" type is very convenient for the test as it will complete quicker than with an "lyse-n-go" type.

Exit the ESP simulator for what follows

Then, in this bufflehead session, prepare the following command but do not launch it yet:

  $ ESPclient=tethyscode:9998 ESPcmdPort=7777 esp

This prepares the subsequent execution of the ESP system once the socket server is running on the simulated vehicle (see below).

On tethyscode:

Under ~tethysadmin/workspace/lrauv-application-carlos I made a copy of the latest nightly build as of 2020-08-12.

There, as usual, I have populated the following under Config/sim/tethysadmin/ to override relevant configs for the sim vehicle:

[tethysadmin@tethyscode lrauv-application]$ ls -lrt Config/sim/tethysadmin/
total 16
-rw-rw-r-- 1 tethysadmin tethysadmin  22 Aug 12 11:01 vehicle.cfg
-rw-rw-r-- 1 tethysadmin tethysadmin 163 Aug 12 11:01 Sensor.cfg
-rw-rw-r-- 1 tethysadmin tethysadmin 700 Aug 12 11:03 secure.cfg
-rw-rw-r-- 1 tethysadmin tethysadmin 662 Aug 12 16:01 Science.cfg

In particular, Config/sim/tethysadmin/Science.cfg has the following:

tethysadmin@tethyscode: lrauv-application-carlos$ cat Config/sim/tethysadmin/Science.cfg
ESPComponent.loadAtStartup          = 1 bool;
ESPComponent.simulateHardware       = 0 bool;

ESPComponent.socketServerPort       = 9998 count;

ESPComponent.debug                  = 1 bool;
ESPComponent.poTimeout              = 30 second;

ESPComponent.upsyncTimeout          = 10 second;
ESPComponent.upsync                 = "rsync -azPq --timeout=60 carueda@bufflehead:'/var/log/carueda/simrapid.* /var/log/carueda/*.spr' /home/tethysadmin/workspace/lrauv-application-carlos/ESPlogs";

Note:

  • Port 9998 on tethyscode is where the ESPComponent will listen as a server and wait for the ESP to connect. (This port was opened (by IS, years ago) so it is accessible from bufflehead.)

  • Created the ESPlogs subdir for the rsync command above, as well as added my tethyscode ssh pub key to bufflehead's authorized_keys and the corresponding files under tethyscode's ~/.ssh/

  • Alternatively (but much less frequently used), instead of having the LRAUV running as the server waiting for the ESP, you can set:

      ESPComponent.espServerHost    = "bufflehead:7777"

    in Config/sim/tethysadmin/Science.cfg and immediately run the ESP command above. In this case, the LRAUV would immediately connect to the already running ESP server.

Running the mission:

On tethyscode

Make sure SimDaemon is running; if not already:

[tethysadmin@tethyscode lrauv-application]$ bin/SimDaemon

Using Maintenance/sample.xml for the testing.

Parameters that can be adjusted for testing convenience are, for example Depth = 1, NumberOfSamples = 2.

We need to tell the ESPComponent that we are running the ESP manually, so we set the ESPCOMPONENT_MANUAL_ESP environment variable for this purpose (so the vehicle skips operations like powering-up/down the ESP):

[tethysadmin@tethyscode lrauv-application]$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x \
     "load Maintenance/sample.xml;set sample.NumberOfSamples 2 count;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;run"

Look out for a "Waiting for ESP to connect" line like the following in the output (it may take a few minutes):

... ESPComponent: Waiting for ESP to connect (timeout=30.0000)

To speed up the test, you can run:

maintain sensor depth_keller.depth 1 cm

On bufflehead

As soon as you see that line, launch the ESP simulator command indicated above (ESPclient=tethyscode:9998 ESPcmdPort=7777 esp). You should see interaction activity on both sides:

Note: exit manually issued at the ESP prompt below once 1st sample is completed, to prepare and then (manually again) re-launch esp (same command) for the 2nd sample according to the tethyscode output (captured below as well).

carueda@bufflehead:~/esp2$ ESPclient=tethyscode:9998 ESPcmdPort=7777 esp
@16:56:01.50PDT12-Aug-20 <simrapid> Simulated gateway v3.24 for core bus
Simulated secondary gateway v3.24 for cartridge bus
@16:56:01.62
Configuration for honu by brent@mbari.org 3/11/20
/home/carueda/esp2/type/auv/honu/configure.rb
@16:56:01.69 Polling Can every 2:00
Clients may connect on TCP port 7777
Connecting to tethyscode:9998
@16:56:02.00 <LRAUV> Session Begun
@16:56:04.40 -> showStatus
@16:56:06.00 -> Cmd.loadCartridge -4
@16:56:06.01 Gate.power :main,:ON
Gate.power :analytic1,:ON
Gate.power :analytic2,:ON
Gate.power :analytic3,:ON
Gate.power :core,:ON
@16:56:06.03 Archive.configure :default
Air.configure :default
@16:56:06.04 Lysis1.configure :default
@16:56:06.05 Lysis2.configure :default
@16:56:06.06 Plunge.configure :default
@16:56:06.07 SamplePump.configure :default
ExtraPump.configure :default
@16:56:06.08 Toroid.configure :default
@16:56:06.09 Carousel.configure :default
Pressure.configure :default
@16:56:06.10 PinPort.configure :default
All elf controllers running firmware version 4.99
Gate.power :motor,:ON
@16:56:06.11 <Archive_home> Archive.reconfigure :default
@16:56:06.12 Archive.home.jog 0
<Air_home> Air.reconfigure :default
@16:56:06.13 Air.home.jog 0
@16:56:06.14 <Lysis1_home> Lysis1.reconfigure :default
<Lysis2_home> Lysis2.reconfigure :default
<Lysis1_home> Lysis1.home.jog 0
<Plunge_home> Plunge.reconfigure :default
@16:56:06.15 <Lysis2_home> Lysis2.home.jog 0
<PinPort_home> PinPort.reconfigure :default
<Plunge_home> Plunge.home.jog 0
@16:56:06.16 <Toroid_home> Toroid.reconfigure :default
<PinPort_home> PinPort.home.jog 0
<Toroid_home> Toroid.home.jog 0
@16:56:06.20 <Archive_home> Archive.setRawPosition! 50
Archive.reconfigure :homing
@16:56:06.21 Archive.seek :home
@16:56:06.22 <Air_home> Air.setRawPosition! 50
Air.reconfigure :homing
Air.seek :home
@16:56:06.23 <Plunge_home> Plunge.setRawPosition! 50
Plunge.reconfigure :homing
Plunge.seek :home
@16:56:06.24 <PinPort_home> PinPort.setRawPosition! 0
@16:56:06.25 PinPort.reconfigure :homing
PinPort.seek :home
@16:56:06.26 <Lysis1_home> Lysis1.setRawPosition! 50
Lysis1.reconfigure :homing
Lysis1.seek :home
@16:56:06.27 <Lysis2_home> Lysis2.setRawPosition! 50
Lysis2.reconfigure :homing
@16:56:06.28 Lysis2.seek :home
@16:56:06.29 <Toroid_home> Toroid.setRawPosition! 0
Toroid.reconfigure :homing
Toroid.seek :home
@16:56:06.32 <PinPort_home> PinPort.reconfigure :default
@16:56:06.36 <Toroid_home> Toroid.reconfigure :default
@16:56:06.48 <Archive_home> Archive.reconfigure :default
@16:56:06.50 <Air_home> Air.reconfigure :default
@16:56:06.51 <Plunge_home> Plunge.reconfigure :default
@16:56:06.54 <Lysis1_home> Lysis1.reconfigure :default
@16:56:06.55 <Lysis2_home> Lysis2.reconfigure :default
@16:56:06.81 <LRAUV> Toroid.seek :clear
@16:56:08.43 Carousel.reconfigure :default
Carousel.home.jog 0
@16:56:08.50 Carousel.setRawPosition! -53
@16:56:08.51 Carousel.reconfigure :homing
Carousel.seek :home
@16:56:08.81 Carousel.reconfigure :default
@16:56:09.07 Carousel.seek 1
@16:56:09.14 Selecting Cartridge 56
@16:56:09.15 Carousel.seek 56
@16:56:20.59 Gate.power :heat,:OFF
Gate.power :cartridge,:OFF
@16:56:20.60 Lysis1.seek :locked
@16:56:24.67 <Plunge> Plunge.seek :locked
<Air> Air.seek :locked
@16:56:28.74 <LRAUV> Gate.power :cartridge,:ON
Gate.power :cartridge,:OFF
Gate.power :cartridge,:OFF
@16:56:29.25 Mounted archive Cartridge
@16:56:42.81 -> Cmd.startFiltering
@16:56:42.82 <FILTERING> Duration of filtering limited to 2:05:00
@16:56:42.83 Priming sample loop w/5ml, bypass w/1.5ml
SamplePump.setPosition! 0ml
Bypass.open
@16:56:43.54 Intake.open
@16:56:45.04 Sea 5.7m deep (23.1psia)
Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
@16:56:47.56 Vacuum tare is 10% of full scale
Pressure.reconfigure :default
Pressure.hold
@16:56:47.64 SamplePump.reconfigure :prime
SamplePump.seek 1.5ml,38 seconds
@16:56:49.41 Pressure.coast
SamplePump.setPosition! 0ml
Exhaust.open
@16:56:51.61 <closeBypass> Bypass.close
@16:56:53.82 <FILTERING> Pressure.hold
@16:56:53.89 Sea 5.7m deep (23.1psia)
SamplePump.reconfigure :prime
SamplePump.seek 5ml,56 seconds
@16:56:58.63 Pressure.coast
Bypass.open
@16:57:00.13 Intake.close
@16:57:01.63 Toroid.reconfigure :hold
Toroid.seek :crack
@16:57:02.43 Toroid.reconfigure :default
Toroid.seek :clear
@16:57:03.93 Toroid.reconfigure :hold
Toroid.seek :cartridge
@16:57:05.75 Toroid.reconfigure :default
Toroid.seek :clear
@16:57:07.57 Pressurizing cartridge to 26psi above 23.1psia
SamplePump.setPosition! 0ml
Intake.open
@16:57:09.06 Bypass.close
@16:57:10.60 Exhaust.close
@16:57:12.07 Pressure.hold
@16:57:12.14 SamplePump.reconfigure :charge
SamplePump.seek 0.2ml,32 seconds
@16:57:12.75 Pressure.coast
Sampling 10.0ml
SamplePump.setPosition! 0ml
Exhaust.open
@16:57:14.25 Pressure.hold
@16:57:14.32 Sea 5.7m deep (23.1psia)
@16:57:14.33 SamplePump.reconfigure :sample
SamplePump.seek 10ml,1:21
@16:57:17.25 <sampling> Cartridge 56 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)
@16:57:27.29 <FILTERING> Pressure.coast
@16:57:27.30 <closeIntake> Intake.close
<closeExhaust> Exhaust.close
@16:57:27.31 <FILTERING> Toroid.reconfigure :hold
Toroid.seek :bypass
@16:57:28.92 Toroid.reconfigure :default
@16:57:28.93 Toroid.seek :clear
@16:57:30.54 Sampled  10.0ml
@16:57:32.02 <LRAUV> -> Cmd.startProcessing
@16:57:32.03 <PROCESSING> Plunge.seek :reagent
@16:57:32.87 Sample loop closed. Ready to Deliver Reagents
Archive.seek :sealed
@16:57:37.14 Archive.seek :evac
@16:57:51.12 delay 1:00
@16:58:51.13 Archive.seek :clear
@16:59:08.89 RNAlater soak for 45 seconds
@16:59:53.90 Archive.seek :tVent
@16:59:56.48 delay 1 second
@16:59:57.48 Archive.seek :evac
@17:00:13.14 delay 10 seconds
@17:00:23.15 Archive.seek :tVent
@17:00:38.82 delay 1 second
@17:00:39.82 Archive.seek :evac
@17:00:55.49 delay 10 seconds
@17:01:05.50 Sample preserved and evacuated
@17:01:06.47 <LRAUV> -> Cmd.stop
Gate.power :heat,:OFF
@17:01:06.48 Gate.power :cartridge,:OFF
Carousel.seek 56
@17:01:06.55 Plunge.seek :locked
@17:01:07.39 PinPort.seek :clear
@17:01:07.46 <Archive> Archive.seek :clear
<Air> Air.seek :clear
@17:01:07.48 <Lysis1> Lysis1.seek :clear
@17:01:25.23 <LRAUV> Archive.coast
Air.coast
Lysis1.coast
Lysis2.coast
@17:01:25.24 Plunge.coast
SamplePump.coast
Toroid.coast
Carousel.coast
PinPort.coast
@17:01:25.26 Gate.power :heat,:OFF
Gate.power :cartridge,:OFF
@17:01:25.31 Gate.power :motor,:OFF
Gate.power :core,:OFF
Gate.power :analytic1,:OFF
@17:01:25.32 Gate.power :analytic2,:OFF
Gate.power :analytic3,:OFF
Gate.power :main,:OFF
Safely stopped and ready to power off
@17:01:44.48 Session Ended
@17:01:54.27 <simrapid> -> exit
carueda@bufflehead:~/esp2$
carueda@bufflehead:~/esp2$
carueda@bufflehead:~/esp2$ ESPclient=tethyscode:9998 ESPcmdPort=7777 esp
@17:11:29.31PDT12-Aug-20 <simrapid> Simulated gateway v3.24 for core bus
Simulated secondary gateway v3.24 for cartridge bus
@17:11:29.43
Configuration for honu by brent@mbari.org 3/11/20
/home/carueda/esp2/type/auv/honu/configure.rb
@17:11:29.51 Polling Can every 2:00
Clients may connect on TCP port 7777
Connecting to tethyscode:9998
@17:11:29.83 <LRAUV> Session Begun
@17:11:31.82 -> showStatus
@17:11:33.82 -> Cmd.loadCartridge -4
@17:11:33.83 Gate.power :main,:ON
Gate.power :analytic1,:ON
Gate.power :analytic2,:ON
Gate.power :analytic3,:ON
@17:11:33.84 Gate.power :core,:ON
@17:11:33.85 Archive.configure :default
Air.configure :default
@17:11:33.86 Lysis1.configure :default
@17:11:33.87 Lysis2.configure :default
@17:11:33.88 Plunge.configure :default
@17:11:33.89 SamplePump.configure :default
ExtraPump.configure :default
@17:11:33.90 Toroid.configure :default
@17:11:33.91 Carousel.configure :default
@17:11:33.92 Pressure.configure :default
@17:11:33.93 PinPort.configure :default
All elf controllers running firmware version 4.99
Gate.power :motor,:ON
@17:11:33.94 <Archive_home> Archive.reconfigure :default
@17:11:33.95 Archive.home.jog 0
<Air_home> Air.reconfigure :default
@17:11:33.96 Air.home.jog 0
<Lysis1_home> Lysis1.reconfigure :default
@17:11:33.97 <Lysis2_home> Lysis2.reconfigure :default
<Lysis1_home> Lysis1.home.jog 0
<Plunge_home> Plunge.reconfigure :default
@17:11:33.98 <Lysis2_home> Lysis2.home.jog 0
<Plunge_home> Plunge.home.jog 0
<PinPort_home> PinPort.reconfigure :default
@17:11:33.99 <Toroid_home> Toroid.reconfigure :default
<PinPort_home> PinPort.home.jog 0
<Toroid_home> Toroid.home.jog 0
@17:11:34.03 <Archive_home> Archive.setRawPosition! 50
Archive.reconfigure :homing
@17:11:34.04 Archive.seek :home
@17:11:34.05 <Air_home> Air.setRawPosition! 50
Air.reconfigure :homing
Air.seek :home
@17:11:34.06 <Plunge_home> Plunge.setRawPosition! 50
Plunge.reconfigure :homing
Plunge.seek :home
@17:11:34.07 <PinPort_home> PinPort.setRawPosition! 0
@17:11:34.08 PinPort.reconfigure :homing
PinPort.seek :home
@17:11:34.09 <Lysis1_home> Lysis1.setRawPosition! 50
Lysis1.reconfigure :homing
Lysis1.seek :home
@17:11:34.11 <Lysis2_home> Lysis2.setRawPosition! 50
Lysis2.reconfigure :homing
Lysis2.seek :home
@17:11:34.12 <Toroid_home> Toroid.setRawPosition! 0
Toroid.reconfigure :homing
Toroid.seek :home
@17:11:34.15 <PinPort_home> PinPort.reconfigure :default
@17:11:34.20 <Toroid_home> Toroid.reconfigure :default
@17:11:34.31 <Archive_home> Archive.reconfigure :default
@17:11:34.33 <Air_home> Air.reconfigure :default
@17:11:34.34 <Plunge_home> Plunge.reconfigure :default
@17:11:34.37 <Lysis1_home> Lysis1.reconfigure :default
@17:11:34.39 <Lysis2_home> Lysis2.reconfigure :default
@17:11:34.64 <LRAUV> Toroid.seek :clear
@17:11:36.26 Carousel.reconfigure :default
Carousel.home.jog 0
@17:11:36.33 Carousel.setRawPosition! -53
Carousel.reconfigure :homing
@17:11:36.34 Carousel.seek :home
@17:11:36.64 Carousel.reconfigure :default
@17:11:36.89 Carousel.seek 1
@17:11:36.97 Selecting Cartridge 55
@17:11:36.98 Carousel.seek 55
@17:11:48.21 Gate.power :heat,:OFF
Gate.power :cartridge,:OFF
@17:11:48.22 Lysis1.seek :locked
@17:11:52.29 <Plunge> Plunge.seek :locked
<Air> Air.seek :locked
@17:11:56.36 <LRAUV> Gate.power :cartridge,:ON
Gate.power :cartridge,:OFF
Gate.power :cartridge,:OFF
@17:11:56.86 Mounted archive Cartridge
@17:12:10.63 -> Cmd.startFiltering
@17:12:10.64 <FILTERING> Duration of filtering limited to 2:05:00
@17:12:10.65 Priming sample loop w/5ml, bypass w/1.5ml
SamplePump.setPosition! 0ml
Bypass.open
@17:12:11.36 Intake.open
@17:12:12.86 Sea 5.7m deep (23.1psia)
Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
@17:12:15.38 Vacuum tare is 10% of full scale
@17:12:15.39 Pressure.reconfigure :default
Pressure.hold
@17:12:15.46 SamplePump.reconfigure :prime
SamplePump.seek 1.5ml,38 seconds
@17:12:17.23 Pressure.coast
SamplePump.setPosition! 0ml
@17:12:17.24 Exhaust.open
@17:12:19.43 <closeBypass> Bypass.close
@17:12:21.64 <FILTERING> Pressure.hold
@17:12:21.71 Sea 5.7m deep (23.1psia)
@17:12:21.72 SamplePump.reconfigure :prime
SamplePump.seek 5ml,56 seconds
@17:12:26.45 Pressure.coast
Bypass.open
@17:12:27.95 Intake.close
@17:12:29.45 Toroid.reconfigure :hold
Toroid.seek :crack
@17:12:30.25 Toroid.reconfigure :default
Toroid.seek :clear
@17:12:31.76 Toroid.reconfigure :hold
Toroid.seek :cartridge
@17:12:33.57 Toroid.reconfigure :default
Toroid.seek :clear
@17:12:35.39 Pressurizing cartridge to 26psi above 23.1psia
SamplePump.setPosition! 0ml
@17:12:35.40 Intake.open
@17:12:36.89 Bypass.close
@17:12:38.39 Exhaust.close
@17:12:39.89 Pressure.hold
@17:12:39.97 SamplePump.reconfigure :charge
SamplePump.seek 0.2ml,32 seconds
@17:12:40.57 Pressure.coast
@17:12:40.58 Sampling 10.0ml
SamplePump.setPosition! 0ml
Exhaust.open
@17:12:42.08 Pressure.hold
@17:12:42.15 Sea 5.7m deep (23.1psia)
SamplePump.reconfigure :sample
@17:12:42.16 SamplePump.seek 10ml,1:21
@17:12:45.08 <sampling> Cartridge 55 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)
@17:12:55.12 <FILTERING> Pressure.coast
<closeIntake> Intake.close
@17:12:55.13 <closeExhaust> Exhaust.close
<FILTERING> Toroid.reconfigure :hold
Toroid.seek :bypass
@17:12:56.75 Toroid.reconfigure :default
Toroid.seek :clear
@17:12:58.37 Sampled  10.0ml
@17:12:59.84 <LRAUV> -> Cmd.startProcessing
@17:12:59.86 <PROCESSING> Plunge.seek :reagent
@17:13:00.69 Sample loop closed. Ready to Deliver Reagents
Archive.seek :sealed
@17:13:04.96 Archive.seek :evac
@17:13:18.94 delay 1:00
@17:14:18.95 Archive.seek :clear
@17:14:36.72 RNAlater soak for 45 seconds
@17:15:21.72 Archive.seek :tVent
@17:15:24.30 delay 1 second
@17:15:25.31 Archive.seek :evac
@17:15:40.97 delay 10 seconds
@17:15:50.98 Archive.seek :tVent
@17:16:06.65 delay 1 second
@17:16:07.65 Archive.seek :evac
@17:16:23.32 delay 10 seconds
@17:16:33.33 Sample preserved and evacuated
@17:16:34.29 <LRAUV> -> Cmd.stop
Gate.power :heat,:OFF
Gate.power :cartridge,:OFF
@17:16:34.30 Carousel.seek 55
@17:16:34.38 Plunge.seek :locked
@17:16:35.21 PinPort.seek :clear
@17:16:35.29 <Archive> Archive.seek :clear
<Air> Air.seek :clear
@17:16:35.31 <Lysis1> Lysis1.seek :clear
@17:16:53.06 <LRAUV> Archive.coast
Air.coast
Lysis1.coast
Lysis2.coast
Plunge.coast
SamplePump.coast
@17:16:53.07 Toroid.coast
Carousel.coast
PinPort.coast
@17:16:53.09 Gate.power :heat,:OFF
Gate.power :cartridge,:OFF
@17:16:53.14 Gate.power :motor,:OFF
Gate.power :core,:OFF
Gate.power :analytic1,:OFF
Gate.power :analytic2,:OFF
@17:16:53.15 Gate.power :analytic3,:OFF
Gate.power :main,:OFF
Safely stopped and ready to power off
@17:17:12.29 Session Ended
@17:18:29.49 <simrapid> -> exit

On tethyscode:

tethysadmin@tethyscode: lrauv-application-carlos$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x      "load Maintenance/sample.xml;set sample.NumberOfSamples 2 count;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;run"
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.
2020-08-12T23:51:45.697Z,1597276305.697 [SyncHandler](INFO): Protected caller Thread ID is 109681
2020-08-12T23:51:45.697Z,1597276305.697 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 109682
2020-08-12T23:51:45.698Z,1597276305.698 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 109683
2020-08-12T23:51:45.698Z,1597276305.698 [logger ThreadHandler](INFO): Protected caller Thread ID is 109684
2020-08-12T23:51:45.698Z,1597276305.698 [Supervisor](INFO): Looking for Config files in directory: Config/
2020-08-12T23:51:45.698Z,1597276305.698 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2020-08-12T23:51:45.703Z,1597276305.703 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2020-08-12T23:51:45.708Z,1597276305.708 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2020-08-12T23:51:45.714Z,1597276305.714 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
tethyscode>2020-08-12T23:51:45.719Z,1597276305.719 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2020-08-12T23:51:45.723Z,1597276305.723 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2020-08-12T23:51:45.726Z,1597276305.726 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2020-08-12T23:51:45.730Z,1597276305.730 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2020-08-12T23:51:45.735Z,1597276305.735 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2020-08-12T23:51:45.738Z,1597276305.738 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2020-08-12T23:51:45.742Z,1597276305.742 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2020-08-12T23:51:45.745Z,1597276305.745 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2020-08-12T23:51:45.749Z,1597276305.749 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2020-08-12T23:51:45.753Z,1597276305.753 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2020-08-12T23:51:45.756Z,1597276305.756 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2020-08-12T23:51:45.763Z,1597276305.763 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2020-08-12T23:51:45.767Z,1597276305.767 [Supervisor](INFO): Looking for Config files in directory: Config/tethyscode/
2020-08-12T23:51:45.767Z,1597276305.767 [Supervisor](INFO): Looking for Config files in directory: Config/tethyscode/tethysadmin/
2020-08-12T23:51:45.767Z,1597276305.767 [Supervisor](INFO): Looking for Config files in directory: Config/sim/
2020-08-12T23:51:45.767Z,1597276305.767 [Supervisor](INFO): Opening Config file at: Config/sim/secure.cfg
2020-08-12T23:51:45.770Z,1597276305.770 [Supervisor](INFO): Opening Config file at: Config/sim/Science.cfg
2020-08-12T23:51:45.773Z,1597276305.773 [Supervisor](INFO): Opening Config file at: Config/sim/Simulator.cfg
2020-08-12T23:51:45.776Z,1597276305.776 [Supervisor](INFO): Opening Config file at: Config/sim/vehicle.cfg
2020-08-12T23:51:45.779Z,1597276305.779 [Supervisor](INFO): Opening Config file at: Config/sim/Servo.cfg
2020-08-12T23:51:45.782Z,1597276305.782 [Supervisor](INFO): Opening Config file at: Config/sim/Sensor.cfg
2020-08-12T23:51:45.785Z,1597276305.785 [Supervisor](INFO): Opening Config file at: Config/sim/Derivation.cfg
2020-08-12T23:51:45.788Z,1597276305.788 [Supervisor](INFO): Looking for Config files in directory: Config/sim/tethysadmin/
2020-08-12T23:51:45.788Z,1597276305.788 [Supervisor](INFO): Opening Config file at: Config/sim/tethysadmin/secure.cfg
2020-08-12T23:51:45.791Z,1597276305.791 [Supervisor](INFO): Opening Config file at: Config/sim/tethysadmin/Science.cfg
2020-08-12T23:51:45.794Z,1597276305.794 [Supervisor](INFO): Opening Config file at: Config/sim/tethysadmin/vehicle.cfg
2020-08-12T23:51:45.797Z,1597276305.797 [Supervisor](INFO): Opening Config file at: Config/sim/tethysadmin/Sensor.cfg
2020-08-12T23:51:45.800Z,1597276305.800 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2020-08-12T23:51:45.805Z,1597276305.805 [ESPComponent](ERROR): Could not open device '/dev/loadA6' at ESPComponent.loadControl
2020-08-12T23:51:45.825Z,1597276305.825 [ESPComponent](ERROR): Could not open device '/dev/loadA7' at ESPComponent.loadControl2
2020-08-12T23:51:45.846Z,1597276305.846 [ESPComponent](IMPORTANT): ESPCOMPONENT_MANUAL_ESP INDICATED.
2020-08-12T23:51:45.849Z,1597276305.849 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2020-08-12T23:51:45.849Z,1597276305.849 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 109766
2020-08-12T23:51:45.862Z,1597276305.862 [AHRS_M2](INFO): created writer for : platform_orientation
2020-08-12T23:51:45.862Z,1597276305.862 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2020-08-12T23:51:45.862Z,1597276305.862 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2020-08-12T23:51:45.862Z,1597276305.862 [AHRS_M2](INFO): created writer for : platform_roll_angle
2020-08-12T23:51:45.865Z,1597276305.865 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 109767
2020-08-12T23:51:45.866Z,1597276305.866 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/voltage_now
2020-08-12T23:51:45.866Z,1597276305.866 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/current_now
2020-08-12T23:51:45.866Z,1597276305.866 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_now
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-0/charge_full
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/voltage_now
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/current_now
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_now
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard](ERROR): Can't open SysFS node file: /sys/class/power_supply/ds2782-1/charge_full
2020-08-12T23:51:45.867Z,1597276305.867 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 109768
2020-08-12T23:51:45.867Z,1597276305.867 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 109769
2020-08-12T23:51:45.874Z,1597276305.874 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 109770
2020-08-12T23:51:45.874Z,1597276305.874 [Supervisor](INFO): Main Thread ID is 109680
2020-08-12T23:51:45.875Z,1597276305.875 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 109776
2020-08-12T23:51:45.875Z,1597276305.875 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 109778
2020-08-12T23:51:45.875Z,1597276305.875 [logger ThreadHandler](INFO): Handler Thread ID is 109774
2020-08-12T23:51:45.878Z,1597276305.878 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 109775
2020-08-12T23:51:45.878Z,1597276305.878 [Onboard ThreadHandler](INFO): Handler Thread ID is 109777
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 109779
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2020-08-12T23:51:45.878Z,1597276305.878 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2020-08-12T23:51:45.881Z,1597276305.881 [CommandLine ThreadHandler](INFO): Handler Thread ID is 109773
2020-08-12T23:51:45.883Z,1597276305.883 [controlThread ThreadHandler](INFO): Handler Thread ID is 109772
2020-08-12T23:51:45.884Z,1597276305.884 [ExternalSim](INFO): ExternalSim initializing...
2020-08-12T23:51:45.884Z,1597276305.884 [CommandLine ThreadHandler](INFO): Handler Thread ID is 109771
2020-08-12T23:51:45.912Z,1597276305.912 [SBIT](INFO): Initialize SBIT Component.
2020-08-12T23:51:45.912Z,1597276305.912 [SBIT](IMPORTANT): git: 2020-07-23-4-gf73e8ad
2020-08-12T23:51:45.912Z,1597276305.912 [SBIT](INFO): git hash: f73e8ad95b55d34bdb49d5e5edbbb75e6888861e
2020-08-12T23:51:45.912Z,1597276305.912 [SBIT](INFO): Kernel Reporting Different Release From Configuration.
Kernel Expected: 2.6.32-45-generic-pae
Kernel Reported: 2.6.32-754.29.1.el6.x86_64
2020-08-12T23:51:45.912Z,1597276305.912 [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 Mon Apr 27 15:30:33 UTC 2020
2020-08-12T23:51:45.912Z,1597276305.912 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.
2020-08-12T23:51:45.912Z,1597276305.912 [IBIT](INFO): Initialize IBIT Component.
tethyscode>load Maintenance2020-08-12T23:51:45.926Z,1597276305.926 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2020-08-12T23:51:45.926Z,1597276305.926 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): DefineArg sample.CartridgeType = -4.000000 count
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2020-08-12T23:51:45.927Z,1597276305.927 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2020-08-12T23:51:45.928Z,1597276305.928 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPCartridgeType = nan count
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2020-08-12T23:51:45.929Z,1597276305.929 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 500.000024 cc
2020-08-12T23:51:45.930Z,1597276305.930 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature
2020-08-12T23:51:45.930Z,1597276305.930 [MissionManager](ERROR): Slate does not contain celsius
2020-08-12T23:51:45.933Z,1597276305.933 [MissionManager](ERROR): Slate does not contain CTD_Seabird.bin_mean_sea_water_temperature
2020-08-12T23:51:45.933Z,1597276305.933 [MissionManager](ERROR): Slate does not contain celsius
2020-08-12T23:51:45.934Z,1597276305.934 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2020-08-12T23:51:45.943Z,1597276305.943 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2020-08-12T23:51:45.943Z,1597276305.943 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2020-08-12T23:51:45.944Z,1597276305.944 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2020-08-12T23:51:45.944Z,1597276305.944 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
tethyscode>set sample.NumberOfSamples 2 count;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;run
2020-08-12T23:51:45.984Z,1597276305.984 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 2.000000 count
2020-08-12T23:51:45.985Z,1597276305.985 [CommandLine](IMPORTANT): got command set sample.Depth 1.000000 centimeter
2020-08-12T23:51:45.985Z,1597276305.985 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2020-08-12T23:51:45.985Z,1597276305.985 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 1.000000 centimeter
2020-08-12T23:51:45.985Z,1597276305.985 [CommandLine](IMPORTANT): got command run
2020-08-12T23:51:45.985Z,1597276305.985 [CommandLine](IMPORTANT): Running
2020-08-12T23:51:49.875Z,1597276309.875 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.000134
2020-08-12T23:51:50.875Z,1597276310.875 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2020-08-12T23:51:51.875Z,1597276311.875 [DataOverHttps](INFO): Radio surface powered ON.
2020-08-12T23:52:06.352Z,1597276326.352 [SBIT](IMPORTANT): Beginning Startup BIT
2020-08-12T23:52:20.357Z,1597276340.357 [NAL9602](INFO): GPS fix at 20200812T235220: (36.803404, -121.822207)
2020-08-12T23:52:21.557Z,1597276341.557 [NAL9602](INFO): No messages in MT queue
2020-08-12T23:52:51.963Z,1597276371.963 [NAL9602](INFO): Not Powering down - fast GPS
2020-08-12T23:52:59.965Z,1597276379.965 [SBIT](IMPORTANT): SBIT PASSED
2020-08-12T23:52:59.965Z,1597276379.965 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2020-08-12T23:52:59.965Z,1597276379.965 [SBIT](IMPORTANT): No configSet variables persisted
2020-08-12T23:53:00.365Z,1597276380.365 [MissionManager](IMPORTANT): Started mission Startup
2020-08-12T23:53:00.365Z,1597276380.365 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-08-12T23:53:05.166Z,1597276385.166 [NAL9602](INFO): GPS fix at 20200812T235305: (36.803409, -121.822216)
2020-08-12T23:53:06.366Z,1597276386.366 [NAL9602](INFO): No messages in MT queue
2020-08-12T23:53:08.883Z,1597276388.883 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20200812T235145/Courier0000.lzma
2020-08-12T23:53:09.883Z,1597276389.883 [DataOverHttps](INFO): Moved sent file to Logs/20200812T235145/Courier0000.lzma.bak
2020-08-12T23:53:09.883Z,1597276389.883 [DataOverHttps](INFO): SBD MOMSN=12551506
2020-08-12T23:53:18.884Z,1597276398.884 [DataOverHttps](INFO): Sending 400 bytes from file Logs/20200812T234630/Express0005.lzma
2020-08-12T23:53:19.884Z,1597276399.884 [DataOverHttps](INFO): Moved sent file to Logs/20200812T234630/Express0005.lzma.bak
2020-08-12T23:53:19.884Z,1597276399.884 [DataOverHttps](INFO): SBD MOMSN=12551510
2020-08-12T23:53:28.885Z,1597276408.885 [DataOverHttps](INFO): Sending 125 bytes from file Logs/20200812T234630/Express0008.lzma
2020-08-12T23:53:29.884Z,1597276409.884 [DataOverHttps](INFO): Moved sent file to Logs/20200812T234630/Express0008.lzma.bak
2020-08-12T23:53:29.884Z,1597276409.884 [DataOverHttps](INFO): SBD MOMSN=12551521
2020-08-12T23:53:36.772Z,1597276416.772 [NAL9602](INFO): Not Powering down - fast GPS
2020-08-12T23:53:38.885Z,1597276418.885 [DataOverHttps](INFO): Sending 663 bytes from file Logs/20200812T235145/Express0001.lzma
2020-08-12T23:53:39.885Z,1597276419.885 [DataOverHttps](INFO): Moved sent file to Logs/20200812T235145/Express0001.lzma.bak
2020-08-12T23:53:39.885Z,1597276419.885 [DataOverHttps](INFO): SBD MOMSN=12551526
2020-08-12T23:53:41.174Z,1597276421.174 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2020-08-12T23:53:41.174Z,1597276421.174 [Startup](INFO): Completed Startup
2020-08-12T23:53:41.174Z,1597276421.174 [MissionManager](INFO): Startup is completed.
2020-08-12T23:53:41.174Z,1597276421.174 [MissionManager](INFO): Uninitializing Mission Startup
2020-08-12T23:53:41.574Z,1597276421.574 [MissionManager](IMPORTANT): Started mission sample
2020-08-12T23:53:41.574Z,1597276421.574 [sample:A.AbortSample](INFO): Initializing AbortSample.
2020-08-12T23:53:42.774Z,1597276422.774 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.010000 m
2020-08-12T23:55:52.404Z,1597276552.404 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2020-08-12T23:55:52.804Z,1597276552.804 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.012824 m , settling for 0.050000 min
2020-08-12T23:55:56.405Z,1597276556.405 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2020-08-12T23:55:56.805Z,1597276556.805 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2020-08-12T23:55:57.205Z,1597276557.205 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4.
2020-08-12T23:55:57.205Z,1597276557.205 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2020-08-12T23:55:57.205Z,1597276557.205 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2020-08-12T23:55:58.405Z,1597276558.405 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::'
2020-08-12T23:55:58.405Z,1597276558.405 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::"
2020-08-12T23:55:58.805Z,1597276558.805 [ESPComponent](IMPORTANT): powerUpESP IGNORED because manualEsp_
2020-08-12T23:55:58.805Z,1597276558.805 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)
2020-08-12T23:56:02.406Z,1597276562.406 [ESPComponent](IMPORTANT): ESP has connected as client
2020-08-12T23:56:03.206Z,1597276563.206 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4
2020-08-12T23:56:03.206Z,1597276563.206 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2020-08-12T23:56:03.607Z,1597276563.607 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](ERROR): data element is not active.
2020-08-12T23:56:03.607Z,1597276563.607 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 0.126759 m inwater with nan ug/l chlorophyll fluorescence.
2020-08-12T23:56:04.406Z,1597276564.406 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2020-08-12T23:56:04.806Z,1597276564.806 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2020-08-12T23:56:06.406Z,1597276566.406 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2020-08-12T23:56:43.214Z,1597276603.214 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@56,archiveHiBiomass_bac)
2020-08-12T23:56:44.815Z,1597276604.815 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@5.0)
2020-08-12T23:56:45.615Z,1597276605.615 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2020-08-12T23:57:16.021Z,1597276636.021 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2020-08-12T23:57:16.421Z,1597276636.421 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2020-08-12T23:57:32.024Z,1597276652.024 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@10.0)
2020-08-12T23:57:32.424Z,1597276652.424 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@10.0)
2020-08-12T23:57:34.825Z,1597276654.825 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@56,archiveHiBiomass_bac)
2020-08-13T00:01:06.875Z,1597276866.875 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@56,archiveHiBiomass_bac)
2020-08-13T00:01:33.681Z,1597276893.681 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 carueda@bufflehead:'/var/log/carueda/simrapid.* /var/log/carueda/*.spr' /home/tethysadmin/workspace/lrauv-application-carlos/ESPlogs &
2020-08-13T00:01:33.685Z,1597276893.685 [ESPComponent](INFO): closing pipe.
2020-08-13T00:01:34.082Z,1597276894.082 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2020-08-13T00:01:44.089Z,1597276904.089 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.
2020-08-13T00:01:44.089Z,1597276904.089 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP
2020-08-13T00:01:44.089Z,1597276904.089 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper
2020-08-13T00:01:44.089Z,1597276904.089 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth
2020-08-13T00:01:44.489Z,1597276904.489 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):
@16:56:09.14 Selecting Cartridge 56
@16:57:30.54 Sampled  10.0ml

2020-08-13T00:01:44.489Z,1597276904.489 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_
2020-08-13T00:01:44.490Z,1597276904.490 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample
2020-08-13T00:01:44.490Z,1597276904.490 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater
2020-08-13T00:01:44.490Z,1597276904.490 [sample:SampleRepeater](INFO): Running loop #2
2020-08-13T00:01:44.889Z,1597276904.889 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.010000 m
2020-08-13T00:11:21.026Z,1597277481.026 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2020-08-13T00:11:21.426Z,1597277481.426 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.008778 m , settling for 0.050000 min
2020-08-13T00:11:25.027Z,1597277485.027 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2020-08-13T00:11:25.427Z,1597277485.427 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2020-08-13T00:11:25.827Z,1597277485.827 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4.
2020-08-13T00:11:25.827Z,1597277485.827 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge:A.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2020-08-13T00:11:25.827Z,1597277485.827 [sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP:SelectESPCartridge
2020-08-13T00:11:27.426Z,1597277487.426 [ESPComponent](IMPORTANT): powerUpESP IGNORED because manualEsp_
2020-08-13T00:11:27.426Z,1597277487.426 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)
2020-08-13T00:11:30.227Z,1597277490.227 [ESPComponent](IMPORTANT): ESP has connected as client
2020-08-13T00:11:31.028Z,1597277491.028 [ESPComponent](IMPORTANT): [sample #2] Setting cartridge argument to -4
2020-08-13T00:11:31.028Z,1597277491.028 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2020-08-13T00:11:31.428Z,1597277491.428 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](ERROR): data element is not active.
2020-08-13T00:11:31.428Z,1597277491.428 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 0.001894 m inwater with nan ug/l chlorophyll fluorescence.
2020-08-13T00:11:31.827Z,1597277491.827 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG
2020-08-13T00:11:32.227Z,1597277492.227 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS
2020-08-13T00:11:34.228Z,1597277494.228 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE
2020-08-13T00:12:11.035Z,1597277531.035 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PRIMING (@55,archiveHiBiomass_bac)
2020-08-13T00:12:12.636Z,1597277532.636 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PRIMING (@5.0)
2020-08-13T00:12:13.436Z,1597277533.436 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_FILTERING (@5.0)
2020-08-13T00:12:43.842Z,1597277563.842 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_FILTERING (@0.0)
2020-08-13T00:12:44.242Z,1597277564.242 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2020-08-13T00:12:59.845Z,1597277579.845 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PAUSED (@10.0)
2020-08-13T00:13:00.246Z,1597277580.246 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PROCESSING (@10.0)
2020-08-13T00:13:02.646Z,1597277582.646 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PROCESSED (@55,archiveHiBiomass_bac)
2020-08-13T00:16:34.691Z,1597277794.691 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPING (@55,archiveHiBiomass_bac)
2020-08-13T00:17:01.497Z,1597277821.497 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 carueda@bufflehead:'/var/log/carueda/simrapid.* /var/log/carueda/*.spr' /home/tethysadmin/workspace/lrauv-application-carlos/ESPlogs &
2020-08-13T00:17:01.502Z,1597277821.502 [ESPComponent](INFO): closing pipe.
2020-08-13T00:17:01.897Z,1597277821.897 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_STOPPED
2020-08-13T00:17:11.899Z,1597277831.899 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence completed normally.
2020-08-13T00:17:11.900Z,1597277831.900 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP
2020-08-13T00:17:11.900Z,1597277831.900 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper
2020-08-13T00:17:11.900Z,1597277831.900 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth
2020-08-13T00:17:12.299Z,1597277832.299 [ESPComponent](IMPORTANT): [sample #2] ESP log summary report (2 messages):
@17:11:36.97 Selecting Cartridge 55
@17:12:58.37 Sampled  10.0ml

2020-08-13T00:17:12.299Z,1597277832.299 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_
2020-08-13T00:17:12.300Z,1597277832.300 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample
2020-08-13T00:17:12.300Z,1597277832.300 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater
2020-08-13T00:17:12.300Z,1597277832.300 [sample](INFO): Completed sample
2020-08-13T00:17:12.300Z,1597277832.300 [MissionManager](INFO): sample is completed.
2020-08-13T00:17:12.300Z,1597277832.300 [MissionManager](INFO): Uninitializing Mission sample
2020-08-13T00:17:12.300Z,1597277832.300 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2020-08-13T00:17:12.700Z,1597277832.700 [MissionManager](IMPORTANT): Started mission Default
2020-08-13T00:17:12.700Z,1597277832.700 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-08-13T00:17:25.902Z,1597277845.902 [Default:A.Wait](INFO): Done Waiting.
tethyscode>quick on
2020-08-13T00:17:29.514Z,1597277849.514 [CommandLine](IMPORTANT): got command quick on
2020-08-13T00:17:29.514Z,1597277849.514 [CommandLine](IMPORTANT): Quicker than real-time state is on
2020-08-13T00:17:31.103Z,1597277851.103 [NAL9602](INFO): GPS fix at 20200813T001731: (36.803540, -121.822477)
2020-08-13T00:17:32.303Z,1597277852.303 [NAL9602](INFO): No messages in MT queue
2020-08-13T00:17:35.039Z,1597277855.039 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20200812T235145/Courier0004.lzma
2020-08-13T00:17:36.039Z,1597277856.039 [DataOverHttps](INFO): Moved sent file to Logs/20200812T235145/Courier0004.lzma.bak
2020-08-13T00:17:36.039Z,1597277856.039 [DataOverHttps](INFO): SBD MOMSN=12551544
2020-08-13T00:17:45.040Z,1597277865.040 [DataOverHttps](INFO): Sending 1376 bytes from file Logs/20200812T235145/Express0005.lzma
2020-08-13T00:17:46.040Z,1597277866.040 [DataOverHttps](INFO): Moved sent file to Logs/20200812T235145/Express0005.lzma.bak
2020-08-13T00:17:46.040Z,1597277866.040 [DataOverHttps](INFO): SBD MOMSN=12551547
2020-08-13T00:18:02.710Z,1597277882.710 [NAL9602](INFO): Not Powering down - fast GPS
tethyscode>exit

Note: quick on issued above after to completion of the mission just to quickly make the vehicle send all data/events to the dash.

Captured ESP.log on vehicle side (tethyscode)

Below are the contents of the ESP.log file as captured by the LRAUV.

Note, it shows all ESP streams due to local config having ESPComponent.debug = 1 bool:

tethysadmin@tethyscode: lrauv-application-carlos$ cat Logs/latest/ESP.log
##-- file opened 2020-08-12T23:56:03.206Z
<unknown> LRAUV
<unknown> \200
 <prompt> \200
 <prompt> \204
    <log> @16:56:04.40 -> showStatus
    <log> \201
 <result> true\200
 <prompt> \204
    <log> @16:56:06.00 -> Cmd.loadCartridge -4
    <log> \207
 <status> STOPPED-->IDLE
 <status> \204
    <log> @16:56:06.01 Gate.power :main,:ON
    <log> Gate.power :analytic1,:ON
    <log> Gate.power :analytic2,:ON
    <log> Gate.power :analytic3,:ON
    <log> Gate.power :core,:ON
    <log> @16:56:06.03 Archive.configure :default
    <log> Air.configure :default
    <log> @16:56:06.04 Lysis1.configure :default
    <log> @16:56:06.05 Lysis2.configure :default
    <log> @16:56:06.06 Plunge.configure :default
    <log> @16:56:06.07 SamplePump.configure :default
    <log> ExtraPump.configure :default
    <log> @16:56:06.08 Toroid.configure :default
    <log> @16:56:06.09 Carousel.configure :default
    <log> Pressure.configure :default
    <log> @16:56:06.10 PinPort.configure :default
    <log> All elf controllers running firmware version 4.99
    <log> Gate.power :motor,:ON
    <log> @16:56:06.11 <Archive_home> Archive.reconfigure :default
    <log> @16:56:06.12 Archive.home.jog 0
    <log> <Air_home> Air.reconfigure :default
    <log> @16:56:06.13 Air.home.jog 0
    <log> @16:56:06.14 <Lysis1_home> Lysis1.reconfigure :default
    <log> <Lysis2_home> Lysis2.reconfigure :default
    <log> <Lysis1_home> Lysis1.home.jog 0
    <log> <Plunge_home> Plunge.reconfigure :default
    <log> @16:56:06.15 <Lysis2_home> Lysis2.home.jog 0
    <log> <PinPort_home> PinPort.reconfigure :default
    <log> <Plunge_home> Plunge.home.jog 0
    <log> @16:56:06.16 <Toroid_home> Toroid.reconfigure :default
    <log> <PinPort_home> PinPort.home.jog 0
    <log> <Toroid_home> Toroid.home.jog 0
    <log> @16:56:06.20 <Archive_home> Archive.setRawPosition! 50
    <log> Archive.reconfigure :homing
    <log> @16:56:06.21 Archive.seek :home
    <log> @16:56:06.22 <Air_home> Air.setRawPosition! 50
    <log> Air.reconfigure :homing
    <log> Air.seek :home
    <log> @16:56:06.23 <Plunge_home> Plunge.setRawPosition! 50
    <log> Plunge.reconfigure :homing
    <log> Plunge.seek :home
    <log> @16:56:06.24 <PinPort_home> PinPort.setRawPosition! 0
    <log> @16:56:06.25 PinPort.reconfigure :homing
    <log> PinPort.seek :home
    <log> @16:56:06.26 <Lysis1_home> Lysis1.setRawPosition! 50
    <log> Lysis1.reconfigure :homing
    <log> Lysis1.seek :home
    <log> @16:56:06.27 <Lysis2_home> Lysis2.setRawPosition! 50
    <log> Lysis2.reconfigure :homing
    <log> @16:56:06.28 Lysis2.seek :home
    <log> @16:56:06.29 <Toroid_home> Toroid.setRawPosition! 0
    <log> Toroid.reconfigure :homing
    <log> Toroid.seek :home
    <log> @16:56:06.32 <PinPort_home> PinPort.reconfigure :default
    <log> @16:56:06.36 <Toroid_home> Toroid.reconfigure :default
    <log> @16:56:06.48 <Archive_home> Archive.reconfigure :default
    <log> @16:56:06.50 <Air_home> Air.reconfigure :default
    <log> @16:56:06.51 <Plunge_home> Plunge.reconfigure :default
    <log> @16:56:06.54 <Lysis1_home> Lysis1.reconfigure :default
    <log> @16:56:06.55 <Lysis2_home> Lysis2.reconfigure :default
    <log> @16:56:06.81 <LRAUV> Toroid.seek :clear
    <log> @16:56:08.43 Carousel.reconfigure :default
    <log> Carousel.home.jog 0
    <log> @16:56:08.50 Carousel.setRawPosition! -53
    <log> @16:56:08.51 Carousel.reconfigure :homing
    <log> Carousel.seek :home
    <log> @16:56:08.81 Carousel.reconfigure :default
    <log> @16:56:09.07 Carousel.seek 1
    <log> \207
 <status> IDLE-->LOADING
 <status> LOADING-->LOADING@56,archiveHiBiomass_bac
 <status> \204
    <log> @16:56:09.14 Selecting Cartridge 56
    <log> @16:56:09.15 Carousel.seek 56
    <log> @16:56:20.59 Gate.power :heat,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @16:56:20.60 Lysis1.seek :locked
    <log> @16:56:24.67 <Plunge> Plunge.seek :locked
    <log> <Air> Air.seek :locked
    <log> @16:56:28.74 <LRAUV> Gate.power :cartridge,:ON
    <log> Gate.power :cartridge,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @16:56:29.25 Mounted archive Cartridge
    <log> \207
 <status> LOADING-->READY@56,archiveHiBiomass_bac
 <status> \201
 <result> 56\200
 <prompt> \204
    <log> @16:56:42.81 -> Cmd.startFiltering
    <log> \207
 <status> READY-->PRIMING@5.0
 <status> \201
 <result> :FILTERING\200
 <prompt> \204
    <log> @16:56:42.82 <FILTERING> Duration of filtering limited to 2:05:00
    <log> @16:56:42.83 Priming sample loop w/5ml, bypass w/1.5ml
    <log> SamplePump.setPosition! 0ml
    <log> Bypass.open
    <log> @16:56:43.54 Intake.open
    <log> @16:56:45.04 Sea 5.7m deep (23.1psia)
    <log> Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
    <log> @16:56:47.56 Vacuum tare is 10% of full scale
    <log> Pressure.reconfigure :default
    <log> Pressure.hold
    <log> @16:56:47.64 SamplePump.reconfigure :prime
    <log> SamplePump.seek 1.5ml,38 seconds
    <log> @16:56:49.41 Pressure.coast
    <log> SamplePump.setPosition! 0ml
    <log> Exhaust.open
    <log> @16:56:51.61 <closeBypass> Bypass.close
    <log> @16:56:53.82 <FILTERING> Pressure.hold
    <log> @16:56:53.89 Sea 5.7m deep (23.1psia)
    <log> SamplePump.reconfigure :prime
    <log> SamplePump.seek 5ml,56 seconds
    <log> @16:56:58.63 Pressure.coast
    <log> Bypass.open
    <log> @16:57:00.13 Intake.close
    <log> @16:57:01.63 Toroid.reconfigure :hold
    <log> Toroid.seek :crack
    <log> @16:57:02.43 Toroid.reconfigure :default
    <log> Toroid.seek :clear
    <log> @16:57:03.93 Toroid.reconfigure :hold
    <log> Toroid.seek :cartridge
    <log> @16:57:05.75 Toroid.reconfigure :default
    <log> Toroid.seek :clear
    <log> @16:57:07.57 Pressurizing cartridge to 26psi above 23.1psia
    <log> SamplePump.setPosition! 0ml
    <log> Intake.open
    <log> @16:57:09.06 Bypass.close
    <log> @16:57:10.60 Exhaust.close
    <log> @16:57:12.07 Pressure.hold
    <log> @16:57:12.14 SamplePump.reconfigure :charge
    <log> SamplePump.seek 0.2ml,32 seconds
    <log> @16:57:12.75 Pressure.coast
    <log> Sampling 10.0ml
    <log> SamplePump.setPosition! 0ml
    <log> Exhaust.open
    <log> \207
 <status> PRIMING-->FILTERING@0.0
 <status> \204
    <log> @16:57:14.25 Pressure.hold
    <log> @16:57:14.32 Sea 5.7m deep (23.1psia)
    <log> @16:57:14.33 SamplePump.reconfigure :sample
    <log> SamplePump.seek 10ml,1:21
    <log> @16:57:17.25 <sampling> Cartridge 56 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)
    <log> @16:57:27.29 <FILTERING> Pressure.coast
    <log> @16:57:27.30 <closeIntake> Intake.close
    <log> <closeExhaust> Exhaust.close
    <log> @16:57:27.31 <FILTERING> Toroid.reconfigure :hold
    <log> Toroid.seek :bypass
    <log> @16:57:28.92 Toroid.reconfigure :default
    <log> @16:57:28.93 Toroid.seek :clear
    <log> @16:57:30.54 Sampled  10.0ml
    <log> \207
 <status> FILTERING-->PAUSED@10.0
 <status> \204
    <log> @16:57:32.02 <LRAUV> -> Cmd.startProcessing
    <log> \207
 <status> PAUSED-->PROCESSING@56,archiveHiBiomass_bac
 <status> \201
 <result> :PROCESSING\200
 <prompt> \204
    <log> @16:57:32.03 <PROCESSING> Plunge.seek :reagent
    <log> @16:57:32.87 Sample loop closed. Ready to Deliver Reagents
    <log> Archive.seek :sealed
    <log> @16:57:37.14 Archive.seek :evac
    <log> @16:57:51.12 delay 1:00
    <log> @16:58:51.13 Archive.seek :clear
    <log> @16:59:08.89 RNAlater soak for 45 seconds
    <log> @16:59:53.90 Archive.seek :tVent
    <log> @16:59:56.48 delay 1 second
    <log> @16:59:57.48 Archive.seek :evac
    <log> @17:00:13.14 delay 10 seconds
    <log> @17:00:23.15 Archive.seek :tVent
    <log> @17:00:38.82 delay 1 second
    <log> @17:00:39.82 Archive.seek :evac
    <log> @17:00:55.49 delay 10 seconds
    <log> @17:01:05.50 Sample preserved and evacuated
    <log> \207
 <status> PROCESSING-->PROCESSED@56,archiveHiBiomass_bac
 <status> \204
    <log> @17:01:06.47 <LRAUV> -> Cmd.stop
    <log> Gate.power :heat,:OFF
    <log> @17:01:06.48 Gate.power :cartridge,:OFF
    <log> Carousel.seek 56
    <log> @17:01:06.55 Plunge.seek :locked
    <log> @17:01:07.39 PinPort.seek :clear
    <log> @17:01:07.46 <Archive> Archive.seek :clear
    <log> <Air> Air.seek :clear
    <log> @17:01:07.48 <Lysis1> Lysis1.seek :clear
    <log> @17:01:25.23 <LRAUV> Archive.coast
    <log> Air.coast
    <log> Lysis1.coast
    <log> Lysis2.coast
    <log> @17:01:25.24 Plunge.coast
    <log> SamplePump.coast
    <log> Toroid.coast
    <log> Carousel.coast
    <log> PinPort.coast
    <log> @17:01:25.26 Gate.power :heat,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @17:01:25.31 Gate.power :motor,:OFF
    <log> Gate.power :core,:OFF
    <log> Gate.power :analytic1,:OFF
    <log> @17:01:25.32 Gate.power :analytic2,:OFF
    <log> Gate.power :analytic3,:OFF
    <log> Gate.power :main,:OFF
    <log> Safely stopped and ready to power off
    <log> \207
 <status> PROCESSED-->STOPPED
 <status> \201
 <result> :STOPPED\200
 <prompt> 7777
##-- file closed 2020-08-13T00:11:31.027Z

##-- file opened 2020-08-13T00:11:31.028Z
 <prompt> LRAUV
 <prompt> \200
 <prompt> \200
 <prompt> \204
    <log> @17:11:31.82 -> showStatus
    <log> \201
 <result> true\200
 <prompt> \204
    <log> @17:11:33.82 -> Cmd.loadCartridge -4
    <log> \207
 <status> STOPPED-->IDLE
 <status> \204
    <log> @17:11:33.83 Gate.power :main,:ON
    <log> Gate.power :analytic1,:ON
    <log> Gate.power :analytic2,:ON
    <log> Gate.power :analytic3,:ON
    <log> @17:11:33.84 Gate.power :core,:ON
    <log> @17:11:33.85 Archive.configure :default
    <log> Air.configure :default
    <log> @17:11:33.86 Lysis1.configure :default
    <log> @17:11:33.87 Lysis2.configure :default
    <log> @17:11:33.88 Plunge.configure :default
    <log> @17:11:33.89 SamplePump.configure :default
    <log> ExtraPump.configure :default
    <log> @17:11:33.90 Toroid.configure :default
    <log> @17:11:33.91 Carousel.configure :default
    <log> @17:11:33.92 Pressure.configure :default
    <log> @17:11:33.93 PinPort.configure :default
    <log> All elf controllers running firmware version 4.99
    <log> Gate.power :motor,:ON
    <log> @17:11:33.94 <Archive_home> Archive.reconfigure :default
    <log> @17:11:33.95 Archive.home.jog 0
    <log> <Air_home> Air.reconfigure :default
    <log> @17:11:33.96 Air.home.jog 0
    <log> <Lysis1_home> Lysis1.reconfigure :default
    <log> @17:11:33.97 <Lysis2_home> Lysis2.reconfigure :default
    <log> <Lysis1_home> Lysis1.home.jog 0
    <log> <Plunge_home> Plunge.reconfigure :default
    <log> @17:11:33.98 <Lysis2_home> Lysis2.home.jog 0
    <log> <Plunge_home> Plunge.home.jog 0
    <log> <PinPort_home> PinPort.reconfigure :default
    <log> @17:11:33.99 <Toroid_home> Toroid.reconfigure :default
    <log> <PinPort_home> PinPort.home.jog 0
    <log> <Toroid_home> Toroid.home.jog 0
    <log> @17:11:34.03 <Archive_home> Archive.setRawPosition! 50
    <log> Archive.reconfigure :homing
    <log> @17:11:34.04 Archive.seek :home
    <log> @17:11:34.05 <Air_home> Air.setRawPosition! 50
    <log> Air.reconfigure :homing
    <log> Air.seek :home
    <log> @17:11:34.06 <Plunge_home> Plunge.setRawPosition! 50
    <log> Plunge.reconfigure :homing
    <log> Plunge.seek :home
    <log> @17:11:34.07 <PinPort_home> PinPort.setRawPosition! 0
    <log> @17:11:34.08 PinPort.reconfigure :homing
    <log> PinPort.seek :home
    <log> @17:11:34.09 <Lysis1_home> Lysis1.setRawPosition! 50
    <log> Lysis1.reconfigure :homing
    <log> Lysis1.seek :home
    <log> @17:11:34.11 <Lysis2_home> Lysis2.setRawPosition! 50
    <log> Lysis2.reconfigure :homing
    <log> Lysis2.seek :home
    <log> @17:11:34.12 <Toroid_home> Toroid.setRawPosition! 0
    <log> Toroid.reconfigure :homing
    <log> Toroid.seek :home
    <log> @17:11:34.15 <PinPort_home> PinPort.reconfigure :default
    <log> @17:11:34.20 <Toroid_home> Toroid.reconfigure :default
    <log> @17:11:34.31 <Archive_home> Archive.reconfigure :default
    <log> @17:11:34.33 <Air_home> Air.reconfigure :default
    <log> @17:11:34.34 <Plunge_home> Plunge.reconfigure :default
    <log> @17:11:34.37 <Lysis1_home> Lysis1.reconfigure :default
    <log> @17:11:34.39 <Lysis2_home> Lysis2.reconfigure :default
    <log> @17:11:34.64 <LRAUV> Toroid.seek :clear
    <log> @17:11:36.26 Carousel.reconfigure :default
    <log> Carousel.home.jog 0
    <log> @17:11:36.33 Carousel.setRawPosition! -53
    <log> Carousel.reconfigure :homing
    <log> @17:11:36.34 Carousel.seek :home
    <log> @17:11:36.64 Carousel.reconfigure :default
    <log> @17:11:36.89 Carousel.seek 1
    <log> \207
 <status> IDLE-->LOADING
 <status> LOADING-->LOADING@55,archiveHiBiomass_bac
 <status> \204
    <log> @17:11:36.97 Selecting Cartridge 55
    <log> @17:11:36.98 Carousel.seek 55
    <log> @17:11:48.21 Gate.power :heat,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @17:11:48.22 Lysis1.seek :locked
    <log> @17:11:52.29 <Plunge> Plunge.seek :locked
    <log> <Air> Air.seek :locked
    <log> @17:11:56.36 <LRAUV> Gate.power :cartridge,:ON
    <log> Gate.power :cartridge,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @17:11:56.86 Mounted archive Cartridge
    <log> \207
 <status> LOADING-->READY@55,archiveHiBiomass_bac
 <status> \201
 <result> 55\200
 <prompt> \204
    <log> @17:12:10.63 -> Cmd.startFiltering
    <log> \207
 <status> READY-->PRIMING@5.0
 <status> \201
 <result> :FILTERING\200
 <prompt> \204
    <log> @17:12:10.64 <FILTERING> Duration of filtering limited to 2:05:00
    <log> @17:12:10.65 Priming sample loop w/5ml, bypass w/1.5ml
    <log> SamplePump.setPosition! 0ml
    <log> Bypass.open
    <log> @17:12:11.36 Intake.open
    <log> @17:12:12.86 Sea 5.7m deep (23.1psia)
    <log> Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi
    <log> @17:12:15.38 Vacuum tare is 10% of full scale
    <log> @17:12:15.39 Pressure.reconfigure :default
    <log> Pressure.hold
    <log> @17:12:15.46 SamplePump.reconfigure :prime
    <log> SamplePump.seek 1.5ml,38 seconds
    <log> @17:12:17.23 Pressure.coast
    <log> SamplePump.setPosition! 0ml
    <log> @17:12:17.24 Exhaust.open
    <log> @17:12:19.43 <closeBypass> Bypass.close
    <log> @17:12:21.64 <FILTERING> Pressure.hold
    <log> @17:12:21.71 Sea 5.7m deep (23.1psia)
    <log> @17:12:21.72 SamplePump.reconfigure :prime
    <log> SamplePump.seek 5ml,56 seconds
    <log> @17:12:26.45 Pressure.coast
    <log> Bypass.open
    <log> @17:12:27.95 Intake.close
    <log> @17:12:29.45 Toroid.reconfigure :hold
    <log> Toroid.seek :crack
    <log> @17:12:30.25 Toroid.reconfigure :default
    <log> Toroid.seek :clear
    <log> @17:12:31.76 Toroid.reconfigure :hold
    <log> Toroid.seek :cartridge
    <log> @17:12:33.57 Toroid.reconfigure :default
    <log> Toroid.seek :clear
    <log> @17:12:35.39 Pressurizing cartridge to 26psi above 23.1psia
    <log> SamplePump.setPosition! 0ml
    <log> @17:12:35.40 Intake.open
    <log> @17:12:36.89 Bypass.close
    <log> @17:12:38.39 Exhaust.close
    <log> @17:12:39.89 Pressure.hold
    <log> @17:12:39.97 SamplePump.reconfigure :charge
    <log> SamplePump.seek 0.2ml,32 seconds
    <log> @17:12:40.57 Pressure.coast
    <log> @17:12:40.58 Sampling 10.0ml
    <log> SamplePump.setPosition! 0ml
    <log> Exhaust.open
    <log> \207
 <status> PRIMING-->FILTERING@0.0
 <status> \204
    <log> @17:12:42.08 Pressure.hold
    <log> @17:12:42.15 Sea 5.7m deep (23.1psia)
    <log> SamplePump.reconfigure :sample
    <log> @17:12:42.16 SamplePump.seek 10ml,1:21
    <log> @17:12:45.08 <sampling> Cartridge 55 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)
    <log> @17:12:55.12 <FILTERING> Pressure.coast
    <log> <closeIntake> Intake.close
    <log> @17:12:55.13 <closeExhaust> Exhaust.close
    <log> <FILTERING> Toroid.reconfigure :hold
    <log> Toroid.seek :bypass
    <log> @17:12:56.75 Toroid.reconfigure :default
    <log> Toroid.seek :clear
    <log> @17:12:58.37 Sampled  10.0ml
    <log> \207
 <status> FILTERING-->PAUSED@10.0
 <status> \204
    <log> @17:12:59.84 <LRAUV> -> Cmd.startProcessing
    <log> \207
 <status> PAUSED-->PROCESSING@55,archiveHiBiomass_bac
 <status> \201
 <result> :PROCESSING\200
 <prompt> \204
    <log> @17:12:59.86 <PROCESSING> Plunge.seek :reagent
    <log> @17:13:00.69 Sample loop closed. Ready to Deliver Reagents
    <log> Archive.seek :sealed
    <log> @17:13:04.96 Archive.seek :evac
    <log> @17:13:18.94 delay 1:00
    <log> @17:14:18.95 Archive.seek :clear
    <log> @17:14:36.72 RNAlater soak for 45 seconds
    <log> @17:15:21.72 Archive.seek :tVent
    <log> @17:15:24.30 delay 1 second
    <log> @17:15:25.31 Archive.seek :evac
    <log> @17:15:40.97 delay 10 seconds
    <log> @17:15:50.98 Archive.seek :tVent
    <log> @17:16:06.65 delay 1 second
    <log> @17:16:07.65 Archive.seek :evac
    <log> @17:16:23.32 delay 10 seconds
    <log> @17:16:33.33 Sample preserved and evacuated
    <log> \207
 <status> PROCESSING-->PROCESSED@55,archiveHiBiomass_bac
 <status> \204
    <log> @17:16:34.29 <LRAUV> -> Cmd.stop
    <log> Gate.power :heat,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @17:16:34.30 Carousel.seek 55
    <log> @17:16:34.38 Plunge.seek :locked
    <log> @17:16:35.21 PinPort.seek :clear
    <log> @17:16:35.29 <Archive> Archive.seek :clear
    <log> <Air> Air.seek :clear
    <log> @17:16:35.31 <Lysis1> Lysis1.seek :clear
    <log> @17:16:53.06 <LRAUV> Archive.coast
    <log> Air.coast
    <log> Lysis1.coast
    <log> Lysis2.coast
    <log> Plunge.coast
    <log> SamplePump.coast
    <log> @17:16:53.07 Toroid.coast
    <log> Carousel.coast
    <log> PinPort.coast
    <log> @17:16:53.09 Gate.power :heat,:OFF
    <log> Gate.power :cartridge,:OFF
    <log> @17:16:53.14 Gate.power :motor,:OFF
    <log> Gate.power :core,:OFF
    <log> Gate.power :analytic1,:OFF
    <log> Gate.power :analytic2,:OFF
    <log> @17:16:53.15 Gate.power :analytic3,:OFF
    <log> Gate.power :main,:OFF
    <log> Safely stopped and ready to power off
    <log> \207
 <status> PROCESSED-->STOPPED
 <status> \201
 <result> :STOPPED\200
##-- file closed 2020-08-13T00:18:11.525Z

Comments (0)

HTTPS SSH

You can clone a snippet to your computer for local editing. Learn more.