very long startup time
gumpinger Aug 9, 2006 9:01 AMWe are using jboss portal 2.2.1 "bundled" with jboss 4.0.4.CR2.
A typical startup time on our development-computers is about 1 or 2 minutes. but on 2 computers startup time is sometimes at about 10 minutes and we didnt find a failure ... its not everytime. we start the server from eclipse via the myeclipse plugin. most time was lost here:
14:45:30,343 INFO [WebService] Using RMI server codebase: http://HS0588:8083/ 14:45:30,390 INFO [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml 14:45:30,937 INFO [NamingService] JNDI bootstrap JNP=/0.0.0.0:1099, RMI=/0.0.0.0:1098, backlog=50, no client SocketFactory, Server SocketFactory=class org.jboss.net.sockets.DefaultSocketFactory 14:50:26,203 INFO [TreeCache] interceptor chain is: class org.jboss.cache.interceptors.CallInterceptor class org.jboss.cache.interceptors.LockInterceptor class org.jboss.cache.interceptors.UnlockInterceptor 14:50:26,203 INFO [TreeCache] cache mode is local, will not create the channel
i already searched the whole internet and didnt found a solution ...
it does not depend on the memory (eclipse vm got 1024M and jboss vm 512M) or on the hardware because all other applications run fine ...
thanks!
Florian Gumpinger
the full output:
14:45:25,062 INFO [Server] Starting JBoss (MX MicroKernel)... 14:45:25,062 INFO [Server] Release ID: JBoss [Zion] 4.0.4.CR2 (build: CVSTag=JBoss_4_0_4_CR2 date=200604241359) 14:45:25,078 INFO [Server] Home Dir: C:\ta31\progs\jboss-portal-2.2.1-bundled 14:45:25,078 INFO [Server] Home URL: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/ 14:45:25,078 INFO [Server] Patch URL: null 14:45:25,078 INFO [Server] Server Name: default 14:45:25,078 INFO [Server] Server Home Dir: C:\ta31\progs\jboss-portal-2.2.1-bundled\server\default 14:45:25,078 INFO [Server] Server Home URL: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/ 14:45:25,078 INFO [Server] Server Log Dir: C:\ta31\progs\jboss-portal-2.2.1-bundled\server\default\log 14:45:25,078 INFO [Server] Server Temp Dir: C:\ta31\progs\jboss-portal-2.2.1-bundled\server\default\tmp 14:45:25,078 INFO [Server] Root Deployment Filename: jboss-service.xml 14:45:25,578 INFO [ServerInfo] Java version: 1.5.0_06,Sun Microsystems Inc. 14:45:25,578 INFO [ServerInfo] Java VM: Java HotSpot(TM) Client VM 1.5.0_06-b05,Sun Microsystems Inc. 14:45:25,578 INFO [ServerInfo] OS-System: Windows XP 5.1,x86 14:45:26,312 INFO [Server] Core system initialized 14:45:30,343 INFO [WebService] Using RMI server codebase: http://HS0588:8083/ 14:45:30,390 INFO [Log4jService$URLWatchTimerTask] Configuring from URL: resource:log4j.xml 14:45:30,937 INFO [NamingService] JNDI bootstrap JNP=/0.0.0.0:1099, RMI=/0.0.0.0:1098, backlog=50, no client SocketFactory, Server SocketFactory=class org.jboss.net.sockets.DefaultSocketFactory 14:50:26,203 INFO [TreeCache] interceptor chain is: class org.jboss.cache.interceptors.CallInterceptor class org.jboss.cache.interceptors.LockInterceptor class org.jboss.cache.interceptors.UnlockInterceptor 14:50:26,203 INFO [TreeCache] cache mode is local, will not create the channel 14:50:29,171 INFO [Embedded] Catalina naming disabled 14:50:29,281 INFO [ClusterRuleSetFactory] Unable to find a cluster rule set in the classpath. Will load the default rule set. 14:50:29,281 INFO [ClusterRuleSetFactory] Unable to find a cluster rule set in the classpath. Will load the default rule set. 14:51:22,875 INFO [Http11BaseProtocol] Initializing Coyote HTTP/1.1 on http-0.0.0.0-8080 14:51:22,875 INFO [Catalina] Initialization processed in 53594 ms 14:51:22,875 INFO [StandardService] Starting service jboss.web 14:51:22,875 INFO [StandardEngine] Starting Servlet Engine: Apache Tomcat/5.5.16 14:51:22,953 INFO [StandardHost] XML validation disabled 14:51:23,015 INFO [Catalina] Server startup in 140 ms 14:51:23,250 INFO [TomcatDeployer] deploy, ctxPath=/invoker, warUrl=.../deploy/http-invoker.sar/invoker.war/ 14:51:34,468 INFO [WebappLoader] Dual registration of jndi stream handler: factory already defined 14:51:40,593 INFO [TomcatDeployer] deploy, ctxPath=/portal-cms, warUrl=.../deploy/jboss-portal.sar/portal-cms.war/ 14:51:46,093 INFO [TomcatDeployer] deploy, ctxPath=/portal-core, warUrl=.../deploy/jboss-portal.sar/portal-core.war/ 14:51:52,312 INFO [FacesConfigurator] Reading standard config org/apache/myfaces/resource/standard-faces-config.xml 14:51:52,546 INFO [FacesConfigurator] Reading config jar:file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/tmp/deploy/tmp23139jsf-facelets.jar!/META-INF/faces-config.xml 14:51:52,562 INFO [FacesConfigurator] Reading config jar:file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/tmp/deploy/tmp23151tomahawk.jar!/META-INF/faces-config.xml 14:51:52,718 INFO [FacesConfigurator] Reading config /WEB-INF/faces-config.xml 14:51:53,015 ERROR [LocaleUtils] Locale name null or empty, ignoring 14:51:54,796 INFO [StartupServletContextListener] ServletContext 'C:\ta31\progs\jboss-portal-2.2.1-bundled\server\default\.\deploy\jboss-portal.sar\portal-core.war\' initialized. 14:51:54,890 INFO [TomcatDeployer] deploy, ctxPath=/portal-samples, warUrl=.../deploy/jboss-portal.sar/portal-samples.war/ 14:52:01,000 INFO [TomcatDeployer] deploy, ctxPath=/portal, warUrl=.../deploy/jboss-portal.sar/portal-server.war/ 14:52:07,015 INFO [TomcatDeployer] deploy, ctxPath=/, warUrl=.../deploy/jbossweb-tomcat55.sar/ROOT.war/ 14:52:13,921 INFO [TomcatDeployer] deploy, ctxPath=/jbossws, warUrl=.../tmp/deploy/tmp23182jbossws-exp.war/ 14:52:19,515 INFO [SubscriptionManager] Bound event dispatcher to java:comp/env/EventDispatcher 14:52:19,953 INFO [TomcatDeployer] deploy, ctxPath=/jbossmq-httpil, warUrl=.../deploy/jms/jbossmq-httpil.sar/jbossmq-httpil.war/ 14:52:29,359 INFO [TomcatDeployer] deploy, ctxPath=/web-console, warUrl=.../deploy/management/console-mgr.sar/web-console.war/ 14:52:36,921 INFO [MailService] Mail Service bound to java:/Mail 14:52:37,468 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-ha-local-jdbc.rar 14:52:37,609 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-ha-xa-jdbc.rar 14:52:37,703 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-local-jdbc.rar 14:52:37,796 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jboss-xa-jdbc.rar 14:52:37,921 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/jms/jms-ra.rar 14:52:38,015 INFO [RARDeployment] Required license terms exist, view META-INF/ra.xml in .../deploy/mail-ra.rar 14:52:38,546 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=esvportalDS' to JNDI name 'java:esvportalDS' 14:52:39,718 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS' 14:52:40,234 INFO [A] Bound to JNDI name: queue/A 14:52:40,234 INFO [B] Bound to JNDI name: queue/B 14:52:40,234 INFO [C] Bound to JNDI name: queue/C 14:52:40,234 INFO [D] Bound to JNDI name: queue/D 14:52:40,234 INFO [ex] Bound to JNDI name: queue/ex 14:52:40,312 INFO [testTopic] Bound to JNDI name: topic/testTopic 14:52:40,312 INFO [securedTopic] Bound to JNDI name: topic/securedTopic 14:52:40,312 INFO [testDurableTopic] Bound to JNDI name: topic/testDurableTopic 14:52:40,328 INFO [testQueue] Bound to JNDI name: queue/testQueue 14:52:40,453 INFO [UILServerILService] JBossMQ UIL service available at : /0.0.0.0:8093 14:52:40,546 INFO [DLQ] Bound to JNDI name: queue/DLQ 14:52:40,968 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA' 14:52:41,203 INFO [Environment] Hibernate 3.2 cr1 14:52:41,234 INFO [Environment] hibernate.properties not found 14:52:41,234 INFO [Environment] Bytecode provider name : cglib 14:52:41,250 INFO [Environment] using JDK 1.4 java.sql.Timestamp handling 14:52:41,859 INFO [Configuration] configuring from url: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/jboss-portal.sar/conf/hibernate/user/hibernate.cfg.xml 14:52:41,890 INFO [Configuration] Reading mappings from resource: conf/hibernate/user/domain.hbm.xml 14:52:42,234 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.user.UserImpl -> jbp_users 14:52:42,343 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.user.UserImpl.dynamic -> jbp_user_prop 14:52:42,359 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.user.UserImpl.roles -> jbp_role_membership 14:52:42,359 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.user.PreferencesGroupImpl -> jbp_user_prefs_group 14:52:42,375 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.user.PreferencesImpl -> jbp_user_pref_set 14:52:42,375 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.user.PreferenceImpl -> jbp_user_pref 14:52:42,375 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.user.PreferenceImpl.strings -> jbp_user_pref_value 14:52:42,375 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.role.RoleImpl -> jbp_roles 14:52:42,375 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.role.RoleImpl.users -> jbp_role_membership 14:52:42,375 INFO [Configuration] Configured SessionFactory: null 14:52:42,390 INFO [Configuration] configuring from url: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/jboss-portal.sar/conf/hibernate/instance/hibernate.cfg.xml 14:52:42,437 INFO [Configuration] Reading mappings from resource: conf/hibernate/instance/domain.hbm.xml 14:52:42,484 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.model.instance.InstanceImpl -> JBP_INSTANCE 14:52:42,531 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.model.instance.PreferenceImpl -> JBP_INSTANCE_PREF 14:52:42,531 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.instance.PreferenceImpl.strings -> JBP_INSTANCE_PREF_VALUE 14:52:42,531 INFO [Configuration] Configured SessionFactory: null 14:52:42,562 INFO [Configuration] configuring from url: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/jboss-portal.sar/conf/hibernate/portal/hibernate.cfg.xml 14:52:42,578 INFO [Configuration] Reading mappings from resource: conf/hibernate/portal/domain.hbm.xml 14:52:42,609 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.model.portal.ObjectNode -> JBP_OBJECT_NODE 14:52:42,812 INFO [HbmBinder] Mapping class: org.jboss.portal.core.impl.model.portal.PortalObjectImpl -> JBP_PORTAL_OBJECT 14:52:42,812 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.portal.PortalObjectImpl.declaredProperties -> JBP_PORTAL_OBJECT_PROPS 14:52:42,921 INFO [HbmBinder] Mapping joined-subclass: org.jboss.portal.core.impl.model.portal.ContextImpl -> JBP_CONTEXT 14:52:42,921 INFO [HbmBinder] Mapping joined-subclass: org.jboss.portal.core.impl.model.portal.PortalImpl -> JBP_PORTAL 14:52:42,921 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.portal.PortalImpl.modes -> JBP_PORTAL_MODE 14:52:42,921 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.portal.PortalImpl.windowStates -> JBP_PORTAL_WINDOW_STATE 14:52:42,921 INFO [HbmBinder] Mapping joined-subclass: org.jboss.portal.core.impl.model.portal.PageImpl -> JBP_PAGE 14:52:42,921 INFO [HbmBinder] Mapping joined-subclass: org.jboss.portal.core.impl.model.portal.WindowImpl -> JBP_WINDOW 14:52:42,921 INFO [Configuration] Configured SessionFactory: null 14:52:43,015 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=PortalDS' to JNDI name 'java:PortalDS' 14:52:43,015 INFO [JCRCMS] Starting JCR CMS 14:52:43,203 INFO [HibernateStore] BUILDING SessionFactory. 14:52:43,218 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/CMSEntry.hbm.xml 14:52:43,265 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.CMSEntry -> jbp_cms_cmsentry 14:52:43,265 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/VersionEntry.hbm.xml 14:52:43,296 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.VersionEntry -> jbp_cms_versionentry 14:52:43,296 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/RepositoryEntry.hbm.xml 14:52:43,328 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.RepositoryEntry -> jbp_cms_repositoryentry 14:52:43,359 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:43,359 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:43,906 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:43,906 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:43,953 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:43,984 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:43,984 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:43,984 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:44,000 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:44,000 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:44,000 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:44,000 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:44,000 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:44,000 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:44,000 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:44,000 INFO [SettingsFactory] Connection release mode: auto 14:52:44,000 INFO [SettingsFactory] Default batch fetch size: 1 14:52:44,000 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:44,000 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:44,000 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:44,015 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:44,015 INFO [SettingsFactory] Query language substitutions: {} 14:52:44,015 INFO [SettingsFactory] Second-level cache: enabled 14:52:44,015 INFO [SettingsFactory] Query cache: disabled 14:52:44,015 INFO [SettingsFactory] Cache provider: org.hibernate.cache.HashtableCacheProvider 14:52:44,031 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:44,031 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:44,046 INFO [SettingsFactory] Statistics: disabled 14:52:44,046 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:44,046 INFO [SettingsFactory] Default entity-mode: pojo 14:52:44,156 INFO [SessionFactoryImpl] building session factory 14:52:45,046 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:45,046 INFO [SchemaUpdate] Running hbm2ddl schema update 14:52:45,046 INFO [SchemaUpdate] fetching database metadata 14:52:45,046 INFO [SchemaUpdate] updating schema 14:52:45,093 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_CMSENTRY 14:52:45,093 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,093 INFO [TableMetadata] foreign keys: [] 14:52:45,093 INFO [TableMetadata] indexes: [sys_pk_46] 14:52:45,109 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_REPOSITORYENTRY 14:52:45,109 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,109 INFO [TableMetadata] foreign keys: [] 14:52:45,109 INFO [TableMetadata] indexes: [sys_pk_47] 14:52:45,125 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSIONENTRY 14:52:45,125 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,125 INFO [TableMetadata] foreign keys: [] 14:52:45,125 INFO [TableMetadata] indexes: [sys_pk_48] 14:52:45,125 INFO [SchemaUpdate] schema update complete 14:52:45,125 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,125 INFO [HibernateStore] HibernateSessionFactory Created. 14:52:45,125 INFO [HibernateStore] BUILDING SessionFactory. 14:52:45,125 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/CMSEntry.hbm.xml 14:52:45,171 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.CMSEntry -> jbp_cms_cmsentry 14:52:45,171 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/VersionEntry.hbm.xml 14:52:45,203 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.VersionEntry -> jbp_cms_versionentry 14:52:45,203 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/RepositoryEntry.hbm.xml 14:52:45,218 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.RepositoryEntry -> jbp_cms_repositoryentry 14:52:45,218 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,218 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:45,218 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:45,218 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:45,218 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:45,218 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:45,218 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,218 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:45,218 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:45,218 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:45,218 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:45,218 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:45,218 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:45,218 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:45,218 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:45,218 INFO [SettingsFactory] Connection release mode: auto 14:52:45,218 INFO [SettingsFactory] Default batch fetch size: 1 14:52:45,218 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:45,218 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:45,218 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:45,218 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:45,218 INFO [SettingsFactory] Query language substitutions: {} 14:52:45,218 INFO [SettingsFactory] Second-level cache: enabled 14:52:45,218 INFO [SettingsFactory] Query cache: disabled 14:52:45,218 INFO [SettingsFactory] Cache provider: org.hibernate.cache.HashtableCacheProvider 14:52:45,218 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:45,234 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:45,234 INFO [SettingsFactory] Statistics: disabled 14:52:45,234 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:45,234 INFO [SettingsFactory] Default entity-mode: pojo 14:52:45,234 INFO [SessionFactoryImpl] building session factory 14:52:45,343 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:45,343 INFO [SchemaUpdate] Running hbm2ddl schema update 14:52:45,343 INFO [SchemaUpdate] fetching database metadata 14:52:45,343 INFO [SchemaUpdate] updating schema 14:52:45,359 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_CMSENTRY 14:52:45,359 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,359 INFO [TableMetadata] foreign keys: [] 14:52:45,359 INFO [TableMetadata] indexes: [sys_pk_46] 14:52:45,359 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_REPOSITORYENTRY 14:52:45,359 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,375 INFO [TableMetadata] foreign keys: [] 14:52:45,375 INFO [TableMetadata] indexes: [sys_pk_47] 14:52:45,390 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSIONENTRY 14:52:45,390 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,390 INFO [TableMetadata] foreign keys: [] 14:52:45,390 INFO [TableMetadata] indexes: [sys_pk_48] 14:52:45,390 INFO [SchemaUpdate] schema update complete 14:52:45,390 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,390 INFO [HibernateStore] HibernateSessionFactory Created. 14:52:45,406 INFO [HibernateStore] BUILDING SessionFactory. 14:52:45,406 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/CMSEntry.hbm.xml 14:52:45,453 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.CMSEntry -> jbp_cms_cmsentry 14:52:45,453 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/VersionEntry.hbm.xml 14:52:45,468 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.VersionEntry -> jbp_cms_versionentry 14:52:45,484 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/RepositoryEntry.hbm.xml 14:52:45,515 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.RepositoryEntry -> jbp_cms_repositoryentry 14:52:45,515 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,531 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:45,531 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:45,531 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:45,531 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:45,531 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:45,531 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,531 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:45,531 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:45,531 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:45,531 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:45,531 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:45,531 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:45,531 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:45,531 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:45,531 INFO [SettingsFactory] Connection release mode: auto 14:52:45,531 INFO [SettingsFactory] Default batch fetch size: 1 14:52:45,531 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:45,531 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:45,531 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:45,531 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:45,531 INFO [SettingsFactory] Query language substitutions: {} 14:52:45,531 INFO [SettingsFactory] Second-level cache: enabled 14:52:45,531 INFO [SettingsFactory] Query cache: disabled 14:52:45,531 INFO [SettingsFactory] Cache provider: org.hibernate.cache.HashtableCacheProvider 14:52:45,531 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:45,531 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:45,531 INFO [SettingsFactory] Statistics: disabled 14:52:45,531 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:45,531 INFO [SettingsFactory] Default entity-mode: pojo 14:52:45,546 INFO [SessionFactoryImpl] building session factory 14:52:45,718 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:45,718 INFO [SchemaUpdate] Running hbm2ddl schema update 14:52:45,718 INFO [SchemaUpdate] fetching database metadata 14:52:45,718 INFO [SchemaUpdate] updating schema 14:52:45,718 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_CMSENTRY 14:52:45,718 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,718 INFO [TableMetadata] foreign keys: [] 14:52:45,718 INFO [TableMetadata] indexes: [sys_pk_46] 14:52:45,750 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_REPOSITORYENTRY 14:52:45,750 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,750 INFO [TableMetadata] foreign keys: [] 14:52:45,750 INFO [TableMetadata] indexes: [sys_pk_47] 14:52:45,765 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSIONENTRY 14:52:45,765 INFO [TableMetadata] columns: [fsentry_path, fsentry_data, fsentry_name, fsentry_length, fsentry_lastmod, pk] 14:52:45,765 INFO [TableMetadata] foreign keys: [] 14:52:45,765 INFO [TableMetadata] indexes: [sys_pk_48] 14:52:45,781 INFO [SchemaUpdate] schema update complete 14:52:45,781 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:45,781 INFO [HibernateStore] HibernateSessionFactory Created. 14:52:47,906 INFO [HibernatePersistenceManager] BUILDING SessionFactory. 14:52:47,921 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPBinVal.hbm.xml 14:52:47,953 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPBinVal -> jbp_cms_wsp_binval 14:52:47,953 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionBinVal.hbm.xml 14:52:48,015 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionBinVal -> jbp_cms_version_binval 14:52:48,015 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPNode.hbm.xml 14:52:48,046 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPNode -> jbp_cms_wsp_node 14:52:48,062 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionNode.hbm.xml 14:52:48,109 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionNode -> jbp_cms_version_node 14:52:48,109 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPProp.hbm.xml 14:52:48,140 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPProp -> jbp_cms_wsp_prop 14:52:48,140 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionProp.hbm.xml 14:52:48,187 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionProp -> jbp_cms_version_prop 14:52:48,187 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPRefs.hbm.xml 14:52:48,203 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPRefs -> jbp_cms_wsp_refs 14:52:48,218 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionRefs.hbm.xml 14:52:48,250 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionRefs -> jbp_cms_version_refs 14:52:48,250 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:48,250 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:48,250 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:48,250 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:48,250 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:48,250 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:48,250 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:48,250 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:48,250 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:48,250 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:48,250 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:48,250 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:48,250 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:48,250 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:48,250 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:48,250 INFO [SettingsFactory] Connection release mode: auto 14:52:48,250 INFO [SettingsFactory] Default batch fetch size: 1 14:52:48,250 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:48,250 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:48,250 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:48,250 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:48,250 INFO [SettingsFactory] Query language substitutions: {} 14:52:48,250 INFO [SettingsFactory] Second-level cache: enabled 14:52:48,250 INFO [SettingsFactory] Query cache: disabled 14:52:48,250 INFO [SettingsFactory] Cache provider: org.hibernate.cache.HashtableCacheProvider 14:52:48,250 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:48,250 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:48,250 INFO [SettingsFactory] Statistics: disabled 14:52:48,250 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:48,250 INFO [SettingsFactory] Default entity-mode: pojo 14:52:48,265 INFO [SessionFactoryImpl] building session factory 14:52:48,500 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:48,500 INFO [SchemaUpdate] Running hbm2ddl schema update 14:52:48,500 INFO [SchemaUpdate] fetching database metadata 14:52:48,500 INFO [SchemaUpdate] updating schema 14:52:48,500 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_BINVAL 14:52:48,500 INFO [TableMetadata] columns: [binval_id, binval_data, pk] 14:52:48,500 INFO [TableMetadata] foreign keys: [] 14:52:48,500 INFO [TableMetadata] indexes: [sys_pk_49] 14:52:48,515 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_NODE 14:52:48,515 INFO [TableMetadata] columns: [node_data, node_id, pk] 14:52:48,515 INFO [TableMetadata] foreign keys: [] 14:52:48,515 INFO [TableMetadata] indexes: [sys_pk_50] 14:52:48,531 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_PROP 14:52:48,531 INFO [TableMetadata] columns: [prop_data, pk, prop_id] 14:52:48,531 INFO [TableMetadata] foreign keys: [] 14:52:48,531 INFO [TableMetadata] indexes: [sys_pk_51] 14:52:48,531 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_REFS 14:52:48,531 INFO [TableMetadata] columns: [refs_data, node_id, pk] 14:52:48,531 INFO [TableMetadata] foreign keys: [] 14:52:48,531 INFO [TableMetadata] indexes: [sys_pk_52] 14:52:48,531 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_BINVAL 14:52:48,531 INFO [TableMetadata] columns: [binval_id, binval_data, pk] 14:52:48,531 INFO [TableMetadata] foreign keys: [] 14:52:48,531 INFO [TableMetadata] indexes: [sys_pk_53] 14:52:48,546 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_NODE 14:52:48,546 INFO [TableMetadata] columns: [node_data, node_id, pk] 14:52:48,546 INFO [TableMetadata] foreign keys: [] 14:52:48,546 INFO [TableMetadata] indexes: [sys_pk_54] 14:52:48,546 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_PROP 14:52:48,546 INFO [TableMetadata] columns: [prop_data, pk, prop_id] 14:52:48,546 INFO [TableMetadata] foreign keys: [] 14:52:48,546 INFO [TableMetadata] indexes: [sys_pk_55] 14:52:48,546 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_REFS 14:52:48,546 INFO [TableMetadata] columns: [refs_data, node_id, pk] 14:52:48,546 INFO [TableMetadata] foreign keys: [] 14:52:48,546 INFO [TableMetadata] indexes: [sys_pk_56] 14:52:48,546 INFO [SchemaUpdate] schema update complete 14:52:48,546 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:48,546 INFO [HibernatePersistenceManager] HibernateSessionFactory Created. 14:52:48,890 INFO [HibernatePersistenceManager] BUILDING SessionFactory. 14:52:48,890 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPBinVal.hbm.xml 14:52:48,921 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPBinVal -> jbp_cms_wsp_binval 14:52:48,921 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionBinVal.hbm.xml 14:52:48,937 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionBinVal -> jbp_cms_version_binval 14:52:48,937 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPNode.hbm.xml 14:52:48,953 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPNode -> jbp_cms_wsp_node 14:52:48,953 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionNode.hbm.xml 14:52:48,953 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionNode -> jbp_cms_version_node 14:52:48,968 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPProp.hbm.xml 14:52:48,968 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPProp -> jbp_cms_wsp_prop 14:52:48,968 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionProp.hbm.xml 14:52:48,984 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionProp -> jbp_cms_version_prop 14:52:48,984 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/WSPRefs.hbm.xml 14:52:49,000 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.WSPRefs -> jbp_cms_wsp_refs 14:52:49,000 INFO [Configuration] Reading mappings from resource: org/jboss/portal/cms/hibernate/state/VersionRefs.hbm.xml 14:52:49,015 INFO [HbmBinder] Mapping class: org.jboss.portal.cms.hibernate.state.VersionRefs -> jbp_cms_version_refs 14:52:49,031 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:49,031 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:49,031 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:49,031 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:49,031 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:49,031 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:49,031 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:49,031 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:49,031 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:49,031 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:49,031 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:49,031 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:49,031 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:49,031 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:49,031 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:49,031 INFO [SettingsFactory] Connection release mode: auto 14:52:49,031 INFO [SettingsFactory] Default batch fetch size: 1 14:52:49,031 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:49,031 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:49,031 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:49,031 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:49,031 INFO [SettingsFactory] Query language substitutions: {} 14:52:49,031 INFO [SettingsFactory] Second-level cache: enabled 14:52:49,031 INFO [SettingsFactory] Query cache: disabled 14:52:49,031 INFO [SettingsFactory] Cache provider: org.hibernate.cache.HashtableCacheProvider 14:52:49,031 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:49,031 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:49,031 INFO [SettingsFactory] Statistics: disabled 14:52:49,031 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:49,031 INFO [SettingsFactory] Default entity-mode: pojo 14:52:49,046 INFO [SessionFactoryImpl] building session factory 14:52:49,265 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:49,265 INFO [SchemaUpdate] Running hbm2ddl schema update 14:52:49,265 INFO [SchemaUpdate] fetching database metadata 14:52:49,265 INFO [SchemaUpdate] updating schema 14:52:49,281 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_BINVAL 14:52:49,281 INFO [TableMetadata] columns: [binval_id, binval_data, pk] 14:52:49,281 INFO [TableMetadata] foreign keys: [] 14:52:49,281 INFO [TableMetadata] indexes: [sys_pk_49] 14:52:49,281 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_NODE 14:52:49,281 INFO [TableMetadata] columns: [node_data, node_id, pk] 14:52:49,281 INFO [TableMetadata] foreign keys: [] 14:52:49,281 INFO [TableMetadata] indexes: [sys_pk_50] 14:52:49,296 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_PROP 14:52:49,296 INFO [TableMetadata] columns: [prop_data, pk, prop_id] 14:52:49,296 INFO [TableMetadata] foreign keys: [] 14:52:49,296 INFO [TableMetadata] indexes: [sys_pk_51] 14:52:49,312 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_VERSION_REFS 14:52:49,312 INFO [TableMetadata] columns: [refs_data, node_id, pk] 14:52:49,312 INFO [TableMetadata] foreign keys: [] 14:52:49,312 INFO [TableMetadata] indexes: [sys_pk_52] 14:52:49,312 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_BINVAL 14:52:49,328 INFO [TableMetadata] columns: [binval_id, binval_data, pk] 14:52:49,328 INFO [TableMetadata] foreign keys: [] 14:52:49,328 INFO [TableMetadata] indexes: [sys_pk_53] 14:52:49,328 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_NODE 14:52:49,328 INFO [TableMetadata] columns: [node_data, node_id, pk] 14:52:49,328 INFO [TableMetadata] foreign keys: [] 14:52:49,328 INFO [TableMetadata] indexes: [sys_pk_54] 14:52:49,328 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_PROP 14:52:49,328 INFO [TableMetadata] columns: [prop_data, pk, prop_id] 14:52:49,328 INFO [TableMetadata] foreign keys: [] 14:52:49,328 INFO [TableMetadata] indexes: [sys_pk_55] 14:52:49,328 INFO [TableMetadata] table found: PUBLIC.JBP_CMS_WSP_REFS 14:52:49,328 INFO [TableMetadata] columns: [refs_data, node_id, pk] 14:52:49,328 INFO [TableMetadata] foreign keys: [] 14:52:49,328 INFO [TableMetadata] indexes: [sys_pk_56] 14:52:49,328 INFO [SchemaUpdate] schema update complete 14:52:49,328 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:49,328 INFO [HibernatePersistenceManager] HibernateSessionFactory Created. 14:52:50,203 INFO [JackrabbitJCRService] Repository 'repotest' created 14:52:50,265 INFO [JackrabbitJCRService] The repository has already the CMS node types registered 14:52:50,359 INFO [Configuration] configuring from url: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/jboss-portal.sar/conf/hibernate/security/hibernate.cfg.xml 14:52:50,390 INFO [Configuration] Reading mappings from resource: conf/hibernate/security/domain.hbm.xml 14:52:50,421 INFO [HbmBinder] Mapping class: org.jboss.portal.core.security.store.SecurityPolicy -> JBP_SECURITY_POLICY 14:52:50,437 INFO [HbmBinder] Mapping class: org.jboss.portal.core.security.store.HbmSecurityConstraint -> JBP_SECURITY_CONSTRAINT 14:52:50,453 INFO [Configuration] Configured SessionFactory: null 14:52:50,484 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.security.store.SecurityPolicy.constraints -> JBP_SECURITY_CONSTRAINT 14:52:50,484 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:50,484 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:50,484 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:50,484 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:50,484 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:50,484 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:50,500 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:50,500 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:50,500 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:50,500 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:50,500 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:50,500 INFO [SettingsFactory] Automatic flush during beforeCompletion(): disabled 14:52:50,500 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:50,500 INFO [SettingsFactory] JDBC batch size: 15 14:52:50,500 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled 14:52:50,500 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:50,500 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:50,500 INFO [SettingsFactory] Connection release mode: auto 14:52:50,500 INFO [SettingsFactory] Default batch fetch size: 1 14:52:50,500 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:50,500 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:50,500 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:50,500 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:50,500 INFO [SettingsFactory] Query language substitutions: {} 14:52:50,500 INFO [SettingsFactory] Second-level cache: disabled 14:52:50,500 INFO [SettingsFactory] Query cache: disabled 14:52:50,500 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:50,500 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:50,500 INFO [SettingsFactory] Statistics: disabled 14:52:50,500 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:50,500 INFO [SettingsFactory] Default entity-mode: pojo 14:52:50,515 INFO [SessionFactoryImpl] building session factory 14:52:50,578 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:50,578 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:50,640 INFO [TreeCache] interceptor chain is: class org.jboss.cache.interceptors.CallInterceptor class org.jboss.cache.interceptors.LockInterceptor class org.jboss.cache.interceptors.CacheLoaderInterceptor class org.jboss.cache.interceptors.UnlockInterceptor class org.jboss.cache.interceptors.CacheStoreInterceptor 14:52:50,640 INFO [TreeCache] cache mode is local, will not create the channel 14:52:50,640 INFO [TreeCache] preloading transient state from cache loader 14:52:54,875 INFO [TreeCache] preloading transient state from cache loader was successful (in 4219 milliseconds) 14:52:54,875 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.user.PreferencesGroupImpl.prefMap -> jbp_user_pref_set 14:52:54,890 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.user.PreferencesImpl.content -> jbp_user_pref 14:52:54,906 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:54,906 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:54,906 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:54,906 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:54,906 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:54,906 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:54,906 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:54,906 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:54,906 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:54,906 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:54,906 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:54,906 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:54,906 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:54,906 INFO [SettingsFactory] JDBC batch size: 15 14:52:54,906 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled 14:52:54,906 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:54,906 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:54,906 INFO [SettingsFactory] Connection release mode: auto 14:52:54,906 INFO [SettingsFactory] Default batch fetch size: 1 14:52:54,906 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:54,906 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:54,906 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:54,906 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:54,906 INFO [SettingsFactory] Query language substitutions: {} 14:52:54,906 INFO [SettingsFactory] Second-level cache: enabled 14:52:54,906 INFO [SettingsFactory] Query cache: enabled 14:52:54,906 INFO [SettingsFactory] Cache provider: org.hibernate.cache.EhCacheProvider 14:52:54,937 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:54,937 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:54,937 INFO [SettingsFactory] Query cache factory: org.hibernate.cache.StandardQueryCacheFactory 14:52:54,937 INFO [SettingsFactory] Statistics: disabled 14:52:54,937 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:54,937 INFO [SettingsFactory] Default entity-mode: pojo 14:52:54,953 INFO [SessionFactoryImpl] building session factory 14:52:54,984 WARN [Configurator] No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/tmp/deploy/tmp23133ehcache.jar!/ehcache-failsafe.xml 14:52:55,015 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.role.RoleImpl]; using defaults. 14:52:55,125 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferenceImpl]; using defaults. 14:52:55,171 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.UserImpl]; using defaults. 14:52:55,218 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferencesImpl]; using defaults. 14:52:55,296 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferencesGroupImpl]; using defaults. 14:52:55,328 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.UserImpl.dynamic]; using defaults. 14:52:55,343 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.role.RoleImpl.users]; using defaults. 14:52:55,343 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferencesImpl.content]; using defaults. 14:52:55,343 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferenceImpl.strings]; using defaults. 14:52:55,359 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.PreferencesGroupImpl.prefMap]; using defaults. 14:52:55,359 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.user.UserImpl.roles]; using defaults. 14:52:55,390 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:55,390 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,406 INFO [UpdateTimestampsCache] starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache 14:52:55,406 WARN [EhCacheProvider] Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults. 14:52:55,406 INFO [StandardQueryCache] starting query cache at region: org.hibernate.cache.StandardQueryCache 14:52:55,406 WARN [EhCacheProvider] Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults. 14:52:55,500 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.instance.InstanceImpl.preferencesMap -> JBP_INSTANCE_PREF 14:52:55,500 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,500 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:55,500 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:55,500 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:55,500 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:55,500 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:55,515 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,515 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:55,515 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:55,515 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:55,515 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:55,515 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:55,515 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:55,515 INFO [SettingsFactory] JDBC batch size: 15 14:52:55,515 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled 14:52:55,515 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:55,515 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:55,515 INFO [SettingsFactory] Connection release mode: auto 14:52:55,515 INFO [SettingsFactory] Default batch fetch size: 1 14:52:55,515 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:55,515 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:55,515 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:55,515 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:55,515 INFO [SettingsFactory] Query language substitutions: {} 14:52:55,515 INFO [SettingsFactory] Second-level cache: enabled 14:52:55,515 INFO [SettingsFactory] Query cache: enabled 14:52:55,515 INFO [SettingsFactory] Cache provider: org.hibernate.cache.EhCacheProvider 14:52:55,515 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:55,515 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:55,515 INFO [SettingsFactory] Query cache factory: org.hibernate.cache.StandardQueryCacheFactory 14:52:55,515 INFO [SettingsFactory] Statistics: disabled 14:52:55,515 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:55,515 INFO [SettingsFactory] Default entity-mode: pojo 14:52:55,546 INFO [SessionFactoryImpl] building session factory 14:52:55,546 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.instance.InstanceImpl]; using defaults. 14:52:55,625 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.instance.PreferenceImpl]; using defaults. 14:52:55,656 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.instance.InstanceImpl.preferencesMap]; using defaults. 14:52:55,671 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.instance.PreferenceImpl.strings]; using defaults. 14:52:55,703 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:55,703 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,703 INFO [UpdateTimestampsCache] starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache 14:52:55,703 INFO [StandardQueryCache] starting query cache at region: org.hibernate.cache.StandardQueryCache 14:52:55,765 INFO [HbmBinder] Mapping collection: org.jboss.portal.core.impl.model.portal.ObjectNode.children -> JBP_OBJECT_NODE 14:52:55,812 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,812 INFO [DatasourceConnectionProvider] Using datasource: java:PortalDS 14:52:55,812 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0 14:52:55,812 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.0 14:52:55,812 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect 14:52:55,812 INFO [TransactionFactoryFactory] Transaction strategy: org.hibernate.transaction.JTATransactionFactory 14:52:55,812 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:55,812 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:55,812 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:55,812 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup 14:52:55,812 INFO [TransactionManagerLookupFactory] instantiated TransactionManagerLookup 14:52:55,812 INFO [SettingsFactory] Automatic flush during beforeCompletion(): enabled 14:52:55,812 INFO [SettingsFactory] Automatic session close at end of transaction: disabled 14:52:55,812 INFO [SettingsFactory] JDBC batch size: 15 14:52:55,812 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled 14:52:55,812 INFO [SettingsFactory] Scrollable result sets: enabled 14:52:55,812 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled 14:52:55,812 INFO [SettingsFactory] Connection release mode: auto 14:52:55,812 INFO [SettingsFactory] Default batch fetch size: 1 14:52:55,812 INFO [SettingsFactory] Generate SQL with comments: disabled 14:52:55,812 INFO [SettingsFactory] Order SQL updates by primary key: disabled 14:52:55,812 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 14:52:55,812 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory 14:52:55,812 INFO [SettingsFactory] Query language substitutions: {} 14:52:55,812 INFO [SettingsFactory] Second-level cache: enabled 14:52:55,812 INFO [SettingsFactory] Query cache: enabled 14:52:55,812 INFO [SettingsFactory] Cache provider: org.hibernate.cache.EhCacheProvider 14:52:55,812 INFO [SettingsFactory] Optimize cache for minimal puts: disabled 14:52:55,812 INFO [SettingsFactory] Structured second-level cache entries: disabled 14:52:55,812 INFO [SettingsFactory] Query cache factory: org.hibernate.cache.StandardQueryCacheFactory 14:52:55,812 INFO [SettingsFactory] Statistics: disabled 14:52:55,812 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled 14:52:55,812 INFO [SettingsFactory] Default entity-mode: pojo 14:52:55,828 INFO [SessionFactoryImpl] building session factory 14:52:55,828 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.PortalObjectImpl]; using defaults. 14:52:56,046 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.ObjectNode]; using defaults. 14:52:56,109 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.PortalImpl.windowStates]; using defaults. 14:52:56,109 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.PortalObjectImpl.declaredProperties]; using defaults. 14:52:56,125 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.ObjectNode.children]; using defaults. 14:52:56,125 WARN [EhCacheProvider] Could not find configuration [org.jboss.portal.core.impl.model.portal.PortalImpl.modes]; using defaults. 14:52:56,156 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured 14:52:56,156 INFO [NamingHelper] JNDI InitialContext properties:{} 14:52:56,156 INFO [UpdateTimestampsCache] starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache 14:52:56,156 INFO [StandardQueryCache] starting query cache at region: org.hibernate.cache.StandardQueryCache 14:53:00,234 INFO [LayoutDeployment] create new layout(s), found in : portal 14:53:00,265 INFO [LayoutDeployment] done creating new layout(s), found in : portal 14:53:00,453 INFO [ThemeDeployment] create new theme(s), found in : portal 14:53:00,484 INFO [ThemeDeployment] done creating new theme(s), found in : portal 14:53:01,062 INFO [FacesConfigurator] Reading standard config org/apache/myfaces/resource/standard-faces-config.xml 14:53:01,234 INFO [FacesConfigurator] Reading config jar:file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/tmp/deploy/tmp23139jsf-facelets.jar!/META-INF/faces-config.xml 14:53:01,281 INFO [FacesConfigurator] Reading config jar:file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/tmp/deploy/tmp23151tomahawk.jar!/META-INF/faces-config.xml 14:53:01,437 INFO [FacesConfigurator] Reading config /WEB-INF/faces-config.xml 14:53:01,500 ERROR [LocaleUtils] Locale name null or empty, ignoring 14:53:01,515 INFO [RenderKitFactoryImpl] RenderKit with renderKitId 'HTML_BASIC' was replaced. 14:53:01,531 INFO [MyFacesGenericPortlet] PortletContext 'C:\ta31\progs\jboss-portal-2.2.1-bundled\server\default\.\deploy\jboss-portal.sar\portal-core.war\' initialized. 14:53:01,812 INFO [LayoutDeployment] create new layout(s), found in : /portal 14:53:01,828 INFO [LayoutDeployment] done creating new layout(s), found in : /portal 14:53:02,781 INFO [EjbModule] Deploying CDSServiceEJB 14:53:03,859 INFO [ProxyFactory] Bound EJB Home 'CDSServiceEJB' to jndi 'CDSServiceEJB' 14:53:03,859 INFO [EJBDeployer] Deployed: file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/esv-cms-service.jar/ 14:53:04,515 INFO [TomcatDeployer] deploy, ctxPath=/cardemo, warUrl=.../tmp/deploy/tmp23216cardemo-exp.war/ 14:53:10,531 INFO [TomcatDeployer] deploy, ctxPath=/esv-head-portlet, warUrl=.../deploy/esv-head-portlet.war/ 14:53:16,687 INFO [XmlBeanDefinitionReader] Loading XML bean definitions from URL [file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/esv-head-portlet.war/WEB-INF/classes/esv-head-portlet-BeanRefContext.xml] 14:53:16,765 INFO [ClassPathXmlApplicationContext] Bean factory for application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=105044]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [esv-head-portlet-RefContext]; root of BeanFactory hierarchy 14:53:16,828 INFO [ClassPathXmlApplicationContext] 1 beans defined in application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=105044] 14:53:16,843 INFO [CollectionFactory] JDK 1.4+ collections available 14:53:16,843 INFO [CollectionFactory] Commons Collections 3.x available 14:53:16,859 INFO [ClassPathXmlApplicationContext] Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@e8873a] 14:53:16,875 INFO [ClassPathXmlApplicationContext] Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@c09a5d] 14:53:16,875 INFO [DefaultListableBeanFactory] Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [esv-head-portlet-RefContext]; root of BeanFactory hierarchy] 14:53:16,875 INFO [DefaultListableBeanFactory] Creating shared instance of singleton bean 'esv-head-portlet-RefContext' 14:53:16,984 INFO [XmlBeanDefinitionReader] Loading XML bean definitions from class path resource [esv-head-portlet-ApplicationContext.xml] 14:53:17,062 INFO [ClassPathXmlApplicationContext] Bean factory for application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=15878090]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [cdsService]; root of BeanFactory hierarchy 14:53:17,062 INFO [ClassPathXmlApplicationContext] 1 beans defined in application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=15878090] 14:53:17,062 INFO [ClassPathXmlApplicationContext] Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@1180bfd] 14:53:17,062 INFO [ClassPathXmlApplicationContext] Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@1bb2525] 14:53:17,062 INFO [DefaultListableBeanFactory] Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [cdsService]; root of BeanFactory hierarchy] 14:53:17,062 INFO [DefaultListableBeanFactory] Creating shared instance of singleton bean 'cdsService' 14:53:17,406 INFO [DefaultAopProxyFactory] CGLIB2 available: proxyTargetClass feature enabled 14:53:17,625 INFO [TomcatDeployer] deploy, ctxPath=/esv-menu-portlet, warUrl=.../deploy/esv-menu-portlet.war/ 14:53:23,312 INFO [XmlBeanDefinitionReader] Loading XML bean definitions from URL [file:/C:/ta31/progs/jboss-portal-2.2.1-bundled/server/default/deploy/esv-menu-portlet.war/WEB-INF/classes/esv-menu-portlet-BeanRefContext.xml] 14:53:23,328 INFO [ClassPathXmlApplicationContext] Bean factory for application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=17975322]: org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [esv-menu-portlet-RefContext]; root of BeanFactory hierarchy 14:53:23,328 INFO [ClassPathXmlApplicationContext] 1 beans defined in application context [org.springframework.context.support.ClassPathXmlApplicationContext;hashCode=17975322] 14:53:23,328 INFO [ClassPathXmlApplicationContext] Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@a16748] 14:53:23,328 INFO [ClassPathXmlApplicationContext] Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@83c0e9] 14:53:23,328 INFO [DefaultListableBeanFactory] Pre-instantiating singletons in factory [org.springframework.beans.factory.support.DefaultListableBeanFactory defining beans [esv-menu-portlet-RefContext]; root of BeanFactory hi