Bug 849719

Summary: IBM perfharness fails to "Connection refused"
Product: Red Hat Enterprise MRG Reporter: ppecka <ppecka>
Component: qpid-javaAssignee: Rajith Attapattu <rattapat+nobody>
Status: CLOSED CURRENTRELEASE QA Contact: ppecka <ppecka>
Severity: high Docs Contact:
Priority: high    
Version: 2.2CC: iboverma, jross, rattapat+nobody
Target Milestone: 2.3   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-09-24 15:52:11 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Comment 1 Rajith Attapattu 2012-08-21 01:56:20 UTC
After futher investigation I found the following.

The connection on the client side is closed by the client, bcos it receives an EOF. The client reads a -1 which will cause it to exit.

At that point I printed the following information.
Closing Connection - socket closed ? false
Closing Connection - socket connected ? true
Closing Connection - socket connection input shutdown ? true
Closing Connection - socket connection output shutdown ? false

This clearly shows the,
1. connection is still alive
2. the client hasn't closed the output stream

I verified that no exception is raised and that the loop exited due to reading -1
(I printed the value of "read" at the time the loop ended).

This cannot be due to heartbeats, as in that case there should be a java.net.SocketTimeoutException

I wonder what is causing the broker to send an EOF?
Could there be an error that is causing the output stream (on the broker side) to shutdown ?

Comment 3 Rajith Attapattu 2012-08-22 15:17:46 UTC
The above turned out to be a non issue. Verified after testing multiple times.

The real issue is as follows.
-----------------------------

While the client waits on a commit, the connection is lost. And subsequent connections are also unsucessful.

This could be due to,

1. The broker closing the connection and refusing subsequent connections. The probability is low, as the broker is still around and there are no logs indicating the broker closing the connection.

2. Intermittent network issues. Probability is high for several reasons,
    1. Difficult to reproduce suggesting it could be an env issue
    2. The connection is lost and subsquent connections lost with broker having no trace of it.

3. The test framework closing the connection due to a timeout. This is unlikely as the codepaths show in the exception is only triggered when the connection is lost - not when it's closed normally.

Comment 4 ppecka 2012-08-22 15:56:21 UTC
(In reply to comment #3)

> 
> 2. Intermittent network issues. Probability is high for several reasons,
>     1. Difficult to reproduce suggesting it could be an env issue
>     2. The connection is lost and subsquent connections lost with broker
> having no trace of it.

we found similar looking issue when two consequent JMS client testcases from our internal QE testsuite was refused/broke connection. Test is running against localhost broker in beaker environment. following testcases are passing as ususal. Again effort to see such exception is ~ "very hard"


12:50:09] -TEST-CASE:V.MRG.M.0015.82;TEST-CASE-DESC:Bug 730977: java client fails to resolve target when assert is used in the address ... (JAVA)------------
[12:50:09] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "amq.direct;{ assert:always, node: { type:topic }, link: {  } }"
[12:50:14] RESPONSE: {}
IoSender - localhost/127.0.0.1:5672 2012-08-21 12:50:14,939 ERROR [transport.network.io.IoSender] error in write thread
java.net.SocketException: Broken pipe
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
	at org.apache.qpid.transport.network.io.IoSender.run(IoSender.java:313)
	at java.lang.Thread.run(Thread.java:679)
Exception in thread "main" org.apache.qpid.AMQConnectionFailureException: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:444)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:215)
	at org.apache.qpid.example.OptionParser.createConnection(OptionParser.java:281)
	at org.apache.qpid.example.Drain.<init>(Drain.java:66)
	at org.apache.qpid.example.Drain.main(Drain.java:104)
Caused by: org.apache.qpid.AMQException: Cannot connect to broker: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:239)
	at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:588)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:367)
	... 4 more
Caused by: org.apache.qpid.transport.ConnectionException: connect() aborted
	at org.apache.qpid.transport.Connection.connect(Connection.java:282)
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:219)
	... 6 more
[12:50:14] [ FAIL ]: ret_code: 1 (not expected)

Comment 5 ppecka 2012-08-22 16:00:26 UTC
here is better snippet out of testlogs regarding my comment 4

[12:50:04] -TEST-CASE:V.MRG.M.0015.81;TEST-CASE-DESC:Bug 731096: Wrong assertion result using python client (JAVA)------------
[12:50:04] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q731096;{ create: always, node: {  }, link: {  } }"
[12:50:05] RESPONSE: {}
[12:50:05] [ PASS ]: ret_code: 0 (expected)
[12:50:05] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q731096;{ assert:always, node: { durable:True }, link: {  } }"
[12:50:06] RESPONSE: {}
Exception in thread "main" javax.jms.JMSException: Error registering consumer: org.apache.qpid.AMQException: The name 'Q731096' supplied in the address doesn't resolve to an exchange or a queue
	at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2056)
	at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2008)
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.executeRetrySupport(AMQConnectionDelegate_0_10.java:369)
	at org.apache.qpid.client.AMQConnection.executeRetrySupport(AMQConnection.java:593)
	at org.apache.qpid.client.failover.FailoverRetrySupport.execute(FailoverRetrySupport.java:102)
	at org.apache.qpid.client.AMQSession.createConsumerImpl(AMQSession.java:2006)
	at org.apache.qpid.client.AMQSession.createConsumer(AMQSession.java:980)
	at org.apache.qpid.example.Drain.<init>(Drain.java:70)
	at org.apache.qpid.example.Drain.main(Drain.java:104)
Caused by: org.apache.qpid.AMQException: The name 'Q731096' supplied in the address doesn't resolve to an exchange or a queue
	at org.apache.qpid.client.AMQSession_0_10.handleAddressBasedDestination(AMQSession_0_10.java:1257)
	at org.apache.qpid.client.AMQSession.registerConsumer(AMQSession.java:2925)
	at org.apache.qpid.client.AMQSession.access$500(AMQSession.java:102)
	at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2033)
	... 8 more
[12:50:06] [ PASS ]: ret_code: 1 (expected)
[12:50:06] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q731096;{ assert:always, node: { x-declare:{exclusive:True} }, link: {  } }"
[12:50:08] RESPONSE: {}
IoSender - localhost/127.0.0.1:5672 2012-08-21 12:50:08,858 ERROR [transport.network.io.IoSender] error in write thread
java.net.SocketException: Broken pipe
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
	at org.apache.qpid.transport.network.io.IoSender.run(IoSender.java:313)
	at java.lang.Thread.run(Thread.java:679)
Exception in thread "main" org.apache.qpid.AMQConnectionFailureException: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:444)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:215)
	at org.apache.qpid.example.OptionParser.createConnection(OptionParser.java:281)
	at org.apache.qpid.example.Drain.<init>(Drain.java:66)
	at org.apache.qpid.example.Drain.main(Drain.java:104)
Caused by: org.apache.qpid.AMQException: Cannot connect to broker: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:239)
	at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:588)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:367)
	... 4 more
Caused by: org.apache.qpid.transport.ConnectionException: connect() aborted
	at org.apache.qpid.transport.Connection.connect(Connection.java:282)
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:219)
	... 6 more
[12:50:08] [ PASS ]: ret_code: 1 (expected)
[12:50:08] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q731096;{ delete:always, node: {  }, link: {  } }"
[12:50:09] RESPONSE: {}
[12:50:09] [ PASS ]: ret_code: 0 (expected)
[12:50:09] -TEST-CASE:V.MRG.M.0015.82;TEST-CASE-DESC:Bug 730977: java client fails to resolve target when assert is used in the address ... (JAVA)------------
[12:50:09] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "amq.direct;{ assert:always, node: { type:topic }, link: {  } }"
[12:50:14] RESPONSE: {}
IoSender - localhost/127.0.0.1:5672 2012-08-21 12:50:14,939 ERROR [transport.network.io.IoSender] error in write thread
java.net.SocketException: Broken pipe
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
	at org.apache.qpid.transport.network.io.IoSender.run(IoSender.java:313)
	at java.lang.Thread.run(Thread.java:679)
Exception in thread "main" org.apache.qpid.AMQConnectionFailureException: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:444)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:215)
	at org.apache.qpid.example.OptionParser.createConnection(OptionParser.java:281)
	at org.apache.qpid.example.Drain.<init>(Drain.java:66)
	at org.apache.qpid.example.Drain.main(Drain.java:104)
Caused by: org.apache.qpid.AMQException: Cannot connect to broker: connect() aborted [error code 200: reply success]
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:239)
	at org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:588)
	at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:367)
	... 4 more
Caused by: org.apache.qpid.transport.ConnectionException: connect() aborted
	at org.apache.qpid.transport.Connection.connect(Connection.java:282)
	at org.apache.qpid.client.AMQConnectionDelegate_0_10.makeBrokerConnection(AMQConnectionDelegate_0_10.java:219)
	... 6 more
[12:50:14] [ FAIL ]: ret_code: 1 (not expected)
[12:50:14] -TEST-CASE:V.MRG.M.0015.83;TEST-CASE-DESC:Bug 731043: timeout waiting for sync (JAVA)------------
[12:50:15] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Spout  "ex;{ create:sender,delete:sender, node: { type:topic,x-declare:{type:direct} }, link: {  } }" (content="")
[12:51:15] RESPONSE: {content=}

------------- Msg -------------
Body:

JMS Correlation ID: null
JMS timestamp: 1345567815519
JMS expiration: 0
JMS priority: 4
JMS delivery mode: 2
JMS reply to: null
JMS Redelivered: false
JMS Destination: 'ex'/None; {
  'create': 'sender',
  'delete': 'sender',
  'link': {},
  'node': {
    'type': 'topic',
    'x-declare': {
      'type': 'direct'
    }
  }
}
JMS Type: null
JMS MessageID: ID:c558475b-4bfa-3509-b17d-4b952db7433f
JMS Content-Type: text/plain
AMQ message number: -1
Properties:
	qpid.subject = 

-------------------------------

main 2012-08-21 12:51:15,526 ERROR [apache.qpid.client.AMQConnection] Throwable Received but no listener set: org.apache.qpid.AMQException: timed out waiting for sync: complete = 2, point = 4 [error code 541: internal error]
Exception in thread "main" javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 2, point = 4 [error code 541: internal error]IoReceiver - localhost/127.0.0.1:5672 2012-08-21 12:51:15,527 ERROR [apache.qpid.client.AMQConnection] Throwable Received but no listener set: org.apache.qpid.AMQException: ch=0 id=1 ExecutionException(errorCode=NOT_FOUND, commandId=4, classCode=8, commandCode=2, fieldIndex=0, description=not-found: Delete failed. No such queue:  (qpid/broker/Broker.cpp:940), errorInfo={}) [error code 404: not found]

	at org.apache.qpid.client.AMQSession.close(AMQSession.java:761)
	at org.apache.qpid.client.AMQSession.close(AMQSession.java:723)
	at org.apache.qpid.client.AMQSession.close(AMQSession.java:569)
	at org.apache.qpid.example.Spout.<init>(Spout.java:103)
	at org.apache.qpid.example.Spout.main(Spout.java:146)
Caused by: org.apache.qpid.AMQException: timed out waiting for sync: complete = 2, point = 4 [error code 541: internal error]
	at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1051)
	at org.apache.qpid.client.AMQSession_0_10.sendClose(AMQSession_0_10.java:403)
	at org.apache.qpid.client.AMQSession.close(AMQSession.java:755)
	... 4 more
[12:51:15] [ FAIL ]: ret_code: 1 (not expected)
[12:51:15] -TEST-CASE:V.MRG.M.0015.84;TEST-CASE-DESC:Bug 730981: Unable to create binding while sending messages on default exchange ... (JAVA)------------
[12:51:15] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q730981;{ create:always, node: {  }, link: {  } }"
[12:51:16] RESPONSE: {}
[12:51:16] [ PASS ]: ret_code: 0 (expected)
[12:51:16] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Spout  "amq.direct;{ create:always, node: { x-bindings:[{queue:'Q730981',key:'key'}] }, link: {  } }" (content="")
[12:51:16] RESPONSE: {content=}

------------- Msg -------------
Body:

JMS Correlation ID: null
JMS timestamp: 1345567876945
JMS expiration: 0
JMS priority: 4
JMS delivery mode: 2
JMS reply to: null
JMS Redelivered: false
JMS Destination: 'amq.direct'/None; {
  'create': 'always',
  'link': {},
  'node': {
    'x-bindings': [
      {
        'key': 'key',
        'queue': 'Q730981'
      }
    ]
  }
}
JMS Type: null
JMS MessageID: ID:dc9afc5f-8288-3f07-867b-9aa09f170634
JMS Content-Type: text/plain
AMQ message number: -1
Properties:
	qpid.subject = 

-------------------------------
[12:51:16] [ PASS ]: ret_code: 0 (expected)
[12:51:16] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q730981;{ delete:always, node: {  }, link: {  } }"
[12:51:17] RESPONSE: {}
[12:51:17] [ PASS ]: ret_code: 0 (expected)
[12:51:17] -TEST-CASE:V.MRG.M.0015.85;TEST-CASE-DESC:Bug 731408: Using assert in address string leads to binding creation + different ... (JAVA)------------
[12:51:17] COMMAND: java -cp /mnt/tests/distribution/MRG/Messaging/qpid_ptest_clients_interoperability/examples/java:/usr/share/java/qpid-deps/log4j-slf4j.jar:/usr/share/java/qpid-deps/qpid-deps-0.18.jar:/usr/share/java/log4j.jar:/usr/share/java/qpid-client-0.18-sources.jar:/usr/share/java/qpid-client-0.18.jar:/usr/share/java/qpid-common-0.18-sources.jar:/usr/share/java/qpid-common-0.18.jar: -Dlog4j.configuration=example.log4j org.apache.qpid.example.Drain  "Q731408;{ create:always, node: {  }, link: {  } }"
[12:51:18] RESPONSE: {}
[12:51:18] [ PASS ]: ret_code: 0 (expected)

Comment 6 Rajith Attapattu 2012-09-20 13:38:04 UTC
Petr,

Are you able to retest this case with the changes we made for the connection issue?

Regards,

Rajith

Comment 7 ppecka 2012-09-21 19:40:20 UTC
(In reply to comment #6)
> Petr,
> 
> Are you able to retest this case with the changes we made for the connection
> issue?
> 
> Regards,
> 
> Rajith

sure, i'll leave test running over weekend

Comment 8 ppecka 2012-09-24 15:41:26 UTC
we heave been re-running test which triggered issue for many times, exception disappeared after we raised max-negotiate-time. it was more likely related to issue BZ851574 which has been already resolved

Comment 9 Justin Ross 2012-09-24 15:52:11 UTC
This issue appears to have been addressed by changes made for bug 851574. -> CLOSED CURRENTRELEASE.