1.4.0 Enterprise installation error Oracle/WinXP/Tomcat 5.5

[pitt1]

Setup:
* 1.4.0 Enterprise – WAR installation
* Oracle 10g enterprise
* Windows XP
* Tomcat 5.5.20

When I go to deploy the WAR in tomcat, I get the following stack trace.  Note that I previously had 1.3.2 Enterprise, tried upgrading to 1.4.0 with data in the system, and it hung.  I subsequently cleaned out my database (dropped/re-created the user), deleted the files on the filesystem and removed all Alfresco temp data from tomcat.  Then I went to deploy the 1.4.0 WAR and got the stack trace, so my Alfresco server won't start up.

12:50:59,671 ERROR [org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/alfresco]] Exception sending context initialized event to listener instance of class org.alfresco.web.app.ContextListener
org.alfresco.error.AlfrescoRuntimeException: Bootstrap failed
        at org.alfresco.repo.importer.ImporterBootstrap.bootstrap(ImporterBootstrap.java:448)
        at org.alfresco.repo.importer.ImporterBootstrap.onBootstrap(ImporterBootstrap.java:670)
        at org.alfresco.util.AbstractLifecycleBean.onApplicationEvent(AbstractLifecycleBean.java:54)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:45)
        at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:225)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:323)
        at org.springframework.web.context.support.AbstractRefreshableWebApplicationContext.refresh(AbstractRefreshableWebApplicationContext.java:134)
        at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:246)
        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:184)
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:49)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3763)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4211)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:739)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:809)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:497)
        at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1204)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.apache.commons.modeler.BaseModelMBean.invoke(BaseModelMBean.java:503)
        at com.sun.jmx.mbeanserver.DynamicMetaDataImpl.invoke(Unknown Source)
        at com.sun.jmx.mbeanserver.MetaDataImpl.invoke(Unknown Source)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)
        at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)
        at org.apache.catalina.manager.ManagerServlet.check(ManagerServlet.java:1377)
        at org.apache.catalina.manager.HTMLManagerServlet.doPost(HTMLManagerServlet.java:213)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:524)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:833)
        at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:639)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1285)
        at java.lang.Thread.run(Unknown Source)
Caused by: org.alfresco.service.cmr.view.ImporterException: Failed to import package at line 27; column 48 due to error: Definition {http://www.alfresco.org/model/content/1.0}homeFolderProvider is not valid; cannot find in Repository dictionary
        at org.alfresco.repo.importer.view.ViewParser.parse(ViewParser.java:171)
        at org.alfresco.repo.importer.ImporterComponent.parserImport(ImporterComponent.java:344)
        at org.alfresco.repo.importer.ImporterComponent.importView(ImporterComponent.java:211)
        at org.alfresco.repo.importer.ImporterBootstrap.bootstrap(ImporterBootstrap.java:429)
        … 43 more
Caused by: org.alfresco.service.cmr.view.ImporterException: Definition {http://www.alfresco.org/model/content/1.0}homeFolderProvider is not valid; cannot find in Repository dictionary
        at org.alfresco.repo.importer.view.ViewParser.processStartElement(ViewParser.java:261)
        at org.alfresco.repo.importer.view.ViewParser.parse(ViewParser.java:157)
        … 46 more
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[derek]

Hi,

Issue 1: The hang
Did you check that the process was in fact dead, or was the system just performing the upgrade and executing the patches?  What was in the log files to indicate that it had hung?

Issue 2: Clean startup
Have you extended the model in your 1.3.2 installation?  The type not being found is new to 1.4, which seems to indicate that the system is running on a 1.3 content model.

Regards

[pitt1]

Issue 1:
Essentially, I let the upgrade run for about an hour (I don't think it should have taken this long, given that I probably had < 300 documents in the system).  The log files indicated that for an hour, it was "checking for patches to apply."  During this time, my CPU usage was sustained at 100%, and my system (laptop system w/ 2GHZ pentium M, 2GB RAM) was unresponsive.  The task manager indicated that tomcat and oracle were taking up most of the cpu.  I was finally able to stop the tomcat service, so undoubtedly the install was at an unstable state.  Here's my logfile:

11:25:13,069 ERROR [org.alfresco.repo.content.transform.magick.AbstractImageMagickContentTransformer] ImageMagickContentTransformer not available: Failed to execute command: imconvert "C:\Program Files\Apache Software Foundation\Tomcat 5.5\temp\Alfresco\ImageMagickContentTransformer_init_source_37203.gif"  "C:\Program Files\Apache Software Foundation\Tomcat 5.5\temp\Alfresco\ImageMagickContentTransformer_init_target_37204.png"
11:25:15,883 WARN  [org.alfresco.util.OpenOfficeConnectionTester] A connection to OpenOffice could not be established.
11:25:21,461 INFO  [org.alfresco.repo.domain.schema.SchemaBootstrap] Executing database script: classpath:alfresco/dbscripts/upgrade/1.4/${db.script.dialect}/AlfrescoSchemaUpdate-1.4-1.sql
11:25:26,118 INFO  [org.alfresco.repo.domain.schema.SchemaBootstrap] Executing database script: classpath:alfresco/dbscripts/upgrade/1.4/${db.script.dialect}/AlfrescoSchemaUpdate-1.4-2.sql
11:25:46,839 INFO  [org.alfresco.repo.domain.schema.SchemaBootstrap] Executing database script: C:\Program Files\Apache Software Foundation\Tomcat 5.5\temp\Alfresco\AlfrescoSchemaUpdate-org.hibernate.dialect.OracleDialect-37207.sql
11:26:02,332 INFO  [org.alfresco.repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: C:\alfresco
11:26:03,193 INFO  [org.alfresco.repo.admin.patch.PatchExecuter] Checking for patches to apply …
‍‍‍‍‍‍‍‍‍

Issue 2:
Yes indeed.  I have not taken the opportunity to understand what changes to the content modeling language or the Alfresco content models themselves that have taken place between 1.3.2 and 1.4.  I used the exact same custom models in 1.4 as I did in 1.3.2, which I placed in TOMCAT_HOME/shared/classes/alfresco/extension.  One of the models actually extends the "cm" model.  For 1.3.2 I was instructed to do this by copying the entire "cm" model into my extension folder and making additions.  I bet this is exactly the issue I'm having right now–I need to re-copy the 1.4 "cm" model and make my changes again.  I'll try this and let you know if it was successful.  Perhaps it is the culprit for Issue 1 as well.  Strange that I was previously able to do a successful 1.3.2 to 1.4.0 upgrade with the same custom models in place…

[pitt1]

As I had surmised, the fact that I was overriding the 1.3.2 content model and not the 1.4.0 one was the problem.  I made changes to the 1.4.0 model, deleted the 1.3.2 one, and my server started up, although not without seemingly unrelated hiccups, with PermGen out of memory errors and once a runtime Cryptix error when attempting to login as admin.  If these problems persist, I'll post another topic about it…

[derek]

With that number of documents, there is definitely something wrong.  We've tested several partners' data before the release - most with many more documents than that.  If you're happy that the VM memory allocation is correct, I'd recommend contacting support directly and we can arrange to take a look at the data.

Regards

[pitt1]

Unfortunately, I am seeing Issue #1 again now that I'm upgrading our central development server.  Our central development server configuration is:

* RedHat
* Tomcat 5.5.17
* Oracle 10g
* Upgrade to 1.4.0 from 1.3.2
* Verified that FK indexes were in place on the database before upgrading
* Using extension (in the form of an override) to Alfresco 1.4.0 cm model (this extension has proven to work on many 1.4.0 install tests in the past).

Log message:

INFO: Deploying web application archive alfresco.war
12:14:18,036 WARN  [alfresco.util.OpenOfficeConnectionTester] A connection to OpenOffice could not be established.
12:14:21,005 INFO  [domain.schema.SchemaBootstrap] Executing database script: classpath:alfresco/dbscripts/upgrade/1.4/${db.script.dialect}/AlfrescoSchemaUpdate-1.4-1.sql
12:14:23,127 INFO  [domain.schema.SchemaBootstrap] Executing database script: classpath:alfresco/dbscripts/upgrade/1.4/${db.script.dialect}/AlfrescoSchemaUpdate-1.4-2.sql
12:14:33,547 INFO  [domain.schema.SchemaBootstrap] Executing database script: /usr/local/apache-tomcat/apache-tomcat-5.5.17/temp/Alfresco/AlfrescoSchemaUpdate-org.hibernate.dialect.Ora
cleDialect-52929.sql
12:14:38,032 INFO  [repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: /alfresco/data
12:14:39,176 INFO  [admin.patch.PatchExecuter] Checking for patches to apply …
‍‍‍‍‍‍‍‍‍‍

It has hung at the point of "checking for patches" for about 20 minutes so far, whereas earlier today, I performed the very same upgrade on my windows desktop with no hang (almost immediately I got a list of patches that were applied and the upgrade continued). 

I am very concerned about this issue, and want to figure out the root of it before upgrading our production system.  Any input is much appreciated.

[derek]

When you did "the very same upgrade", was that with the same data as well?

Could you confirm the memory assigned to the server VM as well as the approximate number of documents in the repository, please.

Put debug on for the following:
org.alfresco.repo.admin.patch.AbstractPatch

During the upgrade, tail the following files:
./InvalidNameEndingPatch.log
./UniqueChildNamePatch.log

Regards

[pitt1]

When you did "the very same upgrade", was that with the same data as well?

No, the data were different in both cases.

Could you confirm the memory assigned to the server VM as well as the approximate number of documents in the repository, please.

The server VM is allocated 2GB of memory, and the number of documents was only in the hundreds at most.

As for the second bit, I don't know that I can reliably reproduce the error.  The outcome of this upgrade was that it did indeed complete after about one hour.  It is worth mentioning that after the upgrade did complete and the alfresco server started, several 'invalid property value' errors were reported, in the form:

Invalid property value: 
   Node: archive://SpacesStore/2f5e2a53-741f-11db-bbf0-d14115aac714
   Type: {http://custommodel.com/1.0}My_Aspect
   Property: {http://custommodel.com/1.0}My_Field
   Constraint: The value is not an allowed value: foo
‍‍‍‍‍‍‍

This was due to the fact that some data was entered with an old content model, and a constraint was later added to an existing property in a new version of it.  This could perhaps be the source of the problem–however I did a prior upgrade on my desktop with nearly identical data, the same content models, and the same integrity issues (and even less memory/compute power), and the upgrade did not hang like this.

I can try to reproduce this problem in a controlled environment, but there are no guarantees…

[derek]

Hi,

A few hundred documents should present virtually no impediment to the patch execution.  As you mention, the upgrade on another system takes significantly less time.  Also, the integrity issue will not be slowing the system down.

It would appear that the execution is being slowed down by something more fundamental.  In the past, we've seen similar behaviour when the log4j settings are incorrect, causing the system to generate DEBUG messages for every category but not output them.  This doesn't happen on Tomcat, though.  And it would appear that the log4j settings are correct on your installation.  Nevertheless, just ensure that there isn't a massive log file being generated somewhere and check that the log settings are the same between the two installations.

The other issue to check would be that the database indexes are present.  You mentioned that these had been applied, but it might be worth comparing the schemas between the two upgrades to see if there is any difference.

If you contact support directly, we would be happy to take it up more formally.  It is likely to be a VM, configuration or database issue.  We may need to repeat the process in-house with the same environment to find out what where the bottleneck is.

Regards