[
https://issues.apache.org/jira/browse/QPIDJMS-290?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16010408#comment-16010408
]
Keith Wall edited comment on QPIDJMS-290 at 5/15/17 12:25 PM:
--------------------------------------------------------------
Apologies for not testing sooner, but I missed the JIRA update.
I am testing on Qpid JMS Client (master) with HelloWorld modified to send a
BytesMessage with the Java Broker configured for plain websockets. I am
seeing two problems:
1) With a bytes payload of 32576 the client reports the following "tail closed"
exception reported as warning. The test seems to pass despite this.
{noformat}
objc[2871]: Class JavaLaunchHelper is implemented in both
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java and
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/libinstrument.dylib.
One of the two will be used. Which one is undefined.
[1160904268:0] -> Open{
containerId='ID:36426f56-fe12-49bd-85ad-8707f3cb5835:1', hostname='localhost',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container],
properties={product=QpidJMS, version=0.24.0-SNAPSHOT, platform=JVM: 1.8.0_131,
25.131-b11, Oracle Corporation, OS: Mac OS X, 10.11.6, x86_64}}
[1160904268:0] <- Open{ containerId='26621e27-52b7-4626-8db9-71a967e11eaf',
hostname='null', maxFrameSize=262144, channelMax=255, idleTimeOut=0,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS], desiredCapabilities=null,
properties={product=qpid, version=7.0.0-SNAPSHOT, qpid.build=,
qpid.instance_name=Broker}}
[1160904268:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1160904268:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1160904268:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] ->
Attach{name='qpid-jms:sender:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=[DELAYED_DELIVERY], properties=null}
[1160904268:1] <-
Attach{name='qpid-jms:sender:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY]}, unsettled=null,
incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
offeredCapabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY],
desiredCapabilities=null, properties={}}
[1160904268:1] <- Flow{nextIncomingId=1, incomingWindow=8192, nextOutgoingId=0,
outgoingWindow=2048, handle=0, deliveryCount=0, linkCredit=20000,
available=null, drain=false, echo=false, properties=null}
[1160904268:1] ->
Attach{name='qpid-jms:receiver:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=Modified{deliveryFailed=true,
undeliverableHere=null, messageAnnotations=null}, outcomes=[amqp:accepted:list,
amqp:rejected:list, amqp:released:list, amqp:modified:list],
capabilities=[queue]}, target=Target{address='null', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] <-
Attach{name='qpid-jms:receiver:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=null, outcomes=null, capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=[SHARED-SUBS],
desiredCapabilities=null, properties={}}
[1160904268:1] -> Flow{nextIncomingId=0, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[1160904268:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=0,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (32733)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x0de}\x00Su\xb0\x00\x00\x7f@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
Done producing
[1160904268:1] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
[1160904268:1] <- Transfer{handle=1, deliveryId=0,
deliveryTag=\x00\x00\x00\x00\x00\x00\x00\x00, messageFormat=0, settled=null,
more=false, rcvSettleMode=null, state=null, resume=false, aborted=false,
batchable=false} (32733)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x0de}\x00Su\xb0\x00\x00\x7f@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
[1160904268:0] -> Close{error=null}
JmsBytesMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsBytesMessageFacade@224edc67 }
32576
2017-05-15 13:20:38,721 [localhost:5670]] - WARN AmqpProvider
- Caught problem during data processing: tail closed
org.apache.qpid.proton.engine.TransportException: tail closed
at
org.apache.qpid.proton.engine.impl.FrameParser.tail(FrameParser.java:508)
at
org.apache.qpid.proton.engine.impl.SaslImpl$SaslTransportWrapper.tail(SaslImpl.java:588)
at
org.apache.qpid.proton.engine.impl.HandshakeSniffingTransportWrapper.tail(HandshakeSniffingTransportWrapper.java:84)
at
org.apache.qpid.proton.engine.impl.TransportImpl.tail(TransportImpl.java:1473)
at
org.apache.qpid.proton.engine.impl.TransportImpl.getInputBuffer(TransportImpl.java:1435)
at
org.apache.qpid.jms.provider.amqp.AmqpProvider$18.run(AmqpProvider.java:778)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
{noformat}
With a bytes message payload of 65348, I see a hang. The producer's message
never makes it to the Broker.
{noformat}
objc[2853]: Class JavaLaunchHelper is implemented in both
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java and
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/libinstrument.dylib.
One of the two will be used. Which one is undefined.
[859661288:0] -> Open{ containerId='ID:3d0eb882-3a98-44c7-809a-5d90cd2db392:1',
hostname='localhost', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container],
properties={product=QpidJMS, version=0.24.0-SNAPSHOT, platform=JVM: 1.8.0_131,
25.131-b11, Oracle Corporation, OS: Mac OS X, 10.11.6, x86_64}}
[859661288:0] <- Open{ containerId='26621e27-52b7-4626-8db9-71a967e11eaf',
hostname='null', maxFrameSize=262144, channelMax=255, idleTimeOut=0,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS], desiredCapabilities=null,
properties={product=qpid, version=7.0.0-SNAPSHOT, qpid.build=,
qpid.instance_name=Broker}}
[859661288:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[859661288:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[859661288:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] ->
Attach{name='qpid-jms:sender:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=[DELAYED_DELIVERY], properties=null}
[859661288:1] <-
Attach{name='qpid-jms:sender:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY]}, unsettled=null,
incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
offeredCapabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY],
desiredCapabilities=null, properties={}}
[859661288:1] <- Flow{nextIncomingId=1, incomingWindow=8192, nextOutgoingId=0,
outgoingWindow=2048, handle=0, deliveryCount=0, linkCredit=20000,
available=null, drain=false, echo=false, properties=null}
[859661288:1] ->
Attach{name='qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=Modified{deliveryFailed=true,
undeliverableHere=null, messageAnnotations=null}, outcomes=[amqp:accepted:list,
amqp:rejected:list, amqp:released:list, amqp:modified:list],
capabilities=[queue]}, target=Target{address='null', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] <-
Attach{name='qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=null, outcomes=null, capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=[SHARED-SUBS],
desiredCapabilities=null, properties={}}
[859661288:1] -> Flow{nextIncomingId=0, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[859661288:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=0,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (65505)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x09\x93S\x00Su\xb0\x00\x00\xffD\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
Done producing
[859661288:0] <- Empty Frame
{noformat}
For this 65348 case, on the Broker, I see an empty {{onMessage}} call arrive
from Jetty in the place where the transfer should be. Client and Broker then
start to exchange empty frames (heartbeating) but the transfer never arrives.
{noformat}
2017-05-15 13:16:13,129 DEBUG [qtp1580504897-243] (o.a.q.s.p.frame) -
SEND[/127.0.0.1:58701|1] :
Attach{name=qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue,handle=1,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=queue,durable=none,expiryPolicy=link-detach,dynamic=false,capabilities=[queue]},target=Target{},initialDeliveryCount=0,offeredCapabilities=[SHARED-SUBS],properties={}}
2017-05-15 13:16:13,130 DEBUG [qtp1580504897-243]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG Sending 166
2017-05-15 13:16:13,133 DEBUG [qtp1580504897-246]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG onMessage 35
2017-05-15 13:16:13,134 DEBUG [qtp1580504897-246] (o.a.q.s.p.frame) -
RECV[/127.0.0.1:58701|1] :
Flow{nextIncomingId=0,incomingWindow=2047,nextOutgoingId=1,outgoingWindow=2147483647,handle=1,deliveryCount=0,linkCredit=1000}
2017-05-15 13:16:13,176 DEBUG [qtp1580504897-247]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG onMessage 0
2017-05-15 13:16:28,134 DEBUG [qtp1580504897-293] (o.a.q.s.p.frame) -
SEND[/127.0.0.1:58701|0] : <<HEARTBEAT>>
2017-05-15 13:16:28,135 DEBUG [qtp1580504897-293]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG Sending 8
{noformat}
was (Author: k-wall):
Apologies, for not testing sooner, but I missed the JIRA update.
I am testing on Qpid JMS Client (master) with HelloWorld modified to send a
BytesMessage with the Java Broker configured for plain websockets. I am
seeing two problems:
1) With a bytes payload of 32576 the client reports the following "tail closed"
exception reported as warning. The test seems to pass despite this.
{noformat}
objc[2871]: Class JavaLaunchHelper is implemented in both
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java and
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/libinstrument.dylib.
One of the two will be used. Which one is undefined.
[1160904268:0] -> Open{
containerId='ID:36426f56-fe12-49bd-85ad-8707f3cb5835:1', hostname='localhost',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container],
properties={product=QpidJMS, version=0.24.0-SNAPSHOT, platform=JVM: 1.8.0_131,
25.131-b11, Oracle Corporation, OS: Mac OS X, 10.11.6, x86_64}}
[1160904268:0] <- Open{ containerId='26621e27-52b7-4626-8db9-71a967e11eaf',
hostname='null', maxFrameSize=262144, channelMax=255, idleTimeOut=0,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS], desiredCapabilities=null,
properties={product=qpid, version=7.0.0-SNAPSHOT, qpid.build=,
qpid.instance_name=Broker}}
[1160904268:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1160904268:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1160904268:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] ->
Attach{name='qpid-jms:sender:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=[DELAYED_DELIVERY], properties=null}
[1160904268:1] <-
Attach{name='qpid-jms:sender:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY]}, unsettled=null,
incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
offeredCapabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY],
desiredCapabilities=null, properties={}}
[1160904268:1] <- Flow{nextIncomingId=1, incomingWindow=8192, nextOutgoingId=0,
outgoingWindow=2048, handle=0, deliveryCount=0, linkCredit=20000,
available=null, drain=false, echo=false, properties=null}
[1160904268:1] ->
Attach{name='qpid-jms:receiver:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=Modified{deliveryFailed=true,
undeliverableHere=null, messageAnnotations=null}, outcomes=[amqp:accepted:list,
amqp:rejected:list, amqp:released:list, amqp:modified:list],
capabilities=[queue]}, target=Target{address='null', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[1160904268:1] <-
Attach{name='qpid-jms:receiver:ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1:queue',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=null, outcomes=null, capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=[SHARED-SUBS],
desiredCapabilities=null, properties={}}
[1160904268:1] -> Flow{nextIncomingId=0, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[1160904268:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=0,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (32733)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x0de}\x00Su\xb0\x00\x00\x7f@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
Done producing
[1160904268:1] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
[1160904268:1] <- Transfer{handle=1, deliveryId=0,
deliveryTag=\x00\x00\x00\x00\x00\x00\x00\x00, messageFormat=0, settled=null,
more=false, rcvSettleMode=null, state=null, resume=false, aborted=false,
batchable=false} (32733)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:71915654-e767-4baa-b2f4-e91da9e32117:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x0de}\x00Su\xb0\x00\x00\x7f@\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
[1160904268:0] -> Close{error=null}
JmsBytesMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsBytesMessageFacade@224edc67 }
32576
2017-05-15 13:20:38,721 [localhost:5670]] - WARN AmqpProvider
- Caught problem during data processing: tail closed
org.apache.qpid.proton.engine.TransportException: tail closed
at
org.apache.qpid.proton.engine.impl.FrameParser.tail(FrameParser.java:508)
at
org.apache.qpid.proton.engine.impl.SaslImpl$SaslTransportWrapper.tail(SaslImpl.java:588)
at
org.apache.qpid.proton.engine.impl.HandshakeSniffingTransportWrapper.tail(HandshakeSniffingTransportWrapper.java:84)
at
org.apache.qpid.proton.engine.impl.TransportImpl.tail(TransportImpl.java:1473)
at
org.apache.qpid.proton.engine.impl.TransportImpl.getInputBuffer(TransportImpl.java:1435)
at
org.apache.qpid.jms.provider.amqp.AmqpProvider$18.run(AmqpProvider.java:778)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:748)
{noformat}
With a bytes message payload of 65348, I see a hang. The producer's message
never makes it to the Broker.
{noformat}
objc[2853]: Class JavaLaunchHelper is implemented in both
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java and
/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/libinstrument.dylib.
One of the two will be used. Which one is undefined.
[859661288:0] -> Open{ containerId='ID:3d0eb882-3a98-44c7-809a-5d90cd2db392:1',
hostname='localhost', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container],
properties={product=QpidJMS, version=0.24.0-SNAPSHOT, platform=JVM: 1.8.0_131,
25.131-b11, Oracle Corporation, OS: Mac OS X, 10.11.6, x86_64}}
[859661288:0] <- Open{ containerId='26621e27-52b7-4626-8db9-71a967e11eaf',
hostname='null', maxFrameSize=262144, channelMax=255, idleTimeOut=0,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS], desiredCapabilities=null,
properties={product=qpid, version=7.0.0-SNAPSHOT, qpid.build=,
qpid.instance_name=Broker}}
[859661288:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[859661288:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[859661288:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=8192,
outgoingWindow=2048, handleMax=4294967295, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] ->
Attach{name='qpid-jms:sender:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=[DELAYED_DELIVERY], properties=null}
[859661288:1] <-
Attach{name='qpid-jms:sender:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='queue', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY]}, unsettled=null,
incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
offeredCapabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY],
desiredCapabilities=null, properties={}}
[859661288:1] <- Flow{nextIncomingId=1, incomingWindow=8192, nextOutgoingId=0,
outgoingWindow=2048, handle=0, deliveryCount=0, linkCredit=20000,
available=null, drain=false, echo=false, properties=null}
[859661288:1] ->
Attach{name='qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=Modified{deliveryFailed=true,
undeliverableHere=null, messageAnnotations=null}, outcomes=[amqp:accepted:list,
amqp:rejected:list, amqp:released:list, amqp:modified:list],
capabilities=[queue]}, target=Target{address='null', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[859661288:1] <-
Attach{name='qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='queue', durable=NONE, expiryPolicy=LINK_DETACH,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
filter=null, defaultOutcome=null, outcomes=null, capabilities=[queue]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=[SHARED-SUBS],
desiredCapabilities=null, properties={}}
[859661288:1] -> Flow{nextIncomingId=0, incomingWindow=2047, nextOutgoingId=1,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[859661288:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=0,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (65505)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0b\x0a\xa1/ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1-1@\xa1\x05queue@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01\x5c\x0c\x09\x93S\x00Su\xb0\x00\x00\xffD\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
Done producing
[859661288:0] <- Empty Frame
{noformat}
For this 65348 case, on the Broker, I see an empty {{onMessage}} call arrive
from Jetty in the place where the transfer should be. Client and Broker then
start to exchange empty frames (heartbeating) but the transfer never arrives.
{noformat}
2017-05-15 13:16:13,129 DEBUG [qtp1580504897-243] (o.a.q.s.p.frame) -
SEND[/127.0.0.1:58701|1] :
Attach{name=qpid-jms:receiver:ID:9dfb6566-eff5-438d-9c00-1155e739bf27:1:1:1:queue,handle=1,role=sender,sndSettleMode=unsettled,rcvSettleMode=first,source=Source{address=queue,durable=none,expiryPolicy=link-detach,dynamic=false,capabilities=[queue]},target=Target{},initialDeliveryCount=0,offeredCapabilities=[SHARED-SUBS],properties={}}
2017-05-15 13:16:13,130 DEBUG [qtp1580504897-243]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG Sending 166
2017-05-15 13:16:13,133 DEBUG [qtp1580504897-246]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG onMessage 35
2017-05-15 13:16:13,134 DEBUG [qtp1580504897-246] (o.a.q.s.p.frame) -
RECV[/127.0.0.1:58701|1] :
Flow{nextIncomingId=0,incomingWindow=2047,nextOutgoingId=1,outgoingWindow=2147483647,handle=1,deliveryCount=0,linkCredit=1000}
2017-05-15 13:16:13,176 DEBUG [qtp1580504897-247]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG onMessage 0
2017-05-15 13:16:28,134 DEBUG [qtp1580504897-293] (o.a.q.s.p.frame) -
SEND[/127.0.0.1:58701|0] : <<HEARTBEAT>>
2017-05-15 13:16:28,135 DEBUG [qtp1580504897-293]
(o.a.q.s.t.w.WebSocketProvider) - KWDEBUG Sending 8
{noformat}
> [Websocket] Receiving bytes message with more than 65347 bytes of content
> fails within the decoder
> --------------------------------------------------------------------------------------------------
>
> Key: QPIDJMS-290
> URL: https://issues.apache.org/jira/browse/QPIDJMS-290
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.22.0
> Reporter: Keith Wall
> Assignee: Timothy Bish
> Fix For: 0.23.0
>
>
> I am using the Qpid JMS Client's web socket implementation with Qpid Broker
> J. Testing current master for both components.
> I notice if the Qpid JMS Client receives a ByteMessage with bytes content
> greater than 65347 bytes, the client fails with the following frame size
> related exception. The sending of the message is unaffected.
> I tried manually override the frame size in the connection url, but this made
> no improvement.
> The exception and proton-j output is below.
> Turning on proton-j trace, I notice that the pair have negotiated a larger
> frame size, but it appears that the client does not respect this for incoming
> frames.
> {noformat}
> /Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java
> -agentlib:jdwp=transport=dt_socket,address=127.0.0.1:54406,suspend=y,server=n
> -Dfile.encoding=UTF-8 -classpath
> "/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/jaccess.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/packager.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/lib/tools.jar:/Users/keith/src/qpid-jms/qpid-jms-examples/target/classes:/Users/keith/src/qpid-jms/qpid-jms-client/target/classes:/Users/keith/.m2/repository/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.jar:/Users/keith/.m2/repository/org/apache/geronimo/specs/geronimo-jms_2.0_spec/1.0-alpha-2/geronimo-jms_2.0_spec-1.0-alpha-2.jar:/Users/keith/.m2/repository/org/apache/qpid/proton-j/0.18.0/proton-j-0.18.0.jar:/Users/keith/.m2/repository/io/netty/netty-buffer/4.1.9.Final/netty-buffer-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-common/4.1.9.Final/netty-common-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-handler/4.1.9.Final/netty-handler-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-codec/4.1.9.Final/netty-codec-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-transport/4.1.9.Final/netty-transport-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-resolver/4.1.9.Final/netty-resolver-4.1.9.Final.jar:/Users/keith/.m2/repository/io/netty/netty-transport-native-epoll/4.1.9.Final/netty-transport-native-epoll-4.1.9.Final-linux-x86_64.jar:/Users/keith/.m2/repository/io/netty/netty-codec-http/4.1.9.Final/netty-codec-http-4.1.9.Final.jar:/Users/keith/.m2/repository/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar:/Users/keith/.m2/repository/log4j/log4j/1.2.17/log4j-1.2.17.jar:/Applications/IntelliJ
> IDEA.app/Contents/lib/idea_rt.jar" org.apache.qpid.jms.example.HelloWS
> Connected to the target VM, address: '127.0.0.1:54406', transport: 'socket'
> [1835065327:0] -> Open{
> containerId='ID:c904232b-c36f-4208-87bb-4283455670c6:1', hostname='default',
> maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
> outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
> desiredCapabilities=[sole-connection-for-container],
> properties={product=QpidJMS, version=0.23.0-SNAPSHOT, platform=JVM:
> 1.8.0_131, 25.131-b11, Oracle Corporation, OS: Mac OS X, 10.12.4, x86_64}}
> [1835065327:0] <- Open{ containerId='d619337c-7198-4ab3-9c72-60b2ad012179',
> hostname='null', maxFrameSize=262144, channelMax=255, idleTimeOut=0,
> outgoingLocales=null, incomingLocales=null,
> offeredCapabilities=[ANONYMOUS-RELAY, SHARED-SUBS], desiredCapabilities=null,
> properties={product=qpid, version=7.0.0-SNAPSHOT,
> qpid.build=e72ac287b51777d6be09f13bb541d2a60b2167e4,
> qpid.instance_name=Broker}}
> [1835065327:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1835065327:0] <- Begin{remoteChannel=0, nextOutgoingId=0,
> incomingWindow=8192, outgoingWindow=2048, handleMax=4294967295,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1835065327:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
> incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1835065327:1] <- Begin{remoteChannel=1, nextOutgoingId=0,
> incomingWindow=8192, outgoingWindow=2048, handleMax=4294967295,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1835065327:1] ->
> Attach{name='qpid-jms:sender:ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1:Q1',
> handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=null},
> target=Target{address='Q1', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
> maxMessageSize=null, offeredCapabilities=null,
> desiredCapabilities=[DELAYED_DELIVERY], properties=null}
> [1835065327:1] <-
> Attach{name='qpid-jms:sender:ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1:Q1',
> handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
> amqp:released:list, amqp:modified:list], capabilities=null},
> target=Target{address='Q1', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null,
> capabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY]}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
> offeredCapabilities=[REJECT_UNROUTABLE, DELAYED_DELIVERY],
> desiredCapabilities=null, properties={}}
> [1835065327:1] <- Flow{nextIncomingId=1, incomingWindow=8192,
> nextOutgoingId=0, outgoingWindow=2048, handle=0, deliveryCount=0,
> linkCredit=20000, available=null, drain=false, echo=false, properties=null}
> [1835065327:1] ->
> Attach{name='qpid-jms:receiver:ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1:Q1',
> handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='Q1', durable=NONE, expiryPolicy=LINK_DETACH,
> timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
> filter=null, defaultOutcome=Modified{deliveryFailed=true,
> undeliverableHere=null, messageAnnotations=null},
> outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list,
> amqp:modified:list], capabilities=[queue]}, target=Target{address='null',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, capabilities=null}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> [1835065327:1] <-
> Attach{name='qpid-jms:receiver:ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1:Q1',
> handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='Q1', durable=NONE, expiryPolicy=LINK_DETACH,
> timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null,
> filter=null, defaultOutcome=null, outcomes=null, capabilities=[queue]},
> target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
> timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
> unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
> maxMessageSize=null, offeredCapabilities=[SHARED-SUBS],
> desiredCapabilities=null, properties={}}
> [1835065327:1] -> Flow{nextIncomingId=0, incomingWindow=2047,
> nextOutgoingId=1, outgoingWindow=2147483647, handle=1, deliveryCount=0,
> linkCredit=1000, available=null, drain=false, echo=false, properties=null}
> [1835065327:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=0,
> messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
> resume=false, aborted=false, batchable=false} (65509)
> "\x00Sp\xc0\x02\x01A\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xc0_\x0a\xa1/ID:66baff0e-d07c-4fd5-a8f3-7f2df806ed9d:1:1:1-1@\xa1\x02Q1@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01[\xc5Ov\xfb\x00Su\xb0\x00\x00\xffD\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"...(truncated)
> [1835065327:1] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
> state=Accepted{}, batchable=false}
> Disconnected from the target VM, address: '127.0.0.1:54406', transport:
> 'socket'
> Connection ExceptionListener fired, exiting.
> javax.jms.JMSException: Max frame length of 65536 has been exceeded.
> at
> org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:85)
> at
> org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:107)
> at
> org.apache.qpid.jms.JmsConnection.onAsyncException(JmsConnection.java:1410)
> at
> org.apache.qpid.jms.JmsConnection.onProviderException(JmsConnection.java:1374)
> at
> org.apache.qpid.jms.JmsConnection.onConnectionFailure(JmsConnection.java:1242)
> at
> org.apache.qpid.jms.provider.amqp.AmqpProvider.fireProviderException(AmqpProvider.java:1045)
> at
> org.apache.qpid.jms.provider.amqp.AmqpProvider$19.run(AmqpProvider.java:818)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:748)
> Caused by: java.io.IOException: Max frame length of 65536 has been exceeded.
> at
> org.apache.qpid.jms.util.IOExceptionSupport.create(IOExceptionSupport.java:45)
> ... 9 more
> Caused by: io.netty.handler.codec.CorruptedFrameException: Max frame length
> of 65536 has been exceeded.
> at
> io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder.protocolViolation(WebSocket08FrameDecoder.java:412)
> at
> io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder.decode(WebSocket08FrameDecoder.java:277)
> at
> io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
> at
> io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
> at
> io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
> at
> io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
> at
> io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
> at
> io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
> at
> io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134)
> at
> io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:624)
> at
> io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:559)
> at
> io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:476)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438)
> at
> io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
> at
> io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
> ... 1 more
> Process finished with exit code 1
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
