Snippets

Carlos Rueda ESPComponent testing with LRAUV and ESP simulators

You are viewing an old version of this snippet. View the current version.
Revised by Carlos Rueda 84bedb8
snippet.markdown
Raw

ESPComponent/ESP testing with simulators on bufflehead and tethyssim:

Note: the config parameter ESPComponent.simulateHardware is false for these tests: the ESP simulator is still an external process and the ESPComponent interacts with it as if it were a real ESP.

Preparations

On bufflehead

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

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

   $ cd esp2
   $ . ESPenv auv honu
   $ ESPmode=simreal

Optional: Tweak in ESP code to expedite the tests

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

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

In utils/auv/cmd.rb, add the line indicated:

def processCartridge cartNum
  ArS.jog 20000   # add this line
  archiveEvacAUV
end

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

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

carueda@bufflehead:~/esp2$ esp
...
@10:16:36.71 <simreal> -> Cmd.slot All=>:dry

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)

Exit the ESP simulator for what follows

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

  $ ESPclient=tethyssim:9998 ESPcmdPort=7777 esp

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

On tethyssim:

Using Missions/Maintenance/sample.xml for this testing. Parameters that can be adjusted for testing convenience, for example Depth = 1, NumberOfSamples = 2.

Here's my local relevant configuration, in Config/sim/carueda/Science.cfg:

   ESPComponent.loadAtStartup          = 1 bool;
   ESPComponent.simulateHardware       = 0 bool;

   ESPComponent.socketServerPort       = 9998 count; 
   ESPComponent.debug                  = 1 bool;
   ESPComponent.poTimeout              = 30 second;

Note: Port 9998 on tethyssim is where the ESPComponent will listen and wait for the ESP to connect. (This port has been opened so it is accessible from bufflehead.)

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():

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

    instead of

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

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

Running the mission:

On tethyssim

[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"

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

on bufflehead

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
/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
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
Gate.power :analytic1,:ON
Gate.power :analytic2,:ON
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
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
<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
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
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
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
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
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
<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
PinPort.coast
@08:08:43.94 Gate.power :motor,:OFF
@08:08:43.95 Gate.power :core,:OFF
Gate.power :analytic1,:OFF
Gate.power :analytic2,:OFF
Gate.power :analytic3,:OFF
Gate.power :main,:OFF
Safely stopped and ready to power off
@08:08:52.12 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
HTTPS SSH

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