Alfresco y el extraño caso del PDF asesino

por / Jueves, 21 Diciembre 2017 / Publicado enBlog
Un breve resumen de Alfresco DevCon 2018
Xenit actualiza su cliente de escritorio para Windows Alfred Desktop

Todo comenzó algún tiempo atrás, cuando el administrador de la máquina (al que llamaremos devops) comprobó que Alfresco había dejado de dar servicio porque el proceso Java del repositorio estaba consumiendo el 200% de las CPUs de la máquina. Esta situación se producía de manera puntual y tras unos minutos el sistema volvía a dar servicio.

Durante una de aquellas crisis el devops generó un Thread Dump de diagnóstico.

$ kill -3 25041

$ tail -f -n 10000 /opt/alfresco/tomcat/logs/catalina.out

java.lang.Thread.State: RUNNABLE
at org.apache.pdfbox.pdmodel.common.PDStream.getFilters(PDStream.java:303)
at org.apache.pdfbox.pdmodel.graphics.xobject.PDXObject.commonXObjectCreation(PDXObject.java:152)
at org.apache.pdfbox.pdmodel.graphics.xobject.PDXObject.createXObject(PDXObject.java:122)
at org.apache.pdfbox.pdmodel.PDResources.getXObjects(PDResources.java:257)
at org.apache.tika.parser.pdf.PDF2XHTML.extractImages(PDF2XHTML.java:286)

Aparentemente había varios procesos Java basados en PDFBox que estaban extrayendo contenido de ficheros PDF, lo que tenía sentido en el escenario provocado tras la migración de varios GiBs al repositorio. El motor de indexación SOLR estaba todavía digiriendo aquella ingesta masiva de información. Para paliar el problema, nuestro devops duplicó el número de CPUs y observó que el proceso Java pasaba a consumir… ¡el 400%!

Como SOLR estaba pidiendo a Alfresco que indexase los nodos pendientes cada 15 segundos y en cada petición Alfresco estaba tratando de extraer el texto e imágenes de todos los documentos PDF asociados a una transacción para enviarlo a SOLR, el sistema se estaba colapsando. Para garantizar el servicio mientras el sistema terminase la tarea, el devops ideó la siguiente estrategia:

  • Bajar momentáneamente la periodicidad del indexador de SOLR para ejecutarlo cada 1 hora
  • Bajar momentáneamente el número de hilos de indexación a 1
$ vi /opt/alfresco/solr4/workspace-SpacesStore/conf/solrcore.properties

alfresco.cron=0 0 * * * ? *
alfresco.corePoolSize=1
alfresco.workQueueSize=10

Sin embargo, a pesar de que el sistema aguantaba mejor en pie, el problema del 400% seguía persistiendo.

Nuestro devops se dispuso a analizar problemas en los índices de SOLR…

https://localhost:8443/solr4/alfresco/afts?q=DOC_TYPE:UnindexedNode
https://localhost:8443/solr4/alfresco/afts?q=DOC_TYPE:ErrorNode

… y descubrió unos 100,000 nodos sin indexar.

Para acceder a uno de esos nodos, dado que no estaba indexado, el devops buscó directamente en la base de datos.

select *
from alf_node, alf_node_properties
where alf_node.id = alf_node_properties.node_id and
alf_node.id = 2685025;

Y vio que había muchos documentos PDF que, en efecto, no estaban siendo indexados.

Se aseguró de que SOLR los estaba dando por perdidos, para poder centrar la identificación del problema únicamente en documentos PDF que fuesen incorporados a Alfresco.

$ tail -f /opt/alfresco/tomcat/logs/localhost_access_log.txt

192.168.30.5 - - [13/Dec/2017:00:00:03 +0100] "GET /alfresco/service/api/solr/transactions?fromCommitTime=1513123178428&
toCommitTime=1513126778428&maxResults=2000&baseUrl=%2Fsolr4%2Falfresco%2F
&hostName=localhost&template=&instance=0&numberOfShards=1&port=8080
&stores=workspace%3A%2F%2FSpacesStore&isMaster=true&hasContent=true&shardMethod=MOD_ACL_ID
&lastUpdated=1513119602928&lastIndexedChangeSetCommitTime=1512991654833
&lastIndexedChangeSetId=1279059&lastIndexedTxCommitTime=1513115926431
&lastIndexedTxId=2181672 HTTP/1.1" 200 120

$ psql -U postgres
# \c alfresco
# select max(id) from alf_transaction;
max
---------
2181672
(1 row)

Y aunque se decidió a activar las trazas de depuración Log4J del indexador de SOLR en Alfresco (NodeContentGet.java) vio que no había mensajes que pudiesen ayudarle en ese código fuente.

Sin perder el ánimo, desarrolló un overwriting de la clase para incorporar los detalles que necesitaba.

<beans>
   <bean id="webscript.org.alfresco.repository.solr.nodeContent.get"
         class="es.keensoft.solr.client.NodeContentGet"
         parent="webscript">
      <property name="contentService" ref="contentService"/>
      <property name="nodeService" ref="nodeService"/>
      <property name="permissionService" ref="permissionService"/>
      <property name="nodeDAO" ref="nodeDAO"/>
      <property name="transformerDebug" ref="transformerDebug" />
      <property name="delegate" ref="webscript.content.streamer" />
   </bean>
</beans>

Aquellas trazas detalladas le hicieron entender que había muchos documentos que estaban tratando de ser indexados en varias ocasiones por PDFBox pero que acaparaban la máquina durante varios minutos.

Descargando uno de esos documentos, logró reproducir la misma situación en su servidor de pruebas. Y después incluso aisló ese comportamiento en un programa de pruebas standalone.

Para mitigar el problema durante el tiempo que se tardaba en resolverlo, creó una regla en la carpeta de entrada para que todos los documentos PDF fuesen marcados con un aspecto que impide que su contenido sea indexado.

var props = new Array(); 
props["cm:isContentIndexed"] = false; 
document.addAspect("cm:indexControl", props);

Comenzó a investigar el problema de los misteriosos PDF, pero sus características no parecían indicar nada especial.

Producer TCPDF 6.2.5 (http://www.tcpdf.org/)
CreationDate Thu Oct 26 18:54:00 2017
ModDate Thu Oct 26 18:54:00 2017
Tagged no
UserProperties no
Suspects no
Form none
JavaScript no
Pages 7
Encrypted no
Page size 595 x 842 pts (A4)
Page rot 0
File size 2025590 bytes
Optimized no
PDF version 1.5

Los indicios apuntaban a un error de PDFBox o Tika, ya que ambos productos son parcheados por Alfresco y se utiliza una versión antigua. Sin embargo, las nuevas versiones de ambos no son compatibles con Alfresco por lo que no podían ser utilizadas. Al poder reproducir el error en un programa standalone, se dio cuenta de que el problema era una incidencia de Tika al parsear imágenes. Se producía una recursividad infinita, parecida a TIKA-1742

La solución, basada en el propio código fuente de la última versión de Tika (PDF2XHTML.java#L170) permitía solventar el problema en las pruebas locales. Así que el devops se decidió a empaquetarlo para poder desplegarlo en Alfresco y… ¡el problema desapareció!

Pensó que no debía ser un problema tan raro, así que acudió al IRC de Alfresco para contrastar con los desarrolladores expertos su opinión. Y fue allí cuando se convenció de que, en efecto, aquella era la primera vez que la Comunidad de Alfresco se enfrentaba a un problema similar.

Para que otros devops de Alfresco alrededor del mundo no sufrieran el mismo calvario que había padecido él, decidió dar de alta la incidencia y publicar la resolución:

Dando así por cerrado uno de los problemas más extraños a los que se había enfrentado.

Trabajar con productos Open Source siempre compensa y si no lo creéis, preguntádselo a nuestro “devops”

Responsable tecnológico para soluciones de gestión documental en keensoft. Especialista en Alfresco y en implantaciones de Administración Electrónica.

Etiquetado bajo: ,

Deja un comentario

SUBIR