-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:
-### 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
>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.
->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
-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 <<<<<<<<<<<<<<
-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
-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
+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 :analytic1,:ON
Gate.power :analytic2,:ON
-Gate.power :analytic3,:ON
+@16:08:45.79 Gate.power :analytic3,:ON
-@08:04:36.41 LyS1.configure LyS1config
-LyS2.configure LyS2config
-AirS.configure AirSconfig
-@08:04:36.42 TV.configure TVconfig
-@08:04:36.43 SC.configure SCconfig
-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
-@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
-<PV_home> PV.reconfigure PVconfig
-@08:04:36.51 <AirS_home> AirS.home.jog 0
-<PinPort_home> PinPort.reconfigure PPconfig
+@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
-@08:04:36.57 <LyS2_home> LyS2.setRawPosition! 50
-LyS2.reconfigure HomeSyringe
-@08:04:36.58 LyS2.seek :home
-<TV_home> TV.setRawPosition! 0
-@08:04:36.59 <PV_home> PV.setRawPosition! 50
-@08:04:36.60 <PinPort_home> PinPort.setRawPosition! 0
-PinPort.reconfigure HomePP
-@08:04:36.61 <LyS1_home> LyS1.setRawPosition! 50
-LyS1.reconfigure HomeSyringe
-@08:04:36.62 <AirS_home> AirS.setRawPosition! 50
-AirS.reconfigure HomeMagSyringe
-@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.84 SC.setRawPosition! -53
-@08:04:39.14 SC.reconfigure SCconfig
-@08:04:39.46 Selecting Cartridge 59
-@08:04:51.53 <LyS2> LyS2.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
+@16:08:45.99 <Air_home> Air.setRawPosition! 50
+@16:08:46.00 Air.seek :home
+@16:08:46.01 <Plunge_home> Plunge.setRawPosition! 50
+Plunge.reconfigure :homing
+@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
+@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
+@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
+@16:08:48.28 Carousel.setRawPosition! -53
+Carousel.reconfigure :homing
+@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
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
+@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
-@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
-@08:05:18.30 SP.reconfigure SPprime
-SP.seek 1.5ml,38 seconds
+@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
-@08:05:22.48 <closeBypass> Bypass.close
-@08:05:24.76 SP.reconfigure SPprime
+@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
-@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
-@08:05:39.35 Intake.open
-@08:05:40.84 Bypass.close
-@08:05:42.34 Exhaust.close
-@08:05:43.91 SP.reconfigure SPcharge
-SP.seek 0.2ml,32 seconds
+@16:11:06.34 Intake.close
+@16:11:07.84 Toroid.reconfigure :hold
+@16:11:08.64 Toroid.reconfigure :default
+@16:11:10.14 Toroid.reconfigure :hold
+@16:11:10.15 Toroid.seek :cartridge
+@16:11:11.96 Toroid.reconfigure :default
+@16:11:13.78 Pressurizing cartridge to 26psi above 23.1psia
+SamplePump.setPosition! 0ml
+@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
-@08:05:46.10 SP.reconfigure SPsample
-@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
-@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
-@08:08:43.87 <LRAUV> ArS.coast
+<closeExhaust> Exhaust.close
+@16:11:34.79 <FILTERING> Toroid.reconfigure :hold
+@16:11:36.41 Toroid.reconfigure :default
+@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
+@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
+@16:13:52.36 <Lysis2> Lysis2.seek :clear
+@16:14:10.11 <LRAUV> Archive.coast
+@16:14:10.12 SamplePump.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 :analytic1,:OFF
Gate.power :analytic2,:OFF
-Gate.power :analytic3,:OFF
+@16:14:10.20 Gate.power :analytic3,:OFF
Safely stopped and ready to power off
-@08:08:52.12 Session Ended
+@16:14:18.23 Session Ended
-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;`:
[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
- <log> @08:04:34.79 -> showStatus
+ <log> @16:08:44.18 -> showStatus
- <log> @08:04:36.39 -> Cmd.loadCartridge
+ <log> @16:08:45.78 -> Cmd.loadCartridge :archive
- <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> @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> @08:04:36.59 <PV_home> PV.setRawPosition! 50
- <log> PV.reconfigure HomePV
- <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> @08:04:36.62 <AirS_home> AirS.setRawPosition! 50
- <log> AirS.reconfigure HomeMagSyringe
- <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> @08:04:38.84 SC.setRawPosition! -53
- <log> SC.reconfigure HomeSC
- <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
- <status> LOADING-->LOADING@59
+ <status> LOADING-->LOADING@59,archive
- <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
- <status> LOADING-->READY@59
+ <status> LOADING-->READY@59,archive
- <log> @08:05:11.99 -> Cmd.startFiltering 10
+ <log> @16:09:21.38 -> Cmd.startFiltering 10
- <status> READY-->PRIMING@0.0
+ <status> READY-->PRIMING@100.0
- <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> @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> @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> @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> @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> @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> SP.setPosition! 0ml
+ <log> SamplePump.setPosition! 0ml
+ <log> @16:11:20.24 Exhaust.open
<status> PRIMING-->FILTERING@0.0
- <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
<status> FILTERING-->PAUSED@10.0
- <log> @08:06:13.19 <LRAUV> -> Cmd.startProcessing
+ <log> @16:11:39.40 <LRAUV> -> Cmd.startProcessing
- <status> PAUSED-->PROCESSING@59
+ <status> PAUSED-->PROCESSING@59,archive
- <log> @08:06:13.20 <PROCESSING> PV.seek :reagent
- <log> @08:06:14.03 Sample loop closed. Ready to Deliver Reagents
- <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
- <status> PROCESSING-->PROCESSED@59
+ <status> PROCESSING-->PROCESSED@59,archive
- <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> @08:08:43.88 SC.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> @16:14:10.12 SamplePump.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
<status> PROCESSED-->STOPPED
+##-- file closed 2019-04-30T23:19:32.721Z