3.0 -> 3.3 Upgrade Problem - PatchExecuter [SOLVED]

[luca]

Hi all,
I have a problem upgrading Alfresco 3.0 to Alfresco 3.3.

From the log I can see that PathExecuter is looping in his attemps to to migrate old-style content URL storage to the newer alf_content_url storage, as I can understand from ContentUrlConverterPatch that is the class that log it. It reach about 36500 URLs and then it start from the beginning again, and again:

…
14:35:24,437 User:System INFO  [admin.patch.PatchExecuter]       Processed 36,500 content URLs from store.
14:39:23,399 User:System INFO  [admin.patch.PatchExecuter]       Processed 500 content URLs from store.
…
‍‍‍‍‍‍

I have about 26GB of data in my contentstore directory, so I think it can be some problem related to the huge load of data to read. I'm using Postgres 8 as database. Or it can be one corrupted node?
Any help is higly appreciated!  :wink:

Another secondary problem is that I noticed that this upgrade was working also in the binary data in the contentstore. In particular some binary file are missing from the contentstore after the upgrade, does anyone know why and where these files are gone???

Complete Stacktrace:

CompilerOracle: exclude org/apache/lucene/index/IndexReader$1.doBody
CompilerOracle: exclude org/alfresco/repo/search/impl/lucene/index/IndexInfo$Merger.mergeIndexes
CompilerOracle: exclude org/alfresco/repo/search/impl/lucene/index/IndexInfo$Merger.mergeDeletions
May 12, 2010 1:25:01 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/local/jdk1.6.0_14/jre/lib/amd64/server:/usr/local/jdk1.6.0_14/jre/lib/amd64:/usr/local/jdk1.6.0_14/jre/../lib/amd64:/usr/java/packages/lib/amd64:/lib:/usr/lib
May 12, 2010 1:25:02 PM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-48080
May 12, 2010 1:25:02 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 327 ms
May 12, 2010 1:25:02 PM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
May 12, 2010 1:25:02 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.18
May 12, 2010 1:25:02 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive alfresco.war
May 12, 2010 1:25:04 PM org.apache.catalina.core.StandardContext addApplicationListener
INFO: The listener "org.apache.myfaces.webapp.StartupServletContextListener" is already configured for this context. The duplicate definition has been ignored.
13:25:07,805  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/repository.properties]
13:25:07,807  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/domain/transaction.properties]
13:25:07,807  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from URL [file:/opt/tomcat_alfresco/shared/classes/alfresco-global.properties]
13:25:07,888  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
13:25:17,521  INFO  [extensions.webscripts.TemplateProcessorRegistry] Registered template processor Repository Template Processor for extension ftl
13:25:17,523  INFO  [extensions.webscripts.ScriptProcessorRegistry] Registered script processor Repository Script Processor for extension js
13:25:21,215  INFO  [domain.schema.SchemaBootstrap] Schema managed by database dialect org.hibernate.dialect.PostgreSQLDialect.
13:25:24,481  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-264249785107181616.sql (Copied from classpath:alfresco/dbscripts/upgrade/2.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoSchemaUpdate-Person.sql).
13:26:11,051  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-5401172435411804623.sql (Copied from classpath:alfresco/dbscripts/create/3.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoPostCreate-3.2-LockTables.sql).
13:26:11,479  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-8674602557853885597.sql (Copied from classpath:alfresco/dbscripts/create/3.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoPostCreate-3.2-ContentTables.sql).
13:26:12,134  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-8699343042461007895.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoSchemaUpdate-3.2-ContentTables2.sql).
13:26:12,222  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-396215000211409638.sql (Copied from classpath:alfresco/dbscripts/create/3.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoPostCreate-3.2-PropertyValueTables.sql).
13:26:13,284  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-5724595892061705517.sql (Copied from classpath:alfresco/dbscripts/create/3.2/org.hibernate.dialect.PostgreSQLDialect/AlfrescoPostCreate-3.2-AuditTables.sql).
13:26:13,707  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-2273017622511937801.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.2/org.hibernate.dialect.PostgreSQLDialect/child-assoc-qname-crc.sql).
13:26:29,729  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-980226137431825728.sql (Generated).
13:26:29,789  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-2047456910438062439.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.1/org.hibernate.dialect.PostgreSQLDialect/IPv6-patch.sql).
13:26:30,115  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-4611781391991990040.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.2/org.hibernate.dialect.PostgreSQLDialect/remove-AVM-issuer.sql).
13:26:30,257  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-3340069529909858782.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.2/org.hibernate.dialect.PostgreSQLDialect/modify-AVM-mimetype.sql).
13:26:30,782  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-2052506887475954118.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.2/org.hibernate.dialect.PostgreSQLDialect/jbpm-upgrade.sql).
13:26:33,195  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-4014227950531214385.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.3/org.hibernate.dialect.PostgreSQLDialect/remove-VersionCount.sql).
13:26:33,227  INFO  [domain.schema.SchemaBootstrap] Executing database script /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-Update-5846534134640375827.sql (Copied from classpath:alfresco/dbscripts/upgrade/3.3/org.hibernate.dialect.PostgreSQLDialect/fix-Repo-seqs_1.sql).
13:26:33,257  INFO  [domain.schema.SchemaBootstrap] All executed statements:  /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-All_Statements-4600111225814754286.sql.
13:26:37,108  INFO  [domain.schema.SchemaBootstrap] Normalized schema (pre-bootstrap)  dumped to file /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-6196099261868001939-Startup.xml.
13:26:37,108  INFO  [domain.schema.SchemaBootstrap] Normalized schema (post-bootstrap) dumped to file /opt/tomcat_alfresco/temp/Alfresco/AlfrescoSchema-PostgreSQLDialect-7475217159011929042.xml.
13:26:37,113  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'sysAdmin' subsystem, ID: [sysAdmin, default]
13:26:37,125  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
13:26:37,136  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'sysAdmin' subsystem, ID: [sysAdmin, default] complete
13:26:38,294  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'thirdparty' subsystem, ID: [thirdparty, default]
13:26:38,306  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
13:26:38,399  ERROR [transform.magick.AbstractImageMagickContentTransformerWorker] ImageMagickContentTransformerWorker not available: 04120000 Failed to perform ImageMagick transformation: 
Execution result: 
   os:         Linux
   command:    [./ImageMagick/bin/convert, /opt/tomcat_alfresco/temp/Alfresco/ImageMagickContentTransformerWorker_init_source_2397814026615326945.gif[0], /opt/tomcat_alfresco/temp/Alfresco/ImageMagickContentTransformerWorker_init_target_8570898305538075100.png]
   succeeded:  false
   exit code:  1
   out:        
   err:        Cannot run program "./ImageMagick/bin/convert": java.io.IOException: error=2, No such file or directory
13:26:38,486  ERROR [content.transform.RuntimeExecutableContentTransformerWorker] Failed to start a runtime executable content transformer: 
Execution result: 
   os:         Linux
   command:    [./bin/pdf2swf, -V]
   succeeded:  false
   exit code:  1
   out:        
   err:        Cannot run program "./bin/pdf2swf": java.io.IOException: error=2, No such file or directory
13:26:38,492  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'thirdparty' subsystem, ID: [thirdparty, default] complete
13:26:38,492  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'OOoDirect' subsystem, ID: [OOoDirect, default]
13:26:38,505  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
13:26:38,746  ERROR [util.exec.RuntimeExecBootstrapBean] Bootstrap command failed: 
Execution result: 
   os:         Linux
   command:    [soffice, -accept=socket,host=localhost,port=8100;urp;StarOffice.ServiceManager, -env:UserInstallation=file:///opt/alfresco_api/alf_data/oouser, -nologo, -headless, -nofirststartwizard, -nocrashrep, -norestore]
   succeeded:  false
   exit code:  2
   out:        
   err:        Cannot run program "soffice": java.io.IOException: error=2, No such file or directory
13:26:38,792  WARN  [alfresco.util.OpenOfficeConnectionTester] An initial OpenOffice connection could not be established.
13:26:38,801  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'OOoDirect' subsystem, ID: [OOoDirect, default] complete
13:26:39,552  INFO  [node.index.FullIndexRecoveryComponent] Index recovery started: 132,816 transactions.
### Excluding compile: org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger::mergeDeletions
13:28:06,970  INFO  [node.index.FullIndexRecoveryComponent]    10 % complete.
13:29:15,491  INFO  [node.index.FullIndexRecoveryComponent]    20 % complete.
13:30:18,824  INFO  [node.index.FullIndexRecoveryComponent]    30 % complete.
13:32:01,676  INFO  [node.index.FullIndexRecoveryComponent]    40 % complete.
13:33:39,264  INFO  [node.index.FullIndexRecoveryComponent]    50 % complete.
13:35:08,419  INFO  [node.index.FullIndexRecoveryComponent]    60 % complete.
13:36:36,264  INFO  [node.index.FullIndexRecoveryComponent]    70 % complete.
13:38:06,321  INFO  [node.index.FullIndexRecoveryComponent]    80 % complete.
13:39:33,028  INFO  [node.index.FullIndexRecoveryComponent]    90 % complete.
13:43:29,323  INFO  [node.index.FullIndexRecoveryComponent]    100 % complete.
13:47:34,597  INFO  [node.index.FullIndexRecoveryComponent] Index recovery completed.
13:47:34,709  WARN  [node.index.AVMFullIndexRecoveryComponent]     Index for avm store sitestore is out of date
13:47:34,709  INFO  [node.index.AVMFullIndexRecoveryComponent] Rebuilding indexes for 1 AVM Stores
13:47:34,709  INFO  [node.index.AVMFullIndexRecoveryComponent]     Auto recovering index for sitestore
13:47:34,717  INFO  [node.index.AVMFullIndexRecoveryComponent]   Reindex   100% complete
13:47:34,717  INFO  [node.index.AVMFullIndexRecoveryComponent] Finished rebuilding indexes for AVM Stores
13:47:35,402  INFO  [repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: /opt/alfresco_api/alf_data
13:47:35,673  INFO  [admin.patch.PatchExecuter] Checking for patches to apply …
13:47:35,767  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.fixNameCrcValues-2' (Fixes name and qname CRC32 values to match UTF-8 encoding.).
13:47:48,433 User:System INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Commencing batch of 204957 entries
13:47:50,035  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 1000 entries out of 204957. 0% complete. Rate: 624 per second. 0 failures detected.
13:47:51,170  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 2000 entries out of 204957. 1% complete. Rate: 730 per second. 0 failures detected.
13:47:52,337  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 3000 entries out of 204957. 1% complete. Rate: 768 per second. 0 failures detected.
13:47:53,400  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 4000 entries out of 204957. 2% complete. Rate: 805 per second. 0 failures detected.
13:47:54,545  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 5000 entries out of 204957. 2% complete. Rate: 818 per second. 0 failures detected.
13:47:55,510  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 6000 entries out of 204957. 3% complete. Rate: 847 per second. 0 failures detected.
13:47:56,388  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 7000 entries out of 204957. 3% complete. Rate: 879 per second. 0 failures detected.
13:47:57,729  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 8000 entries out of 204957. 4% complete. Rate: 860 per second. 0 failures detected.
13:47:58,712  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 9000 entries out of 204957. 4% complete. Rate: 875 per second. 0 failures detected.
13:47:59,598  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 10000 entries out of 204957. 5% complete. Rate: 895 per second. 0 failures detected.
…
13:57:20,072  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 193000 entries out of 204957. 94% complete. Rate: 337 per second. 0 failures detected.
13:57:23,074  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 194000 entries out of 204957. 95% complete. Rate: 337 per second. 0 failures detected.
13:57:25,265  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 195000 entries out of 204957. 95% complete. Rate: 338 per second. 0 failures detected.
13:57:29,029  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 196000 entries out of 204957. 96% complete. Rate: 337 per second. 0 failures detected.
13:57:31,502  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 197000 entries out of 204957. 96% complete. Rate: 337 per second. 0 failures detected.
13:57:36,376  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 198000 entries out of 204957. 97% complete. Rate: 336 per second. 0 failures detected.
13:57:38,858  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 199000 entries out of 204957. 97% complete. Rate: 337 per second. 0 failures detected.
13:57:41,409  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 200000 entries out of 204957. 98% complete. Rate: 337 per second. 0 failures detected.
13:57:44,428  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 201000 entries out of 204957. 98% complete. Rate: 337 per second. 0 failures detected.
13:57:47,414  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 202000 entries out of 204957. 99% complete. Rate: 337 per second. 0 failures detected.
13:57:49,858  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 203000 entries out of 204957. 99% complete. Rate: 337 per second. 0 failures detected.
13:57:53,116  INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 204000 entries out of 204957. 100% complete. Rate: 337 per second. 0 failures detected.
13:57:55,901 User:System INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Processed 204957 entries out of 204957. 100% complete. Rate: 337 per second. 0 failures detected.
13:57:55,901 User:System INFO  [patch.impl.FixNameCrcValuesPatch$HibernateHelper] FixNameCrcValuesPatch: Completed batch of 204957 entries
13:57:56,022  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.zonedAuthorities' (Adds the remodelled cm:authority container to the spaces store).
13:57:56,563  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.redeploySubmitProcess5' (Re-deploy WCM Submit Process Definition.).
13:57:56,796  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.deploySubmitDirectProcess' (Deploy WCM Direct Submit Process Definition.).
13:57:56,891  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.resetWCMToGroupBasedPermissionsPatch' (Reset WCM to group based permissions.).
13:57:56,893 User:System INFO  [patch.impl.ResetWCMToGroupBasedPermissionsPatch] Retrieved list of 1 AVM store descriptors in 0 secs
13:57:56,895 User:System INFO  [patch.impl.ResetWCMToGroupBasedPermissionsPatch] Retrieved store types for 0 WCM stores in 0 secs
13:57:56,902  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.moveWCMToGroupBasedPermissionsPatch' (A placeholder patch; usually marks a superceded patch.).
13:57:56,911  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.wcmPostPermissionSnapshotPatch3' (Snapshot stores (after fixing ACLs so they are only set on the staging area store).).
13:57:57,162  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.wcmPostPermissionSnapshotPatch2' (A placeholder patch; usually marks a superceded patch.).
13:57:57,166  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.redeploySubmitProcess6' (Re-deploy WCM Submit Process Definition.).
13:57:57,475  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.redeploySubmitProcess7' (Re-deploy WCM Submit Process Definition.).
13:57:57,764  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.webSiteAddModerated' (Changing Web Site visibility from a boolean to enum.).
13:57:57,795  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.invitationMigration' (Migrate invitations from old invite service to invitation service).
13:57:57,823  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.mtShareExistingTenants' (Update existing tenants for MT Share.).
13:57:57,826  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.redeployInvitationProcess' (Re-deploy Invitation Process Definitions.).
13:57:57,982  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.authorityMigration' (Copies any old authorities from the user store to the spaces store.).
13:58:10,676 User:System INFO  [admin.patch.PatchExecuter] Authority Migration: Commencing batch of 17109 entries
13:58:12,705  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 100 entries out of 17109. 1% complete. Rate: 49 per second. 0 failures detected.
13:58:13,975  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 200 entries out of 17109. 1% complete. Rate: 60 per second. 0 failures detected.
13:58:15,289  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 300 entries out of 17109. 2% complete. Rate: 65 per second. 0 failures detected.
13:58:16,887  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 400 entries out of 17109. 2% complete. Rate: 64 per second. 0 failures detected.
13:58:18,156  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 500 entries out of 17109. 3% complete. Rate: 66 per second. 0 failures detected.
13:58:19,684  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 600 entries out of 17109. 4% complete. Rate: 66 per second. 0 failures detected.
13:58:21,289  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 700 entries out of 17109. 4% complete. Rate: 65 per second. 0 failures detected.
13:58:22,470  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 800 entries out of 17109. 5% complete. Rate: 67 per second. 0 failures detected.
…
14:03:44,723  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:03:45,195  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16200 entries out of 17109. 95% complete. Rate: 48 per second. 0 failures detected.
14:03:48,117  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16300 entries out of 17109. 95% complete. Rate: 48 per second. 0 failures detected.
14:03:48,330  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:03:50,973  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16400 entries out of 17109. 96% complete. Rate: 48 per second. 0 failures detected.
14:03:52,476  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16500 entries out of 17109. 96% complete. Rate: 48 per second. 0 failures detected.
14:03:52,982  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:03:55,834  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16600 entries out of 17109. 97% complete. Rate: 48 per second. 0 failures detected.
14:03:55,936  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:03:58,965  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16700 entries out of 17109. 98% complete. Rate: 47 per second. 0 failures detected.
14:04:02,661  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:04:04,275  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16800 entries out of 17109. 98% complete. Rate: 47 per second. 0 failures detected.
14:04:04,376  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:04:05,738  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:04:07,139  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 16900 entries out of 17109. 99% complete. Rate: 47 per second. 0 failures detected.
14:04:08,861  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 17000 entries out of 17109. 99% complete. Rate: 47 per second. 0 failures detected.
14:04:09,106  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:04:09,743  WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:04:18,458  INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 17100 entries out of 17109. 100% complete. Rate: 46 per second. 0 failures detected.
14:04:18,458 User:System INFO  [admin.patch.PatchExecuter] Authority Migration: Processed 17109 entries out of 17109. 100% complete. Rate: 46 per second. 0 failures detected.
14:04:18,458 User:System INFO  [admin.patch.PatchExecuter] Authority Migration: Completed batch of 17109 entries
14:04:18,543  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.authorityDefaultZonesPatch' (Adds groups and people to the appropriate zones for wcm, share and everything else.).
14:04:24,991 User:System INFO  [admin.patch.PatchExecuter] Adding users to zones …
14:04:44,844 User:System WARN  [org.alfresco.personTransactionalCache] Transactional update cache 'org.alfresco.personTransactionalCache' is full (1000).
14:04:57,167 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 10% complete, estimated complete at 5/12/10 2:10 PM.
14:05:27,542 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 20% complete, estimated complete at 5/12/10 2:10 PM.
14:05:58,132 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 30% complete, estimated complete at 5/12/10 2:09 PM.
14:06:27,646 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 40% complete, estimated complete at 5/12/10 2:09 PM.
14:06:38,513 User:System INFO  [admin.patch.PatchExecuter] Adding groups to zones …
14:06:41,118 User:System WARN  [org.alfresco.authorityTransactionalCache] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (100).
14:06:52,158 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 50% complete, estimated complete at 5/12/10 2:09 PM.
14:07:11,596 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 60% complete, estimated complete at 5/12/10 2:09 PM.
14:07:33,974 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.authorityDefaultZonesPatch 70% complete, estimated complete at 5/12/10 2:08 PM.
14:10:08,671  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.imapFolders' (Creates folders tree necessary for IMAP functionality).
14:10:38,611  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.personUsagePatch' (Add person 'cm:sizeCurrent' property (if missing).).
14:10:38,611 User:System INFO  [patch.impl.PersonUsagePatch] Checking for people with missing 'cm:sizeCurrent' property …
14:10:38,938 User:System INFO  [patch.impl.PersonUsagePatch] … no people were missing the 'cm:sizeCurrent' property
14:10:38,949  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.redeployNominatedInvitationProcessWithPropsForShare' (Redeploy nominated invitation workflow).
14:10:39,049  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.rendition.rendering_actions' (Creates the Rendering Actions folder.).
14:10:39,266  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.thumbnailsAssocQName' (Update the 'cm:thumbnails' association QName to 'rn:rendition'.).
14:10:39,271  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.emailInviteAndNotifyTemplatesFolder' (Ensures the existence of the 'Email Invite Templates' and 'Email Notify Templates' folders.).
14:10:39,513  INFO  [admin.patch.PatchExecuter]    Applying patch 'patch.convertContentUrls' (Converts pre-3.2 content URLs to use the alf_content_data table.  The conversion work can also be done on a schedule; please contact Alfresco Support for further details.).
14:10:39,526 User:System INFO  [admin.patch.PatchExecuter] Content URL conversion progress:
14:10:39,527 User:System INFO  [admin.patch.PatchExecuter]    Processing ADM Content URLs.
14:10:59,927 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 10% complete, estimated complete at 5/12/10 2:14 PM.
### Excluding compile: org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger::mergeIndexes
14:11:54,085 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 20% complete, estimated complete at 5/12/10 2:16 PM.
14:12:56,154 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 30% complete, estimated complete at 5/12/10 2:18 PM.
14:13:29,047 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 40% complete, estimated complete at 5/12/10 2:17 PM.
14:13:57,375 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 50% complete, estimated complete at 5/12/10 2:17 PM.
14:14:33,224 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 60% complete, estimated complete at 5/12/10 2:17 PM.
14:15:09,746 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 70% complete, estimated complete at 5/12/10 2:17 PM.
14:15:55,998 User:System INFO  [admin.patch.PatchExecuter]       Patch patch.convertContentUrls 80% complete, estimated complete at 5/12/10 2:17 PM.
14:17:22,552 User:System INFO  [admin.patch.PatchExecuter]    Finished processing ADM nodes up to ID 3,386,226.
14:17:22,670 User:System INFO  [admin.patch.PatchExecuter]    Processing AVM Content URLs.
14:17:23,084 User:System INFO  [admin.patch.PatchExecuter]    Finished processing AVM nodes up to ID 3.
14:17:23,221 User:System INFO  [admin.patch.PatchExecuter]    Reading content URLs from store FileContentStore[ root=/opt/alfresco_api/alf_data/contentstore, allowRandomAccess=true, readOnly=false].
14:18:11,429 User:System INFO  [admin.patch.PatchExecuter]       Processed 500 content URLs from store.
14:18:12,232 User:System INFO  [admin.patch.PatchExecuter]       Processed 1,000 content URLs from store.
14:18:13,127 User:System INFO  [admin.patch.PatchExecuter]       Processed 1,500 content URLs from store.
14:18:14,147 User:System INFO  [admin.patch.PatchExecuter]       Processed 2,000 content URLs from store.
14:18:15,218 User:System INFO  [admin.patch.PatchExecuter]       Processed 2,500 content URLs from store.
14:18:16,493 User:System INFO  [admin.patch.PatchExecuter]       Processed 3,000 content URLs from store.
14:18:17,751 User:System INFO  [admin.patch.PatchExecuter]       Processed 3,500 content URLs from store.
…
14:32:56,945 User:System INFO  [admin.patch.PatchExecuter]       Processed 34,000 content URLs from store.
14:33:25,731 User:System INFO  [admin.patch.PatchExecuter]       Processed 34,500 content URLs from store.
14:33:54,770 User:System INFO  [admin.patch.PatchExecuter]       Processed 35,000 content URLs from store.
14:34:24,342 User:System INFO  [admin.patch.PatchExecuter]       Processed 35,500 content URLs from store.
14:34:54,196 User:System INFO  [admin.patch.PatchExecuter]       Processed 36,000 content URLs from store.
14:35:24,437 User:System INFO  [admin.patch.PatchExecuter]       Processed 36,500 content URLs from store.
14:39:23,399 User:System INFO  [admin.patch.PatchExecuter]       Processed 500 content URLs from store.
14:39:24,278 User:System INFO  [admin.patch.PatchExecuter]       Processed 1,000 content URLs from store.
14:39:25,268 User:System INFO  [admin.patch.PatchExecuter]       Processed 1,500 content URLs from store.
14:39:26,363 User:System INFO  [admin.patch.PatchExecuter]       Processed 2,000 content URLs from store.
14:39:27,607 User:System INFO  [admin.patch.PatchExecuter]       Processed 2,500 content URLs from store.
14:39:29,031 User:System INFO  [admin.patch.PatchExecuter]       Processed 3,000 content URLs from store.
…
14:52:14,864 User:System INFO  [admin.patch.PatchExecuter]       Processed 30,000 content URLs from store.
14:52:41,225 User:System INFO  [admin.patch.PatchExecuter]       Processed 30,500 content URLs from store.
14:53:07,773 User:System INFO  [admin.patch.PatchExecuter]       Processed 31,000 content URLs from store.
14:53:34,747 User:System INFO  [admin.patch.PatchExecuter]       Processed 31,500 content URLs from store.
14:54:02,045 User:System INFO  [admin.patch.PatchExecuter]       Processed 32,000 content URLs from store.
…
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[luca]

I found what was causing all the troubles!

You have to increase this value:
-> max_locks_per_transaction <-

We are using Postgres 8.1 and the patch ContentUrlConverter had to write about 45000 records on alf_content_url but at about 35500 record it run out of locks and it gave me this error:

org.springframework.dao.DataAccessResourceFailureException: SqlMapClient operation; SQL [];   
— The error occurred in alfresco/ibatis/#resource.dialect#/content-insert-SqlMap.xml.  
— The error occurred while applying a parameter map.  
— Check the alfresco.content.insert_ContentUrl-InlineParameterMap.  
— Check the statement (update failed).  
— Cause: org.postgresql.util.PSQLException: ERROR: out of shared memory; nested exception is com.ibatis.common.jdbc.exception.NestedSQLException:   
— The error occurred in alfresco/ibatis/#resource.dialect#/content-insert-SqlMap.xml.  
— The error occurred while applying a parameter map.  
— Check the alfresco.content.insert_ContentUrl-InlineParameterMap.  
— Check the statement (update failed).  
— Cause: org.postgresql.util.PSQLException: ERROR: out of shared memory
‍‍‍‍‍‍‍‍‍‍‍‍‍

I want to poin out that Alfresco doesn't log it and simply restart to cycle in the contentstore from the beginning again and this is not the behaviour that I was expecting!!  :evil:

I had to go in debugging mode to found it and replycating this took an entire day, I hope this could be usefull for others that run in this issue.

[louise]

Same effect with 4.0.d…

Just try to increase "max_locks_per_transaction" to "128" in file "/opt/alfresco/alf_data/postgresql/postgresql.conf" …