[
https://issues.apache.org/jira/browse/QPID-5282?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13827398#comment-13827398
]
Keith Wall commented on QPID-5282:
----------------------------------
Changed IoSender to cause the socket to be closed after a sender timeout. If
this problem were to occur owing to back pressure from a client, the Java
Broker will now close the connection and log two additional lines at ERROR:
{noformat}
2013-11-19 21:51:03,204 ERROR [pool-2-thread-5] (io.IoSender) - write timed out
for socket /127.0.0.1:54190: head -2146434265, tail -2146958553
2013-11-19 21:51:03,205 INFO [IoReceiver - /127.0.0.1:54190]
(subscription.close) - [Broker] [sub:1(vh(/default)/qu(myqueue)] SUB-1002 :
Close
2013-11-19 21:51:03,208 INFO [IoReceiver - /127.0.0.1:54190] (channel.close) -
[Broker] [con:1(clientid@/127.0.0.1:54190/default)/ch:0] CHN-1003 : Close
2013-11-19 21:51:03,209 INFO [IoReceiver - /127.0.0.1:54190]
(connection.close) - [Broker] [con:1(clientid@/127.0.0.1:54190/default)]
CON-1002 : Close
2013-11-19 21:51:03,210 ERROR [IoSender - /127.0.0.1:54190] (io.IoSender) -
error in write thread
java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:99)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at org.apache.qpid.transport.network.io.IoSender.run(IoSender.java:308)
at java.lang.Thread.run(Thread.java:695)
{noformat}
If the problem were to occur owing to back pressure from a Broker, the client
will close the connection and logs would show the following (0-9/0-10):
{noformat}
2013-11-19 22:29:54,789 ERROR [main] [IoSender] write timed out for socket
localhost/127.0.0.1:5672: head -2146565522, tail -2146696594
2013-11-19 22:29:54,790 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[AMQProtocolHandler] Session closed called with failover state FailoverState:
NOT STARTED
2013-11-19 22:29:54,790 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[FailoverPolicy] All failover methods exhausted
2013-11-19 22:29:54,790 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[FailoverPolicy] All failover methods exhausted
2013-11-19 22:29:54,790 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[AMQProtocolHandler] Failover not allowed by policy:Failover Policy:
Failover not allowed
Failover policy methods
>Single Server:
Max Retries:0
Current Retry:0
tcp://localhost:5672
javax.jms.JMSException: Exception whilst sending:write timed out for socket
localhost/127.0.0.1:5672: head -2146565522, tail -2146696594
at org.apache.qpid.client.AMQSession.toJMSException(AMQSession.java:3465)
at
org.apache.qpid.client.BasicMessageProducer.sendImpl(BasicMessageProducer.java:504)
at
org.apache.qpid.client.BasicMessageProducer.send(BasicMessageProducer.java:298)
at org.apache.qpid.example.Hello.runTest(Hello.java:65)
at org.apache.qpid.example.Hello.main(Hello.java:43)
Caused by: org.apache.qpid.transport.SenderException: write timed out for
socket localhost/127.0.0.1:5672: head -2146565522, tail -2146696594
at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:156)
at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:1)
at
org.apache.qpid.client.protocol.AMQProtocolHandler.writeFrame(AMQProtocolHandler.java:567)
at
org.apache.qpid.client.protocol.AMQProtocolHandler.writeFrame(AMQProtocolHandler.java:559)
at
org.apache.qpid.client.BasicMessageProducer_0_8.sendMessage(BasicMessageProducer_0_8.java:185)
at
org.apache.qpid.client.BasicMessageProducer.sendImpl(BasicMessageProducer.java:500)
... 3 more
2013-11-19 22:29:54,792 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[AMQConnection] exceptionReceived done by:IoReceiver - localhost/127.0.0.1:5672
org.apache.qpid.AMQDisconnectedException: Server closed connection and
reconnection not permitted.
{noformat}
{noformat}
2013-11-19 22:23:03,739 ERROR [main] [IoSender] write timed out for socket
localhost/127.0.0.1:5672: head -2146696295, tail -2146827367
2013-11-19 22:23:03,740 DEBUG [IoReceiver - localhost/127.0.0.1:5672]
[Connection] connection closed: conn:6c9c035a
2013-11-19 22:23:03,741 ERROR [main] [Session] error sending command
org.apache.qpid.transport.SenderException: write timed out for socket
localhost/127.0.0.1:5672: head -2146696295, tail -2146827367
at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:156)
at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:1)
at org.apache.qpid.transport.network.Disassembler.frame(Disassembler.java:118)
at
org.apache.qpid.transport.network.Disassembler.fragment(Disassembler.java:147)
at org.apache.qpid.transport.network.Disassembler.method(Disassembler.java:242)
at org.apache.qpid.transport.network.Disassembler.command(Disassembler.java:172)
at org.apache.qpid.transport.network.Disassembler.command(Disassembler.java:48)
at org.apache.qpid.transport.Method.delegate(Method.java:159)
at org.apache.qpid.transport.network.Disassembler.send(Disassembler.java:73)
at org.apache.qpid.transport.network.Disassembler.send(Disassembler.java:48)
at org.apache.qpid.transport.Connection.send(Connection.java:405)
at org.apache.qpid.transport.Session.send(Session.java:602)
at org.apache.qpid.transport.Session.invoke(Session.java:772)
at org.apache.qpid.transport.Session.invoke(Session.java:627)
at
org.apache.qpid.transport.SessionInvoker.messageTransfer(SessionInvoker.java:93)
at
org.apache.qpid.client.BasicMessageProducer_0_10.sendMessage(BasicMessageProducer_0_10.java:229)
at
org.apache.qpid.client.BasicMessageProducer.sendImpl(BasicMessageProducer.java:500)
at
org.apache.qpid.client.BasicMessageProducer.send(BasicMessageProducer.java:298)
at org.apache.qpid.example.Hello.runTest(Hello.java:65)
at org.apache.qpid.example.Hello.main(Hello.java:43)
{noformat}
> Sender timeouts may allow the peer to suffer an AMQFrameDecodingException
> -------------------------------------------------------------------------
>
> Key: QPID-5282
> URL: https://issues.apache.org/jira/browse/QPID-5282
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker, Java Client, Java Common
> Affects Versions: 0.25
> Reporter: Keith Wall
> Assignee: Keith Wall
>
> If an IoSender#send suffers a timeout (IoSender.java#159) whilst awaiting
> space in the sender's buffer, the socket which was being written to is left
> open and a SenderException is thrown to the caller. The bytes that were to
> be sent are lost. If the socket is subsequent written to again, the peer may
> suffer an AMQFrameDecodingException as is tries to decode an incomplete
> stream of data.
> We saw this scenario in a support call. The working theory is that the
> application'sJVM (using a JMS consumer) was under pressue, and this caused
> TCP/IP back pressure to be felt by the broker. The Broker IoSender#send
> method timed-out, but as the socket remained open, when a later message was
> sent to the same JMS consumer application, the consuming application failed
> with an AMQFrameDecodingException: the lost bytes meant it tried to process
> message payload as if it were an AMQFrame.
> The two exceptions of interest are (reproduced on trunk):
> Broker side:
> {code}
> 2013-10-31 14:41:18,471 ERROR [IoReceiver - /127.0.0.1:63867]
> (v0_8.AMQProtocolEngine) - Error informing channel that receiving is
> complete. Channel:
> [/127.0.0.1:63867(guest):1]org.apache.qpid.transport.SenderException: write
> timed out: -2147471360, -2147475456
> at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:159)
> at org.apache.qpid.transport.network.io.IoSender.send(IoSender.java:40)
> at
> org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.writeFrame(AMQProtocolEngine.java:689)
> at
> org.apache.qpid.server.protocol.v0_8.output.ProtocolOutputConverterImpl.writeFrame(ProtocolOutputConverterImpl.java:337)
> at
> org.apache.qpid.server.protocol.v0_8.output.ProtocolOutputConverterImpl.writeMessageDelivery(ProtocolOutputConverterImpl.java:127)
> at
> org.apache.qpid.server.protocol.v0_8.output.ProtocolOutputConverterImpl.writeMessageDelivery(ProtocolOutputConverterImpl.java:97)
> at
> org.apache.qpid.server.protocol.v0_8.output.ProtocolOutputConverterImpl.writeDeliver(ProtocolOutputConverterImpl.java:72)
> at
> org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$WriteDeliverMethod.deliverToClient(AMQProtocolEngine.java:1679)
> at
> org.apache.qpid.server.protocol.v0_8.SubscriptionImpl.sendToClient(SubscriptionImpl.java:693)
> at
> org.apache.qpid.server.protocol.v0_8.SubscriptionImpl$AckSubscription.send(SubscriptionImpl.java:303)
> at
> org.apache.qpid.server.queue.SimpleAMQQueue.deliverMessage(SimpleAMQQueue.java:826)
> at
> org.apache.qpid.server.queue.SimpleAMQQueue.deliverToSubscription(SimpleAMQQueue.java:745)
> at
> org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:693)
> at
> org.apache.qpid.server.protocol.v0_8.AMQChannel$MessageDeliveryAction.postCommit(AMQChannel.java:1245)
> at
> org.apache.qpid.server.protocol.v0_8.AMQChannel$AsyncCommand.complete(AMQChannel.java:1623)
> at
> org.apache.qpid.server.protocol.v0_8.AMQChannel.sync(AMQChannel.java:1593)
> at
> org.apache.qpid.server.protocol.v0_8.AMQChannel.receivedComplete(AMQChannel.java:218)
> at
> org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.receivedComplete(AMQProtocolEngine.java:324)
> at
> org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:304)
> at
> org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:104)
> at
> org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:131)
> at
> org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:47)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
> at java.lang.Thread.run(Thread.java:662)
> {code}
> Then later client side:
> {code}
> 2013-10-31 14:47:49,099 DEBUG [Dispatcher-1-Conn-1] [Dispatcher]
> Dispatcher-1-Conn-1 thread terminating for channel
> 1:org.apache.qpid.client.AMQSession_0_8@560932fe
> javax.jms.JMSException: Message consumer forcibly closed due to error:
> org.apache.qpid.framing.AMQFrameDecodingException: End of frame marker not
> found. Read 53 length=65527 type=3
> at
> org.apache.qpid.client.BasicMessageConsumer.returnMessageOrThrow(BasicMessageConsumer.java:531)
> at
> org.apache.qpid.client.BasicMessageConsumer.receive(BasicMessageConsumer.java:419)
> at
> org.apache.qpid.client.BasicMessageConsumer.receive(BasicMessageConsumer.java:393)
> at org.apache.qpid.example.Hello.runTest(Hello.java:60)
> at org.apache.qpid.example.Hello.main(Hello.java:40)
> Caused by: org.apache.qpid.framing.AMQFrameDecodingException: End of frame
> marker not found. Read 53 length=65527 type=3
> at
> org.apache.qpid.framing.AMQDataBlockDecoder.createAndPopulateFrame(AMQDataBlockDecoder.java:104)
> at org.apache.qpid.codec.AMQDecoder.decodeBuffer(AMQDecoder.java:250)
> at
> org.apache.qpid.client.protocol.AMQProtocolHandler.received(AMQProtocolHandler.java:451)
> at
> org.apache.qpid.client.protocol.AMQProtocolHandler.received(AMQProtocolHandler.java:1)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
> at java.lang.Thread.run(Thread.java:662)
> {code}
--
This message was sent by Atlassian JIRA
(v6.1#6144)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
