Martin Varga wrote:

 

What seems suspicious to me in the dependencies - the versions going up and down:

 

 

Any help apprecitated. Sometimes I get the same exception in arqullianBeforeTest as in arquillainAfterTest (the NullPointer)

Your are close to the solution here - make sure you use HtmlUnit 2.12 (which is Selenium 2.35.0 compiled against).

Btw I would prefer PhantomJS instead of HtmlUnit - it will give you more relialable results.

I am working with Martin on this. In order to get it running, we applied a work around in CommandBusOnClient.java as follows:

if (contextRoots.size() == 1) {
    try {
    URI baseURI = context.getServlets().get(0).getBaseURI();
    String path = baseURI.getPath();
    if (path.endsWith("/")) {
    path = path.substring(0, path.length() - 1);
    }
    path = path + CommandBusOnServer.COMMAND_EVENT_BUS_MAPPING;
    return new URI("http", null, baseURI.getHost(), baseURI.getPort(), path, null, null);
    } catch (URISyntaxException e) {
    throw new RuntimeException("Could not convert Servlet to URL, " + context.getServlets().get(0), e);
    }
    } else if (contextRoots.size() > 4) { // <--- temp hack here : Handle the multiple applications - need this as it will fail with NPE otherwise
    try {
    URI baseURI = context.getServlets().get(0).getBaseURI();
    String path = "/test"; //baseURI.getPath();
    if (path.endsWith("/")) {
    path = path.substring(0, path.length() - 1);
    }
    path = path + CommandBusOnServer.COMMAND_EVENT_BUS_MAPPING;
    return new URI("http", null, baseURI.getHost(), baseURI.getPort(), path, null, null);
    } catch (URISyntaxException e) {
    throw new RuntimeException("Could not convert Servlet to URL, " + context.getServlets().get(0), e);
    }
    } else {
    try {
    return new URI("http", null, context.getHost(), context.getPort(),
    CommandBusOnServer.COMMAND_EVENT_BUS_MAPPING, null, null);
    } catch (URISyntaxException e) {
    throw new RuntimeException("Could not convert HTTPContext to URL, " + context, e);
    }
    }

The problem now is the methods in the inspection part are not being executed.

@Test
public void test() {
    System.out.println("Before Test...." + contextPath);
    Warp
    .initiate(new Activity() {
  
    public void perform() {
    String resource1 = contextPath + "/test/index.seam";           
      System.out.println("Navigating to " + resource1);
      browser.navigate().to(resource1);
    }})
  
    .inspect(new Inspection() {
    private static final long serialVersionUID = 1L;

    @AfterPhase(Phase.RESTORE_VIEW)
    public void beforeServlet() {
      System.out.println("###!!! beforeServlet");
    }
  
    @BeforePhase(Phase.RENDER_RESPONSE)
    public void beforePhase() {
      System.out.println("###!!! Before phase");                                  
    }
  
    @AfterPhase(Phase.RENDER_RESPONSE)
    public void theActualTest(@ArquillianResource FacesContext facesContext) {  
          // why is nothing entering here ??
    }  
  }
System.out.println("After Test ...");
);

And the output of the maven test run looks like this

Configuring TestNG with: TestNGMapConfigurator

INFO  17-10 14:59:50,896 [org.xnio.Xnio.<clinit>():63] XNIO Version 3.0.3.GA

INFO  17-10 14:59:50,946 [org.xnio.nio.NioXnio.<clinit>():55] XNIO NIO Implementation Version 3.0.3.GA

INFO  17-10 14:59:51,016 [org.jboss.remoting3.EndpointImpl.<clinit>():70] JBoss Remoting version 3.2.3.GA

DEBUG 17-10 14:59:51,076 [org.xnio.nio.WorkerThread.run():88] Started channel thread 'Remoting "management-client" read-1', selector sun.nio.ch.EPollSelectorImpl@558620f5

DEBUG 17-10 14:59:51,081 [org.xnio.nio.WorkerThread.run():88] Started channel thread 'Remoting "management-client" write-1', selector sun.nio.ch.EPollSelectorImpl@225a8897

13:59:52,015 INFO  [org.jboss.modules] JBoss Modules version 1.1.1.GA

13:59:52,824 INFO  [org.jboss.msc] JBoss MSC version 1.0.2.GA

13:59:52,966 INFO  [org.jboss.as] JBAS015899: JBoss AS 7.1.1.Final "Brontes" starting

13:59:57,530 INFO  [org.xnio] XNIO Version 3.0.3.GA

13:59:57,535 INFO  [org.jboss.as.server] JBAS015888: Creating http management service using socket-binding (management-http)

13:59:57,551 INFO  [org.xnio.nio] XNIO NIO Implementation Version 3.0.3.GA

13:59:57,587 INFO  [org.jboss.remoting] JBoss Remoting version 3.2.3.GA

13:59:57,674 INFO  [org.jboss.as.configadmin] JBAS016200: Activating ConfigAdmin Subsystem

13:59:57,659 INFO  [org.jboss.as.logging] JBAS011502: Removing bootstrap log handlers

DEBUG 17-10 15:00:57,983 [org.xnio.nio.WorkerThread.run():88] Started channel thread 'Remoting "endpoint" read-1', selector sun.nio.ch.EPollSelectorImpl@23a1d5f0

DEBUG 17-10 15:00:57,992 [org.xnio.nio.WorkerThread.run():88] Started channel thread 'Remoting "endpoint" write-1', selector sun.nio.ch.EPollSelectorImpl@79681a61

INFO  17-10 15:01:00,202 [org.littleshoot.proxy.DefaultHttpProxyServer.start():324] Starting proxy on port: 18080

DEBUG 17-10 15:01:00,211 [org.littleshoot.proxy.HttpServerPipelineFactory.<init>():101] Creating server with handshake handler: null

DEBUG 17-10 15:01:06,778 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection():221] Get connection: HttpRoute[{}->http://127.0.0.1:7055], timeout = 120000

DEBUG 17-10 15:01:06,781 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():350] [HttpRoute[{}->http://127.0.0.1:7055]] total kept alive: 0, total issued: 0, total allocated: 0 out of 2000

DEBUG 17-10 15:01:06,782 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getFreeEntry():523] No free connections [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:06,782 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():369] Available capacity: 2000 out of 2000 [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:06,783 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.createEntry():549] Creating new connection [HttpRoute[{}->http://127.0.0.1:7055]]

DEBUG 17-10 15:01:06,810 [org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection():145] Connecting to 127.0.0.1:7055

DEBUG 17-10 15:01:06,867 [org.apache.http.client.protocol.RequestAddCookies.process():132] CookieSpec selected: best-match

DEBUG 17-10 15:01:06,895 [org.apache.http.client.protocol.RequestAuthCache.process():75] Auth cache not set in the context

DEBUG 17-10 15:01:06,896 [org.apache.http.impl.client.DefaultRequestDirector.tryExecute():643] Attempt 1 to execute request

DEBUG 17-10 15:01:06,896 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():264] Sending request: POST /hub/session HTTP/1.1

DEBUG 17-10 15:01:06,900 [org.apache.http.impl.conn.Wire.wire():63] >> "POST /hub/session HTTP/1.1[\r][\n]"

DEBUG 17-10 15:01:06,905 [org.apache.http.impl.conn.Wire.wire():63] >> "Accept: application/json, image/png[\r][\n]"

DEBUG 17-10 15:01:06,906 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Type: application/json; charset=utf-8[\r][\n]"

DEBUG 17-10 15:01:06,906 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Length: 221[\r][\n]"

DEBUG 17-10 15:01:06,907 [org.apache.http.impl.conn.Wire.wire():63] >> "Host: 127.0.0.1:7055[\r][\n]"

DEBUG 17-10 15:01:06,907 [org.apache.http.impl.conn.Wire.wire():63] >> "Connection: Keep-Alive[\r][\n]"

DEBUG 17-10 15:01:06,909 [org.apache.http.impl.conn.Wire.wire():63] >> "[\r][\n]"

DEBUG 17-10 15:01:06,909 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():268] >> POST /hub/session HTTP/1.1

DEBUG 17-10 15:01:06,910 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Accept: application/json, image/png

DEBUG 17-10 15:01:06,911 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Type: application/json; charset=utf-8

DEBUG 17-10 15:01:06,911 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Length: 221

DEBUG 17-10 15:01:06,912 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Host: 127.0.0.1:7055

DEBUG 17-10 15:01:06,913 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Connection: Keep-Alive

DEBUG 17-10 15:01:06,914 [org.apache.http.impl.conn.Wire.wire():77] >> "{"desiredCapabilities":{"loggingPrefs":{"profiling":"INFO","driver":"INFO"},"platform":"ANY","browserName":"firefox","webdriver.firefox.profile":"selenium","webStorageEnabled":true,"version":""},"requiredCapabilities":{}}"

DEBUG 17-10 15:01:06,984 [org.apache.http.impl.conn.Wire.wire():63] << "HTTP/1.1 200 OK[\r][\n]"

DEBUG 17-10 15:01:06,990 [org.apache.http.impl.conn.Wire.wire():63] << "content-type: application/json; charset=UTF-8[\r][\n]"

DEBUG 17-10 15:01:06,991 [org.apache.http.impl.conn.Wire.wire():63] << "connection: close[\r][\n]"

DEBUG 17-10 15:01:06,991 [org.apache.http.impl.conn.Wire.wire():63] << "content-length: 421[\r][\n]"

DEBUG 17-10 15:01:06,992 [org.apache.http.impl.conn.Wire.wire():63] << "server: httpd.js[\r][\n]"

DEBUG 17-10 15:01:06,992 [org.apache.http.impl.conn.Wire.wire():63] << "date: Thu, 17 Oct 2013 14:01:06 GMT[\r][\n]"

DEBUG 17-10 15:01:06,993 [org.apache.http.impl.conn.Wire.wire():63] << "[\r][\n]"

DEBUG 17-10 15:01:06,996 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():249] Receiving response: HTTP/1.1 200 OK

DEBUG 17-10 15:01:06,996 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():252] << HTTP/1.1 200 OK

DEBUG 17-10 15:01:06,997 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-type: application/json; charset=UTF-8

DEBUG 17-10 15:01:06,997 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << connection: close

DEBUG 17-10 15:01:06,998 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-length: 421

DEBUG 17-10 15:01:06,999 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << server: httpd.js

DEBUG 17-10 15:01:06,999 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << date: Thu, 17 Oct 2013 14:01:06 GMT

DEBUG 17-10 15:01:07,014 [org.apache.http.impl.conn.Wire.wire():77] << "{"name":"newSession","sessionId":"8698d75e-5989-4284-9070-99d798831019","status":0,"value":{"cssSelectorsEnabled":true,"browserName":"firefox","handlesAlerts":true,"javascriptEnabled":true,"nativeEvents":false,"platform":"Linux","rotatable":false,"takesScreenshot":true,"version":"10.0.5","webStorageEnabled":true,"applicationCacheEnabled":true,"databaseEnabled":true,"locationContextEnabled":true,"acceptSslCerts":true}}"

DEBUG 17-10 15:01:07,015 [org.apache.http.impl.conn.DefaultClientConnection.shutdown():152] Connection shut down

DEBUG 17-10 15:01:07,016 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection():272] Released connection is not reusable.

DEBUG 17-10 15:01:07,016 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry():434] Releasing connection [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:07,017 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.notifyWaitingThread():679] Notifying no-one, there are no waiting threads

Before Test....http://10.0.21.62:18080

Navigating to http://10.0.21.62:18080/test/index.seam

DEBUG 17-10 15:01:07,131 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection():221] Get connection: HttpRoute[{}->http://127.0.0.1:7055], timeout = 120000

DEBUG 17-10 15:01:07,133 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():350] [HttpRoute[{}->http://127.0.0.1:7055]] total kept alive: 0, total issued: 0, total allocated: 0 out of 2000

DEBUG 17-10 15:01:07,135 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getFreeEntry():523] No free connections [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:07,137 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():369] Available capacity: 2000 out of 2000 [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:07,140 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.createEntry():549] Creating new connection [HttpRoute[{}->http://127.0.0.1:7055]]

DEBUG 17-10 15:01:07,142 [org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection():145] Connecting to 127.0.0.1:7055

DEBUG 17-10 15:01:07,144 [org.apache.http.client.protocol.RequestAddCookies.process():132] CookieSpec selected: best-match

DEBUG 17-10 15:01:07,161 [org.apache.http.client.protocol.RequestAuthCache.process():75] Auth cache not set in the context

DEBUG 17-10 15:01:07,162 [org.apache.http.impl.client.DefaultRequestDirector.tryExecute():643] Attempt 1 to execute request

DEBUG 17-10 15:01:07,165 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():264] Sending request: POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1

DEBUG 17-10 15:01:07,168 [org.apache.http.impl.conn.Wire.wire():63] >> "POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1[\r][\n]"

DEBUG 17-10 15:01:07,170 [org.apache.http.impl.conn.Wire.wire():63] >> "Accept: application/json, image/png[\r][\n]"

DEBUG 17-10 15:01:07,171 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Type: application/json; charset=utf-8[\r][\n]"

DEBUG 17-10 15:01:07,172 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Length: 49[\r][\n]"

DEBUG 17-10 15:01:07,173 [org.apache.http.impl.conn.Wire.wire():63] >> "Host: 127.0.0.1:7055[\r][\n]"

DEBUG 17-10 15:01:07,175 [org.apache.http.impl.conn.Wire.wire():63] >> "Connection: Keep-Alive[\r][\n]"

DEBUG 17-10 15:01:07,176 [org.apache.http.impl.conn.Wire.wire():63] >> "[\r][\n]"

DEBUG 17-10 15:01:07,177 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():268] >> POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1

DEBUG 17-10 15:01:07,179 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Accept: application/json, image/png

DEBUG 17-10 15:01:07,180 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Type: application/json; charset=utf-8

DEBUG 17-10 15:01:07,181 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Length: 49

DEBUG 17-10 15:01:07,182 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Host: 127.0.0.1:7055

DEBUG 17-10 15:01:07,183 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Connection: Keep-Alive

DEBUG 17-10 15:01:07,184 [org.apache.http.impl.conn.Wire.wire():77] >> "{"url":"http://10.0.21.62:18080/test/index.seam"}"

DEBUG 17-10 15:01:07,230 [org.littleshoot.proxy.HttpServerPipelineFactory.getPipeline():142] Accessing pipeline

INFO  17-10 15:01:07,344 [org.littleshoot.proxy.HttpRequestHandler.<init>():212] Creating new request handler...

DEBUG 17-10 15:01:07,409 [org.littleshoot.proxy.HttpRequestHandler.channelOpen():754] New channel opened: [id: 0xb447a5c1, /10.0.21.62:38548 => /10.0.21.62:18080]

DEBUG 17-10 15:01:07,409 [org.littleshoot.proxy.HttpRequestHandler.channelOpen():757] Now 1 browser to proxy channels...

DEBUG 17-10 15:01:07,410 [org.littleshoot.proxy.HttpRequestHandler.channelOpen():759] Now this class has 1 browser to proxy channels...

DEBUG 17-10 15:01:07,457 [org.littleshoot.proxy.HttpRequestHandler.messageReceived():274] Received 1 total messages

DEBUG 17-10 15:01:07,460 [org.littleshoot.proxy.HttpRequestHandler.processRequest():369] Got request: DefaultHttpRequest(chunked: false)

GET /test/index.seam HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive on channel: [id: 0xb447a5c1, /10.0.21.62:38548 => /10.0.21.62:18080]

DEBUG 17-10 15:01:07,462 [org.littleshoot.proxy.HttpRequestHandler.processRequest():457] Establishing new connection

DEBUG 17-10 15:01:07,468 [org.littleshoot.proxy.HttpRequestHandler.newChannelFuture():722] Starting new connection to: 127.0.0.1:19916

DEBUG 17-10 15:01:07,469 [org.littleshoot.proxy.DefaultRelayPipelineFactory.getPipeline():88] Querying for host and port: 127.0.0.1:19916

DEBUG 17-10 15:01:07,469 [org.littleshoot.proxy.DefaultRelayPipelineFactory.getPipeline():101] Using filter: org.jboss.arquillian.warp.impl.client.proxy.DefaultProxyService$7@698114b1

DEBUG 17-10 15:01:07,474 [org.littleshoot.proxy.DefaultRelayPipelineFactory.getPipeline():112] Filtering: true

INFO  17-10 15:01:07,474 [org.littleshoot.proxy.DefaultRelayPipelineFactory.getPipeline():122] Creating relay handler with filter

DEBUG 17-10 15:01:07,523 [org.littleshoot.proxy.HttpRelayingHandler.channelOpen():471] New channel opened from proxy to web: [id: 0xa68e2916]

DEBUG 17-10 15:01:07,531 [org.littleshoot.proxy.HttpRelayingHandler.channelConnected():338] CHANNEL CONNECTED!!

DEBUG 17-10 15:01:07,532 [org.littleshoot.proxy.HttpRequestHandler$1LocalChannelFutureListener.operationComplete():486] Connected successfully to: [id: 0xa68e2916, /127.0.0.1:37432 => /127.0.0.1:19916]

DEBUG 17-10 15:01:07,533 [org.littleshoot.proxy.HttpRequestHandler$1LocalChannelFutureListener.operationComplete():487] Writing message on channel...

DEBUG 17-10 15:01:07,831 [org.littleshoot.proxy.HttpRequestHandler$1LocalChannelFutureListener$1.operationComplete():493] Finished write: org.jboss.netty.channel.DefaultChannelFuture@26bef3ab to: GET /test/index.seam

DEBUG 17-10 15:01:07,834 [org.littleshoot.proxy.HttpRequestHandler$1LocalChannelFutureListener$1.operationComplete():498] Channel is readable: true

DEBUG 17-10 15:01:08,690 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():133] Received raw response: DefaultHttpResponse(chunked: false)

HTTP/1.1 200 OK

Server: Apache-Coyote/1.1

X-Arq-Enrichment-Response: 2629940843487249190

X-Powered-By: JSF/2.0

Set-Cookie: JSESSIONID=Yx6rQV0miWt2x0ivmRAxfju1.main; Path=/test

Content-Type: text/html;charset=UTF-8

Content-Length: 248

Date: Thu, 17 Oct 2013 14:01:07 GMT

DEBUG 17-10 15:01:08,785 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseRemoteConnection():463] Not closing -- response probably keep alive for:

DefaultHttpResponse(chunked: false)

HTTP/1.1 200 OK

Content-Length: 248

Content-Type: text/html;charset=UTF-8

Date: Thu, 17 Oct 2013 14:01:07 GMT

Server: Apache-Coyote/1.1

Set-Cookie: JSESSIONID=Yx6rQV0miWt2x0ivmRAxfju1.main; Path=/test

X-Arq-Enrichment-Response: 2629940843487249190

X-Powered-By: JSF/2.0

DEBUG 17-10 15:01:08,785 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseBrowserConnection():405] Not closing browser/client to proxy connection for request: DefaultHttpRequest(chunked: false)

GET /test/index.seam HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive

X-Arq-Enrichment-Request: 2629940843487249190

DEBUG 17-10 15:01:08,792 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():255] Notifying request handler of completed response.

INFO  17-10 15:01:08,795 [org.littleshoot.proxy.HttpRequestHandler.onRelayHttpResponse():865] Not closing browser to proxy channel. Still awaiting 0 responses...receivedChannelClosed=false

DEBUG 17-10 15:01:08,796 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():299] Making remote channel available for requests

DEBUG 17-10 15:01:08,798 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():326] Finished processing message

DEBUG 17-10 15:01:08,948 [org.littleshoot.proxy.HttpRequestHandler.messageReceived():274] Received 2 total messages

DEBUG 17-10 15:01:08,950 [org.littleshoot.proxy.HttpRequestHandler.processRequest():369] Got request: DefaultHttpRequest(chunked: false)

GET /favicon.ico HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: image/png,image/*;q=0.8,*/*;q=0.5

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive on channel: [id: 0xb447a5c1, /10.0.21.62:38548 => /10.0.21.62:18080]

DEBUG 17-10 15:01:08,950 [org.littleshoot.proxy.HttpRequestHandler.processRequest():434] Using existing connection...

DEBUG 17-10 15:01:08,951 [org.apache.http.impl.conn.Wire.wire():63] << "HTTP/1.1 200 OK[\r][\n]"

DEBUG 17-10 15:01:08,953 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():133] Received raw response: DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Server: Apache-Coyote/1.1

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

DEBUG 17-10 15:01:08,954 [org.apache.http.impl.conn.Wire.wire():63] << "content-type: application/json; charset=UTF-8[\r][\n]"

DEBUG 17-10 15:01:08,956 [org.apache.http.impl.conn.Wire.wire():63] << "connection: close[\r][\n]"

DEBUG 17-10 15:01:08,957 [org.apache.http.impl.conn.Wire.wire():63] << "content-length: 87[\r][\n]"

DEBUG 17-10 15:01:08,958 [org.apache.http.impl.conn.Wire.wire():63] << "server: httpd.js[\r][\n]"

DEBUG 17-10 15:01:08,955 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseRemoteConnection():463] Not closing -- response probably keep alive for:

DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

Server: Apache-Coyote/1.1

DEBUG 17-10 15:01:08,960 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseBrowserConnection():405] Not closing browser/client to proxy connection for request: DefaultHttpRequest(chunked: false)

GET /favicon.ico HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: image/png,image/*;q=0.8,*/*;q=0.5

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive

DEBUG 17-10 15:01:08,960 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():255] Notifying request handler of completed response.

DEBUG 17-10 15:01:08,961 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():299] Making remote channel available for requests

DEBUG 17-10 15:01:08,962 [org.apache.http.impl.conn.Wire.wire():63] << "date: Thu, 17 Oct 2013 14:01:08 GMT[\r][\n]"

INFO  17-10 15:01:08,962 [org.littleshoot.proxy.HttpRequestHandler.onRelayHttpResponse():865] Not closing browser to proxy channel. Still awaiting 0 responses...receivedChannelClosed=false

DEBUG 17-10 15:01:08,962 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():326] Finished processing message

DEBUG 17-10 15:01:08,963 [org.apache.http.impl.conn.Wire.wire():63] << "[\r][\n]"

DEBUG 17-10 15:01:08,966 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():249] Receiving response: HTTP/1.1 200 OK

DEBUG 17-10 15:01:08,967 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():252] << HTTP/1.1 200 OK

DEBUG 17-10 15:01:08,968 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-type: application/json; charset=UTF-8

DEBUG 17-10 15:01:08,969 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << connection: close

DEBUG 17-10 15:01:08,972 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-length: 87

DEBUG 17-10 15:01:08,973 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << server: httpd.js

DEBUG 17-10 15:01:08,975 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << date: Thu, 17 Oct 2013 14:01:08 GMT

DEBUG 17-10 15:01:08,976 [org.apache.http.impl.conn.Wire.wire():77] << "{"name":"get","sessionId":"8698d75e-5989-4284-9070-99d798831019","status":0,"value":""}"

DEBUG 17-10 15:01:08,978 [org.apache.http.impl.conn.DefaultClientConnection.shutdown():152] Connection shut down

DEBUG 17-10 15:01:08,979 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection():272] Released connection is not reusable.

DEBUG 17-10 15:01:08,980 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry():434] Releasing connection [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:08,982 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.notifyWaitingThread():679] Notifying no-one, there are no waiting threads

Navigating to http://10.0.21.62:18080/nothing.here

DEBUG 17-10 15:01:08,984 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection():221] Get connection: HttpRoute[{}->http://127.0.0.1:7055], timeout = 120000

DEBUG 17-10 15:01:08,986 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():350] [HttpRoute[{}->http://127.0.0.1:7055]] total kept alive: 0, total issued: 0, total allocated: 0 out of 2000

DEBUG 17-10 15:01:08,987 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getFreeEntry():523] No free connections [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:08,988 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():369] Available capacity: 2000 out of 2000 [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:08,989 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.createEntry():549] Creating new connection [HttpRoute[{}->http://127.0.0.1:7055]]

DEBUG 17-10 15:01:08,990 [org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection():145] Connecting to 127.0.0.1:7055

DEBUG 17-10 15:01:08,992 [org.apache.http.client.protocol.RequestAddCookies.process():132] CookieSpec selected: best-match

DEBUG 17-10 15:01:08,994 [org.apache.http.client.protocol.RequestAuthCache.process():75] Auth cache not set in the context

DEBUG 17-10 15:01:08,995 [org.apache.http.impl.client.DefaultRequestDirector.tryExecute():643] Attempt 1 to execute request

DEBUG 17-10 15:01:08,996 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():264] Sending request: POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1

DEBUG 17-10 15:01:08,998 [org.apache.http.impl.conn.Wire.wire():63] >> "POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1[\r][\n]"

DEBUG 17-10 15:01:08,999 [org.apache.http.impl.conn.Wire.wire():63] >> "Accept: application/json, image/png[\r][\n]"

DEBUG 17-10 15:01:09,001 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Type: application/json; charset=utf-8[\r][\n]"

DEBUG 17-10 15:01:09,002 [org.apache.http.impl.conn.Wire.wire():63] >> "Content-Length: 46[\r][\n]"

DEBUG 17-10 15:01:09,003 [org.apache.http.impl.conn.Wire.wire():63] >> "Host: 127.0.0.1:7055[\r][\n]"

DEBUG 17-10 15:01:09,004 [org.apache.http.impl.conn.Wire.wire():63] >> "Connection: Keep-Alive[\r][\n]"

DEBUG 17-10 15:01:09,005 [org.apache.http.impl.conn.Wire.wire():63] >> "[\r][\n]"

DEBUG 17-10 15:01:09,007 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():268] >> POST /hub/session/8698d75e-5989-4284-9070-99d798831019/url HTTP/1.1

DEBUG 17-10 15:01:09,008 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Accept: application/json, image/png

DEBUG 17-10 15:01:09,009 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Type: application/json; charset=utf-8

DEBUG 17-10 15:01:09,010 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Content-Length: 46

DEBUG 17-10 15:01:09,011 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Host: 127.0.0.1:7055

DEBUG 17-10 15:01:09,012 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Connection: Keep-Alive

DEBUG 17-10 15:01:09,014 [org.apache.http.impl.conn.Wire.wire():77] >> "{"url":"http://10.0.21.62:18080/nothing.here"}"

DEBUG 17-10 15:01:09,037 [org.littleshoot.proxy.HttpRequestHandler.messageReceived():274] Received 3 total messages

DEBUG 17-10 15:01:09,038 [org.littleshoot.proxy.HttpRequestHandler.processRequest():369] Got request: DefaultHttpRequest(chunked: false)

GET /favicon.ico HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive on channel: [id: 0xb447a5c1, /10.0.21.62:38548 => /10.0.21.62:18080]

DEBUG 17-10 15:01:09,039 [org.littleshoot.proxy.HttpRequestHandler.processRequest():434] Using existing connection...

DEBUG 17-10 15:01:09,041 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():133] Received raw response: DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Server: Apache-Coyote/1.1

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

DEBUG 17-10 15:01:09,042 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseRemoteConnection():463] Not closing -- response probably keep alive for:

DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

Server: Apache-Coyote/1.1

DEBUG 17-10 15:01:09,043 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseBrowserConnection():405] Not closing browser/client to proxy connection for request: DefaultHttpRequest(chunked: false)

GET /favicon.ico HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive

DEBUG 17-10 15:01:09,043 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():255] Notifying request handler of completed response.

DEBUG 17-10 15:01:09,044 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():299] Making remote channel available for requests

DEBUG 17-10 15:01:09,044 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():326] Finished processing message

INFO  17-10 15:01:09,045 [org.littleshoot.proxy.HttpRequestHandler.onRelayHttpResponse():865] Not closing browser to proxy channel. Still awaiting 0 responses...receivedChannelClosed=false

DEBUG 17-10 15:01:09,109 [org.littleshoot.proxy.HttpRequestHandler.messageReceived():274] Received 4 total messages

DEBUG 17-10 15:01:09,109 [org.littleshoot.proxy.HttpRequestHandler.processRequest():369] Got request: DefaultHttpRequest(chunked: false)

GET /nothing.here HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive on channel: [id: 0xb447a5c1, /10.0.21.62:38548 => /10.0.21.62:18080]

DEBUG 17-10 15:01:09,110 [org.littleshoot.proxy.HttpRequestHandler.processRequest():434] Using existing connection...

DEBUG 17-10 15:01:09,112 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():133] Received raw response: DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Server: Apache-Coyote/1.1

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

DEBUG 17-10 15:01:09,114 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseRemoteConnection():463] Not closing -- response probably keep alive for:

DefaultHttpResponse(chunked: false)

HTTP/1.1 404 Not Found

Content-Length: 0

Date: Thu, 17 Oct 2013 14:01:08 GMT

Server: Apache-Coyote/1.1

DEBUG 17-10 15:01:09,115 [org.littleshoot.proxy.HttpRelayingHandler.shouldCloseBrowserConnection():405] Not closing browser/client to proxy connection for request: DefaultHttpRequest(chunked: false)

GET /nothing.here HTTP/1.1

Host: 10.0.21.62:18080

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0.5) Gecko/20120601 Firefox/10.0.5

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip, deflate

Connection: keep-alive

DEBUG 17-10 15:01:09,116 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():255] Notifying request handler of completed response.

INFO  17-10 15:01:09,117 [org.littleshoot.proxy.HttpRequestHandler.onRelayHttpResponse():865] Not closing browser to proxy channel. Still awaiting 0 responses...receivedChannelClosed=false

DEBUG 17-10 15:01:09,117 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():299] Making remote channel available for requests

DEBUG 17-10 15:01:09,118 [org.littleshoot.proxy.HttpRelayingHandler.messageReceived():326] Finished processing message

DEBUG 17-10 15:01:09,366 [org.apache.http.impl.conn.Wire.wire():63] << "HTTP/1.1 200 OK[\r][\n]"

DEBUG 17-10 15:01:09,367 [org.apache.http.impl.conn.Wire.wire():63] << "content-type: application/json; charset=UTF-8[\r][\n]"

DEBUG 17-10 15:01:09,367 [org.apache.http.impl.conn.Wire.wire():63] << "connection: close[\r][\n]"

DEBUG 17-10 15:01:09,368 [org.apache.http.impl.conn.Wire.wire():63] << "content-length: 87[\r][\n]"

DEBUG 17-10 15:01:09,369 [org.apache.http.impl.conn.Wire.wire():63] << "server: httpd.js[\r][\n]"

DEBUG 17-10 15:01:09,369 [org.apache.http.impl.conn.Wire.wire():63] << "date: Thu, 17 Oct 2013 14:01:09 GMT[\r][\n]"

DEBUG 17-10 15:01:09,370 [org.apache.http.impl.conn.Wire.wire():63] << "[\r][\n]"

DEBUG 17-10 15:01:09,370 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():249] Receiving response: HTTP/1.1 200 OK

DEBUG 17-10 15:01:09,371 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():252] << HTTP/1.1 200 OK

DEBUG 17-10 15:01:09,371 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-type: application/json; charset=UTF-8

DEBUG 17-10 15:01:09,372 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << connection: close

DEBUG 17-10 15:01:09,373 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-length: 87

DEBUG 17-10 15:01:09,374 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << server: httpd.js

DEBUG 17-10 15:01:09,375 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << date: Thu, 17 Oct 2013 14:01:09 GMT

DEBUG 17-10 15:01:09,376 [org.apache.http.impl.conn.Wire.wire():77] << "{"name":"get","sessionId":"8698d75e-5989-4284-9070-99d798831019","status":0,"value":""}"

DEBUG 17-10 15:01:09,377 [org.apache.http.impl.conn.DefaultClientConnection.shutdown():152] Connection shut down

DEBUG 17-10 15:01:09,377 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection():272] Released connection is not reusable.

DEBUG 17-10 15:01:09,378 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry():434] Releasing connection [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:09,379 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.notifyWaitingThread():679] Notifying no-one, there are no waiting threads

After Test....

DEBUG 17-10 15:01:09,410 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection():221] Get connection: HttpRoute[{}->http://127.0.0.1:7055], timeout = 120000

DEBUG 17-10 15:01:09,411 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():350] [HttpRoute[{}->http://127.0.0.1:7055]] total kept alive: 0, total issued: 0, total allocated: 0 out of 2000

DEBUG 17-10 15:01:09,412 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getFreeEntry():523] No free connections [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:09,412 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking():369] Available capacity: 2000 out of 2000 [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:09,413 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.createEntry():549] Creating new connection [HttpRoute[{}->http://127.0.0.1:7055]]

DEBUG 17-10 15:01:09,414 [org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection():145] Connecting to 127.0.0.1:7055

DEBUG 17-10 15:01:09,414 [org.apache.http.client.protocol.RequestAddCookies.process():132] CookieSpec selected: best-match

DEBUG 17-10 15:01:09,415 [org.apache.http.client.protocol.RequestAuthCache.process():75] Auth cache not set in the context

DEBUG 17-10 15:01:09,416 [org.apache.http.impl.client.DefaultRequestDirector.tryExecute():643] Attempt 1 to execute request

DEBUG 17-10 15:01:09,417 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():264] Sending request: DELETE /hub/session/8698d75e-5989-4284-9070-99d798831019 HTTP/1.1

DEBUG 17-10 15:01:09,417 [org.apache.http.impl.conn.Wire.wire():63] >> "DELETE /hub/session/8698d75e-5989-4284-9070-99d798831019 HTTP/1.1[\r][\n]"

DEBUG 17-10 15:01:09,418 [org.apache.http.impl.conn.Wire.wire():63] >> "Accept: application/json, image/png[\r][\n]"

DEBUG 17-10 15:01:09,418 [org.apache.http.impl.conn.Wire.wire():63] >> "Host: 127.0.0.1:7055[\r][\n]"

DEBUG 17-10 15:01:09,419 [org.apache.http.impl.conn.Wire.wire():63] >> "Connection: Keep-Alive[\r][\n]"

DEBUG 17-10 15:01:09,420 [org.apache.http.impl.conn.Wire.wire():63] >> "[\r][\n]"

DEBUG 17-10 15:01:09,420 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():268] >> DELETE /hub/session/8698d75e-5989-4284-9070-99d798831019 HTTP/1.1

DEBUG 17-10 15:01:09,420 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Accept: application/json, image/png

DEBUG 17-10 15:01:09,421 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Host: 127.0.0.1:7055

DEBUG 17-10 15:01:09,421 [org.apache.http.impl.conn.DefaultClientConnection.sendRequestHeader():271] >> Connection: Keep-Alive

DEBUG 17-10 15:01:09,426 [org.apache.http.impl.conn.Wire.wire():63] << "HTTP/1.1 200 OK[\r][\n]"

DEBUG 17-10 15:01:09,426 [org.apache.http.impl.conn.Wire.wire():63] << "content-type: application/json; charset=UTF-8[\r][\n]"

DEBUG 17-10 15:01:09,427 [org.apache.http.impl.conn.Wire.wire():63] << "connection: close[\r][\n]"

DEBUG 17-10 15:01:09,427 [org.apache.http.impl.conn.Wire.wire():63] << "content-length: 88[\r][\n]"

DEBUG 17-10 15:01:09,428 [org.apache.http.impl.conn.Wire.wire():63] << "server: httpd.js[\r][\n]"

DEBUG 17-10 15:01:09,428 [org.apache.http.impl.conn.Wire.wire():63] << "date: Thu, 17 Oct 2013 14:01:09 GMT[\r][\n]"

DEBUG 17-10 15:01:09,429 [org.apache.http.impl.conn.Wire.wire():63] << "[\r][\n]"

DEBUG 17-10 15:01:09,429 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():249] Receiving response: HTTP/1.1 200 OK

DEBUG 17-10 15:01:09,430 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():252] << HTTP/1.1 200 OK

DEBUG 17-10 15:01:09,430 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-type: application/json; charset=UTF-8

DEBUG 17-10 15:01:09,430 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << connection: close

DEBUG 17-10 15:01:09,431 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << content-length: 88

DEBUG 17-10 15:01:09,431 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << server: httpd.js

DEBUG 17-10 15:01:09,432 [org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader():255] << date: Thu, 17 Oct 2013 14:01:09 GMT

DEBUG 17-10 15:01:09,432 [org.apache.http.impl.conn.Wire.wire():77] << "{"name":"quit","sessionId":"8698d75e-5989-4284-9070-99d798831019","status":0,"value":""}"

DEBUG 17-10 15:01:09,433 [org.apache.http.impl.conn.DefaultClientConnection.shutdown():152] Connection shut down

DEBUG 17-10 15:01:09,433 [org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager.releaseConnection():272] Released connection is not reusable.

DEBUG 17-10 15:01:09,433 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.freeEntry():434] Releasing connection [HttpRoute[{}->http://127.0.0.1:7055]][null]

DEBUG 17-10 15:01:09,434 [org.apache.http.impl.conn.tsccm.ConnPoolByRoute.notifyWaitingThread():679] Notifying no-one, there are no waiting threads

DEBUG 17-10 15:01:09,460 [org.littleshoot.proxy.HttpRequestHandler.channelClosed():771] Channel closed: [id: 0xb447a5c1, /10.0.21.62:38548 :> /10.0.21.62:18080]

DEBUG 17-10 15:01:09,460 [org.littleshoot.proxy.HttpRequestHandler.channelClosed():775] Now 0 total browser to proxy channels...

DEBUG 17-10 15:01:09,460 [org.littleshoot.proxy.HttpRequestHandler.channelClosed():777] Now this class has 0 browser to proxy channels...

DEBUG 17-10 15:01:09,460 [org.littleshoot.proxy.HttpRequestHandler.channelClosed():783] Closing all proxy to web channels for this browser to proxy connection!!!

DEBUG 17-10 15:01:09,461 [org.littleshoot.proxy.HttpRequestHandler.channelClosed():788] Closing future...

DEBUG 17-10 15:01:09,467 [org.littleshoot.proxy.HttpRelayingHandler.channelClosed():480] Got closed event on proxy -> web connection: [id: 0xa68e2916, /127.0.0.1:37432 :> /127.0.0.1:19916]

DEBUG 17-10 15:01:09,467 [org.littleshoot.proxy.HttpRelayingHandler.channelClosed():487] Unanswered requests: 0

DEBUG 17-10 15:01:09,468 [org.littleshoot.proxy.HttpRequestHandler.onRelayChannelClose():809] this.receivedChannelClosed: true

DEBUG 17-10 15:01:09,468 [org.littleshoot.proxy.HttpRequestHandler.onRelayChannelClose():826] Closing browser to proxy channel

DEBUG 17-10 15:01:09,468 [org.littleshoot.proxy.ProxyUtils.closeOnFlush():345] Closing on flush: [id: 0xb447a5c1, /10.0.21.62:38548 :> /10.0.21.62:18080]

INFO  17-10 15:01:16,249 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():374] Shutting down proxy

INFO  17-10 15:01:16,250 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():381] Closing all channels...

INFO  17-10 15:01:16,276 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():397] Stopping timer

INFO  17-10 15:01:16,295 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():402] Done shutting down proxy

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 88.06 sec

INFO  17-10 15:01:16,480 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():374] Shutting down proxy

INFO  17-10 15:01:16,482 [org.littleshoot.proxy.DefaultHttpProxyServer.stop():376] Already stopped

Results :

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0

[WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent!

[INFO]

[INFO] --- maven-failsafe-plugin:2.14.1:verify (arq) @ common-ejb3 ---

[INFO] Failsafe report directory: /localhome/userabc/tmp/FW-trunk.build.x86_64/_build/core/OAM/common-ejb3/failsafe-reports

[WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent!

[INFO] ------------------------------------------------------------------------

[INFO] BUILD SUCCESS

[INFO] ------------------------------------------------------------------------

[INFO] Total time: 3:43.742s

[INFO] Finished at: Thu Oct 17 15:01:16 IST 2013

[INFO] Final Memory: 52M/418M

[INFO] ------------------------------------------------------------------------

Any ideas why the inspection methods are not executing ?

Five years later, I run into the same error message - but using WildFly 15. Does anybody have any hints on the reasons for this?

I can post a full maven sample.

Best regards

Wolfgang

I found the reason why the "InspectionMethodWasNotInvokedException" was thrown in my situation, with the help of the Arquillian Warp unit tests.

It happened because my test case was the first request to the JSF page (without any other request). After this, I filled some form fields and performed a "submit" click:

Warp
.initiate(new Activity() {
  @Override
  public void perform() {
     
     browser.navigate().to(deploymentUrl.toExternalForm() + "mypage.faces");
     
     ...write values to some form elements...
     
     WebElement btn = browser.findElement(By.id("myInputForm:submitButton"));
    btn.click();
  }
  .inspect(new Inspection() {
     private static final long serialVersionUID = 1L;

    @AfterPhase(Phase.INVOKE_APPLICATION)
    public void afterInvokeApplication() {
       System.out.println("afterInvokeApplication");
    } 
  });

The "afterInvokeApplication" phase method caused the exception.

To make it work, I had to split the two calls:

First call the start page:

Warp
.initiate(new Activity() {
  @Override
  public void perform() {
     
     browser.navigate().to(deploymentUrl.toExternalForm() + "mypage.faces");
  }
  .inspect(new Inspection() {
     private static final long serialVersionUID = 1L;
     
    //No relevant methods here, but the Inspection seems to be required...
  });

Next, submit the form:

Warp
.initiate(new Activity() {
  @Override
  public void perform() {
     
     ...write values to some form elements...
     
     WebElement btn = browser.findElement(By.id("myInputForm:submitButton"));
    btn.click();
  }
  .inspect(new Inspection() {
     private static final long serialVersionUID = 1L;

    @AfterPhase(Phase.INVOKE_APPLICATION)
    public void afterInvokeApplication() {
       System.out.println("afterInvokeApplication");
    } 
  });

Magically, it works now ;-).

My theory is that in my first snippet, two JSF requests are made, and the Inspection seems to be triggered for the first request. At this stage, the JSF page is initialized, but as there is no invocation of a JSF method, some phases are not passed through. Only the phases Phase.RENDER_RESPONSE and Phase.RESTORE_VIEW are possible here. The second request to the JSF page is not handled by the inspection.

Wolfgang