Snippet revisions — Bitbucket

-### ESPComponent/ESP testing with simulators on bufflehead and tethyssim:

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

+## On bufflehead

-Image of the ESP software ([esp3gPress branch](https://github.com/MBARI-ESP/ESP2Gscript/tree/esp3gPress)) ready to be exercised  (under carueda's home):

+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).

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

```

    $ cd esp2

-   $ . bin/ESPenv auv honu

+   $ . ESPenv auv honu

    $ ESPmode=simreal

```

-#### Ad hoc adjustments in ESP code to expedite the tests

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

-In archiveCartridge.rb:

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

-```ruby

-def archiveEvacAUV (incTime='0:05', evacNum=2, cartEmpty=:evac)

-```

-instead of

-```ruby

-def archiveEvacAUV (incTime='10:00', evacNum=2, cartEmpty=:evac)

-```

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

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

-```ruby

-  def startFiltering! maxVolume=1000

-    raise Error, "Cannot filter while in #{@state} state" unless

-      [:READY, :PAUSED, :FILTERING_ERR].include? @state

-    loadedCart = Cartridge.loaded

-    maxVolume=5e6 if CartridgeTimelimit[loadedCart]    # add this line

-    if @filtering and @filtering.alive?

-...

-```

-To simulate an error while processing, in utils/auv/cmd.rb, add the line indicated:

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

 ```ruby

 def processCartridge cartNum

-#### Make sure the ESP simulator has enough "dry" cartridges. For this you can simply run `Cmd.slot All=>:dry`:

+### 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:00.80PST21-Jan-16 <simreal> Copyright 2015 MBARI

...

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

-{All => :dry}

-@10:16:39.27 -> Cmd.map

-{1 => :dry,

- 2 => :dry,

- 3 => :dry,

- 4 => :dry,

- 5 => :dry}

-@10:16:41.42 -> exit            # Note: exit the ESP simulator for what follows.

-carueda@bufflehead:~/esp2$

```

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

+### 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 (see below) once the socket server

+This prepares the subsequent execution of the ESP system once the socket server (see below)

 is running on the simulated vehicle.

-### On tethyssim:

+## On tethyssim:

 Using `Missions/Maintenance/sample.xml` for this testing.

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

    ESPComponent.poTimeout              = 30 second;

```

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

+**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 `Cmd.startFiltering 10`, that is:

-Here's an actual session:

+    ```c++

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

+    ```

+    instead of

+    ```c++

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

+    ```

+- `make`

-### Run the mission:

+# Running the mission:

+## On tethyssim

```

-[carueda@tethyssim lrauv-application]$ bin/LRAUV -r -x "run Maintenance/sample.xml"

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

```

-> Or:

-> ```

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

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

```

-[carueda@tethyssim lrauv-application]$ bin/LRAUV -r -x "run Maintenance/sample.xml"

+[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.

-2016-01-21T17:53:09.283Z,1453398789.283 [SyncHandler](INFO): Protected caller Thread ID is 2640

-2016-01-21T17:53:09.284Z,1453398789.284 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2641

-2016-01-21T17:53:09.284Z,1453398789.284 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2642

-2016-01-21T17:53:09.284Z,1453398789.284 [logger ThreadHandler](INFO): Protected caller Thread ID is 2643

-2016-01-21T17:53:09.285Z,1453398789.285 [Supervisor](INFO): Looking for Config files in directory: Config/

-2016-01-21T17:53:09.285Z,1453398789.285 [Supervisor](INFO): Opening Config file at: Config/secure.cfg

-2016-01-21T17:53:09.292Z,1453398789.292 [Supervisor](INFO): Opening Config file at: Config/Science.cfg

-2016-01-21T17:53:09.303Z,1453398789.303 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg

-2016-01-21T17:53:09.317Z,1453398789.317 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg

-2016-01-21T17:53:09.330Z,1453398789.330 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg

-2016-01-21T17:53:09.339Z,1453398789.339 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg

-2016-01-21T17:53:09.346Z,1453398789.346 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg

-2016-01-21T17:53:09.358Z,1453398789.358 [Supervisor](INFO): Opening Config file at: Config/Control.cfg

-tethyssim>pppd: no process killed

-2016-01-21T17:53:09.369Z,1453398789.369 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg

-2016-01-21T17:53:09.376Z,1453398789.376 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg

-2016-01-21T17:53:09.384Z,1453398789.384 [Supervisor](INFO): Opening Config file at: Config/logger.cfg

-2016-01-21T17:53:09.392Z,1453398789.392 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg

-2016-01-21T17:53:09.401Z,1453398789.401 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg

-2016-01-21T17:53:09.407Z,1453398789.407 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg

-2016-01-21T17:53:09.420Z,1453398789.420 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg

-2016-01-21T17:53:09.428Z,1453398789.428 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/

-2016-01-21T17:53:09.428Z,1453398789.428 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Science.cfg

-t2016-01-21T17:53:09.435Z,1453398789.435 [Supervisor](INFO): Opening Config file at: Config/tethyssim/vehicle.cfg

-2016-01-21T17:53:09.442Z,1453398789.442 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Navigation.cfg

-2016-01-21T17:53:09.449Z,1453398789.449 [Supervisor](INFO): Opening Config file at: Config/tethyssim/workSite.cfg

-2016-01-21T17:53:09.456Z,1453398789.456 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Estimation.cfg

-2016-01-21T17:53:09.463Z,1453398789.463 [Supervisor](INFO): Opening Config file at: Config/tethyssim/BIT.cfg

-2016-01-21T17:53:09.470Z,1453398789.470 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Sensor.cfg

-2016-01-21T17:53:09.479Z,1453398789.479 [Supervisor](INFO): Opening Config file at: Config/tethyssim/Derivation.cfg

-2016-01-21T17:53:09.486Z,1453398789.486 [Supervisor](INFO): Looking for Config files in directory: Config/tethyssim/carueda/

-2016-01-21T17:53:09.486Z,1453398789.486 [Supervisor](INFO): Looking for Config files in directory: Config/sim/

-2016-01-21T17:53:09.486Z,1453398789.486 [Supervisor](INFO): Opening Config file at: Config/sim/secure.cfg

-2016-01-21T17:53:09.493Z,1453398789.493 [Supervisor](INFO): Opening Config file at: Config/sim/Science.cfg

-2016-01-21T17:53:09.500Z,1453398789.500 [Supervisor](INFO): Opening Config file at: Config/sim/Simulator.cfg

-2016-01-21T17:53:09.506Z,1453398789.506 [Supervisor](INFO): Opening Config file at: Config/sim/vehicle.cfg

-2016-01-21T17:53:09.513Z,1453398789.513 [Supervisor](INFO): Opening Config file at: Config/sim/Servo.cfg

-2016-01-21T17:53:09.519Z,1453398789.519 [Supervisor](INFO): Opening Config file at: Config/sim/Sensor.cfg

-2016-01-21T17:53:09.526Z,1453398789.526 [Supervisor](INFO): Opening Config file at: Config/sim/Derivation.cfg

-2016-01-21T17:53:09.533Z,1453398789.533 [Supervisor](INFO): Looking for Config files in directory: Config/sim/carueda/

-2016-01-21T17:53:09.533Z,1453398789.533 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/secure.cfg

-2016-01-21T17:53:09.540Z,1453398789.540 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Science.cfg

-2016-01-21T17:53:09.547Z,1453398789.547 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/vehicle.cfg

-2016-01-21T17:53:09.554Z,1453398789.554 [Supervisor](INFO): Opening Config file at: Config/sim/carueda/Sensor.cfg

-2016-01-21T17:53:09.561Z,1453398789.561 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg

-2016-01-21T17:53:09.627Z,1453398789.627 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2746

-2016-01-21T17:53:09.628Z,1453398789.628 [ESPComponent](ERROR): Could not open device '/dev/loadB7' at ESPComponent.loadControl

-2016-01-21T17:53:09.630Z,1453398789.630 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2747

-2016-01-21T17:53:09.656Z,1453398789.656 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2748

-2016-01-21T17:53:09.672Z,1453398789.672 [StratificationFrontDetector](IMPORTANT): threshold set to: 0.999994 degC

-2016-01-21T17:53:09.672Z,1453398789.672 [StratificationFrontDetector](INFO): (re)initializing

-2016-01-21T17:53:09.676Z,1453398789.676 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2749

-2016-01-21T17:53:09.676Z,1453398789.676 [Supervisor](INFO): Main Thread ID is 2639

-2016-01-21T17:53:09.677Z,1453398789.677 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2750

-2016-01-21T17:53:09.677Z,1453398789.677 [logger ThreadHandler](INFO): Handler Thread ID is 2753

-2016-01-21T17:53:09.677Z,1453398789.677 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2752

-2016-01-21T17:53:09.677Z,1453398789.677 [controlThread ThreadHandler](INFO): Handler Thread ID is 2751

-2016-01-21T17:53:09.677Z,1453398789.677 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2754

-2016-01-21T17:53:09.678Z,1453398789.678 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2755

-2016-01-21T17:53:09.679Z,1453398789.679 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.

-2016-01-21T17:53:09.679Z,1453398789.679 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.

-2016-01-21T17:53:09.679Z,1453398789.679 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.

-2016-01-21T17:53:09.679Z,1453398789.679 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.

-2016-01-21T17:53:09.679Z,1453398789.679 [ExternalSim](INFO): ExternalSim initializing...

-2016-01-21T17:53:09.680Z,1453398789.680 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2756

-2016-01-21T17:53:09.680Z,1453398789.680 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2757

-2016-01-21T17:53:09.680Z,1453398789.680 [NavChartDb](FAULT): Change detected in ENC collection. Wiping NavChart Directory

-2016-01-21T17:53:09.681Z,1453398789.681 [NavChartDb](INFO): Looking for Electronic Nav Chart files in directory: Resources/ElectronicNavigationCharts

-2016-01-21T17:53:09.681Z,1453398789.681 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA62M.000

-2016-01-21T17:53:09.681Z,1453398789.681 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA61M.000

-2016-01-21T17:53:09.682Z,1453398789.682 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US1WC07M.000

-2016-01-21T17:53:09.683Z,1453398789.683 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US4CA60M.000

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](INFO): Initialize SBIT Component.

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](IMPORTANT): git: 2015-11-13-1-gd1d8b46

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](INFO): git hash: d1d8b4686f3fcabed06ed710d9fb79cd14367320

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](INFO): Kernel Reporting Different Release From Configuration.

+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-573.7.1.el6.x86_64

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](INFO): Kernel Reporting Different Version From Configuration.

+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 Sep 22 22:00:00 UTC 2015

-2016-01-21T17:53:09.684Z,1453398789.684 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.

-2016-01-21T17:53:09.684Z,1453398789.684 [IBIT](INFO): Initialize IBIT Component.

-2016-01-21T17:53:09.684Z,1453398789.684 [CBIT](INFO): Last reboot was NOT due to watchdog timer.

-2016-01-21T17:53:09.684Z,1453398789.684 [MissionManager](INFO): Loading Mission: Missions/Startup.xml

-2016-01-21T17:53:09.685Z,1453398789.685 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA50M.000

-2016-01-21T17:53:09.686Z,1453398789.686 [MissionManager](INFO): Loading Mission: Missions/Default.xml

-2016-01-21T17:53:09.686Z,1453398789.686 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US3CA52M.000

-2016-01-21T17:53:09.687Z,1453398789.687 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min

-2016-01-21T17:53:09.687Z,1453398789.687 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US5CA83M.000

-2016-01-21T17:53:09.688Z,1453398789.688 [NavChartDb](IMPORTANT): Will load Electronic Nav Chart data from US2WC11M.000

-2016-01-21T17:53:09.692Z,1453398789.692 [ESPComponent](INFO): powering down ESP

-2016-01-21T17:53:09.713Z,1453398789.713 [DVL_micro](INFO): Initializing

-tethyssim>run Maintenance/sample.xml

-2016-01-21T17:53:09.778Z,1453398789.778 [CommandLine](IMPORTANT): got command run ./Missions/Maintenance/sample.xml

-2016-01-21T17:53:09.778Z,1453398789.778 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml

-2016-01-21T17:53:09.779Z,1453398789.779 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min

-2016-01-21T17:53:09.779Z,1453398789.779 [MissionManager](INFO): DefineArg sample.Depth = 1.000000 m

-2016-01-21T17:53:09.779Z,1453398789.779 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 2.000000 count

-2016-01-21T17:53:09.779Z,1453398789.779 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 1.000000 min

-2016-01-21T17:53:09.779Z,1453398789.779 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml

-2016-01-21T17:53:09.780Z,1453398789.780 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m

-2016-01-21T17:53:09.780Z,1453398789.780 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 30.000000 s

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPComponentTriggerTimeout = 3.000000 min

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 4.750000 min

-2016-01-21T17:53:09.781Z,1453398789.781 [MissionManager](INFO): DefineArg sample:SampleAtDepth.ESPComponentTimeout = 7.000000 min

-2016-01-21T17:53:09.783Z,1453398789.783 [CommandLine](IMPORTANT): Running ./Missions/Maintenance/sample.xml

-2016-01-21T17:53:09.881Z,1453398789.881 [NavChartDb](INFO): Setup scan of Resources/ElectronicNavigationCharts/US5CA83M.000

-2016-01-21T17:53:10.489Z,1453398790.489 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.000121

-2016-01-21T17:53:19.288Z,1453398799.288 [NAL9602](INFO): GPS fix at 20160121T175319: (36.806001, -121.823002)

-2016-01-21T17:53:20.488Z,1453398800.488 [NAL9602](INFO): No messages in MT queue

-2016-01-21T17:53:26.089Z,1453398806.089 [NAL9602](INFO): Powering down

-2016-01-21T17:53:30.089Z,1453398810.089 [SBIT](IMPORTANT): Beginning Startup BIT

-2016-01-21T17:54:24.089Z,1453398864.089 [SBIT](IMPORTANT): SBIT PASSED

-2016-01-21T17:54:24.489Z,1453398864.489 [MissionManager](IMPORTANT): Started mission Startup

-2016-01-21T17:54:25.289Z,1453398865.289 [NAL9602](INFO): Powering up

-2016-01-21T17:54:30.489Z,1453398870.489 [NAL9602](INFO): GPS fix at 20160121T175430: (36.806009, -121.823017)

-2016-01-21T17:54:31.689Z,1453398871.689 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20160121T174518/Courier0004.lzma

-2016-01-21T17:54:31.693Z,1453398871.693 [NAL9602](INFO): No messages in MT queue

-2016-01-21T17:54:32.088Z,1453398872.088 [DataOverHttps](INFO): Moved sent file to Logs/20160121T174518/Courier0004.lzma.bak

-2016-01-21T17:54:32.088Z,1453398872.088 [DataOverHttps](INFO): SBD MOMSN=3824975

-2016-01-21T17:54:34.088Z,1453398874.088 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20160121T175309/Courier0000.lzma

-2016-01-21T17:54:34.489Z,1453398874.489 [DataOverHttps](INFO): Moved sent file to Logs/20160121T175309/Courier0000.lzma.bak

-2016-01-21T17:54:34.489Z,1453398874.489 [DataOverHttps](INFO): SBD MOMSN=3824977

-2016-01-21T17:54:36.488Z,1453398876.488 [DataOverHttps](INFO): Sending 803 bytes from file Logs/20160121T174518/Express0005.lzma

-2016-01-21T17:54:36.888Z,1453398876.888 [DataOverHttps](INFO): Moved sent file to Logs/20160121T174518/Express0005.lzma.bak

-2016-01-21T17:54:36.888Z,1453398876.888 [DataOverHttps](INFO): SBD MOMSN=3824981

-2016-01-21T17:54:37.292Z,1453398877.292 [NAL9602](INFO): Powering down

-2016-01-21T17:54:38.888Z,1453398878.888 [DataOverHttps](INFO): Sending 689 bytes from file Logs/20160121T175309/Express0001.lzma

-2016-01-21T17:54:39.288Z,1453398879.288 [DataOverHttps](INFO): Moved sent file to Logs/20160121T175309/Express0001.lzma.bak

-2016-01-21T17:54:39.288Z,1453398879.288 [DataOverHttps](INFO): SBD MOMSN=3824998

-2016-01-21T17:54:39.693Z,1453398879.693 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms

-2016-01-21T17:54:39.693Z,1453398879.693 [Startup](INFO): Completed Startup

-2016-01-21T17:54:40.089Z,1453398880.089 [MissionManager](IMPORTANT): Started mission sample

-2016-01-21T17:54:40.890Z,1453398880.890 [sample:SampleAtDepth:A](INFO): Moving to 1.000000 m

-2016-01-21T17:58:58.490Z,1453399138.490 [sample:SampleAtDepth:C.Wait](INFO): Done Waiting.

-2016-01-21T17:59:00.488Z,1453399140.488 [ESPComponent](INFO): powering up ESP

-2016-01-21T17:59:00.488Z,1453399140.488 [ESPComponent](INFO): manually powering up ESP

-2016-01-21T17:59:00.488Z,1453399140.488 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyS1 linkname esp noauth local lock 115200 134.89.10.51:134.89.10.60 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 134.89.10.32 ms-dns 134.89.10.10

-tethyssim>! echo 1 > /dev/loadB7sh: /sbin/pppd: No such file or directory

-2016-01-21T17:59:00.492Z,1453399140.492 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)     <<<<-----

-tethyssim>! echo 1 > /dev/loadB7

-2016-01-21T17:59:00.506Z,1453399140.506 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB7

-tethyssim>sh: /dev/loadB7: Permission denied

+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

-@09:59:03.66PST21-Jan-16 <simreal> Copyright 2015 MBARI

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

-ESP 3G "honu" 5 cartridge prototype

-@09:59:03.82 ArS.stop

-ArS.configure ArSconfig

-Rod.stop

-Rod.configure RodConfig

-PV.stop

-PV.configure PVconfig

-SC.stop

-SC.configure SCconfig

-TV.stop

-@09:59:03.83 TV.configure TVconfig

-SP.stop

-SP.configure SPconfig

-All dwarves are running firmware version 3.74sim

-<closeIntake> Intake.close

-<closeExhaust> Exhaust.close

-@09:59:05.14 <simreal> Clients may connect on TCP port 7777

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

-@09:59:05.28 <LRAUV> Session Begun

-```

-On tethyssim:

-```

-2016-01-21T17:59:05.688Z,1453399145.688 [ESPComponent](IMPORTANT): ESP has connected as client

-2016-01-21T17:59:06.489Z,1453399146.489 [ESPComponent](IMPORTANT): ESP sampling sequence starting (sample #1)  sampling state: S_WAITING_INITIAL_PROMPT

-2016-01-21T17:59:06.890Z,1453399146.890 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 1.633221 m in nan degC water with nan ug/l chlorophyll fluorescence.

-2016-01-21T17:59:07.688Z,1453399147.688 [ESPComponent](IMPORTANT): ESP sampling state: S_PREPARING_SHOW_LOG

-2016-01-21T17:59:08.088Z,1453399148.088 [ESPComponent](IMPORTANT): ESP sampling state: S_PREPARING_SHOW_STATUS

-2016-01-21T17:59:09.689Z,1453399149.689 [ESPComponent](IMPORTANT): ESP sampling state: S_LOADING_CARTRIDGE

-2016-01-21T17:59:29.288Z,1453399169.288 [ESPComponent](IMPORTANT): ESP sampling state: S_FILTERING

-2016-01-21T17:59:31.688Z,1453399171.688 [ESPComponent](IMPORTANT): ESP sampling state: S_WAITING_FOR_PAUSED

-2016-01-21T17:59:52.888Z,1453399192.888 [ESPComponent](IMPORTANT): ESP sampling state: S_PROCESSING

-2016-01-21T17:59:55.288Z,1453399195.288 [ESPComponent](IMPORTANT): ESP sampling state: S_WAITING_FOR_PROCESSED

-2016-01-21T18:00:48.888Z,1453399248.888 [ESPComponent](IMPORTANT): ESP sampling state: S_STOPPING

-2016-01-21T18:00:53.289Z,1453399253.289 [ESPComponent](IMPORTANT): ESP sampling sequence completed normally (sample #1)

-2016-01-21T18:00:53.290Z,1453399253.290 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP

-2016-01-21T18:00:53.291Z,1453399253.291 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper

-2016-01-21T18:00:53.291Z,1453399253.291 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth

-2016-01-21T18:00:53.689Z,1453399253.689 [ESPComponent](INFO): powering down ESP

-tethyssim>pppd: no process killed

-2016-01-21T18:00:53.717Z,1453399253.717 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample

-2016-01-21T18:00:53.717Z,1453399253.717 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater

-2016-01-21T18:00:53.717Z,1453399253.717 [sample:SampleRepeater](INFO): Running loop #2

-2016-01-21T18:00:54.091Z,1453399254.091 [sample:SampleAtDepth:A](INFO): Moving to 1.000000 m

-```

-First sample is complete.

-Exit the ESP simulator, to then wait again for `[ESPComponent](IMPORTANT): Waiting for ESP to connect`:

-```

-2016-01-21T18:02:12.489Z,1453399332.489 [sample:SampleAtDepth:C.Wait](INFO): Done Waiting.

-2016-01-21T18:02:14.489Z,1453399334.489 [ESPComponent](INFO): powering up ESP

-2016-01-21T18:02:14.489Z,1453399334.489 [ESPComponent](INFO): manually powering up ESP

-2016-01-21T18:02:14.489Z,1453399334.489 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyS1 linkname esp noauth local lock 115200 134.89.10.51:134.89.10.60 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 134.89.10.32 ms-dns 134.89.10.10

-tethyssim>! echo 1 > /dev/loadB7sh: /sbin/pppd: No such file or directory

-2016-01-21T18:02:14.496Z,1453399334.496 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=30.0000)

-tethyssim>! echo 1 > /dev/loadB7

-2016-01-21T18:02:14.529Z,1453399334.529 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB7

-tethyssim>sh: /dev/loadB7: Permission denied

-```

-Launch ESP simulator as before:

-```

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

-@10:02:19.67PST21-Jan-16 <simreal> Copyright 2015 MBARI

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

-ESP 3G "honu" 5 cartridge prototype

-@10:02:19.84 ArS.stop

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

-Rod.stop

-Rod.configure RodConfig

-PV.stop

-PV.configure PVconfig

-SC.stop

-SC.configure SCconfig

-TV.stop

-TV.configure TVconfig

-SP.stop

+@08:04:36.41 LyS1.configure LyS1config

+LyS2.configure LyS2config

+AirS.configure AirSconfig

+@08:04:36.42 TV.configure TVconfig

 SP.configure SPconfig

-All dwarves are running firmware version 3.74sim

-@10:02:19.85 <closeIntake> Intake.close

-<closeExhaust> Exhaust.close

-@10:02:21.17 <simreal> Clients may connect on TCP port 7777

-Connecting to tethyssim:9998

-@10:02:21.28 <LRAUV> Session Begun

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

```

-And finally on tethyssim:

+## On tethyssim:

```

-2016-01-21T18:02:21.688Z,1453399341.688 [ESPComponent](IMPORTANT): ESP has connected as client

-2016-01-21T18:02:22.489Z,1453399342.489 [ESPComponent](IMPORTANT): ESP sampling sequence starting (sample #2)  sampling state: S_WAITING_INITIAL_PROMPT

-2016-01-21T18:02:22.889Z,1453399342.889 [sample:SampleAtDepth:SampleWrapper:SampleESP:C](IMPORTANT): ESP sampling at 1.129265 m in nan degC water with nan ug/l chlorophyll fluorescence.

-2016-01-21T18:02:23.288Z,1453399343.288 [ESPComponent](IMPORTANT): ESP sampling state: S_PREPARING_SHOW_LOG

-2016-01-21T18:02:23.689Z,1453399343.689 [ESPComponent](IMPORTANT): ESP sampling state: S_PREPARING_SHOW_STATUS

-2016-01-21T18:02:25.689Z,1453399345.689 [ESPComponent](IMPORTANT): ESP sampling state: S_LOADING_CARTRIDGE

-2016-01-21T18:02:45.289Z,1453399365.289 [ESPComponent](IMPORTANT): ESP sampling state: S_FILTERING

-2016-01-21T18:02:47.688Z,1453399367.688 [ESPComponent](IMPORTANT): ESP sampling state: S_WAITING_FOR_PAUSED

-2016-01-21T18:03:08.888Z,1453399388.888 [ESPComponent](IMPORTANT): ESP sampling state: S_PROCESSING

-2016-01-21T18:03:11.288Z,1453399391.288 [ESPComponent](IMPORTANT): ESP sampling state: S_WAITING_FOR_PROCESSED

-2016-01-21T18:04:04.888Z,1453399444.888 [ESPComponent](IMPORTANT): ESP sampling state: S_STOPPING

-2016-01-21T18:04:09.289Z,1453399449.289 [ESPComponent](IMPORTANT): ESP sampling sequence completed normally (sample #2)

-2016-01-21T18:04:09.290Z,1453399449.290 [sample:SampleAtDepth:SampleWrapper:SampleESP](INFO): Completed sample:SampleAtDepth:SampleWrapper:SampleESP

-2016-01-21T18:04:09.290Z,1453399449.290 [sample:SampleAtDepth:SampleWrapper](INFO): Completed sample:SampleAtDepth:SampleWrapper

-2016-01-21T18:04:09.290Z,1453399449.290 [sample:SampleAtDepth](INFO): Completed sample:SampleAtDepth

-2016-01-21T18:04:09.689Z,1453399449.689 [ESPComponent](INFO): powering down ESP

-tethyssim>pppd: no process killed

-2016-01-21T18:04:09.719Z,1453399449.719 [sample:SampleRepeater:Sample](INFO): Completed sample:SampleRepeater:Sample

-2016-01-21T18:04:09.719Z,1453399449.719 [sample:SampleRepeater](INFO): Completed sample:SampleRepeater

-2016-01-21T18:04:09.719Z,1453399449.719 [sample](INFO): Completed sample

-2016-01-21T18:04:10.089Z,1453399450.089 [MissionManager](IMPORTANT): Started mission Default

+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

```

-showing completion of the 2nd ESP sample, and the mission.

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