[QPIDJMS-90] Received empty frames are not logged

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 0.3.0
• Fix Version/s: 0.4.0
• Component/s: qpid-jms-client
• Assignee: Robbie Gemmell
• Reporter: Jakub Scholz
• Created: 23/Jul/15 22:17
• Updated: 06/Jan/16 12:33
• Resolved: 12/Aug/15 14:30

Description

When idle timeout is enabled, the client and broker are using empty frames to keep the connection alive. However, when logging of frames is enabled, only the sent empty frames seem to be logged - the received seem to never appear in the log:
2015-07-24T00:04:18.489+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:04:18.489+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:04:18.489+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:04:18.491+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:04:48.493+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:04:48.493+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:04:48.493+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:04:48.496+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:05:18.500+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:05:18.500+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:05:18.500+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:05:18.502+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:05:48.437+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:05:48.504+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:05:48.504+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:05:48.504+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:06:18.510+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:06:18.511+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:06:18.511+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:06:18.513+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:06:48.437+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:06:48.514+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:06:48.514+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:06:48.514+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000
2015-07-24T00:07:18.438+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - New data read: 8 bytes incoming: UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 65536)
2015-07-24T00:07:18.517+0200 TRACE org.apache.qpid.jms.provider.amqp.FRAMES - SENT: null
2015-07-24T00:07:18.517+0200 TRACE org.apache.qpid.jms.transports.netty.NettyTcpTransport - Attempted write of: 8 bytes
2015-07-24T00:07:18.517+0200 TRACE org.apache.qpid.jms.provider.amqp.AmqpProvider - IdleTimeoutCheck rescheduling with delay: 30000

It would be great if both sent and received empty frames can be logged.

This problem seems to appear both in 0.3.0 as well as in the latest 0.4.0-SNAPSHOT.

Issue Links

• depends upon: PROTON-966 [proton-j] empty frames are logged/traced when sent but not when received
• depends upon: QPIDJMS-84 update proton-j dependency to 0.10