On Wed, Jan 12, 2011 at 12:29 AM, Alex Dean <a...@crackpot.org> wrote:
>
> On Jan 11, 2011, at 8:14 AM, Jeff Rose wrote:
>
> > On Mon, Jan 10, 2011 at 4:57 PM, Alex Dean <a...@crackpot.org> wrote:
> >
> >>
> >> On Jan 10, 2011, at 5:02 AM, Jeff Rose wrote:
> >>
> >
> > The last issue I do see is that fairly often the consumer stops listening
> to
> > the topic even though the ajax poll requests are still coming. I can see
> in
> > jconsole that the consumer count on my topic drops to zero, even though
> at
> > the same time I'm watching empty ajax responses coming back periodically.
>
> Hm. I've never seen that happen.
>
> Can you enable debug logging for activemq-web? I've been adding
> log4j.logger.org.apache.activemq.web=DEBUG
> to config/log4j.properties.
>
> When a new ajax client connects, you should see a line like:
> DEBUG | creating new AjaxWebClient in
> p8v92prp07trmhghrpltw0rh-1294788329515
>
> If you close the browser window and wait a minute, you should then see
> something like:
> DEBUG | Cleaning up expired web clients.
> DEBUG | AjaxWebClient p8v92prp07trmhghrpltw0rh-1294788329515 last accessed
> 95 seconds ago.
> DEBUG | Removing expired AjaxWebClient
> p8v92prp07trmhghrpltw0rh-1294788329515
>
> If you see a message like that 'Removing expired AjaxWebClient' while your
> browser is still actively polling, that's wrong. Not sure what else might
> cause the consumer count to drop back to 0.
>
> alex
Below is a dump of the relevant log messages. Starting from the initial
subscription when the first AJAX request is made. Then showing the 10
messages sent by the test php script, which were correctly sent up to the
browser. But after this first message batch arrived the consumer count in
jconsole dropped to zero and no more messages made it. You can see that the
GET long-poll requests keep coming, and it isn't expiring the client because
it seems to be active. I'm not sure why the consumer is dropped though. I
wonder if there could be an exception firing somewhere in the message
processing that could result in this behavior?
-Jeff
DEBUG | Subscribed: ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true } to
topic://flight.search.result id=result-handler
DEBUG | Cleaning up expired web clients.
DEBUG | AjaxWebClient 1xki1evjkyakl7di3kqfsqs5z-defaultAjaxWebClient last
accessed 3 seconds ago.
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29@ASYNCWAIT
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839231226&r=0.3835270793642849
DEBUG | doMessage timeout=25000
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message: ActiveMQTextMessage {commandId = 3, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245128, arrival = 0, brokerInTime = 1294839245129,
brokerOutTime = 1294839245133, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='0'>test message: 0</result>}
DEBUG | [2] N-Messages: 1
DEBUG | message: ActiveMQTextMessage {commandId = 4, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:2,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245133, arrival = 0, brokerInTime = 1294839245133,
brokerOutTime = 1294839245133, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='1'>test message: 1</result>}
DEBUG | [2] N-Messages: 2
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message: ActiveMQTextMessage {commandId = 5, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:3,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245133, arrival = 0, brokerInTime = 1294839245133,
brokerOutTime = 1294839245134, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='2'>test message: 2</result>}
DEBUG | [2] N-Messages: 3
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message: ActiveMQTextMessage {commandId = 6, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:4,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245133, arrival = 0, brokerInTime = 1294839245133,
brokerOutTime = 1294839245134, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='3'>test message: 3</result>}
DEBUG | [2] N-Messages: 4
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message: ActiveMQTextMessage {commandId = 7, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:5,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245135, arrival = 0, brokerInTime = 1294839245135,
brokerOutTime = 1294839245135, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='4'>test message: 4</result>}
DEBUG | [2] N-Messages: 5
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message for ActiveMQMessageConsumer {
value=ID:teak-39064-1294838564403-2:2:1:1, started=true
}continuation=org.eclipse.jetty.server.asynccontinuat...@184be29
@REDISPATCHED,resumed
DEBUG | message: ActiveMQTextMessage {commandId = 8, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:6,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245141, arrival = 0, brokerInTime = 1294839245141,
brokerOutTime = 1294839245144, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='5'>test message: 5</result>}
DEBUG | [2] N-Messages: 6
DEBUG | message: ActiveMQTextMessage {commandId = 9, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:7,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245142, arrival = 0, brokerInTime = 1294839245142,
brokerOutTime = 1294839245147, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='6'>test message: 6</result>}
DEBUG | [2] N-Messages: 7
DEBUG | message: ActiveMQTextMessage {commandId = 10, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:8,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245142, arrival = 0, brokerInTime = 1294839245142,
brokerOutTime = 1294839245147, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='7'>test message: 7</result>}
DEBUG | [2] N-Messages: 8
DEBUG | message: ActiveMQTextMessage {commandId = 11, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:9,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245142, arrival = 0, brokerInTime = 1294839245142,
brokerOutTime = 1294839245149, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='8'>test message: 8</result>}
DEBUG | [2] N-Messages: 9
DEBUG | message: ActiveMQTextMessage {commandId = 12, responseRequired =
false, messageId = ID:teak-39064-1294838564403-5:1:-1:1:10,
originalDestination = null, originalTransactionId = null, producerId =
ID:teak-39064-1294838564403-5:1:-1:1, destination =
topic://flight.search.result, transactionId = null, expiration = 0,
timestamp = 1294839245142, arrival = 0, brokerInTime = 1294839245142,
brokerOutTime = 1294839245150, correlationId = null, replyTo = null,
persistent = false, type = null, priority = 0, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter =
0, size = 1126, properties = {identifier=123}, readOnlyProperties = true,
readOnlyBody = true, droppable = false, text = <result type='foo'
num='9'>test message: 9</result>}
DEBUG | [2] N-Messages: 10
DEBUG | message: null
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839245166&r=0.3406089080963284
DEBUG | doMessage timeout=25000
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839221335&r=0.34852462634444237
DEBUG | doMessage timeout=25000
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839245166&r=0.3406089080963284
DEBUG | doMessage timeout=25000
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839270172&r=0.10504370275884867
DEBUG | doMessage timeout=25000
DEBUG | Cleaning up expired web clients.
DEBUG | Cleaning up expired web clients.
DEBUG | AjaxWebClient 1xki1evjkyakl7di3kqfsqs5z-defaultAjaxWebClient last
accessed 24 seconds ago.
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839270172&r=0.10504370275884867
DEBUG | doMessage timeout=25000
DEBUG | GET
client=org.apache.activemq.web.ajaxwebcli...@1685e30session=1xki1evjkyakl7di3kqfsqs5z
clientId=null uri=/demo/amq
query=timeout=60000&d=1294839295179&r=0.4715004425961524
DEBUG | doMessage timeout=25000
