Error on intialize: 3002 could not be found in the filesystem attachment store

Brand new instance/install/database running 11.2…I get to Step 2 in the initialization where I install the standard flavor and I get an error that says “failed to retrieve extension data”. When I look at catalina.out I see the following:

2019-04-03 16:19:05,628 [XWiki Solr index thread] ERROR ttachmentSolrMetadataExtractor - Failed to retrieve the content of attachment [Attachment xwiki:XWiki.Notifications.MailTemplate@NEWiki.png]
com.xpn.xwiki.XWikiException: Error number 3002 in 3: The attachment [/var/lib/xwiki/data/store/file/xwiki/5/4/8461a18320e9f8764e4858557cd5ed/attachments/b/a/69c9363e66952675742956ae1ee91f/f.png] could not be found in the filesystem attachment store.
        at org.xwiki.store.legacy.store.internal.FilesystemAttachmentStore.loadAttachmentContent(FilesystemAttachmentStore.java:214)
        at com.xpn.xwiki.doc.XWikiAttachment.loadAttachmentContent(XWikiAttachment.java:1073)
        at com.xpn.xwiki.doc.XWikiAttachment.reloadAttachmentContent(XWikiAttachment.java:893)
        at com.xpn.xwiki.doc.XWikiAttachment.getContentInputStream(XWikiAttachment.java:871)
        at org.xwiki.search.solr.internal.metadata.AbstractSolrMetadataExtractor.getContentAsText(AbstractSolrMetadataExtractor.java:506)
        at org.xwiki.search.solr.internal.metadata.AttachmentSolrMetadataExtractor.setLocaleAndContentFields(AttachmentSolrMetadataExtractor.java:111)
        at org.xwiki.search.solr.internal.metadata.AttachmentSolrMetadataExtractor.setFieldsInternal(AttachmentSolrMetadataExtractor.java:93)
        at org.xwiki.search.solr.internal.metadata.AbstractSolrMetadataExtractor.getSolrDocument(AbstractSolrMetadataExtractor.java:133)
        at org.xwiki.search.solr.internal.DefaultSolrIndexer.getSolrDocument(DefaultSolrIndexer.java:504)
        at org.xwiki.search.solr.internal.DefaultSolrIndexer.processBatch(DefaultSolrIndexer.java:411)
        at org.xwiki.search.solr.internal.DefaultSolrIndexer.run(DefaultSolrIndexer.java:377)
        at java.lang.Thread.run(Thread.java:748)

Pretty sure I shouldnt be getting errors like this on a fresh install when this is the first time im running the initialization. Any ideas?

This seems to suggest it’s maybe not a brand new install as it’s finding some pages with an attachment called f.png which is not present in the filesystem attachment store. I doubt that this f.png attachment is brought by the XWiki Standard Flavor.

Could it be that the DB is not brand new and contains data?

The instance xwiki is running on is brand new…xwiki is installed and configured using Packer and then an auto scaling group spins up an instance using that new ami. The database is new also but the initializaion has not completed successfully yet since I’ve started this. Are you saying that data could be in the database from previous failed initializations and needs to be dumped?

I’m just saying that the DB could contain documents and attachments and you could have kept the DB but without keeping the xwiki permanent directory where the attachment file is located, hence the warning in the logs (it’s just a warning - it says errors because it cannot index the attachment but it won’t make xwiki fail). If you click in the attachment in the UI though, it’ll not work of course.

I dropped the xwiki database and spun up a new instance so there is zero chance there is “old” data in there…now when I get to the initialization step of installing the standard flavor I get a little red box that pops up and says Failed to receive extension data. Server is not responding.

I look at the catalina.out file and i see the following as the latest entries…

03-Apr-2019 17:57:14.907 WARNING [main] org.apache.catalina.startup.ClassLoaderFactory.validateFile Problem with directory [/usr/share/tomcat8/shared], exists: [false], isDirectory: [false], canRead: [false]
03-Apr-2019 17:57:16.637 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.5.30 (Ubuntu)
03-Apr-2019 17:57:16.637 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Aug 13 2018 20:23:56 UTC
03-Apr-2019 17:57:16.637 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.30.0
03-Apr-2019 17:57:16.637 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
03-Apr-2019 17:57:16.637 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            4.15.0-1035-aws
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/lib/jvm/java-8-openjdk-amd64/jre
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_191-8u191-b12-2ubuntu0.18.04.1-b12
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /var/lib/tomcat8
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/share/tomcat8
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/var/lib/tomcat8/conf/logging.properties
03-Apr-2019 17:57:16.638 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=true
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx1024m
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/var/lib/tomcat8
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/share/tomcat8
03-Apr-2019 17:57:16.639 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/tmp/tomcat8-tomcat8-tmp
03-Apr-2019 17:57:16.640 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR based Apache Tomcat Native library [1.2.16] using APR version [1.6.3].
03-Apr-2019 17:57:16.640 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
03-Apr-2019 17:57:16.640 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
03-Apr-2019 17:57:16.643 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.0g  2 Nov 2017]
03-Apr-2019 17:57:17.252 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
03-Apr-2019 17:57:17.320 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
03-Apr-2019 17:57:17.981 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 2964 ms
03-Apr-2019 17:57:18.055 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
03-Apr-2019 17:57:18.055 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.30 (Ubuntu)
03-Apr-2019 17:57:18.104 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor [/etc/tomcat8/Catalina/localhost/xwiki.xml]
2019-04-03 17:57:46,302 [localhost-startStop-1] INFO  iPropertiesConfigurationSource - loading xwiki.properties from default location /etc/xwiki/xwiki.properties
2019-04-03 17:57:46,645 [localhost-startStop-1] INFO  o.x.e.i.ServletEnvironment     - Using permanent directory [/var/lib/xwiki/data]
2019-04-03 17:57:58,073 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolrInstance - Starting embedded Solr server...
2019-04-03 17:57:58,078 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolrInstance - Using Solr home directory: [/var/lib/xwiki/data/solr]
2019-04-03 17:58:01,774 [coreLoadExecutor-6-thread-1] WARN  o.a.s.c.SolrResourceLoader     - Solr loaded a deprecated plugin/analysis class [solr.SynonymFilterFactory]. Please consult documentation how to replace it accordingly.
2019-04-03 17:58:05,505 [localhost-startStop-1] INFO  o.x.s.s.i.EmbeddedSolrInstance - Started embedded Solr server.
03-Apr-2019 17:58:07.421 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor [/etc/tomcat8/Catalina/localhost/xwiki.xml] has finished in [49,317] ms
03-Apr-2019 17:58:07.422 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/var/lib/tomcat8/webapps/ROOT]
03-Apr-2019 17:58:08.208 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
03-Apr-2019 17:58:08.212 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcat8/webapps/ROOT] has finished in [789] ms
03-Apr-2019 17:58:08.215 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
03-Apr-2019 17:58:08.247 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 50265 ms
2019-04-03 18:02:05,467 [XWiki initialization] INFO  .HibernateDataMigrationManager - Checking Hibernate mapping and updating schema if needed for wiki [xwiki]
2019-04-03 18:02:08,106 [XWiki initialization] INFO  .HibernateDataMigrationManager - Storage schema updates and data migrations are enabled
2019-04-03 18:02:08,424 [XWiki initialization] INFO  .HibernateDataMigrationManager - No data migration to apply for wiki [xwiki] currently in version [1100000]
2019-04-03 18:02:08,424 [XWiki initialization] INFO  .HibernateDataMigrationManager - Checking Hibernate mapping and updating schema if needed for wiki [xwiki]
2019-04-03 18:02:14,872 [XWiki initialization] INFO  ationFilterPreferencesMigrator - Wiki [xwiki] has already been migrated.
2019-04-03 18:02:14,924 [org.xwiki.search.solr.internal.job.IndexerJob@f8d7e09([solr, indexer])] INFO  o.x.s.s.i.j.IndexerJob         - Starting job of type [solr.indexer] with identifier [[solr, indexer]]
2019-04-03 18:02:15,099 [org.xwiki.search.solr.internal.job.IndexerJob@f8d7e09([solr, indexer])] INFO  o.x.s.s.i.j.IndexerJob         - 0 documents added, 0 deleted and 0 updated during the synchronization of the Solr index.
2019-04-03 18:02:15,099 [org.xwiki.search.solr.internal.job.IndexerJob@f8d7e09([solr, indexer])] INFO  o.x.s.s.i.j.IndexerJob         - Finished job of type [solr.indexer] with identifier [[solr, indexer]]

Are other people automating the setup and install of xwiki?

This looks good except. Your wiki is empty so you should get the Distribution Wizard starting on the first run.

More than 50% do… using either debian apt installation (apt upgrade to upgrade) or the docker image.

See the distributions on https://www.xwiki.org/xwiki/bin/view/ActiveInstalls/ for more accurate data!

OK…finally figured out what was going on. I have no idea how this happened on a brand new instance with a fresh new empty database…but what I figured out was that when I terminated my existing/known good working instance the ASG would spin up another one and my restore script that kicks off on startup was not copying the files into the exact right spot on the instance…specifically to here…/var/lib/xwiki/data/store/file/xwiki/5/4/8461a18320e9f8764e4858557cd5ed/attachments/b/a/69c9363e66952675742956ae1ee91f/ Once I figured that out I can kick over my instance all day long and it will come back and be restored reliably now.
So if you are looking for a simple backup and restore script to use with an S3 bucket in AWS here is what I did:

Be aware that I use Terraform to create some of the background stuff like the /backups dir in my bucket.

BACKUP.sh

#!/bin/bash

S3BUCKET=NAME_OF_YOUR_BUCKET

TARDATE=$(date '+%Y-%m-%d-%s')
cd /workingdir
rm -rf *.gz
rm -rf TARDATE

touch TARDATE
echo $TARDATE >> TARDATE

#Tar dirs to be backed up
tar -P -zcvf Xwiki-PERM-${TARDATE}.tar.gz /var/lib/xwiki/data
tar -P -zcvf Xwiki-ETC-${TARDATE}.tar.gz /etc/xwiki
tar -P -zcvf NGINX-${TARDATE}.tar.gz /etc/nginx
tar -P -zcvf TOMCAT-${TARDATE}.tar.gz /etc/tomcat8

#Copy tar files to S3 bucket
sudo aws s3 cp Xwiki-PERM-${TARDATE}.tar.gz s3://$S3BUCKET/backups/
sudo aws s3 cp Xwiki-ETC-${TARDATE}.tar.gz s3://$S3BUCKET/backups/
sudo aws s3 cp NGINX-${TARDATE}.tar.gz s3://$S3BUCKET/backups/
sudo aws s3 cp TOMCAT-${TARDATE}.tar.gz s3://$S3BUCKET/backups/
sudo aws s3 cp TARDATE s3://$S3BUCKET/backups/TARDATE

exit 0

RESTORE.sh

#!/bin/bash

S3BUCKET=NAME_OF_YOUR_BUCKET

cd /workingdir
sudo service nginx stop
sudo service tomcat8 stop

sudo aws s3 cp s3://${S3BUCKET}/backups/TARDATE TARDATE
TARDATE=$(<TARDATE)
echo $TARDATE

sudo aws s3 cp s3://${S3BUCKET}/backups/Xwiki-ETC-${TARDATE}.tar.gz .
sudo aws s3 cp s3://${S3BUCKET}/backups/Xwiki-PERM-${TARDATE}.tar.gz .
sudo aws s3 cp s3://${S3BUCKET}/backups/NGINX-${TARDATE}.tar.gz .
sudo aws s3 cp s3://${S3BUCKET}/backups/TOMCAT-${TARDATE}.tar.gz .


sudo tar -zxvf Xwiki-ETC-${TARDATE}.tar.gz -C /.    #/etc/xwiki/
sudo tar -zxvf Xwiki-PERM-${TARDATE}.tar.gz -C /.    #/var/lib/xwiki/data/
sudo tar -zxvf NGINX-${TARDATE}.tar.gz -C /.    #/etc/nginx/
sudo tar -zxvf TOMCAT-${TARDATE}.tar.gz -C /.    #/etc/tomcat8/

exit 0

Script that User_data runs on instance startup:

#!/bin/bash -x

cd /workingdir

echo 'Stop tomcat and nginx'
service tomcat8 stop
service nginx stop

#Here im setting the DBPassword in my hibernate.cfg.xml file. 
#We use param store for the password which Terraform puts in there. 
#The actual line in my hibernate file looks like this:  
#<property name="connection.password">DBPASSWORD</property>

echo 'Setting DB_PASSWORD'
DBPASSWORD=$(aws ssm get-parameters --region us-west-1 --names rds-secret --with-decryption --query "Parameters[*].{Value:Value}" --output text)

echo 'Setting DB_PASSWORD in hibernate...'
if [[ -e "$1/etc/xwiki/hibernate.cfg.xml" ]]; then
    sed -i "s|DBPASSWORD|$DBPASSWORD|g" /etc/xwiki/hibernate.cfg.xml
else
    echo "/etc/xwiki/hibernate.cfg.xml not found" >&2
    exit 100
fi

echo 'Restore in progress...'
if [[ -e "$1/workingdir/xwiki-restore.sh" ]]; then
    /workingdir/xwiki-restore.sh && wait
else
    echo "/workingdir/xwiki-restore.sh not found" >&2
    exit 100
fi

sleep 60

echo 'Starting tomcat and nginx'
service tomcat8 start
service nginx start

echo 'done'

exit 0

Thanks for posting this @sfloydt65 !

And glad you found the problem :slight_smile:

I am facing the same errors but I was not starting from the blank DDB instance.
image
I see this in the attachment, and I cannot remove them. Why is that?

Cheers.

@moscardo The screenshot and message looks similar to this issue https://jira.xwiki.org/browse/XWIKI-10234 but it’s supposed to be fixed in 10.11+ versions. But we would need more details (steps to reproduce, version, etc.) in order to identify if there are still issues.

I am not sure I can reproduce it or give you the necessary steps…
I am running 10.11.8

What I remember is deploying the service, doing a backup and re deploying it again and importing those pages that I had before (but maybe not all of them)

Cheers.