# 1296181148459 Do not modify this line [27/Jan/2011:18:19:08 PST] ================================================================================ Oracle GlassFish(tm) Server Message Queue 4.5 Oracle Version: 4.5 (Build 26-a) Compile: Mon Jan 17 12:47:59 PST 2011 Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved. ================================================================================ Java Runtime: 1.6.0_23 Sun Microsystems Inc. C:\ha\jdk1.6.0_23\jre [27/Jan/2011:18:19:08 PST] IMQ_HOME=C:\ha\glassfish3\mq [27/Jan/2011:18:19:08 PST] IMQ_VARHOME=C:\ha\glassfish3\glassfish\nodes\agent2\instance101\imq [27/Jan/2011:18:19:08 PST] Windows Server 2008 R2 6.1 x86 bigapp-x2250-1.us.oracle.com (4 cpu) cyg_server [27/Jan/2011:18:19:08 PST] Java Heap Size: max=174784k, current=15744k [27/Jan/2011:18:19:08 PST] Arguments: -startRmiRegistry -rmiRegistryPort 27776 -Dimq.imqcmd.user=admin -Dimq.hostname=bigapp-x2250-1.us.oracle.com -save -name stclusterinstance101 -port 27676 -ttyerrors -read-stdin [27/Jan/2011:18:19:08 PST] JMSRA BrokerProps: : imq.persist.jdbc.mysql.user=dbuser, imq.cluster.nowaitForMasterBroker=true, imq.cluster.ha=true, imq.persist.jdbc.dbVendor=mysql, imq.brokerid=stclusterinstance101, imq.persist.jdbc.mysql.password=*****, imq.persist.jdbc.mysql.property.url=jdbc:mysql://asqe-core2.us.oracle.com:3306/dbsmpl1, imq.jmsra.managed=true, imq.cluster.clusterid=stcluster_MQ, imq.imqcmd.password=*****, imq.persist.store=jdbc, imq.cluster.dynamicChangeMasterBrokerEnabled=true [27/Jan/2011:18:19:08 PST] Broker Properties: imq.hostname=bigapp-x2250-1.us.oracle.com, imq.portmapper.port=27676, imq.imqcmd.user=admin, imq.instancename=stclusterinstance101, imq.log.console.output=ERROR|NOFORCE, imq.jmx.rmiregistry.port=27776, imq.jmx.rmiregistry.start=true, imq.readstdin.enabled=true [27/Jan/2011:18:19:08 PST] [B1202]: Broker stclusterinstance101 is running in HA mode as part of the stcluster_MQ cluster [27/Jan/2011:18:19:08 PST] [B1004]: Starting the portmapper service using tcp [ 27676, 50, 10.133.185.27 ] with min threads 1 and max threads of 1 [27/Jan/2011:18:19:08 PST] [B1060]: Loading persistent data... [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.mysql.driver=com.mysql.jdbc.jdbc2.optional.MysqlConnectionPoolDataSource [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.mysql.property.cacheResultSetMetadata=true [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.mysql.property.cachePreparedStatements=true [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.mysql.property.preparedStatementCacheSize=25 [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.mysql.tableoption=ENGINE=InnoDB [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.connection.validationQuery=/* ping */ [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.connection.validateOnGet=true [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.connection.timeoutIdle=true [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.connection.reaptime=300 [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.min_connections=5 [27/Jan/2011:18:19:08 PST] imq.persist.jdbc.max_connections=5 [27/Jan/2011:18:19:08 PST] MySQL, 5.1.33-community, mysql-connector-java-5.1.13 ( Revision: ${bzr.revision-id} ) [27/Jan/2011:18:19:08 PST] Using plugged-in persistent store: version=410 brokerid=stclusterinstance101 database connection url=jdbc:mysql://asqe-core2.us.oracle.com:3306/dbsmpl1 database user=dbuser [27/Jan/2011:18:19:08 PST] [B1170]: Auto Creation of plugged-in persistent store is enabled [27/Jan/2011:18:19:09 PST] WARNING [B2219]: Broker property setting imq.persist.file.newTxnLog.enabled=true will be ignored [27/Jan/2011:18:19:09 PST] [B1204]: Starting HA Monitor Service [27/Jan/2011:18:19:09 PST] [B1206]: Monitor service initializing for brokerid stclusterinstance101 at mq://10.133.185.27:27676/ [27/Jan/2011:18:19:09 PST] imq.cluster.monitor.interval=30 [27/Jan/2011:18:19:09 PST] imq.cluster.monitor.threshold=3 [27/Jan/2011:18:19:09 PST] [B1193]: Broker has started using a store session of 4981875956819909120 and a broker session of 6539839956292832256 [27/Jan/2011:18:19:09 PST] [B1205]: Starting HA Heartbeat Service [27/Jan/2011:18:19:09 PST] [B1187]: Heartbeat service binds to bigapp-x2250-1.us.oracle.com/10.133.185.27:27676 [27/Jan/2011:18:19:09 PST] [B1004]: Starting the heartbeat service using udp ( bigapp-x2250-1.us.oracle.com/10.133.185.27:27676 ) with min threads 1 and max threads of 1 [27/Jan/2011:18:19:09 PST] [B1041]: Cluster initialization successful. [27/Jan/2011:18:19:09 PST] [B1136]: Processing stored transactions [27/Jan/2011:18:19:09 PST] [B1079]: Found 4 transactions. 0 will be rolled back. [27/Jan/2011:18:19:09 PST] [B1080]: Of 4 transactions, 1 are in PREPARED state, 3 are in COMMITTED state [27/Jan/2011:18:19:09 PST] [B1082]: Auto-rollback is disabled. Will leave PREPARED transactions unresolved. [27/Jan/2011:18:19:09 PST] [B1284]: 0 cluster transactions remain in PREPARED state, 0 in COMMITTED state waiting for remote broker completion [27/Jan/2011:18:19:09 PST] Of 0 remote transactions, 0 in PREPARED state, 0 in COMPLETE state, 0 in COMMITTED state [27/Jan/2011:18:19:09 PST] [B1013]: Auto Creation of Queues is enabled [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination mq.sys.dmq [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination mq.sys.dmq [Queue] complete [27/Jan/2011:18:19:09 PST] Loading stored durable TopicMDBBean:TopicMDBBean [27/Jan/2011:18:19:09 PST] Loading stored durable TopicMDBBean:TopicMDBBean [27/Jan/2011:18:19:09 PST] [B3100]: Unexpected Broker Internal Error : [loaded durable consumer [cid=TopicMDBBean, dn=TopicMDBBean] already exists Subscription :[consumer:121647535304986114, type=NONE] - dest=T:Quotes CID=TopicMDBBean DN=TopicMDBBean] [27/Jan/2011:18:19:09 PST] Loading stored durable TopicMDBBean:TopicMDBBean [27/Jan/2011:18:19:09 PST] [B3100]: Unexpected Broker Internal Error : [loaded durable consumer [cid=TopicMDBBean, dn=TopicMDBBean] already exists Subscription :[consumer:4773303000979939330, type=NONE] - dest=T:Quotes CID=TopicMDBBean DN=TopicMDBBean] [27/Jan/2011:18:19:09 PST] Loading stored durable abcdef:SomeName [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination SampleQ [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination SampleQ [Queue] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination FilteredQuotes [Topic] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination FilteredQuotes [Topic] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination queue1 [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination queue1 [Queue] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination nonpersistentQueue [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination nonpersistentQueue [Queue] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination mq.sys.dmq [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination mq.sys.dmq [Queue] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination Quotes [Topic] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination Quotes [Topic] complete [27/Jan/2011:18:19:09 PST] [B1151]: Loading destination persistentQueue [Queue] with 0 messages [27/Jan/2011:18:19:09 PST] [B1152]: Loading of destination persistentQueue [Queue] complete [27/Jan/2011:18:19:09 PST] [B1390]: Loading of transactions has been successfully completed [27/Jan/2011:18:19:09 PST] [B1285]: Reaper thread for committed transactions has started (limit 500, interval 900sec). [27/Jan/2011:18:19:09 PST] [B1239]: Using platform MBean server [27/Jan/2011:18:19:10 PST] RMI Registry started on port 27776 [27/Jan/2011:18:19:10 PST] JESMF classes not present - JESMF support will not be enabled. [27/Jan/2011:18:19:10 PST] JMX Connector Server jmxrmi started successfully with url service:jmx:rmi://bigapp-x2250-1.us.oracle.com/jndi/rmi://bigapp-x2250-1.us.oracle.com:27776/bigapp-x2250-1.us.oracle.com/27676/jmxrmi [27/Jan/2011:18:19:10 PST] [B1004]: Starting the admin service using tcp(host = bigapp-x2250-1.us.oracle.com, port=0, mode=dedicated) with min threads 4 and max threads of 10 [27/Jan/2011:18:19:10 PST] [B1227]: Using file user repository for admin service connection authentication [27/Jan/2011:18:19:10 PST] [B1004]: Starting the jms service using tcp(host = bigapp-x2250-1.us.oracle.com, port=0, mode=dedicated) with min threads 10 and max threads of 1000 [27/Jan/2011:18:19:10 PST] [B1227]: Using file user repository for jms service connection authentication [27/Jan/2011:18:19:10 PST] [B1004]: Starting the cluster service using tcp [ bigapp-x2250-1.us.oracle.com/10.133.185.27:58477 ] with min threads 1 and max threads of 1 [27/Jan/2011:18:19:10 PST] [B1229]: Using cluster ID stcluster_MQ [27/Jan/2011:18:19:10 PST] [B1228]: Cluster ping interval is 60 seconds [27/Jan/2011:18:19:10 PST] [B1039]: Broker "stclusterinstance101@10.133.185.27:27676" ready. [27/Jan/2011:18:19:11 PST] [B1065]: Accepting: admin@10.133.185.27:58479->admin:58473. Count: service=1 broker=1 [27/Jan/2011:18:19:11 PST] WARNING [B2105]: Attempting to initiate a cluster connection to mq://10.133.185.47:27677/?instName=???&brokerID=stclusterinstance105&brokerSessionUID=null&ha=true&storeSessionUID=null failed: Connection refused: connect [27/Jan/2011:18:19:11 PST] WARNING [B2105]: Attempting to initiate a cluster connection to mq://10.133.185.47:27676/?instName=???&brokerID=stclusterinstance103&brokerSessionUID=null&ha=true&storeSessionUID=null failed: Connection refused: connect [27/Jan/2011:18:19:11 PST] WARNING [B2105]: Attempting to initiate a cluster connection to mq://10.133.185.37:27676/?instName=???&brokerID=stclusterinstance102&brokerSessionUID=null&ha=true&storeSessionUID=null failed: Connection refused: connect [27/Jan/2011:18:19:14 PST] [B1185]: Starting heartbeat to stclusterinstance104 [27/Jan/2011:18:19:14 PST] [B1181]: Added heartbeat endpoint /10.133.185.37:27677 [brokerID=stclusterinstance104, brokerSession=6476226611558371840] (seq#=0, ts=1296181154387, interval=2, len=233) [27/Jan/2011:18:19:14 PST] [B1179]: Activated broker Address = mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840 StartTime = 1296181157660 ProtocolVersion = 410 HeartbeatHost = 10.133.185.37 HeartbeatPort = 27677 [27/Jan/2011:18:19:14 PST] [B1071]: Established cluster connection to broker mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840[/10.133.185.37:50784] [27/Jan/2011:18:19:14 PST] [B1185]: Starting heartbeat to stclusterinstance102 [27/Jan/2011:18:19:14 PST] [B1181]: Added heartbeat endpoint /10.133.185.37:27676 [brokerID=stclusterinstance102, brokerSession=8649213431764659968] (seq#=0, ts=1296181154481, interval=2, len=233) [27/Jan/2011:18:19:14 PST] [B1179]: Activated broker Address = mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552 StartTime = 1296181157738 ProtocolVersion = 410 HeartbeatHost = 10.133.185.37 HeartbeatPort = 27676 [27/Jan/2011:18:19:14 PST] [B1071]: Established cluster connection to broker mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552[/10.133.185.37:50798] [27/Jan/2011:18:19:16 PST] [B1185]: Starting heartbeat to stclusterinstance103 [27/Jan/2011:18:19:16 PST] [B1181]: Added heartbeat endpoint /10.133.185.47:27676 [brokerID=stclusterinstance103, brokerSession=1646678961159512320] (seq#=0, ts=1296181156915, interval=2, len=233) [27/Jan/2011:18:19:16 PST] [B1179]: Activated broker Address = mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336 StartTime = 1296181167833 ProtocolVersion = 410 HeartbeatHost = 10.133.185.47 HeartbeatPort = 27676 [27/Jan/2011:18:19:16 PST] [B1071]: Established cluster connection to broker mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336[/10.133.185.47:54675] [27/Jan/2011:18:19:16 PST] [B1185]: Starting heartbeat to stclusterinstance105 [27/Jan/2011:18:19:16 PST] [B1181]: Added heartbeat endpoint /10.133.185.47:27677 [brokerID=stclusterinstance105, brokerSession=1527052096057531392] (seq#=0, ts=1296181156915, interval=2, len=233) [27/Jan/2011:18:19:16 PST] [B1179]: Activated broker Address = mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464 StartTime = 1296181167973 ProtocolVersion = 410 HeartbeatHost = 10.133.185.47 HeartbeatPort = 27677 [27/Jan/2011:18:19:16 PST] [B1071]: Established cluster connection to broker mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464[/10.133.185.47:54689] [27/Jan/2011:18:20:13 PST] [B1173]: Received GOODBYE [requestTakeover=true mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464] from mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464 [27/Jan/2011:18:20:13 PST] [B1072]: Closed cluster connection to broker mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464 [27/Jan/2011:18:20:13 PST] [B1180]: Deactivated broker Address = mq://10.133.185.47:27677/?instName=stclusterinstance105&brokerID=stclusterinstance105&brokerSessionUID=1527052096057531392&ha=true&storeSessionUID=2552183957035518464 StartTime = 1296181167973 ProtocolVersion = 410 HeartbeatHost = 10.133.185.47 HeartbeatPort = 27677 [27/Jan/2011:18:20:13 PST] [B1173]: Received GOODBYE [requestTakeover=true mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840] from mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840 [27/Jan/2011:18:20:13 PST] [B1072]: Closed cluster connection to broker mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840 [27/Jan/2011:18:20:13 PST] [B1180]: Deactivated broker Address = mq://10.133.185.37:27677/?instName=stclusterinstance104&brokerID=stclusterinstance104&brokerSessionUID=6476226611558371840&ha=true&storeSessionUID=6476226611558371840 StartTime = 1296181157660 ProtocolVersion = 410 HeartbeatHost = 10.133.185.37 HeartbeatPort = 27677 [27/Jan/2011:18:20:13 PST] [B1173]: Received GOODBYE [requestTakeover=true mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552] from mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552 [27/Jan/2011:18:20:13 PST] [B1072]: Closed cluster connection to broker mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552 [27/Jan/2011:18:20:13 PST] [B1180]: Deactivated broker Address = mq://10.133.185.37:27676/?instName=stclusterinstance102&brokerID=stclusterinstance102&brokerSessionUID=8649213431764659968&ha=true&storeSessionUID=3396890360381463552 StartTime = 1296181157738 ProtocolVersion = 410 HeartbeatHost = 10.133.185.37 HeartbeatPort = 27676 [27/Jan/2011:18:20:13 PST] [B1172]: Sending GOODBYE[requestTakeover=true mq://10.133.185.27:27676/?instName=stclusterinstance101&brokerID=stclusterinstance101&brokerSessionUID=6539839956292832256&ha=true&storeSessionUID=4981875956819909120] to mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336 [27/Jan/2011:18:20:13 PST] [B1188]: Waiting for cluster service shutdown. 1 link(s) remaining .. [27/Jan/2011:18:20:13 PST] [B1173]: Received GOODBYE [requestTakeover=true mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336] from mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336 [27/Jan/2011:18:20:13 PST] [B1072]: Closed cluster connection to broker mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336 [27/Jan/2011:18:20:13 PST] [B1093]: Shutdown requested by broker administrator [27/Jan/2011:18:20:13 PST] [B1180]: Deactivated broker Address = mq://10.133.185.47:27676/?instName=stclusterinstance103&brokerID=stclusterinstance103&brokerSessionUID=1646678961159512320&ha=true&storeSessionUID=3607715066357070336 StartTime = 1296181167833 ProtocolVersion = 410 HeartbeatHost = 10.133.185.47 HeartbeatPort = 27676 [27/Jan/2011:18:20:13 PST] [B1047]: Shutting down broker...[admin] [27/Jan/2011:18:20:13 PST] [B1077]: Broadcast good-bye to all connections ... [27/Jan/2011:18:20:13 PST] [B1078]: Flushing good-bye messages ... [27/Jan/2011:18:20:13 PST] [B1007]: Stopping Service admin with protocol tcp(host = bigapp-x2250-1.us.oracle.com, port=0, mode=dedicated) [27/Jan/2011:18:20:13 PST] [B1007]: Stopping Service jms with protocol tcp(host = bigapp-x2250-1.us.oracle.com, port=0, mode=dedicated) [27/Jan/2011:18:20:13 PST] [B1286]: Reaper thread for committed transactions is exiting. [27/Jan/2011:18:20:13 PST] WARNING [B2181]: Removing 1 messages associated with destination temporary_destination://queue/10.133.185.27/58479/1 [Queue] [27/Jan/2011:18:20:13 PST] [B1066]: Closing: admin@10.133.185.27:58479->admin:58473 because "[B0061]: Client exited without closing connections". Count: service=0 broker=0 [27/Jan/2011:18:20:13 PST] JMX Connector Server jmxrmi stopped successfully [27/Jan/2011:18:20:13 PST] [B1048]: Shutdown of broker complete.