[jira] [Commented] (QPIDJMS-90) Received empty frames are not logged
[ https://issues.apache.org/jira/browse/QPIDJMS-90?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14647928#comment-14647928 ] Jakub Scholz commented on QPIDJMS-90: - Thanks for fixing this. I can see now both - received and sent - empty frames. > Received empty frames are not logged > - > > Key: QPIDJMS-90 > URL: https://issues.apache.org/jira/browse/QPIDJMS-90 > Project: Qpid JMS > Issue Type: Bug > Components: qpid-jms-client >Affects Versions: 0.3.0 >Reporter: Jakub Scholz >Assignee: Robbie Gemmell >Priority: Minor > Fix For: 0.4.0 > > > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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
[jira] [Commented] (QPIDJMS-90) Received empty frames are not logged
[ https://issues.apache.org/jira/browse/QPIDJMS-90?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14647489#comment-14647489 ] Robbie Gemmell commented on QPIDJMS-90: --- I made an update to Proton via PRTON-966 + PROTON-967 to fix this and make the empty frame logging clearer. I have prodded the nightly snapshot builds for Proton and QpidJMS so the artifacts in the snapshots repo (https://repository.apache.org/content/repositories/snapshots/) should be good if you want to try it without doing a local build. I'll leave this JIRA open until 0.10 is actually out and QPIDJMS-84 gets resolved. > Received empty frames are not logged > - > > Key: QPIDJMS-90 > URL: https://issues.apache.org/jira/browse/QPIDJMS-90 > Project: Qpid JMS > Issue Type: Bug > Components: qpid-jms-client >Affects Versions: 0.3.0 >Reporter: Jakub Scholz >Assignee: Robbie Gemmell >Priority: Minor > Fix For: 0.4.0 > > > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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.j
[jira] [Commented] (QPIDJMS-90) Received empty frames are not logged
[ https://issues.apache.org/jira/browse/QPIDJMS-90?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14639641#comment-14639641 ] Robbie Gemmell commented on QPIDJMS-90: --- This will actually need a change to proton-j, rather than [just] the JMS client. The client is inserting a tracer object into Proton to generate the above frame logs, so if something doesn't appear there it is because proton isn't calling the tracer. From a quick peek, that is because it swallows received empty frames before the handler that receives the constituted frame objects. Will need to look at the best way to work a change in there. I'm going away for a bit, so I probably won't see any replies until mid next week. > Received empty frames are not logged > - > > Key: QPIDJMS-90 > URL: https://issues.apache.org/jira/browse/QPIDJMS-90 > Project: Qpid JMS > Issue Type: Bug > Components: qpid-jms-client >Affects Versions: 0.3.0 >Reporter: Jakub Scholz >Priority: Minor > > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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: 3 > 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