HTTP protocol w/remote client dropping large messages
-----------------------------------------------------
Key: AMQ-3478
URL: https://issues.apache.org/jira/browse/AMQ-3478
Project: ActiveMQ
Issue Type: Bug
Components: Transport
Affects Versions: 5.4.2
Environment: Windows Server 2008 (server) on internet, port 4001 open
thru Windows Firewall, Win7 client home network wireless
Reporter: Jim Flowers
We're having a consistent problem using the HTTP transport on a machine hosted
on the internet and accessed through a firewall. Tests using a client on same
machine work. Tests in a private network with or without firewall work. Only
part of our application is having problems, i.e., we can login to the app on
the hosted machine and open a project; opening a larger dataset chunk-wise
fails apparently due to activity timeout. Our message payload is serialized
Java object graphs.
Have tried following:
1. setting wireFormat.maxInactivityDuration=0 (illegal param w/HTTP)
2. upping all socket timeouts to 30000
3. enabling TimeStampingBrokerPlugin
>From what we can see in the logs, in the remote case, the client sends several
>messages to fetch chunks of the large dataset which never arrive.
One thing we noticed in the activemq logs is a lot of removing and re-adding
consumers. Not sure if that is a sign of a problem.
Here is a bit of the server log. The message
jrflap-50115-1314636017162-1:1:3:17:1, came from the client asking for the
chunk, and the server appears to send it, but the client logs has nothing.
begin server log snipit>>>>>>>>>>>>>>
2011-08-29 12:43:48,527 [qtp17691874-97 ] - DEBUG TimeStampingBrokerPlugin
- Set message ID:jrflap-50115-1314636017162-1:1:3:17:1 timestamp from
1314636216258 to 1314639828527
2011-08-29 12:43:48,527 [Thread-33 ] - TRACE ActiveMQMessageConsumer
- ID:leonardo-50364-1314639588973-3:1:2:38 received message: MessageDispatch
{commandId = 0, responseRequired = false, consumerId =
ID:leonardo-50364-1314639588973-3:1:2:38, destination =
temp-topic://ID:leonardo-50364-1314639588973-3:1:1, message =
ActiveMQTextMessage {commandId = 97, responseRequired = true, messageId =
ID:jrflap-50115-1314636017162-1:1:3:17:1, originalDestination = null,
originalTransactionId = null, producerId =
ID:jrflap-50115-1314636017162-1:1:3:17, destination =
temp-topic://ID:leonardo-50364-1314639588973-3:1:1, transactionId = null,
expiration = 0, timestamp = 1314639828527, arrival = 0, brokerInTime =
1314639828527, brokerOutTime = 1314639828527, correlationId = null, replyTo =
null, persistent = true, type = null, priority = 4, groupID = null,
groupSequence = 0, targetConsumerId = null, compressed = false, userID = null,
content = null, marshalledProperties = null, dataStructure = null,
redeliveryCounter = 0, size = 1024, properties = {status=1}, readOnlyProperties
= true, readOnlyBody = true, droppable = false, text = null}, redeliveryCounter
= 0}
2011-08-29 12:43:48,543 [Thread-33 ] - DEBUG ActiveMQMessageConsumer
- remove: ID:leonardo-50364-1314639588973-3:1:2:38, lastDeliveredSequenceId:640
2011-08-29 12:43:48,558 [qtp17691874-20 ] - DEBUG AbstractRegion
- localhost removing consumer: ID:leonardo-50364-1314639588973-3:1:2:38 for
destination: temp-topic://ID:leonardo-50364-1314639588973-3:1:1
2011-08-29 12:43:49,369 [host] Scheduler] - DEBUG Queue
- Expiring messages ..
2011-08-29 12:43:49,369 [host] Scheduler] - DEBUG Queue
- TEST.QUEUE toPageIn: 0, Inflight: 0, pagedInMessages.size 0, enqueueCount:
0, dequeueCount: 0
2011-08-29 12:43:49,369 [host] Scheduler] - TRACE AbstractStoreCursor
- fillBatch - batchResetNeeded=false, hasMessages=false, size=0
2011-08-29 12:43:49,369 [host] Scheduler] - TRACE AbstractStoreCursor
- fillBatch - batchResetNeeded=false, hasMessages=false, size=0
2011-08-29 12:43:49,385 [host] Scheduler] - DEBUG Queue
- Expiring messages ..
2011-08-29 12:43:49,385 [host] Scheduler] - DEBUG Queue
- TEST.QUEUE toPageIn: 0, Inflight: 0, pagedInMessages.size 0, enqueueCount:
0, dequeueCount: 0
2011-08-29 12:43:49,385 [host] Scheduler] - TRACE AbstractStoreCursor
- fillBatch - batchResetNeeded=false, hasMessages=false, size=0
2011-08-29 12:43:49,385 [host] Scheduler] - TRACE AbstractStoreCursor
- fillBatch - batchResetNeeded=false, hasMessages=false, size=0
2011-08-29 12:43:49,666 [itor WriteCheck] - DEBUG InactivityMonitor
- 10000 ms elapsed since last write check.
2011-08-29 12:43:49,666 [itor WriteCheck] - TRACE InactivityMonitor
- Message sent since last write check, resetting flag
2011-08-29 12:43:50,009 [itor WriteCheck] - DEBUG InactivityMonitor
- 10000 ms elapsed since last write check.
2011-08-29 12:43:50,009 [itor WriteCheck] - TRACE InactivityMonitor
- Message sent since last write check, resetting flag
2011-08-29 12:43:50,508 [itor WriteCheck] - DEBUG InactivityMonitor
- 9999 ms elapsed since last write check.
2011-08-29 12:43:50,508 [itor WriteCheck] - TRACE InactivityMonitor
- Message sent since last write check, resetting flag
2011-08-29 12:43:50,508 [nitor ReadCheck] - DEBUG InactivityMonitor
- 29999 ms elapsed since last read check.
2011-08-29 12:43:50,508 [nitor ReadCheck] - TRACE InactivityMonitor
- Message received since last read check, resetting flag:
2011-08-29 12:43:50,602 [itor WriteCheck] - DEBUG InactivityMonitor
- 10000 ms elapsed since last write check.
2011-08-29 12:43:50,602 [itor WriteCheck] - TRACE InactivityMonitor
- Message sent since last write check, resetting flag
2011-08-29 12:43:50,602 [nitor ReadCheck] - DEBUG InactivityMonitor
- 29999 ms elapsed since last read check.
2011-08-29 12:43:50,602 [nitor ReadCheck] - TRACE InactivityMonitor
- A receive is in progress
2011-08-29 12:43:51,007 [qtp17691874-97 ] - DEBUG TimeStampingBrokerPlugin
- Set message ID:jrflap-50115-1314636017162-1:1:1:2:1 timestamp from
1314636218740 to 1314639831007
2011-08-29 12:43:51,007 [MQ Session Task] - TRACE ActiveMQSession
- ID:leonardo-50364-1314639588973-3:1:3 sending message: ActiveMQTextMessage
{commandId = 0, responseRequired = false, messageId =
ID:leonardo-50364-1314639588973-3:1:3:1:3, originalDestination = null,
originalTransactionId = null, producerId =
ID:leonardo-50364-1314639588973-3:1:3:1, destination =
topic://GPDCommunity.LGMDR_LIST, transactionId = null, expiration = 0,
timestamp = 1314639831007, arrival = 0, brokerInTime = 0, brokerOutTime = 0,
correlationId = null, replyTo = null, persistent = true, type = null, priority
= 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed =
false, userID = null, content = null, marshalledProperties = null,
dataStructure = null, redeliveryCounter = 0, size = 0, properties = {type=9},
readOnlyProperties = true, readOnlyBody = true, droppable = false, text = user1}
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
