11 Replies Latest reply on Feb 12, 2007 2:38 PM by Thomas Heute

    very long startup time

    Ing. Florian Gumpinger Newbie

      We 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