Updated by Carlos Rueda 2019-05-06

File snippet.markdown Modified

 ### ESP simulator with available "dry" cartridges.

+#### Variations

+Due to differences across branches, some misc notes from emails, etc.:

+> Pull the latest code and set up as follows:

+>

+>       -> Cartridge.load!  All=>:dry; Cartridge.identify; Cartridge.dry :archive

+>

+> Cartridge.identify tests all loaded cartridges and changes their type from :generic to :lysis or :archive.

+> The result is a list of all the dry archive cartridges.

+>

+> Once all the cartridges' types are known, you make simply:

+>

+>       ->  Cmd.loadCartridge   :archive

+>

+> to process the next dry archive cartridge.

+>

+> The way we worked out last week relied on the fact that the simulator currently assumes all odd numbered slots contain an archive cartridge.  This method works regardless of how the simulator allocates cartridge types.

+>

+> But, it does rely on features in the trackSlots branch.

+>

+> For the newCfg branch:

+>

+>            -> Cmd.load! All.select{|slotNum|slotNum.odd?}=>:dry

+>

+> This loads only the archive (odd numbered) cartridges such that,

+> Note that this will also work with the trackSlots branch, but you need to use:

+>

+>        -> Cartridge.load! All.select{|slotNum|slotNum.odd?}=>:dry

+>

+> - brent

 For example (as used in this test), with all odd numbered cartridges set to `:archive`:

```

Updated by Carlos Rueda 2019-05-01

View revision

File snippet.markdown Modified

```

 carueda@bufflehead:~/esp2$ esp

...

-@10:16:36.71 <simreal> -> -> Cartridge.load! All.select{|x| x.odd?} => :archive

+ESPhonu:001:0-> Cartridge.load! All.select{|x| x.odd?} => :archive

```

-**NOTE** that every even numbered cartridge in simulation is processed as a Lyse-n-go, which take longer.

-That's why we focus on the :archive type as set above.

+>... every even numbered cartridge in simulation is processed as a Lyse-n-go, which take longer.

+That's why we prefer the **:archive** type as set above.

 ### Exit the ESP simulator for what follows

 ### Optional: Tweaks in LRAUV code to expedite the tests

-- `vi Source/scienceModule/ESPClient.cpp` to use, in method `ESPClient::advanceInteraction()`:

+`vi Source/scienceModule/ESPClient.cpp` to use, in method `ESPClient::advanceInteraction()`:

-    ```

-    issueCommand( "Cmd.startProcessing 10", processResultTimeout_, processCompleteTimeout_ );

-    ```

+```

+issueCommand( "Cmd.startProcessing 10", processResultTimeout_, processCompleteTimeout_ );

+```

-    instead of

+instead of

-    ```

-    issueCommand( "Cmd.startProcessing", processResultTimeout_, processCompleteTimeout_ );

-    ```

+```

+issueCommand( "Cmd.startProcessing", processResultTimeout_, processCompleteTimeout_ );

+```

-- Re-build LRAUV if any changes done above: `make`

+Re-build LRAUV if any changes done above: `make`

 # Running the mission:

 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:

```

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

+[carueda@tethyssim lrauv-application]$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x \

+   "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;run"

```

 Wait until **`[ESPComponent](IMPORTANT): Waiting for ESP to connect`** shows up on the output:

Updated by Carlos Rueda 2019-04-30

View revision

File snippet.markdown Modified

 ## On bufflehead

-Using latest [master branch](https://github.com/MBARI-ESP/ESP2Gscript) of the ESP software (commit 0505a24c6ef / Tue Jan 8 19:19:31 2019 -0800 to be more specific).

+Using [trackSlots branch](https://github.com/MBARI-ESP/ESP2Gscript/tree/trackSlots) of the ESP software (commit cf51a340f91 / Tue Apr 30 10:07:49 2019 -0700).

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

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

```

    $ cd esp2

    $ ESPmode=simreal

```

-### Optional: Tweak in ESP code to expedite the tests

+### Tweak in ESP code to expedite the tests

-Edit type/auv/initialize.rb to set `rapid = true`

+If not already `true`, edit `type/auv/initialize.rb` to set `rapid = true`.

->The "right" way to do all \["trick" to make the processing also run quicker for testing purposes\] this is to set the `rapid` flag in the file

->

->auv/initialize.rb

->

 >I've checked in a version that also reduced the processing time from 10:00 to 45 seconds when rapid = true

-### Optional: Tweak to simulate an error while processing

+### Optional: Tweak in ESP to simulate an error while processing

 (NOTE: not exercised for a long while -- may need adjustment.)

-### Make sure the ESP simulator has enough "dry" cartridges.

+### ESP simulator with available "dry" cartridges.

-For this you can simply run `Cmd.slot All=>:dry`:

+For example (as used in this test), with all odd numbered cartridges set to `:archive`:

```

 carueda@bufflehead:~/esp2$ esp

...

-@10:16:36.71 <simreal> -> Cmd.slot All=>:dry

+@10:16:36.71 <simreal> -> -> Cartridge.load! All.select{|x| x.odd?} => :archive

```

-### Lyse-n-go take longer

->Every even numbered cartridge in simulation is processed as a Lyse-n-go.

->These take longer.

->

->If you want to avoid the Lyse-n-gos, just set only odd numbered slots to :dry

->

-> ->  Cmd.load! ((1..SCslots/2).map{|c| 2*c-1}=>:dry)

+**NOTE** that every even numbered cartridge in simulation is processed as a Lyse-n-go, which take longer.

+That's why we focus on the :archive type as set above.

 ### Exit the ESP simulator for what follows

 ## On tethyssim

-Note the `ESPCOMPONENT_MANUAL_ESP` environment variable:

+Make sure `SimDaemon` is running; if not:

+```

+[carueda@tethyssim lrauv-application]$ bin/SimDaemon

+```

+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:

```

-[carueda@tethyssim lrauv-application]$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;set sample:SampleAtDepth.SettleTime 3 second;run"

+[carueda@tethyssim lrauv-application]$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;run"

```

 Wait until **`[ESPComponent](IMPORTANT): Waiting for ESP to connect`** shows up on the output:

```

...

-tethyssim>load Maintenance/2019-01-09T16:00:36.603Z,1547049636.603 [SyncHandler](INFO): Protected caller Thread ID is 105253

-2019-01-09T16:00:36.603Z,1547049636.603 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 105254

-2019-01-09T16:00:36.603Z,1547049636.603 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 105255

-2019-01-09T16:00:36.603Z,1547049636.603 [logger ThreadHandler](INFO): Protected caller Thread ID is 105256

-2019-01-09T16:00:36.603Z,1547049636.603 [Supervisor](INFO): Looking for Config files in directory: Config/

-2019-01-09T16:00:36.603Z,1547049636.603 [Supervisor](INFO): Opening Config file at: Config/secure.cfg

-2019-01-09T16:00:36.608Z,1547049636.608 [Supervisor](INFO): Opening Config file at: Config/Science.cfg

-2019-01-09T16:00:36.619Z,1547049636.619 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg

-2019-01-09T16:00:36.625Z,1547049636.625 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg

-2019-01-09T16:00:36.631Z,1547049636.631 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg

-2019-01-09T16:00:36.636Z,1547049636.636 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg

-2019-01-09T16:00:36.639Z,1547049636.639 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg

-2019-01-09T16:00:36.644Z,1547049636.644 [Supervisor](INFO): Opening Config file at: Config/Control.cfg

-t2019-01-09T16:00:36.648Z,1547049636.648 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg

-2019-01-09T16:00:36.651Z,1547049636.651 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg

-2019-01-09T16:00:36.654Z,1547049636.654 [Supervisor](INFO): Opening Config file at: Config/logger.cfg

-2019-01-09T16:00:36.657Z,1547049636.657 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg

-2019-01-09T16:00:36.660Z,1547049636.660 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg

-2019-01-09T16:00:36.664Z,1547049636.664 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg

-2019-01-09T16:00:36.669Z,1547049636.669 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg

-2019-01-09T16:00:36.673Z,1547049636.673 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/

-2019-01-09T16:00:36.673Z,1547049636.673 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Science.cfg

-2019-01-09T16:00:36.676Z,1547049636.676 [Supervisor](INFO): Opening Config file at: Config/tethyssim/vehicle.cfg

-2019-01-09T16:00:36.679Z,1547049636.679 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Navigation.cfg

-2019-01-09T16:00:36.681Z,1547049636.681 [Supervisor](INFO): Opening Config file at: Config/tethyssim/workSite.cfg

-2019-01-09T16:00:36.684Z,1547049636.684 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Estimation.cfg

-2019-01-09T16:00:36.686Z,1547049636.686 [Supervisor](INFO): Opening Config file at: Config/tethyssim/BIT.cfg

-2019-01-09T16:00:36.689Z,1547049636.689 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Sensor.cfg

-2019-01-09T16:00:36.692Z,1547049636.692 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Derivation.cfg

-2019-01-09T16:00:36.694Z,1547049636.694 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/carueda/

-2019-01-09T16:00:36.694Z,1547049636.694 [Supervisor](INFO): Looking for Config files in directory: Config/sim/

-2019-01-09T16:00:36.694Z,1547049636.694 [Supervisor](INFO): Opening Config file at: Config/sim/secure.cfg

-2019-01-09T16:00:36.697Z,1547049636.697 [Supervisor](INFO): Opening Config file at: Config/sim/Science.cfg

-2019-01-09T16:00:36.699Z,1547049636.699 [Supervisor](INFO): Opening Config file at: Config/sim/Simulator.cfg

-2019-01-09T16:00:36.701Z,1547049636.701 [Supervisor](INFO): Opening Config file at: Config/sim/vehicle.cfg

-2019-01-09T16:00:36.704Z,1547049636.704 [Supervisor](INFO): Opening Config file at: Config/sim/Servo.cfg

-2019-01-09T16:00:36.706Z,1547049636.706 [Supervisor](INFO): Opening Config file at: Config/sim/Sensor.cfg

-2019-01-09T16:00:36.708Z,1547049636.708 [Supervisor](INFO): Opening Config file at: Config/sim/Derivation.cfg

-2019-01-09T16:00:36.711Z,1547049636.711 [Supervisor](INFO): Looking for Config files in directory: Config/sim/carueda/

-2019-01-09T16:00:36.711Z,1547049636.711 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/secure.cfg

-2019-01-09T16:00:36.713Z,1547049636.713 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Science.cfg

-2019-01-09T16:00:36.715Z,1547049636.715 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/vehicle.cfg

-2019-01-09T16:00:36.717Z,1547049636.717 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Sensor.cfg

-2019-01-09T16:00:36.720Z,1547049636.720 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg

-2019-01-09T16:00:36.767Z,1547049636.767 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 105359

-2019-01-09T16:00:36.767Z,1547049636.767 [ESPComponent](ERROR): Could not open device '/dev/loadA6' at ESPComponent.loadControl

-2019-01-09T16:00:36.787Z,1547049636.787 [ESPComponent](ERROR): Could not open device '/dev/loadA7' at ESPComponent.secLoadControl

-2019-01-09T16:00:36.871Z,1547049636.871 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 105360

-2019-01-09T16:00:36.974Z,1547049636.974 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 105361

-2019-01-09T16:00:37.035Z,1547049637.035 [StratificationFrontDetector](IMPORTANT): threshold set to: 0.999994 degC

-2019-01-09T16:00:37.035Z,1547049637.035 [StratificationFrontDetector](INFO): (re)initializing

-2019-01-09T16:00:37.139Z,1547049637.139 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 105362

-2019-01-09T16:00:37.140Z,1547049637.140 [Supervisor](INFO): Main Thread ID is 105252

-2019-01-09T16:00:37.140Z,1547049637.140 [CommandLine ThreadHandler](INFO): Handler Thread ID is 105363

-2019-01-09T16:00:37.141Z,1547049637.141 [controlThread ThreadHandler](INFO): Handler Thread ID is 105364

-2019-01-09T16:00:37.141Z,1547049637.141 [CommandLine ThreadHandler](INFO): Handler Thread ID is 105365

-2019-01-09T16:00:37.141Z,1547049637.141 [logger ThreadHandler](INFO): Handler Thread ID is 105366

-2019-01-09T16:00:37.141Z,1547049637.141 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 105367

-2019-01-09T16:00:37.142Z,1547049637.142 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 105370

-2019-01-09T16:00:37.142Z,1547049637.142 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 105369

-2019-01-09T16:00:37.142Z,1547049637.142 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml

-2019-01-09T16:00:37.142Z,1547049637.142 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 105368

-2019-01-09T16:00:37.143Z,1547049637.143 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000

-2019-01-09T16:00:37.143Z,1547049637.143 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000

-2019-01-09T16:00:37.146Z,1547049637.146 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min

-2019-01-09T16:00:37.146Z,1547049637.146 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m

-2019-01-09T16:00:37.146Z,1547049637.146 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count

-2019-01-09T16:00:37.146Z,1547049637.146 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min

-2019-01-09T16:00:37.147Z,1547049637.147 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min

-2019-01-09T16:00:37.151Z,1547049637.151 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 500.000024 cc

-2019-01-09T16:00:37.155Z,1547049637.155 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml

-2019-01-09T16:00:37.161Z,1547049637.161 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.

-2019-01-09T16:00:37.161Z,1547049637.161 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.

-2019-01-09T16:00:37.161Z,1547049637.161 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.

-2019-01-09T16:00:37.161Z,1547049637.161 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.

-2019-01-09T16:00:37.161Z,1547049637.161 [ExternalSim](INFO): ExternalSim initializing...

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](INFO): Initialize SBIT Component.

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](IMPORTANT): git: 2018-12-19-15-g7172671

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](INFO): git hash: 7172671dc6c80f1439bfdb9114c42bc6796f101e

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](INFO): Kernel Reporting Different Release From Configuration.

-Kernel Expected: 2.6.32-504.3.3.el6.x86_64

-Kernel Reported: 2.6.32-754.3.5.el6.x86_64

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](INFO): Kernel Reporting Different Version From Configuration.

-Kernel Expected: #1 SMP Wed Dec 17 01:55:02 UTC 2014

-Kernel Reported: #1 SMP Tue Aug 14 20:46:41 UTC 2018

-2019-01-09T16:00:37.167Z,1547049637.167 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.

-2019-01-09T16:00:37.167Z,1547049637.167 [IBIT](INFO): Initialize IBIT Component.

-2019-01-09T16:00:37.198Z,1547049637.198 [CBIT](INFO): Last reboot was NOT due to watchdog timer.

-2019-01-09T16:00:37.198Z,1547049637.198 [MissionManager](INFO): Loading Mission: Missions/Startup.xml

-2019-01-09T16:00:37.198Z,1547049637.198 [MissionManager](INFO): Loading Mission: Missions/Default.xml

-2019-01-09T16:00:37.198Z,1547049637.198 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min

-2019-01-09T16:00:37.199Z,1547049637.199 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_

-2019-01-09T16:00:37.200Z,1547049637.200 [DVL_micro](INFO): Initializing

-tethyssim>set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;set sample:SampleAtDepth.SettleTime 3 second;run

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): got command set sample.Depth 1.000000 centimeter

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 1.000000 centimeter

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SettleTime 3.000000 second

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): got command run

-2019-01-09T16:00:37.241Z,1547049637.241 [CommandLine](IMPORTANT): Running

-2019-01-09T16:00:37.000Z,1547049638.000 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.000104

-2019-01-09T16:00:57.612Z,1547049657.612 [SBIT](IMPORTANT): Beginning Startup BIT

-2019-01-09T16:01:11.600Z,1547049671.600 [NAL9602](INFO): GPS fix at 20190109T160111: (36.806004, -121.823007)

-2019-01-09T16:01:12.800Z,1547049672.800 [NAL9602](INFO): No messages in MT queue

-2019-01-09T16:01:43.200Z,1547049703.200 [NAL9602](INFO): Powering down

-2019-01-09T16:01:51.611Z,1547049711.611 [SBIT](IMPORTANT): SBIT PASSED

-tethyssim>configSet list

-2019-01-09T16:01:51.644Z,1547049711.644 [CommandLine](IMPORTANT): got command configSet list

-2019-01-09T16:01:51.644Z,1547049711.644 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg

-2019-01-09T16:01:51.644Z,1547049711.644 [CommandLine](IMPORTANT): No configSet variables persisted

-2019-01-09T16:01:52.001Z,1547049712.001 [MissionManager](IMPORTANT): Started mission Startup

-2019-01-09T16:01:52.001Z,1547049712.001 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.

-2019-01-09T16:01:52.800Z,1547049712.800 [NAL9602](INFO): Powering up

-2019-01-09T16:01:58.000Z,1547049718.000 [NAL9602](INFO): GPS fix at 20190109T160157: (36.806009, -121.823017)

-2019-01-09T16:01:59.200Z,1547049719.200 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190109T041201/Courier0007.lzma

-2019-01-09T16:01:59.200Z,1547049719.200 [NAL9602](INFO): No messages in MT queue

-2019-01-09T16:01:59.600Z,1547049719.600 [DataOverHttps](INFO): Moved sent file to Logs/20190109T041201/Courier0007.lzma.bak

-2019-01-09T16:01:59.600Z,1547049719.600 [DataOverHttps](INFO): SBD MOMSN=9160470

-2019-01-09T16:02:02.800Z,1547049722.800 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20190109T155932/Courier0000.lzma

-2019-01-09T16:02:03.200Z,1547049723.200 [DataOverHttps](INFO): Moved sent file to Logs/20190109T155932/Courier0000.lzma.bak

-2019-01-09T16:02:03.200Z,1547049723.200 [DataOverHttps](INFO): SBD MOMSN=9160472

-2019-01-09T16:02:05.200Z,1547049725.200 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190109T160036/Courier0000.lzma

-2019-01-09T16:02:05.600Z,1547049725.600 [DataOverHttps](INFO): Moved sent file to Logs/20190109T160036/Courier0000.lzma.bak

-2019-01-09T16:02:05.600Z,1547049725.600 [DataOverHttps](INFO): SBD MOMSN=9160476

-2019-01-09T16:02:07.600Z,1547049727.600 [DataOverHttps](INFO): Sending 53 bytes from file Logs/20190109T041201/Express0008.lzma

-2019-01-09T16:02:07.000Z,1547049728.000 [DataOverHttps](INFO): Moved sent file to Logs/20190109T041201/Express0008.lzma.bak

-2019-01-09T16:02:07.000Z,1547049728.000 [DataOverHttps](INFO): SBD MOMSN=9160480

-2019-01-09T16:02:09.000Z,1547049730.000 [DataOverHttps](INFO): Sending 647 bytes from file Logs/20190109T155932/Express0001.lzma

-2019-01-09T16:02:10.400Z,1547049730.400 [DataOverHttps](INFO): Moved sent file to Logs/20190109T155932/Express0001.lzma.bak

-2019-01-09T16:02:10.400Z,1547049730.400 [DataOverHttps](INFO): SBD MOMSN=9160483

-2019-01-09T16:02:12.400Z,1547049732.400 [DataOverHttps](INFO): Sending 726 bytes from file Logs/20190109T160036/Express0001.lzma

-2019-01-09T16:02:12.800Z,1547049732.800 [DataOverHttps](INFO): Moved sent file to Logs/20190109T160036/Express0001.lzma.bak

-2019-01-09T16:02:12.800Z,1547049732.800 [DataOverHttps](INFO): SBD MOMSN=9160504

-2019-01-09T16:02:13.204Z,1547049733.204 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms

-2019-01-09T16:02:13.204Z,1547049733.204 [Startup](INFO): Completed Startup

-2019-01-09T16:02:13.204Z,1547049733.204 [MissionManager](INFO): Startup is completed.

-2019-01-09T16:02:13.204Z,1547049733.204 [MissionManager](INFO): Uninitializing Mission Startup

-2019-01-09T16:02:13.601Z,1547049733.601 [MissionManager](IMPORTANT): Started mission sample

-2019-01-09T16:02:14.401Z,1547049734.401 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.010000 m

-2019-01-09T16:02:30.000Z,1547049750.000 [NAL9602](INFO): Powering down

-2019-01-09T16:04:24.004Z,1547049864.004 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth

-2019-01-09T16:04:24.401Z,1547049864.401 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.012003 m , settling for 0.050000 min

-2019-01-09T16:04:28.001Z,1547049868.001 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.

-2019-01-09T16:04:29.600Z,1547049869.600 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'

-2019-01-09T16:04:29.600Z,1547049869.600 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"

-2019-01-09T16:04:29.000Z,1547049870.000 [ESPComponent](IMPORTANT): powerUpESP IGNORED because manualEsp_

-2019-01-09T16:04:29.000Z,1547049870.000 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)       <<<<<<<<<<<<<  HERE <<<<<<<<<<<<<<

+2019-04-30T23:06:20.192Z,1556665580.192 [MissionManager](IMPORTANT): Started mission sample

+2019-04-30T23:06:20.992Z,1556665580.992 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.010000 m

+2019-04-30T23:08:30.611Z,1556665710.611 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth

+2019-04-30T23:08:31.011Z,1556665711.011 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.011770 m , settling for 0.050000 min

+2019-04-30T23:08:34.612Z,1556665714.612 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.

+2019-04-30T23:08:36.612Z,1556665716.612 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::'

+2019-04-30T23:08:36.612Z,1556665716.612 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Fail|Retry|Cmd::|Sampler::"

+2019-04-30T23:08:37.012Z,1556665717.012 [ESPComponent](IMPORTANT): powerUpESP IGNORED because manualEsp_

+2019-04-30T23:08:37.012Z,1556665717.012 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)       <<<<<<<<<<<<<  HERE <<<<<<<<<<<<<<

```

 ## on bufflehead

-Launch the ESP simulator on the bufflehead session:

+Right away launch the ESP simulator on the bufflehead session:

```

 carueda@bufflehead:~/esp2$ ESPclient=tethyssim:9998 ESPcmdPort=7777 esp

-@08:04:31.71PST09-Jan-19 <simreal> Simulated gateway v3.24 for core bus

-Simulated secondary gateway v3.24 for cartridge bus

-@08:04:31.93

-Configuration for honu by brent@mbari.org

+@16:08:41.45PDT30-Apr-19 <simreal> Simulated gateway v3.24 for core bus

+@16:08:41.46 Simulated secondary gateway v3.24 for cartridge bus

+@16:08:41.53

+Configuration for honu by brent@mbari.org 4/4/19

 /home/carueda/esp2/type/auv/honu/configure.rb

-@08:04:31.97 Cartridge::Sampler::Warning in simreal -- Max sea pressure reduced from 525 to 522psia

-@08:04:32.03 Polling Can every 5:00

-@08:04:32.05 Clients may connect on TCP port 7777

+@16:08:41.60 Polling Can every 5:00

+Clients may connect on TCP port 7777

 Connecting to tethyssim:9998

-@08:04:32.40 <LRAUV> Session Begun

-@08:04:34.79 -> showStatus

-@08:04:36.39 -> Cmd.loadCartridge

-@08:04:36.40 Gate.power :main,:ON

+@16:08:41.78 <LRAUV> Session Begun

+@16:08:44.18 -> showStatus

+@16:08:45.78 -> Cmd.loadCartridge :archive

+Gate.power :main,:ON

 Gate.power :analytic1,:ON

 Gate.power :analytic2,:ON

-Gate.power :analytic3,:ON

+@16:08:45.79 Gate.power :analytic3,:ON

 Gate.power :core,:ON

-ArS.configure ArSconfig

-@08:04:36.41 LyS1.configure LyS1config

-LyS2.configure LyS2config

-AirS.configure AirSconfig

-@08:04:36.42 TV.configure TVconfig

-SP.configure SPconfig

-@08:04:36.43 SC.configure SCconfig

-PV.configure PVconfig

-PinPort.configure PPconfig

-@08:04:36.44 Abs.configure AbsConfig

+@16:08:45.80 Archive.configure :default

+@16:08:45.81 Air.configure :default

+@16:08:45.82 Lysis1.configure :default

+Lysis2.configure :default

+@16:08:45.83 Plunge.configure :default

+@16:08:45.84 SamplePump.configure :default

+@16:08:45.85 ExtraPump.configure :default

+@16:08:45.86 Toroid.configure :default

+Carousel.configure :default

+@16:08:45.87 Pressure.configure :default

+PinPort.configure :default

 All elf controllers running firmware version 4.99

-Gate.power :motor,:ON

-@08:04:36.47 <ArS_home> ArS.reconfigure ArSconfig

-@08:04:36.48 ArS.home.jog 0

-@08:04:36.49 <LyS1_home> LyS1.reconfigure LyS1config

-<LyS2_home> LyS2.reconfigure LyS2config

-<LyS1_home> LyS1.home.jog 0

-<TV_home> TV.reconfigure TVconfig

-@08:04:36.50 <LyS2_home> LyS2.home.jog 0

-<AirS_home> AirS.reconfigure AirSconfig

-<TV_home> TV.home.jog 0

-<PV_home> PV.reconfigure PVconfig

-@08:04:36.51 <AirS_home> AirS.home.jog 0

-<PinPort_home> PinPort.reconfigure PPconfig

-<PV_home> PV.home.jog 0

+@16:08:45.88 Gate.power :motor,:ON

+@16:08:45.89 <Archive_home> Archive.reconfigure :default

+@16:08:45.90 Archive.home.jog 0

+<Air_home> Air.reconfigure :default

+@16:08:45.91 Air.home.jog 0

+<Lysis1_home> Lysis1.reconfigure :default

+<Lysis2_home> Lysis2.reconfigure :default

+@16:08:45.92 <Lysis1_home> Lysis1.home.jog 0

+<Plunge_home> Plunge.reconfigure :default

+<Lysis2_home> Lysis2.home.jog 0

+<PinPort_home> PinPort.reconfigure :default

+@16:08:45.93 <Plunge_home> Plunge.home.jog 0

+<Toroid_home> Toroid.reconfigure :default

 <PinPort_home> PinPort.home.jog 0

-@08:04:36.55 <ArS_home> ArS.setRawPosition! 50

-@08:04:36.56 ArS.reconfigure HomeMagSyringe

-ArS.seek :home

-@08:04:36.57 <LyS2_home> LyS2.setRawPosition! 50

-LyS2.reconfigure HomeSyringe

-@08:04:36.58 LyS2.seek :home

-<TV_home> TV.setRawPosition! 0

-TV.reconfigure HomeTV

-TV.seek :home

-@08:04:36.59 <PV_home> PV.setRawPosition! 50

-PV.reconfigure HomePV

-PV.seek :home

-@08:04:36.60 <PinPort_home> PinPort.setRawPosition! 0

-PinPort.reconfigure HomePP

-PinPort.seek :home

-@08:04:36.61 <LyS1_home> LyS1.setRawPosition! 50

-LyS1.reconfigure HomeSyringe

-LyS1.seek :home

-@08:04:36.62 <AirS_home> AirS.setRawPosition! 50

-AirS.reconfigure HomeMagSyringe

-AirS.seek :home

-@08:04:36.65 <TV_home> TV.reconfigure TVconfig

-@08:04:36.67 <PinPort_home> PinPort.reconfigure PPconfig

-@08:04:36.83 <ArS_home> ArS.reconfigure ArSconfig

-@08:04:36.85 <LyS2_home> LyS2.reconfigure LyS2config

-@08:04:36.87 <PV_home> PV.reconfigure PVconfig

-@08:04:36.89 <LyS1_home> LyS1.reconfigure LyS1config

-@08:04:36.90 <AirS_home> AirS.reconfigure AirSconfig

-@08:04:37.15 <LRAUV> TV.seek :clear

-@08:04:38.77 TV.coast

-SC.reconfigure SCconfig

-SC.home.jog 0

-@08:04:38.84 SC.setRawPosition! -53

-SC.reconfigure HomeSC

-SC.seek :home

-@08:04:39.14 SC.reconfigure SCconfig

-@08:04:39.39 SC.seek 1

-@08:04:39.46 Selecting Cartridge 59

-@08:04:39.47 SC.seek 59

-@08:04:51.53 <LyS2> LyS2.seek :locked

-<PV> PV.seek :locked

-@08:04:51.54 <AirS> AirS.seek :locked

-@08:04:55.61 <LRAUV> Gate.power :cartridge,:ON

+@16:08:45.94 <Toroid_home> Toroid.home.jog 0

+@16:08:45.98 <Archive_home> Archive.setRawPosition! 50

+Archive.reconfigure :homing

+Archive.seek :home

+@16:08:45.99 <Air_home> Air.setRawPosition! 50

+Air.reconfigure :homing

+@16:08:46.00 Air.seek :home

+@16:08:46.01 <Plunge_home> Plunge.setRawPosition! 50

+Plunge.reconfigure :homing

+Plunge.seek :home

+@16:08:46.02 <PinPort_home> PinPort.setRawPosition! 0

+PinPort.reconfigure :homing

+@16:08:46.03 PinPort.seek :home

+<Lysis1_home> Lysis1.setRawPosition! 50

+@16:08:46.04 Lysis1.reconfigure :homing

+Lysis1.seek :home

+@16:08:46.05 <Lysis2_home> Lysis2.setRawPosition! 50

+Lysis2.reconfigure :homing

+@16:08:46.06 Lysis2.seek :home

+@16:08:46.07 <Toroid_home> Toroid.setRawPosition! 0

+Toroid.reconfigure :homing

+Toroid.seek :home

+@16:08:46.10 <PinPort_home> PinPort.reconfigure :default

+@16:08:46.14 <Toroid_home> Toroid.reconfigure :default

+@16:08:46.26 <Archive_home> Archive.reconfigure :default

+@16:08:46.27 <Air_home> Air.reconfigure :default

+@16:08:46.29 <Plunge_home> Plunge.reconfigure :default

+@16:08:46.32 <Lysis1_home> Lysis1.reconfigure :default

+@16:08:46.33 <Lysis2_home> Lysis2.reconfigure :default

+@16:08:46.59 <LRAUV> Toroid.seek :clear

+@16:08:48.20 Carousel.reconfigure :default

+Carousel.home.jog 0

+@16:08:48.28 Carousel.setRawPosition! -53

+Carousel.reconfigure :homing

+Carousel.seek :home

+@16:08:48.58 Carousel.reconfigure :default

+@16:08:48.84 Carousel.seek 1

+@16:08:48.91 Selecting Cartridge 59

+@16:08:48.92 Carousel.seek 59

+@16:09:00.98 <Lysis2> Lysis2.seek :locked

+@16:09:00.99 <Plunge> Plunge.seek :locked

+@16:09:01.00 <Air> Air.seek :locked

+@16:09:05.07 <LRAUV> Gate.power :cartridge,:ON

 Loaded Archive Cartridge

 Gate.power :cartridge,:OFF

-@08:05:11.99 -> Cmd.startFiltering 10

-@08:05:12.00 <FILTERING> Duration of filtering limited to 1:05:00

-@08:05:12.01 Priming sample loop w/5ml, bypass w/1.5ml

-SP.setPosition! 0ml

+@16:09:21.38 -> Cmd.startFiltering 10

+@16:09:21.39 <FILTERING> Duration of filtering limited to 2:05:00

+@16:09:21.40 Priming sample loop w/100ml, bypass w/10ml

+SamplePump.setPosition! 0ml

 Bypass.open

-@08:05:12.71 Intake.open

-@08:05:14.21 Waiting 3.0..20s for sea pressure to stabilize +/-0.50psi

-@08:05:18.23 Vacuum tare is 10% of full scale

-Abs.reconfigure AbsConfig

-Abs.hold

-@08:05:18.30 SP.reconfigure SPprime

-SP.seek 1.5ml,38 seconds

-@08:05:20.28 Abs.coast

-SP.setPosition! 0ml

+@16:09:22.11 Intake.open

+@16:09:23.61 Sea 5.7m deep (23.1psia)

+Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi

+@16:09:26.13 Vacuum tare is 10% of full scale

+Pressure.reconfigure :default

+@16:09:26.14 Pressure.hold

+@16:09:26.21 SamplePump.reconfigure :prime

+SamplePump.seek 10ml,1:21

+@16:09:35.18 Pressure.coast

+@16:09:35.19 SamplePump.setPosition! 0ml

 Exhaust.open

-@08:05:22.48 <closeBypass> Bypass.close

-<FILTERING> Intake.open

-@08:05:24.68 Abs.hold

-@08:05:24.76 SP.reconfigure SPprime

-SP.seek 5ml,56 seconds

-@08:05:30.40 Abs.coast

+@16:09:37.38 <closeBypass> Bypass.close

+@16:09:39.58 <FILTERING> Pressure.hold

+@16:09:39.65 Sea 5.7m deep (23.1psia)

+@16:09:39.66 SamplePump.reconfigure :prime

+SamplePump.seek 100ml,8:51

+@16:11:04.84 Pressure.coast

 Bypass.open

-@08:05:31.90 Intake.close

-@08:05:33.42 TV.seek :crack

-@08:05:34.21 TV.seek :clear

-@08:05:35.72 TV.seek :cartridge

-@08:05:37.53 TV.seek :clear

-@08:05:39.34 Pressurizing cartridge to 26psi above 14.6psia

-SP.setPosition! 0ml

-@08:05:39.35 Intake.open

-@08:05:40.84 Bypass.close

-@08:05:42.34 Exhaust.close

-@08:05:43.84 Abs.hold

-@08:05:43.91 SP.reconfigure SPcharge

-SP.seek 0.2ml,32 seconds

-@08:05:44.52 Abs.coast

+@16:11:06.34 Intake.close

+@16:11:07.84 Toroid.reconfigure :hold

+Toroid.seek :crack

+@16:11:08.64 Toroid.reconfigure :default

+Toroid.seek :clear

+@16:11:10.14 Toroid.reconfigure :hold

+@16:11:10.15 Toroid.seek :cartridge

+@16:11:11.96 Toroid.reconfigure :default

+Toroid.seek :clear

+@16:11:13.78 Pressurizing cartridge to 26psi above 23.1psia

+SamplePump.setPosition! 0ml

+Intake.open

+@16:11:15.27 Bypass.close

+@16:11:16.77 Exhaust.close

+@16:11:18.28 Pressure.hold

+@16:11:18.35 SamplePump.reconfigure :charge

+SamplePump.seek 2.3ml,42 seconds

+@16:11:20.23 Pressure.coast

 Sampling 10.0ml

-SP.setPosition! 0ml

-Exhaust.open

-@08:05:46.02 Abs.hold

-@08:05:46.10 SP.reconfigure SPsample

-SP.seek 10ml,1:21

-@08:05:49.02 <sampling> sampling 1/10ml at 0.45ml/s with 0.0psi vacuum

-@08:06:08.86 <FILTERING> Abs.coast

+SamplePump.setPosition! 0ml

+@16:11:20.24 Exhaust.open

+@16:11:21.73 Pressure.hold

+@16:11:21.81 Sea 5.7m deep (23.1psia)

+SamplePump.reconfigure :sample

+SamplePump.seek 10ml,1:21

+@16:11:24.74 <sampling> Cartridge 59 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)

+@16:11:34.78 <FILTERING> Pressure.coast

 <closeIntake> Intake.close

-@08:06:08.87 <closeExhaust> Exhaust.close

-@08:06:08.88 <FILTERING> TV.seek :bypass

-@08:06:10.49 TV.seek :clear

-@08:06:12.11 Sampled  10.0ml

-@08:06:13.19 <LRAUV> -> Cmd.startProcessing

-@08:06:13.20 <PROCESSING> PV.seek :reagent

-@08:06:14.03 Sample loop closed. Ready to Deliver Reagents

-ArS.seek :sealed

-@08:06:18.30 ArS.seek :evac

-@08:06:32.28 delay 20 seconds

-@08:06:52.28 ArS.seek :clear

-@08:07:10.04 RNAlater soak for 45 seconds

-@08:07:55.05 ArS.seek :tVent

-@08:07:57.63 delay 1 second

-@08:07:58.63 ArS.seek :evac

-@08:08:14.29 delay 10 seconds

-@08:08:24.30 Sample preserved and evacuated

-@08:08:25.19 <LRAUV> -> Cmd.stop

-@08:08:25.20 PV.seek :locked

-@08:08:26.04 PinPort.seek :clear

-@08:08:26.10 <ArS> ArS.seek :clear

-@08:08:26.11 <LyS2> LyS2.seek :clear

-<AirS> AirS.seek :clear

-@08:08:43.87 <LRAUV> ArS.coast

-LyS1.coast

-LyS2.coast

-AirS.coast

-TV.coast

-SP.coast

-@08:08:43.88 SC.coast

-PV.coast

+<closeExhaust> Exhaust.close

+@16:11:34.79 <FILTERING> Toroid.reconfigure :hold

+Toroid.seek :bypass

+@16:11:36.41 Toroid.reconfigure :default

+Toroid.seek :clear

+@16:11:38.02 Sampled  10.0ml

+@16:11:39.40 <LRAUV> -> Cmd.startProcessing

+@16:11:39.41 <PROCESSING> Plunge.seek :reagent

+@16:11:40.25 Sample loop closed. Ready to Deliver Reagents

+Archive.seek :sealed

+@16:11:44.52 Archive.seek :evac

+@16:11:58.50 delay 20 seconds

+@16:12:18.51 Archive.seek :clear

+@16:12:36.28 RNAlater soak for 45 seconds

+@16:13:21.28 Archive.seek :tVent

+@16:13:23.86 delay 1 second

+@16:13:24.86 Archive.seek :evac

+@16:13:40.53 delay 10 seconds

+@16:13:50.54 Sample preserved and evacuated

+@16:13:51.42 <LRAUV> -> Cmd.stop

+@16:13:51.43 Plunge.seek :locked

+@16:13:52.27 PinPort.seek :clear

+@16:13:52.34 <Archive> Archive.seek :clear

+<Air> Air.seek :clear

+@16:13:52.36 <Lysis2> Lysis2.seek :clear

+@16:14:10.11 <LRAUV> Archive.coast

+Air.coast

+Lysis1.coast

+Lysis2.coast

+Plunge.coast

+@16:14:10.12 SamplePump.coast

+Toroid.coast

+Carousel.coast

 PinPort.coast

-@08:08:43.94 Gate.power :motor,:OFF

-@08:08:43.95 Gate.power :core,:OFF

+@16:14:10.19 Gate.power :motor,:OFF

+Gate.power :core,:OFF

 Gate.power :analytic1,:OFF

 Gate.power :analytic2,:OFF

-Gate.power :analytic3,:OFF

+@16:14:10.20 Gate.power :analytic3,:OFF

 Gate.power :main,:OFF

 Safely stopped and ready to power off

-@08:08:52.12 Session Ended

+@16:14:18.23 Session Ended

```

 ## On tethyssim:

```

-2019-01-09T16:04:32.800Z,1547049872.800 [ESPComponent](IMPORTANT): ESP has connected as client

-2019-01-09T16:04:33.600Z,1547049873.600 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT

-2019-01-09T16:04:34.001Z,1547049874.001 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.104001 m in nan degC water with nan ug/l chlorophyll fluorescence.

-2019-01-09T16:04:34.800Z,1547049874.800 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG

-2019-01-09T16:04:35.200Z,1547049875.200 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS

-2019-01-09T16:04:36.800Z,1547049876.800 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE

-2019-01-09T16:05:12.400Z,1547049912.400 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING

-2019-01-09T16:05:13.000Z,1547049914.000 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING

-2019-01-09T16:05:14.800Z,1547049914.800 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING

-2019-01-09T16:05:47.600Z,1547049947.600 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING

-2019-01-09T16:05:47.000Z,1547049948.000 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED

-2019-01-09T16:06:13.600Z,1547049973.600 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING

-2019-01-09T16:06:15.000Z,1547049976.000 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED

-2019-01-09T16:08:25.600Z,1547050105.600 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING

-2019-01-09T16:08:51.600Z,1547050131.600 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.

-2019-01-09T16:08:51.601Z,1547050131.601 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP

-2019-01-09T16:08:51.601Z,1547050131.601 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper

-2019-01-09T16:08:51.601Z,1547050131.601 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth

-2019-01-09T16:08:51.000Z,1547050132.000 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):

-@08:04:39.46 Selecting Cartridge 59

-@08:06:12.11 Sampled  10.0ml

-2019-01-09T16:08:51.000Z,1547050132.000 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_

-2019-01-09T16:08:52.001Z,1547050132.001 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample

-2019-01-09T16:08:52.001Z,1547050132.001 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater

-2019-01-09T16:08:52.001Z,1547050132.001 [sample](INFO): Completed sample

-2019-01-09T16:08:52.001Z,1547050132.001 [MissionManager](INFO): sample is completed.

-2019-01-09T16:08:52.001Z,1547050132.001 [MissionManager](INFO): Uninitializing Mission sample

-2019-01-09T16:08:52.401Z,1547050132.401 [MissionManager](IMPORTANT): Started mission Default

-2019-01-09T16:08:52.401Z,1547050132.401 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.

-2019-01-09T16:09:05.601Z,1547050145.601 [Default:A.Wait](INFO): Done Waiting.

-2019-01-09T16:09:06.800Z,1547050146.800 [NAL9602](INFO): Powering up

-2019-01-09T16:09:11.000Z,1547050152.000 [NAL9602](INFO): GPS fix at 20190109T160911: (36.806052, -121.823112)

-2019-01-09T16:09:13.200Z,1547050153.200 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190109T160036/Courier0004.lzma

-2019-01-09T16:09:13.200Z,1547050153.200 [NAL9602](INFO): No messages in MT queue

-2019-01-09T16:09:13.599Z,1547050153.599 [DataOverHttps](INFO): Moved sent file to Logs/20190109T160036/Courier0004.lzma.bak

-2019-01-09T16:09:13.599Z,1547050153.599 [DataOverHttps](INFO): SBD MOMSN=9160524

-2019-01-09T16:09:15.600Z,1547050155.600 [DataOverHttps](INFO): Sending 878 bytes from file Logs/20190109T160036/Express0005.lzma

-2019-01-09T16:09:15.000Z,1547050156.000 [DataOverHttps](INFO): Moved sent file to Logs/20190109T160036/Express0005.lzma.bak

-2019-01-09T16:09:15.000Z,1547050156.000 [DataOverHttps](INFO): SBD MOMSN=9160527

-2019-01-09T16:09:43.600Z,1547050183.600 [NAL9602](INFO): Powering down

+2019-04-30T23:08:42.213Z,1556665722.213 [ESPComponent](IMPORTANT): ESP has connected as client

+2019-04-30T23:08:43.013Z,1556665723.013 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to :archive

+2019-04-30T23:08:43.013Z,1556665723.013 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT

+2019-04-30T23:08:43.414Z,1556665723.414 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](ERROR): data element is not active.

+2019-04-30T23:08:43.414Z,1556665723.414 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](ERROR): data element is not active.

+2019-04-30T23:08:43.414Z,1556665723.414 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 0.152651 m in nan degC water with nan ug/l chlorophyll fluorescence.

+2019-04-30T23:08:44.213Z,1556665724.213 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG

+2019-04-30T23:08:44.613Z,1556665724.613 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS

+2019-04-30T23:08:46.213Z,1556665726.213 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE

+2019-04-30T23:09:21.819Z,1556665761.819 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@59,archive)

+2019-04-30T23:09:23.419Z,1556665763.419 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@100.0)

+2019-04-30T23:09:24.219Z,1556665764.219 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@100.0)

+2019-04-30T23:11:23.038Z,1556665883.038 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)

+2019-04-30T23:11:23.438Z,1556665883.438 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)

+2019-04-30T23:11:39.440Z,1556665899.440 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PAUSED (@10.0)

+2019-04-30T23:11:39.840Z,1556665899.840 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PROCESSING (@10.0)

+2019-04-30T23:11:42.241Z,1556665902.241 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PROCESSED (@59,archive)

+2019-04-30T23:13:51.860Z,1556666031.860 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@59,archive)

+2019-04-30T23:14:17.864Z,1556666057.864 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence completed normally.

+2019-04-30T23:14:17.865Z,1556666057.865 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP

+2019-04-30T23:14:17.865Z,1556666057.865 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper

+2019-04-30T23:14:17.865Z,1556666057.865 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth

+2019-04-30T23:14:18.264Z,1556666058.264 [ESPComponent](IMPORTANT): [sample #1] ESP log summary report (2 messages):

+@16:08:48.91 Selecting Cartridge 59

+@16:11:38.02 Sampled  10.0ml

+2019-04-30T23:14:18.264Z,1556666058.264 [ESPComponent](IMPORTANT): powerDownESP IGNORED because manualEsp_

+2019-04-30T23:14:18.265Z,1556666058.265 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample

+2019-04-30T23:14:18.265Z,1556666058.265 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater

+2019-04-30T23:14:18.265Z,1556666058.265 [sample](INFO): Completed sample

+2019-04-30T23:14:18.265Z,1556666058.265 [MissionManager](INFO): sample is completed.

+...

```

 ### Captured ESP.log on vehicle side

 Note, it shows all ESP streams due to my local config entry `ESPComponent.debug = 1 bool;`:

```

+tethyssim>

 [carueda@tethyssim lrauv-application]$ cat Logs/latest/ESP.log

-##-- file opened 2019-01-09T16:04:33.600Z

+##-- file opened 2019-04-30T23:08:43.013Z

 <unknown> LRAUV

 <unknown> \200

  <prompt> \200

  <prompt> \204

-    <log> @08:04:34.79 -> showStatus

+    <log> @16:08:44.18 -> showStatus

     <log> \201

  <result> true\200

  <prompt> \204

-    <log> @08:04:36.39 -> Cmd.loadCartridge

+    <log> @16:08:45.78 -> Cmd.loadCartridge :archive

     <log> \207

  <status> STOPPED-->IDLE

  <status> \204

-    <log> @08:04:36.40 Gate.power :main,:ON

+    <log> Gate.power :main,:ON

     <log> Gate.power :analytic1,:ON

     <log> Gate.power :analytic2,:ON

-    <log> Gate.power :analytic3,:ON

+    <log> @16:08:45.79 Gate.power :analytic3,:ON

     <log> Gate.power :core,:ON

-    <log> ArS.configure ArSconfig

-    <log> @08:04:36.41 LyS1.configure LyS1config

-    <log> LyS2.configure LyS2config

-    <log> AirS.configure AirSconfig

-    <log> @08:04:36.42 TV.configure TVconfig

-    <log> SP.configure SPconfig

-    <log> @08:04:36.43 SC.configure SCconfig

-    <log> PV.configure PVconfig

-    <log> PinPort.configure PPconfig

-    <log> @08:04:36.44 Abs.configure AbsConfig

+    <log> @16:08:45.80 Archive.configure :default

+    <log> @16:08:45.81 Air.configure :default

+    <log> @16:08:45.82 Lysis1.configure :default

+    <log> Lysis2.configure :default

+    <log> @16:08:45.83 Plunge.configure :default

+    <log> @16:08:45.84 SamplePump.configure :default

+    <log> @16:08:45.85 ExtraPump.configure :default

+    <log> @16:08:45.86 Toroid.configure :default

+    <log> Carousel.configure :default

+    <log> @16:08:45.87 Pressure.configure :default

+    <log> PinPort.configure :default

     <log> All elf controllers running firmware version 4.99

-    <log> Gate.power :motor,:ON

-    <log> @08:04:36.47 <ArS_home> ArS.reconfigure ArSconfig

-    <log> @08:04:36.48 ArS.home.jog 0

-    <log> @08:04:36.49 <LyS1_home> LyS1.reconfigure LyS1config

-    <log> <LyS2_home> LyS2.reconfigure LyS2config

-    <log> <LyS1_home> LyS1.home.jog 0

-    <log> <TV_home> TV.reconfigure TVconfig

-    <log> @08:04:36.50 <LyS2_home> LyS2.home.jog 0

-    <log> <AirS_home> AirS.reconfigure AirSconfig

-    <log> <TV_home> TV.home.jog 0

-    <log> <PV_home> PV.reconfigure PVconfig

-    <log> @08:04:36.51 <AirS_home> AirS.home.jog 0

-    <log> <PinPort_home> PinPort.reconfigure PPconfig

-    <log> <PV_home> PV.home.jog 0

+    <log> @16:08:45.88 Gate.power :motor,:ON

+    <log> @16:08:45.89 <Archive_home> Archive.reconfigure :default

+    <log> @16:08:45.90 Archive.home.jog 0

+    <log> <Air_home> Air.reconfigure :default

+    <log> @16:08:45.91 Air.home.jog 0

+    <log> <Lysis1_home> Lysis1.reconfigure :default

+    <log> <Lysis2_home> Lysis2.reconfigure :default

+    <log> @16:08:45.92 <Lysis1_home> Lysis1.home.jog 0

+    <log> <Plunge_home> Plunge.reconfigure :default

+    <log> <Lysis2_home> Lysis2.home.jog 0

+    <log> <PinPort_home> PinPort.reconfigure :default

+    <log> @16:08:45.93 <Plunge_home> Plunge.home.jog 0

+    <log> <Toroid_home> Toroid.reconfigure :default

     <log> <PinPort_home> PinPort.home.jog 0

-    <log> @08:04:36.55 <ArS_home> ArS.setRawPosition! 50

-    <log> @08:04:36.56 ArS.reconfigure HomeMagSyringe

-    <log> ArS.seek :home

-    <log> @08:04:36.57 <LyS2_home> LyS2.setRawPosition! 50

-    <log> LyS2.reconfigure HomeSyringe

-    <log> @08:04:36.58 LyS2.seek :home

-    <log> <TV_home> TV.setRawPosition! 0

-    <log> TV.reconfigure HomeTV

-    <log> TV.seek :home

-    <log> @08:04:36.59 <PV_home> PV.setRawPosition! 50

-    <log> PV.reconfigure HomePV

-    <log> PV.seek :home

-    <log> @08:04:36.60 <PinPort_home> PinPort.setRawPosition! 0

-    <log> PinPort.reconfigure HomePP

-    <log> PinPort.seek :home

-    <log> @08:04:36.61 <LyS1_home> LyS1.setRawPosition! 50

-    <log> LyS1.reconfigure HomeSyringe

-    <log> LyS1.seek :home

-    <log> @08:04:36.62 <AirS_home> AirS.setRawPosition! 50

-    <log> AirS.reconfigure HomeMagSyringe

-    <log> AirS.seek :home

-    <log> @08:04:36.65 <TV_home> TV.reconfigure TVconfig

-    <log> @08:04:36.67 <PinPort_home> PinPort.reconfigure PPconfig

-    <log> @08:04:36.83 <ArS_home> ArS.reconfigure ArSconfig

-    <log> @08:04:36.85 <LyS2_home> LyS2.reconfigure LyS2config

-    <log> @08:04:36.87 <PV_home> PV.reconfigure PVconfig

-    <log> @08:04:36.89 <LyS1_home> LyS1.reconfigure LyS1config

-    <log> @08:04:36.90 <AirS_home> AirS.reconfigure AirSconfig

-    <log> @08:04:37.15 <LRAUV> TV.seek :clear

-    <log> @08:04:38.77 TV.coast

-    <log> SC.reconfigure SCconfig

-    <log> SC.home.jog 0

-    <log> @08:04:38.84 SC.setRawPosition! -53

-    <log> SC.reconfigure HomeSC

-    <log> SC.seek :home

-    <log> @08:04:39.14 SC.reconfigure SCconfig

-    <log> @08:04:39.39 SC.seek 1

+    <log> @16:08:45.94 <Toroid_home> Toroid.home.jog 0

+    <log> @16:08:45.98 <Archive_home> Archive.setRawPosition! 50

+    <log> Archive.reconfigure :homing

+    <log> Archive.seek :home

+    <log> @16:08:45.99 <Air_home> Air.setRawPosition! 50

+    <log> Air.reconfigure :homing

+    <log> @16:08:46.00 Air.seek :home

+    <log> @16:08:46.01 <Plunge_home> Plunge.setRawPosition! 50

+    <log> Plunge.reconfigure :homing

+    <log> Plunge.seek :home

+    <log> @16:08:46.02 <PinPort_home> PinPort.setRawPosition! 0

+    <log> PinPort.reconfigure :homing

+    <log> @16:08:46.03 PinPort.seek :home

+    <log> <Lysis1_home> Lysis1.setRawPosition! 50

+    <log> @16:08:46.04 Lysis1.reconfigure :homing

+    <log> Lysis1.seek :home

+    <log> @16:08:46.05 <Lysis2_home> Lysis2.setRawPosition! 50

+    <log> Lysis2.reconfigure :homing

+    <log> @16:08:46.06 Lysis2.seek :home

+    <log> @16:08:46.07 <Toroid_home> Toroid.setRawPosition! 0

+    <log> Toroid.reconfigure :homing

+    <log> Toroid.seek :home

+    <log> @16:08:46.10 <PinPort_home> PinPort.reconfigure :default

+    <log> @16:08:46.14 <Toroid_home> Toroid.reconfigure :default

+    <log> @16:08:46.26 <Archive_home> Archive.reconfigure :default

+    <log> @16:08:46.27 <Air_home> Air.reconfigure :default

+    <log> @16:08:46.29 <Plunge_home> Plunge.reconfigure :default

+    <log> @16:08:46.32 <Lysis1_home> Lysis1.reconfigure :default

+    <log> @16:08:46.33 <Lysis2_home> Lysis2.reconfigure :default

+    <log> @16:08:46.59 <LRAUV> Toroid.seek :clear

+    <log> @16:08:48.20 Carousel.reconfigure :default

+    <log> Carousel.home.jog 0

+    <log> @16:08:48.28 Carousel.setRawPosition! -53

+    <log> Carousel.reconfigure :homing

+    <log> Carousel.seek :home

+    <log> @16:08:48.58 Carousel.reconfigure :default

+    <log> @16:08:48.84 Carousel.seek 1

     <log> \207

  <status> IDLE-->LOADING

- <status> LOADING-->LOADING@59

+ <status> LOADING-->LOADING@59,archive

  <status> \204

-    <log> @08:04:39.46 Selecting Cartridge 59

-    <log> @08:04:39.47 SC.seek 59

-    <log> @08:04:51.53 <LyS2> LyS2.seek :locked

-    <log> <PV> PV.seek :locked

-    <log> @08:04:51.54 <AirS> AirS.seek :locked

-    <log> @08:04:55.61 <LRAUV> Gate.power :cartridge,:ON

+    <log> @16:08:48.91 Selecting Cartridge 59

+    <log> @16:08:48.92 Carousel.seek 59

+    <log> @16:09:00.98 <Lysis2> Lysis2.seek :locked

+    <log> @16:09:00.99 <Plunge> Plunge.seek :locked

+    <log> @16:09:01.00 <Air> Air.seek :locked

+    <log> @16:09:05.07 <LRAUV> Gate.power :cartridge,:ON

     <log> Loaded Archive Cartridge

     <log> Gate.power :cartridge,:OFF

     <log> \207

- <status> LOADING-->READY@59

+ <status> LOADING-->READY@59,archive

  <status> \201

  <result> 59\200

  <prompt> \204

-    <log> @08:05:11.99 -> Cmd.startFiltering 10

+    <log> @16:09:21.38 -> Cmd.startFiltering 10

     <log> \207

- <status> READY-->PRIMING@0.0

+ <status> READY-->PRIMING@100.0

  <status> \201

  <result> :FILTERING\200

  <prompt> \204

-    <log> @08:05:12.00 <FILTERING> Duration of filtering limited to 1:05:00

-    <log> @08:05:12.01 Priming sample loop w/5ml, bypass w/1.5ml

-    <log> SP.setPosition! 0ml

+    <log> @16:09:21.39 <FILTERING> Duration of filtering limited to 2:05:00

+    <log> @16:09:21.40 Priming sample loop w/100ml, bypass w/10ml

+    <log> SamplePump.setPosition! 0ml

     <log> Bypass.open

-    <log> @08:05:12.71 Intake.open

-    <log> @08:05:14.21 Waiting 3.0..20s for sea pressure to stabilize +/-0.50psi

-    <log> @08:05:18.23 Vacuum tare is 10% of full scale

-    <log> Abs.reconfigure AbsConfig

-    <log> Abs.hold

-    <log> @08:05:18.30 SP.reconfigure SPprime

-    <log> SP.seek 1.5ml,38 seconds

-    <log> @08:05:20.28 Abs.coast

-    <log> SP.setPosition! 0ml

+    <log> @16:09:22.11 Intake.open

+    <log> @16:09:23.61 Sea 5.7m deep (23.1psia)

+    <log> Waiting up to 20 seconds for sea pressure to stabilize +/-0.50psi

+    <log> @16:09:26.13 Vacuum tare is 10% of full scale

+    <log> Pressure.reconfigure :default

+    <log> @16:09:26.14 Pressure.hold

+    <log> @16:09:26.21 SamplePump.reconfigure :prime

+    <log> SamplePump.seek 10ml,1:21

+    <log> @16:09:35.18 Pressure.coast

+    <log> @16:09:35.19 SamplePump.setPosition! 0ml

     <log> Exhaust.open

-    <log> @08:05:22.48 <closeBypass> Bypass.close

-    <log> <FILTERING> Intake.open

-    <log> @08:05:24.68 Abs.hold

-    <log> @08:05:24.76 SP.reconfigure SPprime

-    <log> SP.seek 5ml,56 seconds

-    <log> @08:05:30.40 Abs.coast

+    <log> @16:09:37.38 <closeBypass> Bypass.close

+    <log> @16:09:39.58 <FILTERING> Pressure.hold

+    <log> @16:09:39.65 Sea 5.7m deep (23.1psia)

+    <log> @16:09:39.66 SamplePump.reconfigure :prime

+    <log> SamplePump.seek 100ml,8:51

+    <log> @16:11:04.84 Pressure.coast

     <log> Bypass.open

-    <log> @08:05:31.90 Intake.close

-    <log> @08:05:33.42 TV.seek :crack

-    <log> @08:05:34.21 TV.seek :clear

-    <log> @08:05:35.72 TV.seek :cartridge

-    <log> @08:05:37.53 TV.seek :clear

-    <log> @08:05:39.34 Pressurizing cartridge to 26psi above 14.6psia

-    <log> SP.setPosition! 0ml

-    <log> @08:05:39.35 Intake.open

-    <log> @08:05:40.84 Bypass.close

-    <log> @08:05:42.34 Exhaust.close

-    <log> @08:05:43.84 Abs.hold

-    <log> @08:05:43.91 SP.reconfigure SPcharge

-    <log> SP.seek 0.2ml,32 seconds

-    <log> @08:05:44.52 Abs.coast

+    <log> @16:11:06.34 Intake.close

+    <log> @16:11:07.84 Toroid.reconfigure :hold

+    <log> Toroid.seek :crack

+    <log> @16:11:08.64 Toroid.reconfigure :default

+    <log> Toroid.seek :clear

+    <log> @16:11:10.14 Toroid.reconfigure :hold

+    <log> @16:11:10.15 Toroid.seek :cartridge

+    <log> @16:11:11.96 Toroid.reconfigure :default

+    <log> Toroid.seek :clear

+    <log> @16:11:13.78 Pressurizing cartridge to 26psi above 23.1psia

+    <log> SamplePump.setPosition! 0ml

+    <log> Intake.open

+    <log> @16:11:15.27 Bypass.close

+    <log> @16:11:16.77 Exhaust.close

+    <log> @16:11:18.28 Pressure.hold

+    <log> @16:11:18.35 SamplePump.reconfigure :charge

+    <log> SamplePump.seek 2.3ml,42 seconds

+    <log> @16:11:20.23 Pressure.coast

     <log> Sampling 10.0ml

-    <log> SP.setPosition! 0ml

-    <log> Exhaust.open

+    <log> SamplePump.setPosition! 0ml

+    <log> @16:11:20.24 Exhaust.open

     <log> \207

  <status> PRIMING-->FILTERING@0.0

  <status> \204

-    <log> @08:05:46.02 Abs.hold

-    <log> @08:05:46.10 SP.reconfigure SPsample

-    <log> SP.seek 10ml,1:21

-    <log> @08:05:49.02 <sampling> sampling 1/10ml at 0.45ml/s with 0.0psi vacuum

-    <log> @08:06:08.86 <FILTERING> Abs.coast

+    <log> @16:11:21.73 Pressure.hold

+    <log> @16:11:21.81 Sea 5.7m deep (23.1psia)

+    <log> SamplePump.reconfigure :sample

+    <log> SamplePump.seek 10ml,1:21

+    <log> @16:11:24.74 <sampling> Cartridge 59 sampling 2/10ml at 0.83ml/s with 0.0psi vacuum 5.7m deep (23.1psia)

+    <log> @16:11:34.78 <FILTERING> Pressure.coast

     <log> <closeIntake> Intake.close

-    <log> @08:06:08.87 <closeExhaust> Exhaust.close

-    <log> @08:06:08.88 <FILTERING> TV.seek :bypass

-    <log> @08:06:10.49 TV.seek :clear

-    <log> @08:06:12.11 Sampled  10.0ml

+    <log> <closeExhaust> Exhaust.close

+    <log> @16:11:34.79 <FILTERING> Toroid.reconfigure :hold

+    <log> Toroid.seek :bypass

+    <log> @16:11:36.41 Toroid.reconfigure :default

+    <log> Toroid.seek :clear

+    <log> @16:11:38.02 Sampled  10.0ml

     <log> \207

  <status> FILTERING-->PAUSED@10.0

  <status> \204

-    <log> @08:06:13.19 <LRAUV> -> Cmd.startProcessing

+    <log> @16:11:39.40 <LRAUV> -> Cmd.startProcessing

     <log> \207

- <status> PAUSED-->PROCESSING@59

+ <status> PAUSED-->PROCESSING@59,archive

  <status> \201

  <result> :PROCESSING\200

  <prompt> \204

-    <log> @08:06:13.20 <PROCESSING> PV.seek :reagent

-    <log> @08:06:14.03 Sample loop closed. Ready to Deliver Reagents

-    <log> ArS.seek :sealed

-    <log> @08:06:18.30 ArS.seek :evac

-    <log> @08:06:32.28 delay 20 seconds

-    <log> @08:06:52.28 ArS.seek :clear

-    <log> @08:07:10.04 RNAlater soak for 45 seconds

-    <log> @08:07:55.05 ArS.seek :tVent

-    <log> @08:07:57.63 delay 1 second

-    <log> @08:07:58.63 ArS.seek :evac

-    <log> @08:08:14.29 delay 10 seconds

-    <log> @08:08:24.30 Sample preserved and evacuated

+    <log> @16:11:39.41 <PROCESSING> Plunge.seek :reagent

+    <log> @16:11:40.25 Sample loop closed. Ready to Deliver Reagents

+    <log> Archive.seek :sealed

+    <log> @16:11:44.52 Archive.seek :evac

+    <log> @16:11:58.50 delay 20 seconds

+    <log> @16:12:18.51 Archive.seek :clear

+    <log> @16:12:36.28 RNAlater soak for 45 seconds

+    <log> @16:13:21.28 Archive.seek :tVent

+    <log> @16:13:23.86 delay 1 second

+    <log> @16:13:24.86 Archive.seek :evac

+    <log> @16:13:40.53 delay 10 seconds

+    <log> @16:13:50.54 Sample preserved and evacuated

     <log> \207

- <status> PROCESSING-->PROCESSED@59

+ <status> PROCESSING-->PROCESSED@59,archive

  <status> \204

-    <log> @08:08:25.19 <LRAUV> -> Cmd.stop

-    <log> @08:08:25.20 PV.seek :locked

-    <log> @08:08:26.04 PinPort.seek :clear

-    <log> @08:08:26.10 <ArS> ArS.seek :clear

-    <log> @08:08:26.11 <LyS2> LyS2.seek :clear

-    <log> <AirS> AirS.seek :clear

-    <log> @08:08:43.87 <LRAUV> ArS.coast

-    <log> LyS1.coast

-    <log> LyS2.coast

-    <log> AirS.coast

-    <log> TV.coast

-    <log> SP.coast

-    <log> @08:08:43.88 SC.coast

-    <log> PV.coast

+    <log> @16:13:51.42 <LRAUV> -> Cmd.stop

+    <log> @16:13:51.43 Plunge.seek :locked

+    <log> @16:13:52.27 PinPort.seek :clear

+    <log> @16:13:52.34 <Archive> Archive.seek :clear

+    <log> <Air> Air.seek :clear

+    <log> @16:13:52.36 <Lysis2> Lysis2.seek :clear

+    <log> @16:14:10.11 <LRAUV> Archive.coast

+    <log> Air.coast

+    <log> Lysis1.coast

+    <log> Lysis2.coast

+    <log> Plunge.coast

+    <log> @16:14:10.12 SamplePump.coast

+    <log> Toroid.coast

+    <log> Carousel.coast

     <log> PinPort.coast

-    <log> @08:08:43.94 Gate.power :motor,:OFF

-    <log> @08:08:43.95 Gate.power :core,:OFF

+    <log> @16:14:10.19 Gate.power :motor,:OFF

+    <log> Gate.power :core,:OFF

     <log> Gate.power :analytic1,:OFF

     <log> Gate.power :analytic2,:OFF

-    <log> Gate.power :analytic3,:OFF

+    <log> @16:14:10.20 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 2019-04-30T23:19:32.721Z

```

Updated by Carlos Rueda 2019-02-27

View revision

File snippet.markdown Modified

 ### Optional: Tweaks in LRAUV code to expedite the tests

-- `vi Source/scienceModule/ESPComponent.cpp` to set `manualEsp_` to `true`.

 - `vi Source/scienceModule/ESPClient.cpp` to use, in method `ESPClient::advanceInteraction()`:

```

 # Running the mission:

 ## On tethyssim

+Note the `ESPCOMPONENT_MANUAL_ESP` environment variable:

```

-[carueda@tethyssim lrauv-application]$ bin/LRAUV -r -x "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set > sample:SampleAtDepth.TargetDepth 1 centimeter;set sample:SampleAtDepth.SettleTime 3 second;run"

+[carueda@tethyssim lrauv-application]$ ESPCOMPONENT_MANUAL_ESP=1 bin/LRAUV -r -x "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 1 centimeter;set sample:SampleAtDepth.SettleTime 3 second;run"

```

 Wait until **`[ESPComponent](IMPORTANT): Waiting for ESP to connect`** shows up on the output:

```

-[carueda@tethyssim lrauv-application]$ bin/LRAUV -r -x "load Maintenance/sample.xml;set sample.Depth 1 centimeter;set sample.WaitBeforeSample 3 second;set > sample:SampleAtDepth.TargetDepth 1 centimeter;set sample:SampleAtDepth.SettleTime 3 second;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.

+...

 tethyssim>load Maintenance/2019-01-09T16:00:36.603Z,1547049636.603 [SyncHandler](INFO): Protected caller Thread ID is 105253

 2019-01-09T16:00:36.603Z,1547049636.603 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 105254

 2019-01-09T16:00:36.603Z,1547049636.603 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 105255

Updated by Carlos Rueda 2019-01-09

View revision

File snippet.markdown Modified

 2019-01-09T16:09:15.000Z,1547050156.000 [DataOverHttps](INFO): SBD MOMSN=9160527

 2019-01-09T16:09:43.600Z,1547050183.600 [NAL9602](INFO): Powering down

```

+### Captured ESP.log on vehicle side

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

+Note, it shows all ESP streams due to my local config entry `ESPComponent.debug = 1 bool;`:

+```

+[carueda@tethyssim lrauv-application]$ cat Logs/latest/ESP.log

+##-- file opened 2019-01-09T16:04:33.600Z

+<unknown> LRAUV

+<unknown> \200

+ <prompt> \200

+ <prompt> \204

+    <log> @08:04:34.79 -> showStatus

+    <log> \201

+ <result> true\200

+ <prompt> \204

+    <log> @08:04:36.39 -> Cmd.loadCartridge

+    <log> \207

+ <status> STOPPED-->IDLE

+ <status> \204

+    <log> @08:04:36.40 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> ArS.configure ArSconfig

+    <log> @08:04:36.41 LyS1.configure LyS1config

+    <log> LyS2.configure LyS2config

+    <log> AirS.configure AirSconfig

+    <log> @08:04:36.42 TV.configure TVconfig

+    <log> SP.configure SPconfig

+    <log> @08:04:36.43 SC.configure SCconfig

+    <log> PV.configure PVconfig

+    <log> PinPort.configure PPconfig

+    <log> @08:04:36.44 Abs.configure AbsConfig

+    <log> All elf controllers running firmware version 4.99

+    <log> Gate.power :motor,:ON

+    <log> @08:04:36.47 <ArS_home> ArS.reconfigure ArSconfig

+    <log> @08:04:36.48 ArS.home.jog 0

+    <log> @08:04:36.49 <LyS1_home> LyS1.reconfigure LyS1config

+    <log> <LyS2_home> LyS2.reconfigure LyS2config

+    <log> <LyS1_home> LyS1.home.jog 0

+    <log> <TV_home> TV.reconfigure TVconfig

+    <log> @08:04:36.50 <LyS2_home> LyS2.home.jog 0

+    <log> <AirS_home> AirS.reconfigure AirSconfig

+    <log> <TV_home> TV.home.jog 0

+    <log> <PV_home> PV.reconfigure PVconfig

+    <log> @08:04:36.51 <AirS_home> AirS.home.jog 0

+    <log> <PinPort_home> PinPort.reconfigure PPconfig

+    <log> <PV_home> PV.home.jog 0

+    <log> <PinPort_home> PinPort.home.jog 0

+    <log> @08:04:36.55 <ArS_home> ArS.setRawPosition! 50

+    <log> @08:04:36.56 ArS.reconfigure HomeMagSyringe

+    <log> ArS.seek :home

+    <log> @08:04:36.57 <LyS2_home> LyS2.setRawPosition! 50

+    <log> LyS2.reconfigure HomeSyringe

+    <log> @08:04:36.58 LyS2.seek :home

+    <log> <TV_home> TV.setRawPosition! 0

+    <log> TV.reconfigure HomeTV

+    <log> TV.seek :home

+    <log> @08:04:36.59 <PV_home> PV.setRawPosition! 50

+    <log> PV.reconfigure HomePV

+    <log> PV.seek :home

+    <log> @08:04:36.60 <PinPort_home> PinPort.setRawPosition! 0

+    <log> PinPort.reconfigure HomePP

+    <log> PinPort.seek :home

+    <log> @08:04:36.61 <LyS1_home> LyS1.setRawPosition! 50

+    <log> LyS1.reconfigure HomeSyringe

+    <log> LyS1.seek :home

+    <log> @08:04:36.62 <AirS_home> AirS.setRawPosition! 50

+    <log> AirS.reconfigure HomeMagSyringe

+    <log> AirS.seek :home

+    <log> @08:04:36.65 <TV_home> TV.reconfigure TVconfig

+    <log> @08:04:36.67 <PinPort_home> PinPort.reconfigure PPconfig

+    <log> @08:04:36.83 <ArS_home> ArS.reconfigure ArSconfig

+    <log> @08:04:36.85 <LyS2_home> LyS2.reconfigure LyS2config

+    <log> @08:04:36.87 <PV_home> PV.reconfigure PVconfig

+    <log> @08:04:36.89 <LyS1_home> LyS1.reconfigure LyS1config

+    <log> @08:04:36.90 <AirS_home> AirS.reconfigure AirSconfig

+    <log> @08:04:37.15 <LRAUV> TV.seek :clear

+    <log> @08:04:38.77 TV.coast

+    <log> SC.reconfigure SCconfig

+    <log> SC.home.jog 0

+    <log> @08:04:38.84 SC.setRawPosition! -53

+    <log> SC.reconfigure HomeSC

+    <log> SC.seek :home

+    <log> @08:04:39.14 SC.reconfigure SCconfig

+    <log> @08:04:39.39 SC.seek 1

+    <log> \207

+ <status> IDLE-->LOADING

+ <status> LOADING-->LOADING@59

+ <status> \204

+    <log> @08:04:39.46 Selecting Cartridge 59

+    <log> @08:04:39.47 SC.seek 59

+    <log> @08:04:51.53 <LyS2> LyS2.seek :locked

+    <log> <PV> PV.seek :locked

+    <log> @08:04:51.54 <AirS> AirS.seek :locked

+    <log> @08:04:55.61 <LRAUV> Gate.power :cartridge,:ON

+    <log> Loaded Archive Cartridge

+    <log> Gate.power :cartridge,:OFF

+    <log> \207

+ <status> LOADING-->READY@59

+ <status> \201

+ <result> 59\200

+ <prompt> \204

+    <log> @08:05:11.99 -> Cmd.startFiltering 10

+    <log> \207

+ <status> READY-->PRIMING@0.0

+ <status> \201

+ <result> :FILTERING\200

+ <prompt> \204

+    <log> @08:05:12.00 <FILTERING> Duration of filtering limited to 1:05:00

+    <log> @08:05:12.01 Priming sample loop w/5ml, bypass w/1.5ml

+    <log> SP.setPosition! 0ml

+    <log> Bypass.open

+    <log> @08:05:12.71 Intake.open

+    <log> @08:05:14.21 Waiting 3.0..20s for sea pressure to stabilize +/-0.50psi

+    <log> @08:05:18.23 Vacuum tare is 10% of full scale

+    <log> Abs.reconfigure AbsConfig

+    <log> Abs.hold

+    <log> @08:05:18.30 SP.reconfigure SPprime

+    <log> SP.seek 1.5ml,38 seconds

+    <log> @08:05:20.28 Abs.coast

+    <log> SP.setPosition! 0ml

+    <log> Exhaust.open

+    <log> @08:05:22.48 <closeBypass> Bypass.close

+    <log> <FILTERING> Intake.open

+    <log> @08:05:24.68 Abs.hold

+    <log> @08:05:24.76 SP.reconfigure SPprime

+    <log> SP.seek 5ml,56 seconds

+    <log> @08:05:30.40 Abs.coast

+    <log> Bypass.open

+    <log> @08:05:31.90 Intake.close

+    <log> @08:05:33.42 TV.seek :crack

+    <log> @08:05:34.21 TV.seek :clear

+    <log> @08:05:35.72 TV.seek :cartridge

+    <log> @08:05:37.53 TV.seek :clear

+    <log> @08:05:39.34 Pressurizing cartridge to 26psi above 14.6psia

+    <log> SP.setPosition! 0ml

+    <log> @08:05:39.35 Intake.open

+    <log> @08:05:40.84 Bypass.close

+    <log> @08:05:42.34 Exhaust.close

+    <log> @08:05:43.84 Abs.hold

+    <log> @08:05:43.91 SP.reconfigure SPcharge

+    <log> SP.seek 0.2ml,32 seconds

+    <log> @08:05:44.52 Abs.coast

+    <log> Sampling 10.0ml

+    <log> SP.setPosition! 0ml

+    <log> Exhaust.open

+    <log> \207

+ <status> PRIMING-->FILTERING@0.0

+ <status> \204

+    <log> @08:05:46.02 Abs.hold

+    <log> @08:05:46.10 SP.reconfigure SPsample

+    <log> SP.seek 10ml,1:21

+    <log> @08:05:49.02 <sampling> sampling 1/10ml at 0.45ml/s with 0.0psi vacuum

+    <log> @08:06:08.86 <FILTERING> Abs.coast

+    <log> <closeIntake> Intake.close

+    <log> @08:06:08.87 <closeExhaust> Exhaust.close

+    <log> @08:06:08.88 <FILTERING> TV.seek :bypass

+    <log> @08:06:10.49 TV.seek :clear

+    <log> @08:06:12.11 Sampled  10.0ml

+    <log> \207

+ <status> FILTERING-->PAUSED@10.0

+ <status> \204

+    <log> @08:06:13.19 <LRAUV> -> Cmd.startProcessing

+    <log> \207

+ <status> PAUSED-->PROCESSING@59

+ <status> \201

+ <result> :PROCESSING\200

+ <prompt> \204

+    <log> @08:06:13.20 <PROCESSING> PV.seek :reagent

+    <log> @08:06:14.03 Sample loop closed. Ready to Deliver Reagents

+    <log> ArS.seek :sealed

+    <log> @08:06:18.30 ArS.seek :evac

+    <log> @08:06:32.28 delay 20 seconds

+    <log> @08:06:52.28 ArS.seek :clear

+    <log> @08:07:10.04 RNAlater soak for 45 seconds

+    <log> @08:07:55.05 ArS.seek :tVent

+    <log> @08:07:57.63 delay 1 second

+    <log> @08:07:58.63 ArS.seek :evac

+    <log> @08:08:14.29 delay 10 seconds

+    <log> @08:08:24.30 Sample preserved and evacuated

+    <log> \207

+ <status> PROCESSING-->PROCESSED@59

+ <status> \204

+    <log> @08:08:25.19 <LRAUV> -> Cmd.stop

+    <log> @08:08:25.20 PV.seek :locked

+    <log> @08:08:26.04 PinPort.seek :clear

+    <log> @08:08:26.10 <ArS> ArS.seek :clear

+    <log> @08:08:26.11 <LyS2> LyS2.seek :clear

+    <log> <AirS> AirS.seek :clear

+    <log> @08:08:43.87 <LRAUV> ArS.coast

+    <log> LyS1.coast

+    <log> LyS2.coast

+    <log> AirS.coast

+    <log> TV.coast

+    <log> SP.coast

+    <log> @08:08:43.88 SC.coast

+    <log> PV.coast

+    <log> PinPort.coast

+    <log> @08:08:43.94 Gate.power :motor,:OFF

+    <log> @08:08:43.95 Gate.power :core,:OFF

+    <log> Gate.power :analytic1,:OFF

+    <log> 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

+```

HTTPS

SSH

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

Snippets

Carlos Rueda ESPComponent testing with LRAUV and ESP simulators

File snippet.markdown Modified

File snippet.markdown Modified

File snippet.markdown Modified

File snippet.markdown Modified

File snippet.markdown Modified