Attachment 827784 Details for Bug 1019807 – server.log(part)

server.log(part)

server.log (text/x-log), 31.81 KB, created by Armine Hovsepyan on 2013-11-22 13:41:34 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Armine Hovsepyan

Created: 2013-11-22 13:41:34 UTC

Size: 31.81 KB

patch

obsolete

>07:17:15,220 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-7) StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=INSTALLED, mtime=1385122344081] is an existing storage node. No cluster maintenance is necessary.
>07:17:30,777 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 5) jon312.bc.jonqe.lab.eng.bos.redhat.com took [122]ms to reload global cache
>07:17:30,940 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 5) jon312.bc.jonqe.lab.eng.bos.redhat.com took [110]ms to reload cache for 1 agents
>07:18:00,752 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 9) jon312.bc.jonqe.lab.eng.bos.redhat.com took [89]ms to reload cache for 1 agents
>07:24:52,269 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/richfaces-ui-3.3.4.Final.jar/META-INF/jsp.taglib.xml
>07:24:52,323 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/richfaces-ui-3.3.4.Final.jar/META-INF/ajax4jsf.taglib.xml
>07:24:52,362 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/richfaces-ui-3.3.4.Final.jar/META-INF/richfaces.taglib.xml
>07:24:52,365 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/richfaces-ui-3.3.4.Final.jar/META-INF/a4j.taglib.xml
>07:24:52,371 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/richfaces-ui-3.3.4.Final.jar/META-INF/rich.taglib.xml
>07:24:52,373 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/rhq-core-gui-4.9.0.JON320ER7.jar/META-INF/rhq.taglib.xml
>07:24:52,378 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/jsf-facelets-1.1.15.B1.jar/META-INF/jstl-fn.taglib.xml
>07:24:52,386 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/jsf-facelets-1.1.15.B1.jar/META-INF/jstl-core.taglib.xml
>07:24:52,405 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/jsf-facelets-1.1.15.B1.jar/META-INF/jsf-ui.taglib.xml
>07:24:52,435 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/jsf-facelets-1.1.15.B1.jar/META-INF/jsf-core.taglib.xml
>07:24:52,440 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/lib/jsf-facelets-1.1.15.B1.jar/META-INF/jsf-html.taglib.xml
>07:24:52,442 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/tags/on.function.taglib.xml
>07:24:52,444 INFO  [facelets.compiler] (http-/0.0.0.0:7080-3) Added Library from: vfs:/home/hudson/jon-server-3.2.0.ER7/modules/org/rhq/server-startup/main/deployments/rhq.ear/rhq-portal.war/WEB-INF/tags/on.component.taglib.xml
>07:42:36,643 WARN  [org.rhq.enterprise.communications.command.server.CommandProcessor] (http-/0.0.0.0:7080-1) {CommandProcessor.failed-authentication}Command failed to be authenticated!  This command will be ignored and not processed: Command: type=[remotepojo]; cmd-in-response=[false]; config=[{rhq.agent-name=joner7.bc.jonqe.lab.eng.bos.redhat.com, rhq.security-token=62y/Swm7IPcsVzhEPwV04dOsx+T5jJoJkqxNgjTxvxoj47VJ159SizRUS+iFl4EDLqw=, rhq.externalizable-strategy=AGENT}]; params=[{invocation=NameBasedInvocation[connectAgent], targetInterfaceName=org.rhq.core.clientapi.server.core.CoreServerService}]
>07:42:37,790 INFO  [org.rhq.enterprise.server.core.CoreServerServiceImpl] (http-/0.0.0.0:7080-1) Got agent registration request for new agent: joner7.bc.jonqe.lab.eng.bos.redhat.com[10.16.23.61:16163][4.9.0.JON320ER7(ff0061d)]
>07:42:37,954 INFO  [org.rhq.enterprise.server.core.CoreServerServiceImpl] (http-/0.0.0.0:7080-2) Agent [joner7.bc.jonqe.lab.eng.bos.redhat.com][4.9.0.JON320ER7(ff0061d)] would like to connect to this server
>07:42:38,144 INFO  [org.rhq.enterprise.server.core.CoreServerServiceImpl] (http-/0.0.0.0:7080-2) Agent [joner7.bc.jonqe.lab.eng.bos.redhat.com] has connected to this server at Fri Nov 22 07:42:38 EST 2013
>07:42:59,005 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-2) Linking Resource[id=10093, uuid=fc88f1bd-4d8a-49b0-a084-ee7f752b24af, type={RHQStorage}RHQ Storage Node, key=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), name=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), parent=joner7.bc.jonqe.lab.eng.bos.redhat.com, version=4.9.0.JON320ER7] to storage node at joner7.bc.jonqe.lab.eng.bos.redhat.com
>07:42:59,029 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-2) Did not find storage node with address [joner7.bc.jonqe.lab.eng.bos.redhat.com] Searching by IP address [10.16.23.61]
>07:42:59,041 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-2) Scheduling cluster maintenance to deploy StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=INSTALLED, mtime=1385124179039] into the storage cluster...
>07:42:59,041 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-2) Deploying StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=INSTALLED, mtime=1385124179039]
>07:42:59,059 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (http-/0.0.0.0:7080-2) Announcing StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ANNOUNCE, mtime=1385124179039] to storage node cluster.
>07:42:59,067 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (http-/0.0.0.0:7080-2) Announcing StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ANNOUNCE, mtime=1385124179039] to cluster node StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>07:43:00,687 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 10) jon312.bc.jonqe.lab.eng.bos.redhat.com took [34]ms to reload global cache
>07:43:00,757 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 10) jon312.bc.jonqe.lab.eng.bos.redhat.com took [54]ms to reload cache for 1 agents
>07:43:02,569 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 3) Successfully announced new storage node to storage cluster
>07:43:02,677 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 3) Preparing to bootstrap StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=BOOTSTRAP, mtime=1385124179039] into cluster...
>07:43:08,376 INFO  [com.datastax.driver.core.Cluster] (Scheduled Tasks-0) New Cassandra host /10.16.23.61 added
>07:43:08,396 INFO  [org.rhq.server.metrics.StorageSession] (Scheduled Tasks-0) /10.16.23.61 added
>07:43:08,396 INFO  [org.rhq.server.metrics.StorageSession] (Scheduled Tasks-0) Storage cluster is up
>07:43:08,397 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Scheduled Tasks-0) Storage cluster is up
>07:43:08,397 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Scheduled Tasks-0) Storage node at 10.16.23.61 is up
>07:43:08,400 INFO  [org.rhq.server.metrics.StorageSession] (Cassandra Java Driver worker-1) /10.16.23.61 is down
>07:43:08,400 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Cassandra Java Driver worker-1) Storage node at 10.16.23.61 is down
>07:43:30,814 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 4) jon312.bc.jonqe.lab.eng.bos.redhat.com took [149]ms to reload cache for 1 agents
>07:43:33,615 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) The prepare for bootstrap operation completed successfully for StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=BOOTSTRAP, mtime=1385124179039]
>07:43:36,435 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) Running addNodeMaintenance for storage node StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ADD_MAINTENANCE, mtime=1385124179039]
>07:43:38,791 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 3) Finished running add node maintenance for StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ADD_MAINTENANCE, mtime=1385124179039]
>07:43:38,810 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 3) Running addNodeMaintenance for storage node StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>07:44:12,296 INFO  [org.rhq.server.metrics.StorageSession] (Reconnection-0) /10.16.23.61 is up
>07:44:12,297 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Reconnection-0) Storage node at 10.16.23.61 is up
>07:45:47,308 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 6) Finished running add node maintenance for StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>07:45:47,321 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 6) Finished running add node maintenance on all cluster nodes
>07:47:55,546 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-3) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 68 ms
>07:48:07,656 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-11) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 51 ms
>07:48:13,120 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-1) Retrieved unacked alerts for StorageNode[id=1001, address=null, cqlPort=0, operationMode=null, mtime=0] in 661
>07:48:13,681 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-11) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 45 ms
>07:48:20,949 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-1) Retrieved unacked alerts for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 334
>07:48:21,587 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-11) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 49 ms
>07:48:24,950 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-1) Retrieved unacked alerts for StorageNode[id=1001, address=null, cqlPort=0, operationMode=null, mtime=0] in 539
>07:48:25,545 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-11) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 42 ms
>07:50:04,917 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-3) Retrieved unacked alerts for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 406
>07:50:05,605 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-11) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 85 ms
>07:52:09,652 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-10) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 47 ms
>07:52:14,259 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-1) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 84 ms
>07:53:46,978 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-2) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 50 ms
>07:54:03,018 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-10) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 45 ms
>07:54:11,748 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (http-/0.0.0.0:7080-9) Preparing to decommission StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385124179039]
>07:54:53,424 INFO  [com.datastax.driver.core.Cluster] (Scheduled Tasks-0) Cassandra host /10.16.23.61 removed
>07:54:53,437 INFO  [org.rhq.server.metrics.StorageSession] (Scheduled Tasks-0) /10.16.23.61 has been removed
>07:54:53,438 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Scheduled Tasks-0) Storage node at 10.16.23.61 has been removed from the cluster
>07:55:23,635 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 4) Successfully decommissioned StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=DECOMMISSION, mtime=1385124179039]
>07:55:23,739 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 4) Running remove node maintenance for storage node StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>07:55:26,715 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 1) Finished remove node maintenance for StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>07:55:26,727 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 1) Finished running remove node maintenance on all cluster nodes
>07:55:26,821 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 1) Unannouncing StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNANNOUNCE, mtime=1385124179039]
>07:55:29,490 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 10) Successfully unannounced StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNANNOUNCE, mtime=1385124179039] to storage cluster
>07:55:29,583 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 10) Uninstalling StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNINSTALL, mtime=1385124179039]
>07:55:30,263 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) Successfully uninstalled StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNINSTALL, mtime=1385124179039] from disk
>07:55:30,280 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) Removing storage node resource Resource[id=10093, uuid=fc88f1bd-4d8a-49b0-a084-ee7f752b24af, type={RHQStorage}RHQ Storage Node, key=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), name=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), parent=joner7.bc.jonqe.lab.eng.bos.redhat.com, version=4.9.0.JON320ER7] from inventory
>07:55:30,398 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) Removing storage node entity StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNINSTALL, mtime=1385124179039] from database
>07:55:30,399 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 2) StorageNode[id=10001, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=UNINSTALL, mtime=1385124179039] has been undeployed
>07:57:31,114 INFO  [org.rhq.enterprise.server.scheduler.jobs.AsyncResourceDeleteJob] (RHQScheduler_Worker-4) Async resource deletion - 1 successful, 0 failed, took [372] ms
>07:58:36,476 INFO  [org.rhq.enterprise.server.core.AgentManagerBean] (http-/0.0.0.0:7080-9) Removed agent: Agent[id=10011,name=joner7.bc.jonqe.lab.eng.bos.redhat.com,address=10.16.23.61,port=16163,remote-endpoint=socket://10.16.23.61:16163/?rhq.communications.connector.rhqtype=agent&numAcceptThreads=1&maxPoolSize=303&clientMaxPoolSize=304&socketTimeout=60000&enableTcpNoDelay=true&backlog=200,last-availability-ping=1385125068602,last-availability-report=1385124625571]
>07:58:36,557 ERROR [org.rhq.enterprise.server.discovery.DiscoveryServerServiceImpl] (http-/0.0.0.0:7080-38) Received invalid inventory report from agent [Agent[id=0,name=joner7.bc.jonqe.lab.eng.bos.redhat.com,address=null,port=0,remote-endpoint=null,last-availability-ping=null,last-availability-report=null]]: Unknown Agent named [joner7.bc.jonqe.lab.eng.bos.redhat.com] sent an inventory report - that report will be ignored. This error is harmless and should stop appearing after a short while if the platform of the agent [joner7.bc.jonqe.lab.eng.bos.redhat.com] was recently removed from the inventory. In any other case this is a bug.
>07:58:37,624 INFO  [org.rhq.enterprise.server.core.CoreServerServiceImpl] (http-/0.0.0.0:7080-38) Got agent registration request for new agent: joner7.bc.jonqe.lab.eng.bos.redhat.com[10.16.23.61:16163][4.9.0.JON320ER7(ff0061d)]
>08:00:00,057 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Data Purge Job STARTING
>08:00:00,067 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Measurement data compression starting at Fri Nov 22 08:00:00 EST 2013
>08:00:04,246 INFO  [org.rhq.server.metrics.MetricsServer] (RHQScheduler_Worker-2) Finished computing aggregates for table [raw_metrics]4178 ms
>08:00:05,087 INFO  [org.rhq.server.metrics.MetricsServer] (RHQScheduler_Worker-2) Finished computing aggregates for table [one_hour_metrics] 0 ms
>08:00:05,088 INFO  [org.rhq.server.metrics.MetricsServer] (RHQScheduler_Worker-2) Finished computing aggregates for table [six_hour_metrics] 1 ms
>08:00:05,088 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Measurement data compression completed in [5022]ms
>08:00:05,088 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Measurement calltime data purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,089 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging calltime data that is older than Tue Oct 22 09:00:05 EDT 2013
>08:00:05,095 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Calltime purged [0] - completed in [7]ms
>08:00:05,095 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Event data purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,095 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging event data older than Fri Nov 08 08:00:05 EST 2013
>08:00:05,104 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Event data purged [0] - completed in [8]ms
>08:00:05,104 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert data purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,104 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging alert data older than Tue Oct 22 09:00:05 EDT 2013
>08:00:05,111 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert data purged [0] - completed in [7]ms
>08:00:05,111 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert definition unused purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,114 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert definitions purged [0] - completed in [3]ms
>08:00:05,115 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert condition orphan purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,118 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purged [0] orphan alert conditions - completed in [3]ms
>08:00:05,118 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Alert notification orphan purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,121 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purged [0] orphan alert notifications - completed in [3]ms
>08:00:05,121 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Trait data purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,122 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging traits that are older than Thu Nov 22 08:00:05 EST 2012
>08:00:05,125 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Traits data purged [0] - completed in [4]ms
>08:00:05,126 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Availability data purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,126 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging availablities that are older than Thu Nov 22 08:00:05 EST 2012
>08:00:05,130 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Availability data purged [0] - completed in [4]ms
>08:00:05,131 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Drift file orphan purge starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,132 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purging orphaned drift files older than Tue Oct 22 09:00:05 EDT 2013
>08:00:05,149 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Purged [0] orphaned drift files - completed in [18]ms
>08:00:05,150 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Database maintenance starting at Fri Nov 22 08:00:05 EST 2013
>08:00:05,151 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Performing hourly database maintenance
>08:00:07,594 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Database maintenance completed in [2444]ms
>08:00:07,596 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Auto-calculation of baselines starting at Fri Nov 22 08:00:07 EST 2013
>08:00:07,619 INFO  [org.rhq.enterprise.server.measurement.MeasurementBaselineManagerBean] (RHQScheduler_Worker-2) Calculating auto baselines
>08:00:07,619 INFO  [org.rhq.enterprise.server.measurement.MeasurementBaselineManagerBean] (RHQScheduler_Worker-2) Deleting baselines computations older than Tue Nov 19 08:00:07 EST 2013
>08:00:07,619 INFO  [org.rhq.enterprise.server.measurement.MeasurementBaselineManagerBean] (RHQScheduler_Worker-2) Inserting new baselines using last 7 days of 1H data
>08:00:07,636 INFO  [org.rhq.enterprise.server.measurement.MeasurementBaselineManagerBean] (RHQScheduler_Worker-2) Removed [0] old baselines - they will now be recalculated (16)ms
>08:00:13,805 INFO  [org.rhq.enterprise.server.measurement.MeasurementBaselineManagerBean] (RHQScheduler_Worker-2) Calculated and inserted [927] new baselines. (6169)ms
>08:00:13,824 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Auto-calculation of baselines completed in [6229]ms
>08:00:13,824 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Auto-calculation of OOBs starting
>08:00:13,828 INFO  [org.rhq.enterprise.server.measurement.MeasurementOOBManagerBean] (RHQScheduler_Worker-2) Removed [0] outdated OOBs
>08:00:13,845 INFO  [org.rhq.enterprise.server.measurement.MeasurementOOBManagerBean] (RHQScheduler_Worker-2) Computing OOBs
>08:00:15,468 INFO  [org.rhq.enterprise.server.measurement.MeasurementOOBManagerBean] (RHQScheduler_Worker-2) Finished calculating 0 OOBs in 1623 ms
>08:00:15,469 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Auto-calculation of OOBs completed in [1645]ms
>08:00:15,469 INFO  [org.rhq.enterprise.server.scheduler.jobs.DataPurgeJob] (RHQScheduler_Worker-2) Data Purge Job FINISHED [15412]ms
>08:00:30,984 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 10) jon312.bc.jonqe.lab.eng.bos.redhat.com took [169]ms to reload cache for 2 agents
>08:02:32,813 INFO  [org.rhq.enterprise.server.scheduler.jobs.AsyncResourceDeleteJob] (RHQScheduler_Worker-1) Async resource deletion - 9 successful, 0 failed, took [2057] ms
>08:09:30,749 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 6) jon312.bc.jonqe.lab.eng.bos.redhat.com took [83]ms to reload cache for 1 agents
>08:13:00,826 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-35) Linking Resource[id=10122, uuid=9d8a76e2-b456-47e5-a7ad-267a10c130a3, type={RHQStorage}RHQ Storage Node, key=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), name=RHQ Storage Node(joner7.bc.jonqe.lab.eng.bos.redhat.com), parent=joner7.bc.jonqe.lab.eng.bos.redhat.com, version=4.9.0.JON320ER7] to storage node at joner7.bc.jonqe.lab.eng.bos.redhat.com
>08:13:00,949 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-35) Did not find storage node with address [joner7.bc.jonqe.lab.eng.bos.redhat.com] Searching by IP address [10.16.23.61]
>08:13:00,961 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-35) Scheduling cluster maintenance to deploy StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=INSTALLED, mtime=1385125980959] into the storage cluster...
>08:13:00,961 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-35) Deploying StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=INSTALLED, mtime=1385125980959]
>08:13:00,970 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (http-/0.0.0.0:7080-35) Announcing StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ANNOUNCE, mtime=1385125980959] to storage node cluster.
>08:13:00,974 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (http-/0.0.0.0:7080-35) Announcing StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ANNOUNCE, mtime=1385125980959] to cluster node StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>08:13:04,012 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 6) Successfully announced new storage node to storage cluster
>08:13:04,111 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 6) Preparing to bootstrap StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=BOOTSTRAP, mtime=1385125980959] into cluster...
>08:13:12,682 INFO  [com.datastax.driver.core.Cluster] (Scheduled Tasks-0) New Cassandra host /10.16.23.61 added
>08:13:12,713 INFO  [org.rhq.server.metrics.StorageSession] (Scheduled Tasks-0) /10.16.23.61 added
>08:13:12,714 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Scheduled Tasks-0) Storage node at 10.16.23.61 is up
>08:13:12,716 INFO  [org.rhq.server.metrics.StorageSession] (Cassandra Java Driver worker-5) /10.16.23.61 is down
>08:13:12,717 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Cassandra Java Driver worker-5) Storage node at 10.16.23.61 is down
>08:13:30,701 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 3) jon312.bc.jonqe.lab.eng.bos.redhat.com took [39]ms to reload global cache
>08:13:30,826 INFO  [org.rhq.enterprise.server.cloud.instance.CacheConsistencyManagerBean] (EJB default - 3) jon312.bc.jonqe.lab.eng.bos.redhat.com took [71]ms to reload cache for 1 agents
>08:13:36,973 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 9) The prepare for bootstrap operation completed successfully for StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=BOOTSTRAP, mtime=1385125980959]
>08:13:39,442 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 9) Running addNodeMaintenance for storage node StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ADD_MAINTENANCE, mtime=1385125980959]
>08:13:41,067 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 7) Finished running add node maintenance for StorageNode[id=10011, address=joner7.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=ADD_MAINTENANCE, mtime=1385125980959]
>08:13:41,088 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 7) Running addNodeMaintenance for storage node StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>08:13:52,190 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 1) Finished running add node maintenance for StorageNode[id=1001, address=jon32er1.bc.jonqe.lab.eng.bos.redhat.com, cqlPort=9142, operationMode=NORMAL, mtime=1385122344081]
>08:13:52,204 INFO  [org.rhq.enterprise.server.storage.StorageNodeOperationsHandlerBean] (EJB default - 1) Finished running add node maintenance on all cluster nodes
>08:14:16,194 INFO  [org.rhq.server.metrics.StorageSession] (Reconnection-0) /10.16.23.61 is up
>08:14:16,194 INFO  [org.rhq.enterprise.server.storage.StorageClusterMonitor] (Reconnection-0) Storage node at 10.16.23.61 is up
>08:35:50,844 WARN  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-5) There is no storage node with id [10001] stored in the database.
>08:35:50,844 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-5) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 34 ms
>08:35:52,360 WARN  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-14) There is no storage node with id [10001] stored in the database.
>08:35:52,361 INFO  [org.rhq.enterprise.server.cloud.StorageNodeManagerBean] (http-/0.0.0.0:7080-14) Retrieved load metrics for StorageNode[id=10001, address=null, cqlPort=0, operationMode=null, mtime=0] in 35 ms
>
>

Actions: View

Attachments on bug 1019807: 812904 | 827784