worker thread waited more than 720 secs for server, abandoning game

classic Classic list List threaded Threaded
17 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

worker thread waited more than 720 secs for server, abandoning game

Porag
Hi

In some games I got this error, as a result my broker didn't enter the game resulting 0 balance. Any idea why this is happening?

Connecting to TS at http://ts.powertac.org:8080/TournamentScheduler/faces/brokerLogin.jsp
Tournament : 2016_seeding_2
Parsing message..
login response: [#document: null]
Login response received!
Login message receieved!
  jmsUrl=tcp://wolf35.ict.eur.nl:61616
  queueName=-1jr9spa3io40l
  serverQueue=-bggrmome9k1dm

worker thread waited more than 720 secs for server, abandoning game


Thanks
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

gbuijs
Hi Porag,

This happens when the broker isn't able to log into the game.
The game waits max. 10 minutes for brokers to connect.
So after 12 mins. the broker concludes the game started without him.
Hence the resulting 0 balance.

Do you know in which game this happened?

Cheers,

Govert
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
This post was updated on .
This happened in a few games, the recent game number is 645, 652, 535, 606, 648. :( this is happening at the very beginning of any object initialization i.e. market manager service or protfoliomanagerservice.  

Thanks
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

gbuijs
This is weird, i see your broker logging into the sim just fine.
But after that the sim didn't receive any messages.
And cleanly disables the broker as it deems it unresponsive.

Is there anything strange in your logfiles?
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

SPOT
I looked into the trace.log files and got this. I believe this is for game 517.

43833207 INFO  core.BrokerRunner: Starting session 6
43833207 INFO  core.BrokerPropertiesService: adding broker.properties
43833209 INFO  core.BrokerPropertiesService: Validating resource file:/usr/local/porag/2016_Qual/joint-broker_v1/target/classes/config/broker.properties
43833209 INFO  core.BrokerPropertiesService: loading config from file:/usr/local/porag/2016_Qual/joint-broker_v1/target/classes/config/broker.properties
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(BalancingControlEvent)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(SimEnd)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(CustomerBootstrapData)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(TariffTransaction)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(TariffStatus)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(TariffSpecification)
43833211 INFO  core.PowerTacBroker: Register PortfolioManagerService.handleMessage(TariffRevoke)
43833211 INFO  core.PowerTacBroker: Register ContextManagerService.handleMessage(Competition)
43833211 INFO  core.PowerTacBroker: Register ContextManagerService.handleMessage(Properties)
43833211 INFO  core.PowerTacBroker: Register ContextManagerService.handleMessage(CashPosition)
43833211 INFO  core.PowerTacBroker: Register ContextManagerService.handleMessage(DistributionReport)
43833211 INFO  core.PowerTacBroker: Register ContextManagerService.handleMessage(BankTransaction)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(DistributionTransaction)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(MarketBootstrapData)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(BalancingOrder)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(WeatherForecast)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(Orderbook)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(MarketTransaction)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(WeatherReport)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(MarketPosition)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(BalancingTransaction)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(Competition)
43833212 INFO  core.PowerTacBroker: Register MarketManagerService.handleMessage(ClearedTrade)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(SimPause)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(Competition)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(BrokerAccept)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(SimEnd)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(TimeslotUpdate)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(TimeslotComplete)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(SimStart)
43833212 INFO  core.PowerTacBroker: Register PowerTacBroker.handleMessage(SimResume)
43833212 INFO  core.BrokerTournamentService: Connecting to TS with http://ts.powertac.org:8080/TournamentScheduler/faces/brokerLogin.jsp?authToken=1caef514ad9c0f02eadf7c53e98d36a3&requestJoin=2016_seeding_2&type=xml
43833212 INFO  core.BrokerTournamentService: Tournament : 2016_seeding_2
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
I just compared the trace file with a successful complete game trace file. I can see that I am missing these lines

"
7096 INFO  core.JmsManagementService: registerMessageListener(SPOT, org.powertac.samplebroker.core.BrokerMessageReceiver@751e664e)
8946 INFO  core.PowerTacBroker: Listening on queue SPOT
"

Is there any reason my broker agent is failing to register Message Listener. Our broker version is 1.3.2.

Thanks
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

gbuijs
Hi Porag,

For completeness sake i've included a snippet from a successful login with the change from TS to sim.
I'm also assuming you didn't modify broker-core.

The fact you don't see a "core.JmsManagementService: registerMessageListener" in your logs is really weird.
In game 517 / 2016_seeding_2_61 your agent did connect to the sim, there's "Log in broker SPOT" in the sim-trace file.
That's only possible if your agent has an established JMS connection.

This is the login on the TS, responses are server + broker queue names and jms-url
73170358 INFO  core.BrokerTournamentService: Connecting to TS with http://ts.powertac.org:8080/TournamentScheduler/faces/brokerLogin.jsp?authToken=<<AUTH TOKEN>>&requestJoin=2016_seeding_2&type=xml
73170358 INFO  core.BrokerTournamentService: Tournament : 2016_seeding_2
73170486 INFO  core.BrokerTournamentService: Login response received!
73170486 INFO  core.BrokerTournamentService: jmsUrl=tcp://wolf33.ict.eur.nl:61616
73170486 INFO  core.BrokerTournamentService: brokerQueueName=<<BROKER QUEUE>>
73170486 INFO  core.BrokerTournamentService: serverQueueName=<<SERVER QUEUE>>
73170487 INFO  core.BrokerTournamentService: Login Successful!
Setup the JMS listener with those params
73170487 INFO  core.JmsManagementService: registerMessageListener(<<BROKER QUEUE>>, org.powertac.samplebroker.core.BrokerMessageReceiver@1788cb61)
73170497 INFO  core.PowerTacBroker: Listening on queue <<BROKER QUEUE>>
Login on the sim
73170498 INFO  core.MessageDispatcher: sending text:
<broker-authentication username="<<BROKER NAME>>" password="secret" brokerTime="1466489314174"/>
Login successful
73170525 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<broker-accept prefix="<<PREFIX>>" key="<<BROKER KEY>>" serverTime="1466489314192"/>
Start of the game
73184663 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<competition id="0" name="2016_seeding_2_19" pomId="1.3.3-SNAPSHOT" timeslotLength="60" bootstrapTimeslotCount="336" bootstrapDiscardedTimeslots="24" timeslotsOpen="24" deactivateTimeslotsAhead="1" minimumOrderQuantity="0.01" timezoneOffset="-7" latitude="45" simulationRate="720" simulationModulo="3600000">
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
This post was updated on .
I ran a local game and I got this errors...

<market-tx id="24220" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24222" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24224" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
92175 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6048, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-62469-1466920711544-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1988, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1988, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:1:5:1:1988 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24226" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24228" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24230" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94363 INFO  core.BrokerMessageReceiver: onMessage(String) - received message:
<market-tx id="24232" postedTimeslot="364" price="-14.07044246004165" mWh="0.21100000000000002" timeslot="382">
  <broker>SPOT</broker>
</market-tx>
94363 ERROR samplebroker.MarketManagerService: order corresponding to market tx MktTx: time 382, 0.21100000000000002@-14.07044246004165 is null
94453 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6049, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-62469-1466920711544-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1989, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1989, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:1:5:1:1989 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
94453 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6050, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-62469-1466920711544-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1990, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1990, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:1:5:1:1990 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
94453 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6051, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-62469-1466920711544-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1991, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1991, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:1:5:1:1991 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
94453 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6052, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-62469-1466920711544-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1992, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:1:5:1:1992, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:1:5:1:1992 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
132479 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: java.io.EOFException
        at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:49) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.ActiveMQConnection.onAsyncException(ActiveMQConnection.java:1934) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.ActiveMQConnection.onException(ActiveMQConnection.java:1951) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:101) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.ResponseCorrelator.onException(ResponseCorrelator.java:126) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:101) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:101) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onException(WireFormatNegotiator.java:160) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onException(AbstractInactivityMonitor.java:268) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.onException(TransportSupport.java:96) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:208) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
Caused by: java.io.EOFException
        at java.io.DataInputStream.readInt(DataInputStream.java:392) ~[?:1.8.0_71]
        at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        ... 1 more
194966 WARN  core.PowerTacBroker: worker thread waited more than 120 secs for server, abandoning game
194966 INFO  core.PowerTacBroker: worker thread exits at ts 363

Any idea why this is happening ? In my bidding strategy I am trying to submit less than 100 orders per hour ahead auctions. The main problem is this is not happening all the time and I am not always able to reproduce this game abandoning error. The maximum of bids and asks I am submitting per timeslot is less than 2400. is that a problem?


Regards,
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
This post was updated on .
This happened in another local game found in the broker.trace file :

46137 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6358, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
47273 WARN  connection.CachingConnectionFactory: Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6359, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) ~[activemq-core-5.6.0.jar:5.6.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) ~[activemq-core-5.6.0.jar:5.6.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
156668 WARN  core.PowerTacBroker: worker thread waited more than 120 secs for server, abandoning game
156668 INFO  core.PowerTacBroker: worker thread exits at ts 363


And below logs are found in server's trace.log file.

10721540 WARN  TransportConnection.Service: Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6358, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124 in dispatched-list (start of ack)
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6358, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2124 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) [activemq-core-5.7.0.jar:5.7.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]
10721660 WARN  TransportConnection.Service: Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6359, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125 in dispatched-list (start of ack)
javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 6359, responseRequired = false, ackType = 2, consumerId = ID:IASRL-139219-64613-1466930720602-1:1:1:1, firstMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, lastMessageId = ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125, destination = queue://SPOT, transactionId = null, messageCount = 1, poisonCause = null}; Could not find Message-ID ID:IASRL-139219-62465-1466920656771-3:12:5:1:2125 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:481) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:206) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:427) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:529) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:77) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:287) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:87) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:458) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.command.MessageAck.visit(MessageAck.java:236) ~[activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:256) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222) [activemq-core-5.7.0.jar:5.7.0]
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204) [activemq-core-5.7.0.jar:5.7.0]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_71]




Can anyone please help me? This is not always happening!

Thanks
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

gbuijs
This usually indicative of networking problems.

You say that this is from a local game.
Do you mean that you ran the server and the broker on the same machine?

If so, could you try the setup on a different machine?
Also, which OS are you running this on?
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
gbuijs wrote
This usually indicative of networking problems.

You say that this is from a local game.
Do you mean that you ran the server and the broker on the same machine?
Yes, I ran the server and broker on the same machine.

gbuijs wrote
If so, could you try the setup on a different machine?
Also, which OS are you running this on?
Can you please tell me what is needed to be changed in the configuration files(both server and broker) to run a server on a different machine. I am using windows 7. But for running my brokers in the real tournaments, I was using linux.

Thanks
Porag
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
FYI, I have been sending maximum 100 bids per auction. So I am sending maximum of 2400 bids per timeslot as a timeslot has 24 auctions. Is this a problem? What is the maximum limit of bids a broker can send per timeslot?
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

gbuijs
There isn't a hard limit on the max amount of messages.
It has probably more to do with hardware limitations, although that's just a wild guess.
You could send me the binary so i could test it on my machine.

To run a game on a different machine than the broker:
- For the server, set the jms url to it's IP address with
--jms-url tcp://<<IP ADDRESS>>:61616
- For the broker, set the jmsBrokerUrl in broker.properties to the same url
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: worker thread waited more than 720 secs for server, abandoning game

Porag
Dear Govert, I have sent my broker binary to your buijs@rsm.nl email. Btw is it possible that the garbage collector is not being called and the broker java processes are occupying all the ram memory? If so should I make the system.gc() call inside the broker code for requesting a garbage collection?

Thanks
Porag  
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

AW: worker thread waited more than 720 secs for server, abandoning game

turban

Hi Porag,

 

As far as I know: in JAVA your own Code is not  responsible for the garbage collection. The JVM will do the job for you whenever it thinks it might be needed.

 

Calling System.gc(). Is *bad practice* and should be avoided. There are some reasons to avoid it (1) you actually don’t start the garbage collection you just suggest that the JVM should do it. Most of the times when your code depends on garbage collection (at a specific point) is most likely broken (2) It might be really inefficient to run the garbage collection at some given point (3) You will never know which garbage collector will run because you have no influence about it.

 

If you are facing “OutOfMemoryError” exceptions calling System.gc() will probably not solve it.

 

Cheers, Tobias

 

 

Von: Porag [via Power TAC Developers] [mailto:ml-node+[hidden email]]
Gesendet: Dienstag, 28. Juni 2016 12:32
An: Tobias Urban <[hidden email]>
Betreff: Re: worker thread waited more than 720 secs for server, abandoning game

 

Dear Govert, I have sent my broker binary to your [hidden email] email. Btw is it possible that the garbage collector is not being called and the broker java processes are occupying all the ram memory? If so should I make the system.gc() call inside the broker code for requesting a garbage collection?

Thanks
Porag  


To start a new topic under Power TAC Developers, email [hidden email]
To unsubscribe from Power TAC Developers, click here.
NAML

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: AW: worker thread waited more than 720 secs for server, abandoning game

Porag
This post was updated on .
Thanks for the suggestions Tobias. Btw I have figured out the error, it was in the orderbook message handler. In some simulations (I don't know why) the difference between orderbooktimeslotindex and currenttimeslot index is -1 and more than 23. This should not be happening, right? Cause we have 24 auctions running for each timeslot! This was causing my broker to get array index out of bound error. Any one got this error in their broker?? Is it possible to have negative difference or a difference more than 23 between the  orderbooktimeslotindex and currenttimeslot in the orderbook message handler? and also sometime I am getting the value of remaining tries for an auction -11? i.e. the value of this code

int remainingTries = (timeslot - current - Competition
                                .currentCompetition().getDeactivateTimeslotsAhead());


It should be always 0~23. right??
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: AW: worker thread waited more than 720 secs for server, abandoning game

grampajohn
Administrator
Hello, Porag -

Porag wrote
... In some simulations (I don't know why) the difference between orderbooktimeslotindex and currenttimeslot index is -1 and more than 23. This should not be happening, right? Cause we have 24 auctions running for each timeslot! This was causing my broker to get array index out of bound error. Any one got this error in their broker?? Is it possible to have negative difference or a difference more than 23 between the  orderbooktimeslotindex and currenttimeslot in the orderbook message handler? and also sometime I am getting the value of remaining tries for an auction -11? i.e. the value of this code

int remainingTries = (timeslot - current - Competition
                                .currentCompetition().getDeactivateTimeslotsAhead());


It should be always 0~23. right??
Yes, it should always be 0-23, as long as the "current" timeslot is the same as it was when the "timeslot" value was generated. In the server, this is guaranteed, otherwise the server exits with an error. In the broker, this can be violated if the timeslot boundary has passed between the time the "timeslot" value was generated in the server, and the time you inspect it in the broker. This can happen for two reasons: latency (your broker has been busy, or swapped out, and the timeslot boundary has passed), or you have a clock-synchronization problem - which would mean that your ntp process is not working correctly.

Does this make sense?

John
Loading...