[OAK-2144] Intermittent Node not found at given revision with DocumentNodeStore

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.0.7, 1.1.1
• Component/s: mongomk
• Assignee: Marcel Reutegger
• Reporter: Chetan Mehrotra
• Created: 26/Sep/14 09:39
• Updated: 13/Oct/14 09:20
• Resolved: 09/Oct/14 11:36

Description

In a cluster deployment intermittent issue related to node not found at given revision are observed. Mostly such logs are coming from Onservation logic which performs diff and read node from two different revision.

24.09.2014 09:11:45.513 *WARN* [pool-5-thread-5] org.apache.jackrabbit.oak.jcr.observation.ChangeProcessor Error while dispatching observation events
java.lang.NullPointerException: Node at [/var/eventing/jobs/assigned/62f1f24b-027e-4434-b1ef-a7a3c2c90e16/logouttopic/2014/9/24/15/12] not found for fromRev [r148a837accc-0-4]
	at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:236)

For the timings (all converted to UTC)

• Log - 2014-09-24T16:11:45.513 UTC
• Read Revision r148a837accc-0-4 - 2014-09-24T15:11:34.092 UTC (T1)
• Created Revision r148a83824e4-0-2 - 2014-09-24T15:12:04.836 UTC (T2)

As can be seen that node is actually created at time T2 > T1. Now DocumentNodeStore has a logic [1] which determines the revision based on prevision revision seen for a given cluster instance. Now it can happen that when some read call fetches child for a given path then it records that those child exist at given readRevision and this readRevision might be in past. Later when revision node cache gets purged and revision child node cache still retains the entry call to read node at given revision would fail.

qa:PRIMARY> db.nodes.findOne({_id: "11:/var/eventing/jobs/assigned/62f1f24b-027e-4434-b1ef-a7a3c2c90e16/logouttopic/2014/9/24/15/12" })
{
        "_id" : "11:/var/eventing/jobs/assigned/62f1f24b-027e-4434-b1ef-a7a3c2c90e16/logouttopic/2014/9/24/15/12",
        "_lastRev" : {
                "r0-0-2" : "r148a873e2ee-0-2",
                "r0-0-1" : "r148a8b3ffa7-0-1"
        },
        "jcr:primaryType" : {
                "r148a83824e4-0-2" : "\"nam:sling:Folder\"",
                "r148a8b3ffa7-0-1" : null
        },
        "_commitRoot" : {
                "r148a83824e4-0-2" : "0",
                "r148a8382505-0-2" : "0",
                "r148a8b3ffa7-0-1" : "0"
        },
        "_modified" : NumberLong(1411579640),
        "jcr:createdBy" : {
                "r148a83824e4-0-2" : "\"admin\"",
                "r148a8b3ffa7-0-1" : null
        },
        "_deleted" : {
                "r148a83824e4-0-2" : "false",
                "r148a8b3ffa7-0-1" : "true"
        },
        "sling:resourceType" : {
                "r148a83824e4-0-2" : "\"sling:Folder\"",
                "r148a8b3ffa7-0-1" : null
        },
        "jcr:created" : {
                "r148a83824e4-0-2" : "\"dat:2014-09-24T15:12:04.825Z\"",
                "r148a8b3ffa7-0-1" : null
        },
        "_modCount" : NumberLong(42),
        "_children" : true,
        "_deletedOnce" : true
}

[1] https://github.com/apache/jackrabbit-oak/blob/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/Revision.java#L543-615

Issue Links

• is related to: OAK-2143 NodeObservor should catch exception in case event processing