'Node does not exist' Errors

[ebogaard]

Recently I discovered that the Alfresco-logfiles were growing rapidly. This was caused by an unstoppable stream of errors like this:

 2013-01-24 09:29:13,672  ERROR [post.lookup.PostLookup] [DefaultScheduler_Worker-9] Skipping activity post 892: org.alfresco.service.cmr.repository.InvalidNodeRefException: Node does not exist: workspace://SpacesStore/53878128-dd03-4042-8902-2b0223222e9e(Status[changeTxnId=ace3d139-5a84-49cc-894a-52ad0073cde5, dbTxnId=10134, deleted=true])‍

Every few seconds, a new 2000 lines are added tot the log, after which the following error is shown:

 2013-01-24 09:36:16,840  ERROR [post.lookup.PostLookup] [DefaultScheduler_Worker-4] Exception during update of posts
 org.alfresco.service.cmr.repository.InvalidNodeRefException: Node does not exist: workspace://SpacesStore/18f6af13-1138-4425-9f53-8916776ad86e(Status[changeTxnId=6dcb25d1-446f-4c7c-b901-fb4b52705961, dbTxnId=9876, deleted=true])
        at org.alfresco.repo.node.db.DbNodeServiceImpl.getNodePairNotNull(DbNodeServiceImpl.java:178)
        at org.alfresco.repo.node.db.DbNodeServiceImpl.getPaths(DbNodeServiceImpl.java:2301)
        at org.alfresco.repo.node.db.DbNodeServiceImpl.getPath(DbNodeServiceImpl.java:2285)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:105)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy7.getPath(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.alfresco.repo.service.StoreRedirectorProxyFactory$RedirectorInvocationHandler.invoke(StoreRedirectorProxyFactory.java:215)
        at $Proxy35.getPath(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.alfresco.repo.tagging.TagScopePropertyMethodInterceptor.invoke(TagScopePropertyMethodInterceptor.java:152)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:306)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:269)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy7.getPath(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196)
        at $Proxy7.getPath(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at org.alfresco.repo.audit.DisableAuditableBehaviourInterceptor.invoke(DisableAuditableBehaviourInterceptor.java:113)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:80)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:46)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:159)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.alfresco.repo.transaction.RetryingTransactionInterceptor$1.execute(RetryingTransactionInterceptor.java:69)
        at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:433)
        at org.alfresco.repo.transaction.RetryingTransactionInterceptor.invoke(RetryingTransactionInterceptor.java:59)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy7.getPath(Unknown Source)
        at org.alfresco.repo.activities.post.lookup.PostLookup$4.doWork(PostLookup.java:460)
        at org.alfresco.repo.activities.post.lookup.PostLookup$4.doWork(PostLookup.java:429)
        at org.alfresco.repo.tenant.TenantUtil.runAsWork(TenantUtil.java:171)
        at org.alfresco.repo.tenant.TenantUtil.access$000(TenantUtil.java:28)
        at org.alfresco.repo.tenant.TenantUtil$5.doWork(TenantUtil.java:162)
        at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:529)
        at org.alfresco.repo.tenant.TenantUtil.runAsSystemTenant(TenantUtil.java:158)
        at org.alfresco.repo.activities.post.lookup.PostLookup.rollupPosts(PostLookup.java:428)
        at org.alfresco.repo.activities.post.lookup.PostLookup.access$100(PostLookup.java:60)
        at org.alfresco.repo.activities.post.lookup.PostLookup$2.execute(PostLookup.java:203)
        at org.alfresco.repo.activities.post.lookup.PostLookup$2.execute(PostLookup.java:199)
        at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:433)
        at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:323)
        at org.alfresco.repo.activities.post.lookup.PostLookup.execute(PostLookup.java:198)
        at org.alfresco.repo.activities.post.lookup.PostLookupJob.execute(PostLookupJob.java:50)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:563)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

As there is some info on this on this forum, I tried to delete the node from alf_node and alf_child_assoc.
The only thing that changed was the error (this is from a different node):

2013-01-24 09:35:43,596  ERROR [post.lookup.PostLookup] [DefaultScheduler_Worker-5] Skipping activity post 870: org.alfresco.service.cmr.repository.InvalidNodeRefException: Node does not exist: workspace://SpacesStore/10a37e23-eb12-437b-9505-6044d2e3eacb(null)‍

It appeared that there were some entries in alf_activity_post. After I deleted those entries for the node, the errors in the logfile stopped.
I have several questions:
1. How is this possible? Why are all there errors happening? Why aren't the nodes and the activity_posts deleted/cleaned nicely?
2. Is it OK to delete the error-causing entries from alf_node, alf_child_assoc and alf_activity_post manually, or is there a better (safer) way?
3. How to prevent this in the future?

We're using 4.2c + mainly WebDav (Netdrive) - Webdav is show as app_tool in most of the alf_activity_post entries.

[mitpatoliya]

Some times it happens because of corrupted indexes.
If you go for full index recovery then most of times problem gets solved.

[ebogaard]

Should have said that I've already deleted all solr indexes and let them rebuild. No effect whatsoever.


Update:
It appears I fixed the excessive logging of ERRORs by deleting the node mentioned in the last ERROR.
This node was found twice in alf_node, which might have been the problem.

Does anyone know how this can happen? (And how one can prevent this?)

Update2:
apparently it wasn't fixed: the list of 'Node does not exist' ERRORs returned and keeps on growing.

[ebogaard]

After some further research, it looks like there is something wrong in the way Alfresco 4.2c 'deletes' nodes. According to this blog: http://www.ixxus.com/blog/2011/09/alfresco-node-lifecycle/ (step 2), if a file (node) is deleted by an user, the store_id property of that node is changed from 6 to 5. When I look at the alf_node table, all nodes that give the ERROR are referred to twice in this table: once with store_id=5 once store_id=6. This doesn't seem right.
Am I right that this is wrong, or is this the correct behaviour for 4.2c?
If it's actually wrong, is this a bug and/or is there a fix for it? (As Jira is currently not available)

Update:
After posting this, Jira was back on-line. It seems that there is a very similar problem in 4.2b (and in my experciences, also in 4.2c), which is stated to be resolved in 4.2d. See: https://issues.alfresco.com/jira/browse/ALF-16739

[ebogaard]

After deleting several hundreds of rows from table 'alf_activity_feed', there were no more ERRORs.
Also, after several weeks of working in Alfresco 4.2x, this problem didn't show up anymore. Is this a known bug, or did something strange and unknown happen?

[lista]

Since you had to delete those rows, I'd say something strange definitely happened. I'd suggest raising a JIRA issue and having Alfresco guys have a look.

[ebogaard]

It seems that there already was a JIRA issue: https://issues.alfresco.com/jira/browse/ALF-16739
It should be fixed in 4.2d. I hope it really is, because recently the problem returned to the same instance.

[phloyd]

How did you know which table to look. I am seeing a similar error, but I am looking through all these tables and I don't know which one to look in.
I am not having problems with the tables you have described.

ERROR [org.alfresco.repo.activities.post.lookup.PostLookup] Skipping activity post 8084: org.alfresco.service.cmr.repository.InvalidNodeRefEx
ception: Node does not exist: workspace://SpacesStore/f18410d4-719c-4085-881f-94557ce424ee(Status[changeTxnId=e6e09cbf-2158-4530-bb4a-9bdaf1ce92a7, dbTxnI
d=416519, deleted=true])‍‍‍