Problemas en indices continuados en Alfresco Community 4.2

[NachoJimenez]

Hace unas semanas hicimos un cambio de servidor, por una cuestión de espacio para los datos. Junto con el cambio de servidor, cambiamos igualmente la ubicación del “alfresco_data”. Todo aparentemente iba bien, excepto que en el reinicio nos aparecieron unos warn:

2020-07-26 17:55:56,733  WARN  [cache.node.aspectsTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.aspectsTransactionalCache' is full (65000).

2020-07-26 17:55:56,799  WARN  [cache.node.propertiesTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.propertiesTransactionalCache' is full (65000).

2020-07-26 17:57:00,375  WARN  [cache.node.nodesTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.nodesTransactionalCache' is full (250000).

Sea como fuere, el sistema funcionaba y no prestamos mucha atención a estos WARN. He de decir que ya antes había algunos problemas con los índices (el gestor documental que tenemos por encima de Alfresco daba de vez en cuando algún error indicando que se estaba intentando guardar en una carpeta que no existía, aunque al final los documentos se iban guardando correctamente.)

El viernes pasado de pronto Alfresco cayó, y dejó de funcionar, dando continuamente errores de índices. Estuve todo el fin de semana intentando hacer una reindexación FULL, y aunque no lo conseguía, al final lo conseguí incrementando los parámetros

cache.node.nodesSharedCache.tx.maxItems=250000 (este lo cambié a 500000)

cache.node.nodesSharedCache.maxItems=2500000 (este lo cambie a 5000000)

Pero tras reindexar correctamente, no arrancaba el tomcat de Alfresco, tras lo que volví a dejar los parámetros a los valores anteriores arriba indicados (250000 y 2500000). En esta ocasión el Alfresco arrancó únicamente dando los WARN que te comenté al principio.

Vuelve a funcionar aparentemente bien, pero siguen apareciendo muchos errores en los logs de Alfresco, incluso hice una ultima prueba incrementando el parámetro cache.node.nodesSharedCache.tx.maxItems a 350000, pero lo único que ha cambiado es el WARN que da al arrancar, que ahora es:

2020-07-26 17:57:00,375  WARN  [cache.node.nodesTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.nodesTransactionalCache' is full (350000)

Y bueno, aunque parece funcionar, siguen apareciendo muchos errores, como éstos:

. 2020-07-27 09:17:24,881  WARN  [content.metadata.AbstractMappingMetadataExtracter] [http-bio-8080-exec-4] Metadata extraction failed (turn on DEBUG for full error):

   Extracter: org.alfresco.repo.content.metadata.TikaAutoMetadataExtracter@30264d47

   Content:   ContentAccessor[ contentUrl=store://2020/7/27/9/17/ce4ae26a-2d54-485b-919f-59c853b9bec2.bin, mimetype=application/pkcs7-signature, size=6078, encoding=UTF-8, locale=es_ES]

   Failure:   cannot parse detached pkcs7 signature (no signed data to parse)null

2020-07-27 09:20:31,539  WARN  [content.metadata.AbstractMappingMetadataExtracter] [http-bio-8080-exec-37] Metadata extraction failed (turn on DEBUG for full error):

   Extracter: org.alfresco.repo.content.metadata.TikaAutoMetadataExtracter@30264d47

   Content:   ContentAccessor[ contentUrl=store://2020/7/27/9/20/298564b5-c5ab-43e6-a03c-646c34b274fc.bin, mimetype=application/pkcs7-signature, size=6078, encoding=UTF-8, locale=es_ES]

   Failure:   cannot parse detached pkcs7 signature (no signed data to parse)null

Por ejemplo, o este es otro que aparece a menudo:

jul 27, 2020 9:13:13 AM org.apache.catalina.core.StandardWrapperValve invoke

GRAVE: Servlet.service() para servlet cmisatom10 lanzó excepción

java.lang.IllegalStateException: Current state = FLUSHED, new state = CODING_END

        at java.nio.charset.CharsetDecoder.throwIllegalStateException(CharsetDecoder.java:968)

        at java.nio.charset.CharsetDecoder.decode(CharsetDecoder.java:554)

        at java.nio.charset.CharsetDecoder.decode(CharsetDecoder.java:783)

        at org.alfresco.repo.webdav.auth.AuthenticationFilter.doFilter(AuthenticationFilter.java:139)

        at sun.reflect.GeneratedMethodAccessor468.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

        at java.lang.reflect.Method.invoke(Method.java:606)

        at org.alfresco.repo.management.subsystems.ChainingSubsystemProxyFactory$1.invoke(ChainingSubsystemProxyFactory.java:125)

        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

        at com.sun.proxy.$Proxy291.doFilter(Unknown Source)

        at org.alfresco.repo.web.filter.beans.BeanProxyFilter.doFilter(BeanProxyFilter.java:82)

        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

        at org.alfresco.web.app.servlet.CmisSecurityContextCleanerFilter.doFilter(CmisSecurityContextCleanerFilter.java:49)

        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

        at org.alfresco.web.app.servlet.GlobalLocalizationFilter.doFilter(GlobalLocalizationFilter.java:61)

        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)

        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)

        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)

        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)

        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)

        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)

        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)

        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)

        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)

        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)

        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

        at java.lang.Thread.run(Thread.java:745)

También aparece este tipo de error, pero este aparecía ya antes de la reindexación, y ahora vuelve a aparecer:

2020-07-27 11:17:48,560  WARN  [lucene.index.IndexInfo] [indexThread7] Index merger failed with
 java.io.IOException: read past EOF
        at org.apache.lucene.store.BufferedIndexInput.refill(BufferedIndexInput.java:151)
        at org.apache.lucene.store.BufferedIndexInput.readByte(BufferedIndexInput.java:38)
        at org.apache.lucene.store.IndexInput.readVInt(IndexInput.java:78)
        at org.apache.lucene.index.SegmentTermDocs.next(SegmentTermDocs.java:110)
        at org.apache.lucene.index.SegmentTermPositions.next(SegmentTermPositions.java:98)
        at org.apache.lucene.index.SegmentMerger.appendPostings(SegmentMerger.java:634)
        at org.apache.lucene.index.SegmentMerger.mergeTermInfo(SegmentMerger.java:586)
        at org.apache.lucene.index.SegmentMerger.mergeTermInfos(SegmentMerger.java:547)
        at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:500)
        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:140)
        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:116)
        at org.apache.lucene.index.IndexWriter.addIndexes(IndexWriter.java:3220)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger.mergeIndexes(IndexInfo.java:4276)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger.runImpl(IndexInfo.java:3579)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$AbstractSchedulable.run(IndexInfo.java:3428)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2020-07-27 11:17:48,577  WARN  [lucene.index.IndexInfo] [indexThread7] Index merger recovered from
 java.io.IOException: read past EOF
        at org.apache.lucene.store.BufferedIndexInput.refill(BufferedIndexInput.java:151)
        at org.apache.lucene.store.BufferedIndexInput.readByte(BufferedIndexInput.java:38)
        at org.apache.lucene.store.IndexInput.readVInt(IndexInput.java:78)
        at org.apache.lucene.index.SegmentTermDocs.next(SegmentTermDocs.java:110)
        at org.apache.lucene.index.SegmentTermPositions.next(SegmentTermPositions.java:98)
        at org.apache.lucene.index.SegmentMerger.appendPostings(SegmentMerger.java:634)
        at org.apache.lucene.index.SegmentMerger.mergeTermInfo(SegmentMerger.java:586)
        at org.apache.lucene.index.SegmentMerger.mergeTermInfos(SegmentMerger.java:547)
        at org.apache.lucene.index.SegmentMerger.mergeTerms(SegmentMerger.java:500)
        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:140)
        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:116)
        at org.apache.lucene.index.IndexWriter.addIndexes(IndexWriter.java:3220)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger.mergeIndexes(IndexInfo.java:4276)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger.runImpl(IndexInfo.java:3579)
        at org.alfresco.repo.search.impl.lucene.index.IndexInfo$AbstractSchedulable.run(IndexInfo.java:3428)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)

Así que temo que vuelva a caer en breve nuestro Alfresco.

¿Creeis que debería incrementar aún más el valor del parámetro?
¿Puede ser ese el problema, o puede que falte añadir algún parámetro más?

Gracias por anticipado

[angelborroy]

¿Estáis usando Lucene o SOLR para indexar?

[NachoJimenez]

Gracias por la rápida respuesta.

Estamos usando Lucene

[angelborroy]

Como primera medida, trataría de actualizar a SOLR:

https://hub.alfresco.com/t5/alfresco-content-services-hub/community-file-list-4-2-f/ba-p/289696

Eso solucionaría (espero) los problemas de actualización del índice.

En relación a los otros problemas, son "normales". Quiero decir, se está re-indexando todo el repositorio, por lo que se usan transacciones muy grandes para llevar todo los metadatos desde Alfresco a Lucene. Puedes incrementar los límites para facilitar el trabajo y volver a establecerlos por defecto una vez la indexación haya terminado.