AnsweredAssumed Answered

EM fails to start

Question asked by ZhangZhao on Jul 26, 2012
Latest reply on Aug 17, 2012 by Adoss
Below is the snapshot from log... It shows APM database was unreachable, please check the connectivity.. I did check the APM database.. Didn't find anything wrong there... Is there anyone can help?
Zhang



7/27/12 10:54:56.869 AM EDT [INFO] [main] [Manager] Starting server...
7/27/12 10:54:57.734 AM EDT [INFO] [main] [Manager.Cluster] The Enterprise Manager is running in a Collector role.
7/27/12 10:54:57.735 AM EDT [INFO] [main] [Manager.Cluster] Setting the Enterprise Manager Collector identifier to (m1004d@5001)
7/27/12 10:54:59.233 AM EDT [INFO] [main] [Manager.Authentication] Introscope WebView connections are enabled
7/27/12 10:54:59.234 AM EDT [INFO] [main] [Manager.Authentication] Introscope WebView connections will be assigned the name "WilyWebView"
7/27/12 10:54:59.520 AM EDT [INFO] [main] [Manager.Authentication] Configured the Manager of Managers user using private key internal/server/EM.private
7/27/12 10:55:00.474 AM EDT [INFO] [main] [Manager] Started hot config polling. Polling interval set to 60 seconds
7/27/12 10:55:02.621 AM EDT [INFO] [main] [Manager.ServerSocketFactory] Created Server Socket Factory: com.wily.jip.server.ext.DefaultServerSocketFactory
7/27/12 10:55:02.643 AM EDT [INFO] [main] [Manager] Using data directory: /opt/CA/APM/data
7/27/12 10:55:02.666 AM EDT [INFO] [main] [Manager] Using archive directory /opt/CA/APM/data/archive
7/27/12 10:55:02.671 AM EDT [INFO] [main] [Manager] Reading Smartstor Metadata
7/27/12 10:55:02.706 AM EDT [INFO] [main] [Manager] Loading metadata file: data/metrics.metadata
7/27/12 10:55:05.198 AM EDT [INFO] [main] [Manager] Finished reading Smartstor Metadata
7/27/12 10:55:05.199 AM EDT [INFO] [main] [Manager] The system will store non-counter zero values.
7/27/12 10:55:05.200 AM EDT [INFO] [main] [Manager] The system will shut down if there are Disk I/O errors in 5 continuous timeslices.
7/27/12 10:55:05.232 AM EDT [INFO] [main] [Manager] Thread priority set at 1
7/27/12 10:55:05.235 AM EDT [INFO] [main] [Manager] Data tier 1 configured at collection frequency 15 seconds for 7 days
7/27/12 10:55:05.235 AM EDT [INFO] [main] [Manager] Data tier 2 configured at collection frequency 60 seconds for 23 days
7/27/12 10:55:05.236 AM EDT [INFO] [main] [Manager] Data tier 3 configured at collection frequency 900 seconds for 335 days
7/27/12 10:55:05.237 AM EDT [INFO] [main] [Manager] SmartStor Tiering time offset configured to 0:00
7/27/12 10:55:05.238 AM EDT [INFO] [main] [Manager] SmartStor conversion of Spool to Data time offset configured to 0 minute
7/27/12 10:55:05.783 AM EDT [INFO] [PO Async Executor] [Manager.Agent] Configured EM Global Live Metric count limit at 500000
7/27/12 10:55:05.798 AM EDT [INFO] [PO Async Executor] [Manager.Agent] Configured per-agent metric count limit at 50000
7/27/12 10:55:05.799 AM EDT [INFO] [PO Async Executor] [Manager.Agent] Configured EM Global Historical Metric count limit at 1200000
7/27/12 10:55:05.810 AM EDT [INFO] [main] [Manager] Available processors is 128
7/27/12 10:55:05.818 AM EDT [INFO] [main] [Manager.ConnectionTicket] Agent connection tickets = 128
7/27/12 10:55:06.147 AM EDT [INFO] [main] [Manager.Agent] Agent automatic unmount delay configured to 60 minute(s).
7/27/12 10:55:30.019 AM EDT [ERROR] [main] [Apm.Data.Model] APM Database is not reachable. Please check the connectivity...
org.springframework.jdbc.UncategorizedSQLException: Hibernate operation: Cannot open connection; uncategorized SQLException for SQL [???]; SQL state [null]; error code [0]; Connections could not be acquired from the underlying database!; nested exception is java.sql.SQLException: Connections could not be acquired from the underlying database!
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:83)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
at org.springframework.orm.hibernate3.HibernateAccessor.convertJdbcAccessException(HibernateAccessor.java:424)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:410)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:424)
at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:339)
at com.wily.apm.model.dao.impl.VertexTypeDao.getVertexTypeByName(VertexTypeDao.java:42)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:54)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at $Proxy45.getVertexTypeByName(Unknown Source)
at com.wily.apm.model.impl.ApmDataService.<init>(ApmDataService.java:95)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:100)
at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:87)
at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:248)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:925)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:835)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:440)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
at java.security.AccessController.doPrivileged(Native Method)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:93)
at com.wily.apm.model.SpringAppContext.init(SpringAppContext.java:53)
at com.wily.apm.model.SpringAppContext.<init>(SpringAppContext.java:28)
at com.wily.apm.model.SpringAppContext.<clinit>(SpringAppContext.java:23)
at com.wily.introscope.server.enterprise.entity.appmap.AppMapEntity.initApmDataService(AppMapEntity.java:224)
at com.wily.introscope.server.enterprise.entity.appmap.AppMapEntity.<init>(AppMapEntity.java:160)
at com.wily.introscope.server.enterprise.EnterpriseServer.initialize(EnterpriseServer.java:545)
at com.wily.introscope.server.enterprise.EnterpriseServer.doStart(EnterpriseServer.java:355)
at com.wily.util.ALifeCycle.start(ALifeCycle.java:86)
at com.wily.introscope.server.enterprise.EnterpriseServer.<init>(EnterpriseServer.java:298)
at com.wily.introscope.server.enterprise.EnterpriseServer.<init>(EnterpriseServer.java:277)
at com.wily.introscope.server.enterprise.EnterpriseServer.start(EnterpriseServer.java:1320)
at com.wily.introscope.em.internal.Activator.startEM(Activator.java:116)
at com.wily.introscope.em.internal.Application.start(Application.java:27)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:193)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:386)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:549)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:504)
at org.eclipse.equinox.launcher.Main.run(Main.java:1236)
at org.eclipse.equinox.launcher.Main.main(Main.java:1212)
at org.eclipse.core.launcher.Main.main(Main.java:30)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.zerog.lax.LAX.launch(DashoA10*..)
at com.zerog.lax.LAX.main(DashoA10*..)
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:529)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:82)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1538)
at org.hibernate.loader.Loader.doQuery(Loader.java:661)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.doList(Loader.java:2211)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
at org.hibernate.loader.Loader.list(Loader.java:2090)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:95)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)
at org.hibernate.impl.CriteriaImpl.uniqueResult(CriteriaImpl.java:305)
at com.wily.apm.model.dao.impl.VertexTypeDao$1.doInHibernate(VertexTypeDao.java:48)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:419)
... 74 more
Caused by: com.mchange.v2.resourcepool.CannotAcquireResourceException: A ResourcePool could not acquire a resource from its primary factory or source.
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1319)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
... 91 more
7/27/12 10:55:30.473 AM EDT [INFO] [main] [Manager.MG] introscope.enterprisemanager.metricgroup.matchagent is false
7/27/12 10:55:30.546 AM EDT [INFO] [main] [Manager.TransactionTracer] Storage directory configured to /opt/CA/APM/traces
7/27/12 10:55:30.547 AM EDT [INFO] [main] [Manager.TransactionTracer] Configured introscope.enterprisemanager.transactionevents.storage.queue.limit to 1000
7/27/12 10:55:33.467 AM EDT [INFO] [main] [Manager.TransactionTracer] First Live Perst Storage Rollover will be run at Sat Jul 28 00:00:00 EDT 2012
7/27/12 10:55:33.475 AM EDT [INFO] [main] [Manager] Optimization frequency configured to 24 hours
7/27/12 10:55:33.476 AM EDT [INFO] [main] [Manager] Optimization time offset configured to 2:00
7/27/12 10:55:33.476 AM EDT [INFO] [main] [Manager] Data age configured to 14 days
7/27/12 10:55:33.478 AM EDT [INFO] [main] [Manager] First scheduled optimization will be run at Sat Jul 28 02:00:00 EDT 2012
7/27/12 10:55:33.492 AM EDT [INFO] [Event Pump Entity] [Manager.TransactionTracer] Enabling ErrorDetector...
7/27/12 10:55:33.494 AM EDT [INFO] [Event Pump Entity] [Manager.TransactionTracer] ErrorDetector started
7/27/12 10:55:33.579 AM EDT [INFO] [PO Async Executor] [Manager] Configured EM global maximum data points fetched from disk for any metric query to unlimited
7/27/12 10:55:33.580 AM EDT [INFO] [PO Async Executor] [Manager] Configured EM global maximum data points returned for any metric query to unlimited
7/27/12 10:55:33.800 AM EDT [INFO] [main] [Manager.Database] Database queue limited to 153600 data points.
7/27/12 10:55:33.824 AM EDT [INFO] [main] [Manager.Database] Using default value for introscope.enterprisemanager.db.numberOfReconnectionAttempts: 0
7/27/12 10:55:33.844 AM EDT [INFO] [main] [Manager.FlatFile] Flat files will be written to /opt/CA/APM/flatfiles
7/27/12 10:55:33.845 AM EDT [INFO] [main] [Manager.FlatFile] Archiving flat files based on time is disabled
7/27/12 10:55:33.850 AM EDT [INFO] [main] [Manager.FlatFile] Flat files will be archived when they are larger than 100M
7/27/12 10:55:33.851 AM EDT [INFO] [main] [Manager.FlatFile] Flat files will be closed after 10 consecutive errors.
7/27/12 10:55:33.852 AM EDT [INFO] [main] [Manager.FlatFile] The maximum number of concurrent flat file archiver threads will be 5.
7/27/12 10:55:33.852 AM EDT [INFO] [main] [Manager.FlatFile] Flat file compression is enabled
7/27/12 10:55:33.969 AM EDT [INFO] [main] [Manager.Action] At most 5 actions will be triggered at any one time
7/27/12 10:55:34.213 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Scripts directory configured to /opt/CA/APM/./scripts
7/27/12 10:55:34.218 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Using default value for introscope.enterprisemanager.javascript.refresh: 60
7/27/12 10:55:34.219 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Value of introscope.enterprisemanager.javascript.refresh is 60 seconds
7/27/12 10:55:34.264 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Deploying JavaScript calculator /opt/CA/APM/./scripts/BtStats-DefectPercent.js
7/27/12 10:55:34.295 AM EDT [INFO] [main] [Manager.JavascriptEngine] Initializing script from /opt/CA/APM/./scripts/BtStats-DefectPercent.js
7/27/12 10:55:34.313 AM EDT [INFO] [PO Async Executor] [Manager] Heuristics enabled for agents matching expression: ".*"
7/27/12 10:55:34.922 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Successfully added script /opt/CA/APM/./scripts/BtStats-DefectPercent.js
7/27/12 10:55:34.924 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Deploying JavaScript calculator /opt/CA/APM/./scripts/BtStats-AggregatedTree.js
7/27/12 10:55:34.924 AM EDT [INFO] [main] [Manager.JavascriptEngine] Initializing script from /opt/CA/APM/./scripts/BtStats-AggregatedTree.js
7/27/12 10:55:35.092 AM EDT [INFO] [main] [Manager.JavaScriptCalculator] Successfully added script /opt/CA/APM/./scripts/BtStats-AggregatedTree.js
7/27/12 10:55:36.225 AM EDT [INFO] [main] [Manager.IscopeAlertsExtension] Following Management Modules have been selected for status and Inventory creation: ALL
7/27/12 10:55:36.226 AM EDT [INFO] [main] [Manager.IscopeAlertsExtension] Alerts Update Check Polling Interval being used is: 60 seconds
7/27/12 10:55:36.243 AM EDT [INFO] [main] [Manager.IscopeAlertsExtension] Isengard Alert Extension Bean has been activated
7/27/12 10:55:36.252 AM EDT [INFO] [main] [Manager] XmlMarshallingService is activating
7/27/12 10:55:36.254 AM EDT [INFO] [main] [Manager] XmlMarshallingService is activated
7/27/12 10:55:36.267 AM EDT [INFO] [main] [Manager.SNMPAdapter] The SNMP Adapter is not available.
7/27/12 10:55:36.293 AM EDT [INFO] [main] [Manager] Successfully started embedded scheduler
7/27/12 10:55:36.584 AM EDT [INFO] [main] [Manager] APM Data Notification Service Bean is successfully started
7/27/12 10:55:36.598 AM EDT [INFO] [main] [Manager] APM Service Bean is successfully started
7/27/12 10:55:36.603 AM EDT [INFO] [main] [Manager] [ The APM Data  property : introscope.apm.pruning.enabled set to value : true]
7/27/12 10:55:36.609 AM EDT [INFO] [main] [Manager] [ The APM Data  property : introscope.apm.data.agingTime set to value : [ PropertyWithTimeUnit : 1 DAY]]
7/27/12 10:55:36.610 AM EDT [INFO] [main] [Manager] [ The APM Data  property : introscope.apm.data.timeWindow set to value : [ PropertyWithTimeUnit : 3 DAYS]]
7/27/12 10:55:36.610 AM EDT [INFO] [main] [Manager] [ The APM Data  property : introscope.apm.pruning.cron.trigger.expression set to value : 0 0 6 * * ?]
7/27/12 10:55:36.722 AM EDT [INFO] [main] [Manager.Extension] Locating EM Services...
7/27/12 10:55:36.808 AM EDT [WARN] [main] [Manager.RaveServerExtension] ChangeDetector server has been disabled and won't run. To enable the ChangeDetector server set the property introscope.changeDetector.disable to false.
7/27/12 10:55:36.809 AM EDT [INFO] [main] [Manager.Extension] Succesfully loaded service ChangeDetector Server Extension
7/27/12 10:55:36.848 AM EDT [INFO] [main] [Manager.EMWebServer] EM webapps port: 8081
7/27/12 10:55:36.849 AM EDT [INFO] [main] [Manager.EMWebServer] EM max server threads: 100
7/27/12 10:55:36.850 AM EDT [INFO] [main] [Manager.EMWebServer] EM webapps directory: /opt/CA/APM/webapps
7/27/12 10:55:36.850 AM EDT [INFO] [main] [Manager.EMWebServer] EM webapps checks for new webapps every 60 seconds
7/27/12 10:55:36.965 AM EDT [INFO] [main] [Manager] Fully-qualified domain name is m1004d
7/27/12 10:55:36.966 AM EDT [INFO] [main] [Manager] domain is null
7/27/12 10:55:37.226 AM EDT [ERROR] [main] [Manager] The EM failed to start. Provider org.apache.xerces.jaxp.SAXParserFactoryImpl not found
7/27/12 10:55:37.536 AM EDT [INFO] [main] [Manager] Shutting down data persistence subsystem
7/27/12 10:55:37.546 AM EDT [INFO] [main] [Manager] Shutting down the Isengard server
7/27/12 10:55:37.571 AM EDT [INFO] [main] [Manager.IscopeAlertsExtension] Isengard Alert Extension Bean has been passivated
7/27/12 10:55:37.733 AM EDT [INFO] [main] [Manager] Orderly shutdown complete.

Outcomes