PathNotFoundException on nodes below root

[ericasmith]

Hi everyone,

I have a rather bizarre situation, which has now happened to me twice in the past two months (so alas I can no longer just dismiss it as a fluke).

I am running ModeShape 2.8.1.Final in JBoss AS6, using the standard JBoss AS deployment instructions and storing out to a Postgres database. What happens is this:

My code seems to run correctly for some time, adding items to the repository and updating them, but after some time (often several weeks of healthy running in a developer environment) the repository seems to become corrupt. Some records can still be updated, others silently fail on save (the save code returns without exception or error log, but the next time I try to retrieve that record none of the changes have been persisted).

The most alarming symptom though, is that I completely loose the ability to append new nodes of a particular type to the root node. I stepped through the ModeShape code for this scenario quite closely, and can provide the following details:

The save call has the following requests in it, bundled into a composite request (lines have been trimmed and element names have been changed by hand):

create '/{http://mydomain.com/inf}elGroup'

update '/{http://mydomain.com/inf}elGroup[17]' [{http://www.modeshape.org/1.0}uuid = 0daf3c2b-7491-41e2-91c2-e7f62a387903]

create '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents'

set '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents' [{http://www.modeshape.org/1.0}uuid = 700bc5c8-718a-460b-a229-c9b3bb5f3c93]

create '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents/{http://mydomain.com/inf}contents'

create '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents/{http://mydomain.com/inf}contents/{http://mydomain.com/inf}contentData'

update '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents/{http://mydomain.com/inf}contents/{http://mydomain.com/inf}contentData' [{http://www.modeshape.org/1.0}uuid = 029cf3e8-3bd7-40fe-9f4b-033c44ce9729]

create '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents/{http://mydomain.com/inf}contents/{http://mydomain.com/inf}contentData/{http://www.jcp.org/jcr/1.0}content'

update '/{http://mydomain.com/inf}elGroup[17]/{http://mydomain.com/inf}documents/{http://mydomain.com/inf}contents/{http://mydomain.com/inf}contentData/{http://www.jcp.org/jcr/1.0}content'

The first two embedded requests finish apparently without incident. The third line (the second of the 'create' statements) causes the error:

org.modeshape.graph.property.PathNotFoundException: Unable to find "/{http://mydomain.com/inf}elGroup[17]"; lowest existing path is "/"

    at org.modeshape.graph.connector.map.MapRequestProcessor.process(MapRequestProcessor.java:248) [:2.8.1.Final]

    at org.modeshape.graph.request.processor.RequestProcessor.process(RequestProcessor.java:250) [:2.8.1.Final]

    at org.modeshape.graph.request.processor.RequestProcessor.process(RequestProcessor.java:363) [:2.8.1.Final]

    at org.modeshape.graph.request.processor.RequestProcessor.process(RequestProcessor.java:235) [:2.8.1.Final]

    at org.modeshape.connector.store.jpa.model.simple.SimpleJpaConnection.execute(SimpleJpaConnection.java:133) [:2.8.1.Final]

    at org.modeshape.graph.connector.RepositoryConnectionPool$ConnectionWrapper.execute(RepositoryConnectionPool.java:1124) [:2.8.1.Final]

    at org.modeshape.graph.request.CompositeRequestChannel$2.call(CompositeRequestChannel.java:222) [:2.8.1.Final]

    at org.modeshape.graph.request.CompositeRequestChannel$2.call(CompositeRequestChannel.java:211) [:2.8.1.Final]

    at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source) [:1.6.0_23]

    at java.util.concurrent.FutureTask.run(Unknown Source) [:1.6.0_23]

    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) [:1.6.0_23]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [:1.6.0_23]

    at java.lang.Thread.run(Unknown Source) [:1.6.0_23]

According to the REST API, there are indeed 16 'elGroup' items existing before the call is made. 17 should be the next number, so it is picking that correctly, but after creating it and setting its attributes, it seems to be incapable of finding that node again to create a child at the next level.

As noted earlier, this code has previously run without issue, but once the repository starts behaving in this way the only solution I've found is to completely delete it and start with a fresh repository (which is fine during development, but would probably raise some objections in production!)

Can anyone suggest what might be causing the repository to get into this state, and ideally, how to fix it now that it has already done so?

Thanks in advance,

Erica

[bwallis42]

Do you have debug logs from a time when this occurred?

Does this occur close (in time) to a restart, ie: soon after launch of the application?

I'm wondering if it might be worth writing some code to walk the repository everytime after a restart with a few simple consistency checks to try to find any problems before you get the error (above).

To all: Are there any tools or recommendations about how and what might be a good "fsck" type operation for a repository?

[ericasmith]

Hi Brian,

I turned logging to debug for ModeShape in JBoss while this was occurring, but did not get any log messages. Is there anything unusual I need to do to get more detailed logging?

It's difficult to tell whether this is occuring close to a restart. It's happened twice to me now, but I do not always notice immediately when it fails. When it's in this state I can still read the data fine, it's just updates and creates which cause errors, and during development there will often be several restarts between attempts to add new nodes.

A startup 'integrity' check sounds like a helpful idea... A check you wouldn't really want it to change data though (in case a partial failure results in bogus 'test' data living in a production repository) so I'm not sure how you'd test the ability to create nodes without actually creating nodes.

Thanks,

Erica

[bwallis42]

I've had a play with this problem as it looked like it was probably a multi-thread contention issue (I should note that I work with Erica so I know this problem quite well).

What we did with the application that is exhibiting the problem was to change the concurrency of the MDB that did the document inserts into modeshape down to 1. This seems to have made the problem go away for the time being.

So, I wrote a simple standalone app to add documents into a repository in a simple 5 level tree of nodes under the root node

/inf:documentGroup/inf:document->inf:content->inf:contentData->nt:file

the jcr:data property of the nt:file node is set to some amount of binary data (1000+ bytes) but I have tried it with 0 bytes of data as well.

The app has a couple of loops, the outer loop creates threads and the inner one creates document trees. There is a random delay introduced between thread launches and also between document creations. Running this app with a single thread works fine for 100's of node adds. Increasing the number of threads and  decreasing the delay between document creations causes the problem described above to occur sooner.

I also added transactions around the session login/node creation/save/session logout and also just around the node creation/save but it makes no difference.

I started out testing against 2.8.1.Final but have tried it with 2.8.2.Final and 2.8.3.Final as well.

The system I'm testing on is a MacBook Pro with a 2 core i7 processor, hyperthreaded, giving effectivly 4 concurrent threads. The system is running MacOSX 10.6.8 and the JDK is the apple one, 1.6.0_33.

I've attached a zip of a maven project that includes all the code. The code I'm using to create the threads and call the document creation is:

{code}
        ArrayList<Thread> threads = new ArrayList<Thread>();
        for(int t = 0; t < 4; t++)
        {
            final int tt = t;
            threads.add(new Thread()
                {
                    public void run()
                    {
                        Random rand = new Random();
                        long   tid  = Thread.currentThread().getId();
                        byte[] data = new byte[(tt + 1) * 1000];
                        Arrays.fill(data, (byte) 0);
                        for(int i = 0; i < 100; i++)
                        {
                            if(addDocumentToJcr(tid, i, data) == null)
                            {
                                break;
                            }
                            try
                            {
                                Thread.sleep(rand.nextInt(500));
                            }
                            catch(InterruptedException e)
                            {
                                log.error("Sleep interrupted");
                            }
                        }
                    }
                });
        }
        for(Thread thread : threads)
        {
            thread.start();
            try
            {
                Thread.sleep(2000);
            }
            catch(InterruptedException e)
            {
                log.error("Problem with sleep");
            }
        }
{code}

and the document creation method is:

{code}
    public static String addDocumentToJcr(long   tid, int    n, byte[] value)
    {
        log.debug("{" + tid + "}[" + n + "] Add a new document");
        try
        {
            TransactionManager txnm = new JBossStandaloneJTAManagerLookup().getTransactionManager();
            Session              session = null;
            ByteArrayInputStream bis     = null;
            try
            {
                session = repository.login();
                txnm.begin();
                Node rootNode = session.getRootNode();
                // Store content
                Node docGroupNode = rootNode.addNode("inf:documentGroup", DOCUMENT_GROUP_TYPE);
                Node doc          = docGroupNode.addNode("inf:documents", DOCUMENT_TYPE);
                doc.setProperty("inf:type", "type/type");
                Node content     = doc.addNode("inf:contents", CONTENT_TYPE);
                Node contentData = content.addNode("inf:contentData", CONTENT_DATA_TYPE);
                Node file        = contentData.addNode("jcr:content", RESOURCE_DATA_TYPE);
                bis = new ByteArrayInputStream(value);
                Binary b = session.getValueFactory().createBinary(bis);
                file.setProperty("jcr:data", b);
                session.save();
                txnm.commit();
                session.logout();
                session = null;
                log.debug("{" + tid + "}[" + n + "] Added a new document");
                return docGroupNode.getIdentifier();
            }
            catch(InvalidItemStateException e)
            {
                txnm.rollback();
                log.error("{" + tid + "}[" + n + "] InvalidItemState when creating new document", e);
            }
            catch(RepositoryException e)
            {
                txnm.rollback();
                log.error("{" + tid + "}[" + n + "] Error creating new document", e);
            }
            finally
            {
                if(bis != null)
                {
                    try
                    {
                        bis.close();
                    }
                    catch(IOException e)
                    {
                        log.warn("{" + tid + "}[" + n + "] Failed to close ByteArrayInputStream", e);
                    }
                }
                if(session != null)
                {
                    session.logout();
                    session = null;
                }
            }
        }
        catch(Exception e)
        {
            log.error("Problem with TransactionManager", e);
        }
        return null;
    }
{code}

[bwallis42]

I have tried running my test app with the in memory repository and cannot get that to fail at all, 20 thread, 200 documents and minimal thread sleeps (<20ms) each and still no problems.

[bwallis42]

Created a ticket for this, MODE-1623.

[bwallis42]

I've also tried with a disk source repository and could not get that to fail either so the problem may be in the jpa source.

[rhauch]

Thanks, Brian. I updated the issue with that information, which should be very useful.

[kiskandar]

Sorry to bump this old ticket. We've recently encountered this issue in production, and while we're planning to upgrade to the latest version of ModeShape, we're still running ModeShape 2.8.1.Final on production and we want to deploy the fix for MODE-1623 so we won't encounter this issue until we can switch to the latest version of ModeShape. The fix version in the ticket is 2.8.4.Final but I couldn't find that particular version anywhere. Was there ever a 2.8.4.Final build or do we need to build the 2.x branch of ModeShape for this fix?

Kind regards

Kris

[hchiorean]

There is no 2.8.4 community release, so you'll have to build this locally from the 2.x branch.