Skip to content

Instantly share code, notes, and snippets.

@carueda

carueda/gist:74a646f726e61e878b23

Last active August 29, 2015 14:25
Show Gist options
  • Save carueda/74a646f726e61e878b23 to your computer and use it in GitHub Desktop.
Save carueda/74a646f726e61e878b23 to your computer and use it in GitHub Desktop.
Download ZIP
bin/LRAUV -r -x "run Engineering/sample.xml" -- a complete run with simulators using tethyssim and bufflehead
Raw
gistfile1.txt
(note, with the trick of setting true for isDataRequested so the sampling can start promptly in this test)
[carueda@tethyssim LRAUV3]$ bin/LRAUV -r -x "run Engineering/sample.xml"
2015-07-15T21:50:41.770Z,1436997041.770 [ESPComponent](INFO): start simulateHardware()=0
2015-07-15T21:50:41.770Z,1436997041.770 [ESPComponent](INFO): ESPComm: ESPComm::open: opening server socket on port 9998
2015-07-15T21:50:41.770Z,1436997041.770 [ESPComponent](INFO): Powering up
2015-07-15T21:50:41.770Z,1436997041.770 [ESPComponent](INFO): ESPComponent::start: powering up ESP
2015-07-15T21:50:41.770Z,1436997041.770 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 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
2015-07-15T21:50:41.785Z,1436997041.785 [ESPComponent](INFO): Ready to accept ESP connection: startTimeAccept_=2015-07-15T21:50:41.770Z poTimeout_=150.0000
2015-07-15T21:50:41.849Z,1436997041.849 [CommandLine](IMPORTANT): got command run ./Missions/Engineering/sample.xml
2015-07-15T21:50:41.849Z,1436997041.849 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/sample.xml
2015-07-15T21:50:41.880Z,1436997041.880 [CommandLine](IMPORTANT): Running ./Missions/Engineering/sample.xml
2015-07-15T21:50:42.166Z,1436997042.166 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:42.566Z,1436997042.566 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:42.966Z,1436997042.966 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:43.366Z,1436997043.366 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:43.766Z,1436997043.766 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:44.166Z,1436997044.166 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:44.566Z,1436997044.566 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:44.966Z,1436997044.966 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
2015-07-15T21:50:44.966Z,1436997044.966 [ESPComponent](INFO): ESPComm: ESPComm::acceptClient: accepted ESP as client
2015-07-15T21:50:44.966Z,1436997044.966 [ESPComponent](INFO): ESPComm: |>| "LRAUV-tethyssim\n"
2015-07-15T21:50:45.366Z,1436997045.366 [ESPComponent](INFO): ESPComponent::starting: ESP connected. startTimeForLine_=2015-07-15T21:50:45.366Z
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <UNKNOWN> "7777\n"
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): :-<: UNKNOWN "7777"
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): R_WAITING_FOR_PORT line=<UNKNOWN> "7777"
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): scanEspServerPort: scanned port=7777
2015-07-15T21:50:45.766Z,1436997045.766 [ESPComponent](INFO): ESPComm: getPeerAddress: '134.89.10.91'
2015-07-15T21:50:45.767Z,1436997045.767 [ESPComponent](INFO): setVehicleAsClient: closed previous connection with vehicle as server. Now connecting as client to: 134.89.10.91:7777
2015-07-15T21:50:45.767Z,1436997045.767 [ESPComponent](INFO): ESPComm: ESPComm::connectAsClient: connected as a client to the ESP as server on 134.89.10.91:7777
2015-07-15T21:50:45.767Z,1436997045.767 [ESPComponent](INFO): ESPClient: --ESPClient::startSampling--
2015-07-15T21:50:45.767Z,1436997045.767 [ESPComponent](INFO): ESPClient: startSampling complete; samplingState_=S_WAITING_INITIAL_PROMPT
2015-07-15T21:50:46.166Z,1436997046.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:46.166Z,1436997046.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <UNKNOWN> "LRAUV-tethyssim\n"
2015-07-15T21:50:46.166Z,1436997046.166 [ESPComponent](INFO): :-<: UNKNOWN "LRAUV-tethyssim"
2015-07-15T21:50:46.566Z,1436997046.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:46.566Z,1436997046.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <UNKNOWN> "\200\n"
2015-07-15T21:50:46.566Z,1436997046.566 [ESPComponent](INFO): ESPComm: stream change: UNKNOWN -> PROMPT
2015-07-15T21:50:46.566Z,1436997046.566 [ESPComponent](INFO): ESPComm: |>| "\tshowlog nil, true\000\n"
2015-07-15T21:50:46.566Z,1436997046.566 [ESPComponent](INFO): ESPClient: issueCommand: cmd='\tshowlog nil, true'
2015-07-15T21:50:46.966Z,1436997046.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:46.966Z,1436997046.966 [ESPComponent](INFO): samplingState_=S_PREPARING_SHOW_LOG
2015-07-15T21:50:46.966Z,1436997046.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <PROMPT> "\200\n"
2015-07-15T21:50:46.966Z,1436997046.966 [ESPComponent](INFO): ESPComm: |>| "showStatus\000\n"
2015-07-15T21:50:46.966Z,1436997046.966 [ESPComponent](INFO): ESPClient: issueCommand: cmd='showStatus'
2015-07-15T21:50:47.366Z,1436997047.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:47.366Z,1436997047.366 [ESPComponent](INFO): samplingState_=S_PREPARING_SHOW_STATUS
2015-07-15T21:50:47.366Z,1436997047.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <PROMPT> "\204\n"
2015-07-15T21:50:47.366Z,1436997047.366 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:50:47.766Z,1436997047.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:47.766Z,1436997047.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:46.96 -> showStatus\n"
2015-07-15T21:50:47.766Z,1436997047.766 [ESPComponent](INFO): :-<: LOG "@14:50:46.96 -> showStatus"
2015-07-15T21:50:48.166Z,1436997048.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:48.166Z,1436997048.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "\201\n"
2015-07-15T21:50:48.166Z,1436997048.166 [ESPComponent](INFO): ESPComm: stream change: LOG -> RESULT
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): runnable
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <RESULT> "true\200\n"
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): ESPComm: stream change: RESULT -> PROMPT
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): :-<: RESULT "true"
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): ESPClient: In S_PREPARING_SHOW_STATUS, for cmd='showStatus', consuming result: <<true\n>> which took 1.6002
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): ESPComm: |>| "Cmd.slot All=>:dry\000\n"
2015-07-15T21:50:48.567Z,1436997048.567 [ESPComponent](INFO): ESPClient: issueCommand: cmd='Cmd.slot All=>:dry'
2015-07-15T21:50:48.966Z,1436997048.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:48.966Z,1436997048.966 [ESPComponent](INFO): samplingState_=S_PREPARING_SIMULATION
2015-07-15T21:50:48.966Z,1436997048.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <PROMPT> "\204\n"
2015-07-15T21:50:48.966Z,1436997048.966 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:50:49.366Z,1436997049.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:49.366Z,1436997049.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:48.56 -> Cmd.slot All=>:dry\n"
2015-07-15T21:50:49.366Z,1436997049.366 [ESPComponent](INFO): :-<: LOG "@14:50:48.56 -> Cmd.slot All=>:dry"
2015-07-15T21:50:49.766Z,1436997049.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:49.766Z,1436997049.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "\201\n"
2015-07-15T21:50:49.766Z,1436997049.766 [ESPComponent](INFO): ESPComm: stream change: LOG -> RESULT
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <RESULT> "{All => :dry}\200\n"
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): ESPComm: stream change: RESULT -> PROMPT
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): :-<: RESULT "{All => :dry}"
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): ESPClient: In S_PREPARING_SIMULATION, for cmd='Cmd.slot All=>:dry', consuming result: <<{All => :dry}\n>> which took 1.5993
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): ESPComm: |>| "Cmd.loadCartridge\000\n"
2015-07-15T21:50:50.166Z,1436997050.166 [ESPComponent](INFO): ESPClient: issueCommand: cmd='Cmd.loadCartridge'
2015-07-15T21:50:50.566Z,1436997050.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:50.566Z,1436997050.566 [ESPComponent](INFO): samplingState_=S_LOADING_CARTRIDGE
2015-07-15T21:50:50.566Z,1436997050.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <PROMPT> "\204\n"
2015-07-15T21:50:50.566Z,1436997050.566 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:50:50.966Z,1436997050.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:50.966Z,1436997050.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:50.16 -> Cmd.loadCartridge\n"
2015-07-15T21:50:50.966Z,1436997050.966 [ESPComponent](INFO): :-<: LOG "@14:50:50.16 -> Cmd.loadCartridge"
2015-07-15T21:50:51.366Z,1436997051.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:51.366Z,1436997051.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<ArS_home> ArS.setRawPosition! -50\n"
2015-07-15T21:50:51.367Z,1436997051.367 [ESPComponent](INFO): :-<: LOG "<ArS_home> ArS.setRawPosition! -50"
2015-07-15T21:50:51.367Z,1436997051.367 [NAL9602](INFO): GPS fix at 20150715T215051: (36.799232, -121.913960)
2015-07-15T21:50:51.766Z,1436997051.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:51.766Z,1436997051.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<Rod_home> Rod.setRawPosition! -50\n"
2015-07-15T21:50:51.766Z,1436997051.766 [ESPComponent](INFO): :-<: LOG "<Rod_home> Rod.setRawPosition! -50"
2015-07-15T21:50:52.166Z,1436997052.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:52.166Z,1436997052.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:50.17 <ArS_home> ArS.seek :home\n"
2015-07-15T21:50:52.166Z,1436997052.166 [ESPComponent](INFO): :-<: LOG "@14:50:50.17 <ArS_home> ArS.seek :home"
2015-07-15T21:50:52.566Z,1436997052.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:52.566Z,1436997052.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<Rod_home> Rod.seek :home\n"
2015-07-15T21:50:52.566Z,1436997052.566 [ESPComponent](INFO): :-<: LOG "<Rod_home> Rod.seek :home"
2015-07-15T21:50:52.567Z,1436997052.567 [NAL9602](INFO): No messages in MT queue
2015-07-15T21:50:52.966Z,1436997052.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:52.966Z,1436997052.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<PV_home> PV.setRawPosition! -50\n"
2015-07-15T21:50:52.966Z,1436997052.966 [ESPComponent](INFO): :-<: LOG "<PV_home> PV.setRawPosition! -50"
2015-07-15T21:50:53.366Z,1436997053.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:53.366Z,1436997053.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<TV_home> TV.setRawPosition! -10\n"
2015-07-15T21:50:53.366Z,1436997053.366 [ESPComponent](INFO): :-<: LOG "<TV_home> TV.setRawPosition! -10"
2015-07-15T21:50:53.766Z,1436997053.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:53.766Z,1436997053.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<PV_home> PV.seek :home\n"
2015-07-15T21:50:53.766Z,1436997053.766 [ESPComponent](INFO): :-<: LOG "<PV_home> PV.seek :home"
2015-07-15T21:50:54.166Z,1436997054.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:54.166Z,1436997054.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "<TV_home> TV.seek :home\n"
2015-07-15T21:50:54.166Z,1436997054.166 [ESPComponent](INFO): :-<: LOG "<TV_home> TV.seek :home"
2015-07-15T21:50:54.566Z,1436997054.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:54.566Z,1436997054.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:50.70 <LRAUV-tethyssim> TV.seek :clear\n"
2015-07-15T21:50:54.566Z,1436997054.566 [ESPComponent](INFO): :-<: LOG "@14:50:50.70 <LRAUV-tethyssim> TV.seek :clear"
2015-07-15T21:50:54.966Z,1436997054.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:54.966Z,1436997054.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:51.22 SC.setRawPosition! -85\n"
2015-07-15T21:50:54.966Z,1436997054.966 [ESPComponent](INFO): :-<: LOG "@14:50:51.22 SC.setRawPosition! -85"
2015-07-15T21:50:55.366Z,1436997055.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:55.366Z,1436997055.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "SC.seek :home\n"
2015-07-15T21:50:55.366Z,1436997055.366 [ESPComponent](INFO): :-<: LOG "SC.seek :home"
2015-07-15T21:50:55.766Z,1436997055.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:55.766Z,1436997055.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:51.74 TV.seek :bypass\n"
2015-07-15T21:50:55.766Z,1436997055.766 [ESPComponent](INFO): :-<: LOG "@14:50:51.74 TV.seek :bypass"
2015-07-15T21:50:56.166Z,1436997056.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:56.166Z,1436997056.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:52.26 TV.seek :free\n"
2015-07-15T21:50:56.166Z,1436997056.166 [ESPComponent](INFO): :-<: LOG "@14:50:52.26 TV.seek :free"
2015-07-15T21:50:56.566Z,1436997056.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:56.566Z,1436997056.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:52.78 TV.coast\n"
2015-07-15T21:50:56.566Z,1436997056.566 [ESPComponent](INFO): :-<: LOG "@14:50:52.78 TV.coast"
2015-07-15T21:50:56.966Z,1436997056.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:56.966Z,1436997056.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "SC.hold\n"
2015-07-15T21:50:56.966Z,1436997056.966 [ESPComponent](INFO): :-<: LOG "SC.hold"
2015-07-15T21:50:57.366Z,1436997057.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:57.366Z,1436997057.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:53.05 SC.seek 2\n"
2015-07-15T21:50:57.366Z,1436997057.366 [ESPComponent](INFO): :-<: LOG "@14:50:53.05 SC.seek 2"
2015-07-15T21:50:57.766Z,1436997057.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:57.766Z,1436997057.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:53.57 TV.seek :bypass\n"
2015-07-15T21:50:57.766Z,1436997057.766 [ESPComponent](INFO): :-<: LOG "@14:50:53.57 TV.seek :bypass"
2015-07-15T21:50:58.166Z,1436997058.166 [ESPComponent](INFO): runnable
2015-07-15T21:50:58.166Z,1436997058.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:54.09 TV.seek :free\n"
2015-07-15T21:50:58.166Z,1436997058.166 [ESPComponent](INFO): :-<: LOG "@14:50:54.09 TV.seek :free"
2015-07-15T21:50:58.166Z,1436997058.166 [NAL9602](INFO): Powering down
2015-07-15T21:50:58.566Z,1436997058.566 [ESPComponent](INFO): runnable
2015-07-15T21:50:58.566Z,1436997058.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:54.60 TV.coast\n"
2015-07-15T21:50:58.566Z,1436997058.566 [ESPComponent](INFO): :-<: LOG "@14:50:54.60 TV.coast"
2015-07-15T21:50:58.966Z,1436997058.966 [ESPComponent](INFO): runnable
2015-07-15T21:50:58.966Z,1436997058.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:54.61 SC.hold\n"
2015-07-15T21:50:58.966Z,1436997058.966 [ESPComponent](INFO): :-<: LOG "@14:50:54.61 SC.hold"
2015-07-15T21:50:59.366Z,1436997059.366 [ESPComponent](INFO): runnable
2015-07-15T21:50:59.366Z,1436997059.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:54.88 SC.seek 3\n"
2015-07-15T21:50:59.366Z,1436997059.366 [ESPComponent](INFO): :-<: LOG "@14:50:54.88 SC.seek 3"
2015-07-15T21:50:59.766Z,1436997059.766 [ESPComponent](INFO): runnable
2015-07-15T21:50:59.766Z,1436997059.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:55.40 TV.seek :bypass\n"
2015-07-15T21:50:59.766Z,1436997059.766 [ESPComponent](INFO): :-<: LOG "@14:50:55.40 TV.seek :bypass"
2015-07-15T21:51:00.166Z,1436997060.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:00.166Z,1436997060.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:55.91 TV.seek :free\n"
2015-07-15T21:51:00.166Z,1436997060.166 [ESPComponent](INFO): :-<: LOG "@14:50:55.91 TV.seek :free"
2015-07-15T21:51:00.566Z,1436997060.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:00.566Z,1436997060.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:56.43 TV.coast\n"
2015-07-15T21:51:00.566Z,1436997060.566 [ESPComponent](INFO): :-<: LOG "@14:50:56.43 TV.coast"
2015-07-15T21:51:00.966Z,1436997060.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:00.966Z,1436997060.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "SC.hold\n"
2015-07-15T21:51:00.966Z,1436997060.966 [ESPComponent](INFO): :-<: LOG "SC.hold"
2015-07-15T21:51:01.366Z,1436997061.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:01.366Z,1436997061.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:56.71 SC.seek 4\n"
2015-07-15T21:51:01.366Z,1436997061.366 [ESPComponent](INFO): :-<: LOG "@14:50:56.71 SC.seek 4"
2015-07-15T21:51:01.767Z,1436997061.767 [ESPComponent](INFO): runnable
2015-07-15T21:51:01.767Z,1436997061.767 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:57.22 TV.seek :bypass\n"
2015-07-15T21:51:01.767Z,1436997061.767 [ESPComponent](INFO): :-<: LOG "@14:50:57.22 TV.seek :bypass"
2015-07-15T21:51:02.166Z,1436997062.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:02.166Z,1436997062.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:57.74 TV.seek :free\n"
2015-07-15T21:51:02.166Z,1436997062.166 [ESPComponent](INFO): :-<: LOG "@14:50:57.74 TV.seek :free"
2015-07-15T21:51:02.566Z,1436997062.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:02.566Z,1436997062.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:58.26 TV.coast\n"
2015-07-15T21:51:02.566Z,1436997062.566 [ESPComponent](INFO): :-<: LOG "@14:50:58.26 TV.coast"
2015-07-15T21:51:02.966Z,1436997062.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:02.966Z,1436997062.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "SC.hold\n"
2015-07-15T21:51:02.966Z,1436997062.966 [ESPComponent](INFO): :-<: LOG "SC.hold"
2015-07-15T21:51:03.366Z,1436997063.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:03.366Z,1436997063.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:58.53 SC.seek 5\n"
2015-07-15T21:51:03.366Z,1436997063.366 [ESPComponent](INFO): :-<: LOG "@14:50:58.53 SC.seek 5"
2015-07-15T21:51:03.766Z,1436997063.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:03.766Z,1436997063.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:59.05 TV.seek :bypass\n"
2015-07-15T21:51:03.766Z,1436997063.766 [ESPComponent](INFO): :-<: LOG "@14:50:59.05 TV.seek :bypass"
2015-07-15T21:51:04.166Z,1436997064.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:04.166Z,1436997064.166 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:50:59.57 TV.seek :free\n"
2015-07-15T21:51:04.166Z,1436997064.166 [ESPComponent](INFO): :-<: LOG "@14:50:59.57 TV.seek :free"
2015-07-15T21:51:04.566Z,1436997064.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:04.566Z,1436997064.566 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "@14:51:00.09 TV.coast\n"
2015-07-15T21:51:04.566Z,1436997064.566 [ESPComponent](INFO): :-<: LOG "@14:51:00.09 TV.coast"
2015-07-15T21:51:04.966Z,1436997064.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:04.966Z,1436997064.966 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "Selecting Cartridge slot 1\n"
2015-07-15T21:51:04.966Z,1436997064.966 [ESPComponent](INFO): :-<: LOG "Selecting Cartridge slot 1"
2015-07-15T21:51:05.366Z,1436997065.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:05.366Z,1436997065.366 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <LOG> "\207\n"
2015-07-15T21:51:05.366Z,1436997065.366 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T21:51:05.766Z,1436997065.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:05.766Z,1436997065.766 [ESPComponent](INFO): ESPComm: |<| ES_IDLE <STATUS> "IDLE-->LOADING@1\n"
2015-07-15T21:51:05.766Z,1436997065.766 [ESPComponent](INFO): ESPComm: got status line='IDLE-->LOADING@1' ESP transitioned to: 2: ES_LOADING
2015-07-15T21:51:05.766Z,1436997065.766 [ESPComponent](INFO): :-<: STATUS "IDLE-->LOADING@1"
2015-07-15T21:51:06.166Z,1436997066.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:06.166Z,1436997066.166 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <STATUS> "\204\n"
2015-07-15T21:51:06.166Z,1436997066.166 [ESPComponent](INFO): ESPComm: stream change: STATUS -> LOG
2015-07-15T21:51:06.566Z,1436997066.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:06.566Z,1436997066.566 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "SC.hold\n"
2015-07-15T21:51:06.566Z,1436997066.566 [ESPComponent](INFO): :-<: LOG "SC.hold"
2015-07-15T21:51:06.966Z,1436997066.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:06.966Z,1436997066.966 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "@14:51:00.36 SC.seek 1\n"
2015-07-15T21:51:06.966Z,1436997066.966 [ESPComponent](INFO): :-<: LOG "@14:51:00.36 SC.seek 1"
2015-07-15T21:51:07.366Z,1436997067.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:07.366Z,1436997067.366 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "@14:51:00.88 <Rod> Rod.seek :cartridge\n"
2015-07-15T21:51:07.366Z,1436997067.366 [ESPComponent](INFO): :-<: LOG "@14:51:00.88 <Rod> Rod.seek :cartridge"
2015-07-15T21:51:07.766Z,1436997067.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:07.766Z,1436997067.766 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "<PV> PV.seek :cartridge\n"
2015-07-15T21:51:07.766Z,1436997067.766 [ESPComponent](INFO): :-<: LOG "<PV> PV.seek :cartridge"
2015-07-15T21:51:08.166Z,1436997068.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:08.166Z,1436997068.166 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "@14:51:01.43 <LRAUV-tethyssim> SC.coast\n"
2015-07-15T21:51:08.166Z,1436997068.166 [ESPComponent](INFO): :-<: LOG "@14:51:01.43 <LRAUV-tethyssim> SC.coast"
2015-07-15T21:51:08.566Z,1436997068.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:08.566Z,1436997068.566 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <LOG> "\207\n"
2015-07-15T21:51:08.566Z,1436997068.566 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T21:51:08.966Z,1436997068.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:08.966Z,1436997068.966 [ESPComponent](INFO): ESPComm: |<| ES_LOADING <STATUS> "LOADING-->READY@1\n"
2015-07-15T21:51:08.966Z,1436997068.966 [ESPComponent](INFO): ESPComm: got status line='LOADING-->READY@1' ESP transitioned to: 3: ES_READY
2015-07-15T21:51:08.966Z,1436997068.966 [ESPComponent](INFO): :-<: STATUS "LOADING-->READY@1"
2015-07-15T21:51:09.366Z,1436997069.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:09.366Z,1436997069.366 [ESPComponent](INFO): ESPComm: |<| ES_READY <STATUS> "\201\n"
2015-07-15T21:51:09.366Z,1436997069.366 [ESPComponent](INFO): ESPComm: stream change: STATUS -> RESULT
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): ESPComm: |<| ES_READY <RESULT> "1\200\n"
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): ESPComm: stream change: RESULT -> PROMPT
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): :-<: RESULT "1"
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): ESPClient: In S_LOADING_CARTRIDGE, for cmd='Cmd.loadCartridge', consuming result: <<1\n>> which took 19.5996
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): ESPComm: |>| "Cmd.startFiltering\000\n"
2015-07-15T21:51:09.766Z,1436997069.766 [ESPComponent](INFO): ESPClient: issueCommand: cmd='Cmd.startFiltering'
2015-07-15T21:51:10.166Z,1436997070.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:10.166Z,1436997070.166 [ESPComponent](INFO): samplingState_=S_FILTERING
2015-07-15T21:51:10.166Z,1436997070.166 [ESPComponent](INFO): ESPComm: |<| ES_READY <PROMPT> "\204\n"
2015-07-15T21:51:10.166Z,1436997070.166 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:51:10.566Z,1436997070.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:10.566Z,1436997070.566 [ESPComponent](INFO): ESPComm: |<| ES_READY <LOG> "@14:51:09.76 -> Cmd.startFiltering\n"
2015-07-15T21:51:10.566Z,1436997070.566 [ESPComponent](INFO): :-<: LOG "@14:51:09.76 -> Cmd.startFiltering"
2015-07-15T21:51:10.966Z,1436997070.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:10.966Z,1436997070.966 [ESPComponent](INFO): ESPComm: |<| ES_READY <LOG> "\207\n"
2015-07-15T21:51:10.966Z,1436997070.966 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T21:51:11.366Z,1436997071.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:11.366Z,1436997071.366 [ESPComponent](INFO): ESPComm: |<| ES_READY <STATUS> "READY-->FILTERING@0.0\n"
2015-07-15T21:51:11.366Z,1436997071.366 [ESPComponent](INFO): ESPComm: got status line='READY-->FILTERING@0.0' ESP transitioned to: 4: ES_FILTERING
2015-07-15T21:51:11.366Z,1436997071.366 [ESPComponent](INFO): :-<: STATUS "READY-->FILTERING@0.0"
2015-07-15T21:51:11.766Z,1436997071.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:11.766Z,1436997071.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <STATUS> "\201\n"
2015-07-15T21:51:11.766Z,1436997071.766 [ESPComponent](INFO): ESPComm: stream change: STATUS -> RESULT
2015-07-15T21:51:12.166Z,1436997072.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:12.166Z,1436997072.166 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <RESULT> ":FILTERING\200\n"
2015-07-15T21:51:12.166Z,1436997072.166 [ESPComponent](INFO): ESPComm: stream change: RESULT -> PROMPT
2015-07-15T21:51:12.166Z,1436997072.166 [ESPComponent](INFO): :-<: RESULT ":FILTERING"
2015-07-15T21:51:12.166Z,1436997072.166 [ESPComponent](INFO): ESPClient: In S_FILTERING, for cmd='Cmd.startFiltering', consuming result: <<:FILTERING\n>> which took 2.3999
2015-07-15T21:51:12.566Z,1436997072.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:12.566Z,1436997072.566 [ESPComponent](INFO): samplingState_=S_WAITING_FOR_PAUSED
2015-07-15T21:51:12.566Z,1436997072.566 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <PROMPT> "\204\n"
2015-07-15T21:51:12.566Z,1436997072.566 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:51:12.966Z,1436997072.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:12.966Z,1436997072.966 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:09.82 <FILTERING> Pressurizing cartridge to 20psi\n"
2015-07-15T21:51:12.966Z,1436997072.966 [ESPComponent](INFO): :-<: LOG "@14:51:09.82 <FILTERING> Pressurizing cartridge to 20psi"
2015-07-15T21:51:13.366Z,1436997073.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:13.366Z,1436997073.366 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "TV.seek :cartridge\n"
2015-07-15T21:51:13.366Z,1436997073.366 [ESPComponent](INFO): :-<: LOG "TV.seek :cartridge"
2015-07-15T21:51:13.766Z,1436997073.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:13.766Z,1436997073.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:10.34 TV.seek :free\n"
2015-07-15T21:51:13.766Z,1436997073.766 [ESPComponent](INFO): :-<: LOG "@14:51:10.34 TV.seek :free"
2015-07-15T21:51:14.166Z,1436997074.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:14.166Z,1436997074.166 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:10.86 TV.coast\n"
2015-07-15T21:51:14.166Z,1436997074.166 [ESPComponent](INFO): :-<: LOG "@14:51:10.86 TV.coast"
2015-07-15T21:51:14.566Z,1436997074.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:14.566Z,1436997074.566 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "Intake.open\n"
2015-07-15T21:51:14.566Z,1436997074.566 [ESPComponent](INFO): :-<: LOG "Intake.open"
2015-07-15T21:51:14.966Z,1436997074.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:14.966Z,1436997074.966 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:12.36 SP.setPosition! 0.00ml\n"
2015-07-15T21:51:14.966Z,1436997074.966 [ESPComponent](INFO): :-<: LOG "@14:51:12.36 SP.setPosition! 0.00ml"
2015-07-15T21:51:15.366Z,1436997075.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:15.366Z,1436997075.366 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "SP.reconfigure SPcharge\n"
2015-07-15T21:51:15.366Z,1436997075.366 [ESPComponent](INFO): :-<: LOG "SP.reconfigure SPcharge"
2015-07-15T21:51:15.766Z,1436997075.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:15.766Z,1436997075.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "SP.seek 10.00ml,55 seconds\n"
2015-07-15T21:51:15.766Z,1436997075.766 [ESPComponent](INFO): :-<: LOG "SP.seek 10.00ml,55 seconds"
2015-07-15T21:51:16.166Z,1436997076.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:16.166Z,1436997076.166 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:13.85 SP.coast\n"
2015-07-15T21:51:16.166Z,1436997076.166 [ESPComponent](INFO): :-<: LOG "@14:51:13.85 SP.coast"
2015-07-15T21:51:16.566Z,1436997076.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:16.566Z,1436997076.566 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:13.87 Sampling 1000.0ml\n"
2015-07-15T21:51:16.566Z,1436997076.566 [ESPComponent](INFO): :-<: LOG "@14:51:13.87 Sampling 1000.0ml"
2015-07-15T21:51:16.966Z,1436997076.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:16.966Z,1436997076.966 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "Exhaust.open\n"
2015-07-15T21:51:16.966Z,1436997076.966 [ESPComponent](INFO): :-<: LOG "Exhaust.open"
2015-07-15T21:51:17.366Z,1436997077.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:17.366Z,1436997077.366 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:15.37 SP.setPosition! 0.00ml\n"
2015-07-15T21:51:17.366Z,1436997077.366 [ESPComponent](INFO): :-<: LOG "@14:51:15.37 SP.setPosition! 0.00ml"
2015-07-15T21:51:17.766Z,1436997077.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:17.766Z,1436997077.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "SP.reconfigure SPsample\n"
2015-07-15T21:51:17.766Z,1436997077.766 [ESPComponent](INFO): :-<: LOG "SP.reconfigure SPsample"
2015-07-15T21:51:18.166Z,1436997078.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:18.166Z,1436997078.166 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "SP.seek 1000.00ml,1:23:25\n"
2015-07-15T21:51:18.166Z,1436997078.166 [ESPComponent](INFO): :-<: LOG "SP.seek 1000.00ml,1:23:25"
2015-07-15T21:51:18.566Z,1436997078.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:18.566Z,1436997078.566 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:18.17 SP.coast\n"
2015-07-15T21:51:18.566Z,1436997078.566 [ESPComponent](INFO): :-<: LOG "@14:51:18.17 SP.coast"
2015-07-15T21:51:18.966Z,1436997078.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:18.966Z,1436997078.966 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "Exhaust.close\n"
2015-07-15T21:51:18.966Z,1436997078.966 [ESPComponent](INFO): :-<: LOG "Exhaust.close"
2015-07-15T21:51:19.366Z,1436997079.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:19.766Z,1436997079.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:19.766Z,1436997079.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:19.67 Intake.close\n"
2015-07-15T21:51:19.766Z,1436997079.766 [ESPComponent](INFO): :-<: LOG "@14:51:19.67 Intake.close"
2015-07-15T21:51:20.166Z,1436997080.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:20.566Z,1436997080.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:20.966Z,1436997080.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:21.366Z,1436997081.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:21.366Z,1436997081.366 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "@14:51:21.17 Sampled 1000.0ml\n"
2015-07-15T21:51:21.366Z,1436997081.366 [ESPComponent](INFO): :-<: LOG "@14:51:21.17 Sampled 1000.0ml"
2015-07-15T21:51:21.766Z,1436997081.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:21.766Z,1436997081.766 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <LOG> "\207\n"
2015-07-15T21:51:21.766Z,1436997081.766 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T21:51:22.166Z,1436997082.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:22.166Z,1436997082.166 [ESPComponent](INFO): ESPComm: |<| ES_FILTERING <STATUS> "FILTERING-->PAUSED@1000.0\n"
2015-07-15T21:51:22.166Z,1436997082.166 [ESPComponent](INFO): ESPComm: got status line='FILTERING-->PAUSED@1000.0' ESP transitioned to: 5: ES_PAUSED
2015-07-15T21:51:22.166Z,1436997082.166 [ESPComponent](INFO): :-<: STATUS "FILTERING-->PAUSED@1000.0"
2015-07-15T21:51:22.167Z,1436997082.167 [ESPComponent](INFO): ESPComm: |>| "Cmd.startProcessing\000\n"
2015-07-15T21:51:22.167Z,1436997082.167 [ESPComponent](INFO): ESPClient: issueCommand: cmd='Cmd.startProcessing'
2015-07-15T21:51:22.566Z,1436997082.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:22.566Z,1436997082.566 [ESPComponent](INFO): samplingState_=S_PROCESSING
2015-07-15T21:51:22.566Z,1436997082.566 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <STATUS> "\204\n"
2015-07-15T21:51:22.566Z,1436997082.566 [ESPComponent](INFO): ESPComm: stream change: STATUS -> LOG
2015-07-15T21:51:22.966Z,1436997082.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:22.966Z,1436997082.966 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <LOG> "TV.seek :bypass\n"
2015-07-15T21:51:22.966Z,1436997082.966 [ESPComponent](INFO): :-<: LOG "TV.seek :bypass"
2015-07-15T21:51:23.366Z,1436997083.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:23.366Z,1436997083.366 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <LOG> "@14:51:21.69 TV.seek :free\n"
2015-07-15T21:51:23.366Z,1436997083.366 [ESPComponent](INFO): :-<: LOG "@14:51:21.69 TV.seek :free"
2015-07-15T21:51:23.766Z,1436997083.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:23.766Z,1436997083.766 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <LOG> "@14:51:22.16 <LRAUV-tethyssim> -> Cmd.startProcessing\n"
2015-07-15T21:51:23.766Z,1436997083.766 [ESPComponent](INFO): :-<: LOG "@14:51:22.16 <LRAUV-tethyssim> -> Cmd.startProcessing"
2015-07-15T21:51:24.166Z,1436997084.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:24.166Z,1436997084.166 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <LOG> "\207\n"
2015-07-15T21:51:24.166Z,1436997084.166 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T21:51:24.566Z,1436997084.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:24.566Z,1436997084.566 [ESPComponent](INFO): ESPComm: |<| ES_PAUSED <STATUS> "PAUSED-->PROCESSING@1\n"
2015-07-15T21:51:24.566Z,1436997084.566 [ESPComponent](INFO): ESPComm: got status line='PAUSED-->PROCESSING@1' ESP transitioned to: 7: ES_PROCESSING
2015-07-15T21:51:24.566Z,1436997084.566 [ESPComponent](INFO): :-<: STATUS "PAUSED-->PROCESSING@1"
2015-07-15T21:51:24.966Z,1436997084.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:24.966Z,1436997084.966 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <STATUS> "\201\n"
2015-07-15T21:51:24.966Z,1436997084.966 [ESPComponent](INFO): ESPComm: stream change: STATUS -> RESULT
2015-07-15T21:51:25.366Z,1436997085.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:25.366Z,1436997085.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <RESULT> ":PROCESSING\200\n"
2015-07-15T21:51:25.366Z,1436997085.366 [ESPComponent](INFO): ESPComm: stream change: RESULT -> PROMPT
2015-07-15T21:51:25.366Z,1436997085.366 [ESPComponent](INFO): :-<: RESULT ":PROCESSING"
2015-07-15T21:51:25.366Z,1436997085.366 [ESPComponent](INFO): ESPClient: In S_PROCESSING, for cmd='Cmd.startProcessing', consuming result: <<:PROCESSING\n>> which took 3.1993
2015-07-15T21:51:25.766Z,1436997085.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:25.766Z,1436997085.766 [ESPComponent](INFO): samplingState_=S_WAITING_FOR_PROCESSED
2015-07-15T21:51:25.766Z,1436997085.766 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <PROMPT> "\204\n"
2015-07-15T21:51:25.766Z,1436997085.766 [ESPComponent](INFO): ESPComm: stream change: PROMPT -> LOG
2015-07-15T21:51:26.166Z,1436997086.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:26.166Z,1436997086.166 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:22.22 <PROCESSING> PV.seek :cartridge\n"
2015-07-15T21:51:26.166Z,1436997086.166 [ESPComponent](INFO): :-<: LOG "@14:51:22.22 <PROCESSING> PV.seek :cartridge"
2015-07-15T21:51:26.566Z,1436997086.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:26.566Z,1436997086.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:22.23 <FILTERING> TV.coast\n"
2015-07-15T21:51:26.566Z,1436997086.566 [ESPComponent](INFO): :-<: LOG "@14:51:22.23 <FILTERING> TV.coast"
2015-07-15T21:51:26.966Z,1436997086.966 [ESPComponent](INFO): runnable
2015-07-15T21:51:26.966Z,1436997086.966 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:22.49 <PROCESSING> PV.seek :reagent\n"
2015-07-15T21:51:26.966Z,1436997086.966 [ESPComponent](INFO): :-<: LOG "@14:51:22.49 <PROCESSING> PV.seek :reagent"
2015-07-15T21:51:27.366Z,1436997087.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:27.366Z,1436997087.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:23.01 Sample loop closed. Ready to Deliver Reagents\n"
2015-07-15T21:51:27.366Z,1436997087.366 [ESPComponent](INFO): :-<: LOG "@14:51:23.01 Sample loop closed. Ready to Deliver Reagents"
2015-07-15T21:51:27.766Z,1436997087.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:27.766Z,1436997087.766 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "ArS.seek :sealed\n"
2015-07-15T21:51:27.766Z,1436997087.766 [ESPComponent](INFO): :-<: LOG "ArS.seek :sealed"
2015-07-15T21:51:28.166Z,1436997088.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:28.166Z,1436997088.166 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:23.72 ArS.seek :empty\n"
2015-07-15T21:51:28.166Z,1436997088.166 [ESPComponent](INFO): :-<: LOG "@14:51:23.72 ArS.seek :empty"
2015-07-15T21:51:28.566Z,1436997088.566 [ESPComponent](INFO): runnable
2015-07-15T21:51:28.566Z,1436997088.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:24.61 delay 20 seconds\n"
2015-07-15T21:51:28.566Z,1436997088.566 [ESPComponent](INFO): :-<: LOG "@14:51:24.61 delay 20 seconds"
2015-07-15T21:51:28.966Z,1436997088.966 [ESPComponent](INFO): runnable
...
2015-07-15T21:51:44.966Z,1436997104.966 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:44.62 ArS.seek :clear\n"
2015-07-15T21:51:44.967Z,1436997104.967 [ESPComponent](INFO): :-<: LOG "@14:51:44.62 ArS.seek :clear"
2015-07-15T21:51:45.366Z,1436997105.366 [ESPComponent](INFO): runnable
2015-07-15T21:51:45.766Z,1436997105.766 [ESPComponent](INFO): runnable
2015-07-15T21:51:45.766Z,1436997105.766 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@14:51:45.61 RNAlater soak for 10:00\n"
2015-07-15T21:51:45.766Z,1436997105.766 [ESPComponent](INFO): :-<: LOG "@14:51:45.61 RNAlater soak for 10:00"
2015-07-15T21:51:46.166Z,1436997106.166 [ESPComponent](INFO): runnable
2015-07-15T21:51:46.166Z,1436997106.166 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "delay 10:00\n"
2015-07-15T21:51:46.167Z,1436997106.167 [ESPComponent](INFO): :-<: LOG "delay 10:00"
2015-07-15T21:51:46.566Z,1436997106.566 [ESPComponent](INFO): runnable
...
2015-07-15T22:01:45.766Z,1436997705.766 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:45.61 ArS.seek :tVent\n"
2015-07-15T22:01:45.766Z,1436997705.766 [ESPComponent](INFO): :-<: LOG "@15:01:45.61 ArS.seek :tVent"
2015-07-15T22:01:46.566Z,1436997706.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:46.26 delay 1 second\n"
2015-07-15T22:01:46.566Z,1436997706.566 [ESPComponent](INFO): :-<: LOG "@15:01:46.26 delay 1 second"
2015-07-15T22:01:47.366Z,1436997707.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:47.26 ArS.seek :empty\n"
2015-07-15T22:01:47.366Z,1436997707.366 [ESPComponent](INFO): :-<: LOG "@15:01:47.26 ArS.seek :empty"
2015-07-15T22:01:47.766Z,1436997707.766 [ESPComponent](INFO): runnable
2015-07-15T22:01:48.566Z,1436997708.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:48.18 delay 10 seconds\n"
2015-07-15T22:01:48.566Z,1436997708.566 [ESPComponent](INFO): :-<: LOG "@15:01:48.18 delay 10 seconds"
2015-07-15T22:01:48.966Z,1436997708.966 [ESPComponent](INFO): runnable
...
2015-07-15T22:01:58.166Z,1436997718.166 [ESPComponent](INFO): runnable
2015-07-15T22:01:58.566Z,1436997718.566 [ESPComponent](INFO): runnable
2015-07-15T22:01:58.566Z,1436997718.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:58.19 ArS.seek :tVent\n"
2015-07-15T22:01:58.566Z,1436997718.566 [ESPComponent](INFO): :-<: LOG "@15:01:58.19 ArS.seek :tVent"
2015-07-15T22:01:58.966Z,1436997718.966 [ESPComponent](INFO): runnable
2015-07-15T22:01:59.366Z,1436997719.366 [ESPComponent](INFO): runnable
2015-07-15T22:01:59.366Z,1436997719.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:01:59.11 delay 1 second\n"
2015-07-15T22:01:59.366Z,1436997719.366 [ESPComponent](INFO): :-<: LOG "@15:01:59.11 delay 1 second"
2015-07-15T22:01:59.766Z,1436997719.766 [ESPComponent](INFO): runnable
2015-07-15T22:02:00.166Z,1436997720.166 [ESPComponent](INFO): runnable
2015-07-15T22:02:00.166Z,1436997720.166 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:02:00.11 ArS.seek :empty\n"
2015-07-15T22:02:00.166Z,1436997720.166 [ESPComponent](INFO): :-<: LOG "@15:02:00.11 ArS.seek :empty"
2015-07-15T22:02:00.566Z,1436997720.566 [ESPComponent](INFO): runnable
2015-07-15T22:02:00.966Z,1436997720.966 [ESPComponent](INFO): runnable
2015-07-15T22:02:01.366Z,1436997721.366 [ESPComponent](INFO): runnable
2015-07-15T22:02:01.366Z,1436997721.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:02:01.04 delay 10 seconds\n"
2015-07-15T22:02:01.366Z,1436997721.366 [ESPComponent](INFO): :-<: LOG "@15:02:01.04 delay 10 seconds"
2015-07-15T22:02:01.766Z,1436997721.766 [ESPComponent](INFO): runnable
2015-07-15T22:02:02.166Z,1436997722.166 [ESPComponent](INFO): runnable
...
5-07-15T22:02:10.566Z,1436997730.566 [ESPComponent](INFO): runnable
2015-07-15T22:02:10.966Z,1436997730.966 [ESPComponent](INFO): runnable
2015-07-15T22:02:11.366Z,1436997731.366 [ESPComponent](INFO): runnable
2015-07-15T22:02:11.366Z,1436997731.366 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:02:11.04 ArS.seek :clear\n"
2015-07-15T22:02:11.366Z,1436997731.366 [ESPComponent](INFO): :-<: LOG "@15:02:11.04 ArS.seek :clear"
2015-07-15T22:02:11.766Z,1436997731.766 [ESPComponent](INFO): runnable
2015-07-15T22:02:12.166Z,1436997732.166 [ESPComponent](INFO): runnable
2015-07-15T22:02:12.166Z,1436997732.166 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "@15:02:12.03 Sample preserved and evacuated\n"
2015-07-15T22:02:12.166Z,1436997732.166 [ESPComponent](INFO): :-<: LOG "@15:02:12.03 Sample preserved and evacuated"
2015-07-15T22:02:12.566Z,1436997732.566 [ESPComponent](INFO): runnable
2015-07-15T22:02:12.566Z,1436997732.566 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <LOG> "\207\n"
2015-07-15T22:02:12.566Z,1436997732.566 [ESPComponent](INFO): ESPComm: stream change: LOG -> STATUS
2015-07-15T22:02:12.966Z,1436997732.966 [ESPComponent](INFO): runnable
2015-07-15T22:02:12.966Z,1436997732.966 [ESPComponent](INFO): ESPComm: |<| ES_PROCESSING <STATUS> "PROCESSING-->PROCESSED@1\n"
2015-07-15T22:02:12.966Z,1436997732.966 [ESPComponent](INFO): ESPComm: got status line='PROCESSING-->PROCESSED@1' ESP transitioned to: 9: ES_PROCESSED
2015-07-15T22:02:12.966Z,1436997732.966 [ESPComponent](INFO): :-<: STATUS "PROCESSING-->PROCESSED@1"
2015-07-15T22:02:13.366Z,1436997733.366 [ESPComponent](INFO): ESPComponent::stop
2015-07-15T22:02:13.366Z,1436997733.366 [ESPComponent](INFO): Powering down
tethyssim>pppd: no process killed
2015-07-15T22:02:13.766Z,1436997733.766 [ESPComponent](INFO): ESPComponent::stopping
--- Then, for a second "sample" phase, similarly: ---
2015-07-15T22:02:14.566Z,1436997734.566 [ESPComponent](INFO): start simulateHardware()=0
2015-07-15T22:02:14.566Z,1436997734.566 [ESPComponent](INFO): ESPComm: ESPComm::open: opening server socket on port 9998
2015-07-15T22:02:14.566Z,1436997734.566 [ESPComponent](INFO): Powering up
2015-07-15T22:02:14.566Z,1436997734.566 [ESPComponent](INFO): ESPComponent::start: powering up ESP
2015-07-15T22:02:14.566Z,1436997734.566 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 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>sh: /sbin/pppd: No such file or directory
2015-07-15T22:02:14.569Z,1436997734.569 [ESPComponent](INFO): Ready to accept ESP connection: startTimeAccept_=2015-07-15T22:02:14.566Z poTimeout_=150.0000
2015-07-15T22:02:14.966Z,1436997734.966 [ESPComponent](INFO): ESPComponent: waiting for ESP to connect
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment