FeedNotifier does not send emails

[upforsin]

Hello

Daily activities emails were up and running and then, a couple of days ago it just stopped working.

In the catalina.out I can see that it is running and getting user feed entries but does not detect any new activities.

... 
 2020-12-01 14:33:52,034  DEBUG [activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: user1, 122850368
 2020-12-01 14:33:52,044  DEBUG [activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: use2, -1
 2020-12-01 14:33:52,055  DEBUG [activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: user3, 232641756
 2020-12-01 14:33:52,064  INFO  [activities.feed.FeedNotifier] [DefaultScheduler_Worker-3] FeedNotifier: Processed 67 entries out of 67. 100% complete. Rate: 74 per second. 0 failures detected.
 2020-12-01 14:33:52,064  INFO  [activities.feed.FeedNotifier] [DefaultScheduler_Worker-3] FeedNotifier: Completed batch of 67 entries
 2020-12-01 14:33:52,064  TRACE [activities.feed.FeedNotifier] [DefaultScheduler_Worker-3] Nothing to send since no new user activities found
 2020-12-01 14:33:52,064  TRACE [activities.feed.FeedNotifier] [DefaultScheduler_Worker-3] Activities email notification completed

Do you have any idea what the problem might be?

[abhinavmishra14]

Seems like not all logs are printing from this class: https://github.com/Alfresco/alfresco-community-repo/blob/master/repository/src/main/java/org/alfresc...

Can you enable debug logs for the following and see what you get:

log4j.logger.org.alfresco.repo.activities=DEBUG
log4j.logger.org.alfresco.repo.transaction.RetryingTransactionHelper=DEBUG
log4j.logger.org.alfresco.repo.action.executer.MailActionExecuter=debug

[upforsin]

That you for the reply abhinavmishra14.

Below are the logs with those Log4j settings you asked to turn on. I executed feedNotifierJob. 

2020-12-01 16:45:09,154 TRACE [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] Activities email notification started
2020-12-01 16:45:09,185 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] Share URL configured as: https://mysite.com/share
2020-12-01 16:45:09,190 INFO  [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] FeedNotifier: Commencing batch of 67 entries
2020-12-01 16:45:09,229 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] RETRY TXNS: []
2020-12-01 16:45:09,235 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] FeedNotifier1 ready to execute
2020-12-01 16:45:09,238 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: admin, 237640757
2020-12-01 16:45:09,244 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [FeedNotifier1] Selected feed entries for user : 'admin',
 for site : 'null',
 excluding this user : 'false',
 excluding other users : 'false',
 with min feed id : '237640757',
 with max feed items : '100
2020-12-01 16:45:09,253 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: user1, 120852935
2020-12-01 16:45:09,257 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [FeedNotifier1] Selected feed entries for user : 'user1',
 for site : 'null',
 excluding this user : 'false',
 excluding other users : 'false',
 with min feed id : '120852935',
 with max feed items : '100
2020-12-01 16:45:09,263 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: user2, 120852888
2020-12-01 16:45:09,266 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [FeedNotifier1] Selected feed entries for user : 'user2',
 for site : 'null',
 excluding this user : 'false',
 excluding other users : 'false',
 with min feed id : '120852888',
 with max feed items : '100
2020-12-01 16:45:09,271 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: user3, 120852926
2020-12-01 16:45:09,274 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [FeedNotifier1] Selected feed entries for user : 'user3',
....
 for site : 'null',
 excluding this user : 'false',
 excluding other users : 'false',
 with min feed id : '-1',
 with max feed items : '100
2020-12-01 16:45:09,882 DEBUG [org.alfresco.repo.activities.feed.FeedNotifier] [FeedNotifier1] Get user feed entries: userX, 237640756
2020-12-01 16:45:09,885 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [FeedNotifier1] Selected feed entries for user : 'userX',
 for site : 'null',
 excluding this user : 'false',
 excluding other users : 'false',
 with min feed id : '237640756',
 with max feed items : '100
2020-12-01 16:45:09,894 INFO  [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] FeedNotifier: Processed 67 entries out of 67. 100% complete. Rate: 95 per second. 0 failures detected.
2020-12-01 16:45:09,895 INFO  [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] FeedNotifier: Completed batch of 67 entries
2020-12-01 16:45:09,895 TRACE [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] Nothing to send since no new user activities found
2020-12-01 16:45:09,895 TRACE [org.alfresco.repo.activities.feed.FeedNotifier] [DefaultScheduler_Worker-4] Activities email notification completed
2020-12-01 16:45:15,012  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-7] Lock acquired: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: 6942d00b-7fe9-4ccc-b274-e464b368e4b0
 2020-12-01 16:45:15,013  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-7] Selecting activity posts with status: PENDING
 2020-12-01 16:45:15,020  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-7] Lock released: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: 6942d00b-7fe9-4ccc-b274-e464b368e4b0
 2020-12-01 16:45:30,011  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-6] Lock acquired: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: b213167a-b99e-43f1-9cca-924e7fefa936
 2020-12-01 16:45:30,011  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-6] Selecting activity posts with status: PENDING
 2020-12-01 16:45:30,012  DEBUG [activities.feed.AbstractFeedGenerator] [DefaultScheduler_Worker-3] lock acquired: {http://www.alfresco.org/model/system/1.0}FeedGenerator: f7aad395-23e5-4014-9958-727380af0311
 2020-12-01 16:45:30,020  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-6] Lock released: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: b213167a-b99e-43f1-9cca-924e7fefa936
 2020-12-01 16:45:30,028  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator2]
Transaction marked for rollback:
   Thread: LocalFeedGenerator2
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@30929ab, status=0]
   Iteration: 0
 2020-12-01 16:45:30,054  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator1]
Transaction marked for rollback:
   Thread: LocalFeedGenerator1
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@3dbb12, status=0]
   Iteration: 0
 2020-12-01 16:45:30,797  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator2]
Transaction marked for rollback:
   Thread: LocalFeedGenerator2
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@433bd264, status=0]
   Iteration: 0
 2020-12-01 16:45:32,265  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator4]
Transaction marked for rollback:
   Thread: LocalFeedGenerator4
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1e47dd41, status=0]
   Iteration: 0
 2020-12-01 16:45:39,206  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator3]
Transaction marked for rollback:
   Thread: LocalFeedGenerator3
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@28a3f7cf, status=0]
   Iteration: 0
 2020-12-01 16:45:39,212  DEBUG [activities.feed.AbstractFeedGenerator] [DefaultScheduler_Worker-3] Lock released: {http://www.alfresco.org/model/system/1.0}FeedGenerator: f7aad395-23e5-4014-9958-727380af0311
 2020-12-01 16:45:45,015  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-2] Lock acquired: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: 360d6519-3094-4cf2-a9d3-d53dc30b1e39
 2020-12-01 16:45:45,015  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-2] Selecting activity posts with status: PENDING
 2020-12-01 16:45:45,023  DEBUG [post.lookup.PostLookup] [DefaultScheduler_Worker-2] Lock released: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: 360d6519-3094-4cf2-a9d3-d53dc30b1e39
  2020-12-01 16:47:00,049  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator2]
Transaction marked for rollback:
   Thread: LocalFeedGenerator2
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@15f794ef, status=0]
   Iteration: 0
 2020-12-01 16:47:00,066  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator1]
Transaction marked for rollback:
   Thread: LocalFeedGenerator1
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@50252f65, status=0]
   Iteration: 0
 2020-12-01 16:47:00,913  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator4]
Transaction marked for rollback:
   Thread: LocalFeedGenerator4
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@1cdfcd1e, status=0]
   Iteration: 0
 2020-12-01 16:47:02,345  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator2]
Transaction marked for rollback:
   Thread: LocalFeedGenerator2
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@dde329b, status=0]
   Iteration: 0
 2020-12-01 16:47:09,807  DEBUG [repo.transaction.RetryingTransactionHelper] [LocalFeedGenerator3]
Transaction marked for rollback:
   Thread: LocalFeedGenerator3
   Txn:    UserTransaction[object=org.alfresco.util.transaction.SpringAwareUserTransaction@460e3b5d, status=0]
   Iteration: 0
....

EDIT. It is a bit strange because new feeds seem to generate

2020-12-01 22:20:30,016 TRACE [org.alfresco.repo.activities.feed.AbstractFeedGenerator] [DefaultScheduler_Worker-8] Activities feed generator started
2020-12-01 22:20:30,037 DEBUG [org.alfresco.repo.activities.post.lookup.PostLookup] [DefaultScheduler_Worker-1] Lock released: {http://www.alfresco.org/model/system/1.0}ActivityPostLookup: d802deb2-5f85-43a6-ba06-b4e179cf534c
2020-12-01 22:20:36,226 TRACE [org.alfresco.repo.activities.feed.AbstractFeedGenerator] [DefaultScheduler_Worker-8] Activities feed generator completed
2020-12-01 22:20:36,230 DEBUG [org.alfresco.repo.activities.feed.AbstractFeedGenerator] [DefaultScheduler_Worker-8] Lock released: {http://www.alfresco.org/model/system/1.0}FeedGenerator: f427aba9-2cf6-4752-a233-ec041bb1310e
2020-12-01 22:20:40,085 DEBUG [org.alfresco.repo.activities.ActivityServiceImpl] [http-nio-8080-exec-18] Posted: ActivityPost
[id=5042,status=PENDING,postDate=Tue Dec 01 22:20:40 CET 2020,userId=userX,siteNetwork=sampleSite,appTool=documentlibrary,type=org.alfresco.documentlibrary.file-previewed,jobTaskNode=1,data=
{"title": "dummy.pdf", "nodeRef": "workspace:\/\/SpacesStore\/aaedddc1-9f28-4294-8b58-14eb1bd75dac", "page": "document-details?nodeRef=workspace:\/\/SpacesStore\/aaedddc1-9f28-4294-8b58-14eb1bd75dac"}
...
[id=5042,status=POSTED,postDate=Tue Dec 01 22:20:40 CET 2020,userId=userX,siteNetwork=sampleSite,appTool=documentlibrary,type=org.alfresco.documentlibrary.file-previewed,jobTaskNode=1,data=  ...
2020-12-01 22:42:00,050 INFO [org.alfresco.repo.activities.post.lookup.PostLookup] [DefaultScheduler_Worker-6] Updated: 1 activity post (in 39 msecs)

but when I enter /alfresco/s/api/activities/feed/site/sampleSite or look at 'Recent Site activities dashlet' I don't see any events

EDIT 2. I switched org.alfresco Log4j to debug and I found out AbstractFeedGenerator error...

2020-12-02 12:13:00,275 DEBUG [org.alfresco.repo.security.permissions.impl.acegi.ACLEntryVoter] [LocalFeedGenerator3] Method: public abstract boolean org.alfresco.service.cmr.repository.NodeService.exists(org.alfresco.service.cmr.repository.NodeRef)
2020-12-02 12:13:00,275 DEBUG [org.alfresco.repo.security.permissions.impl.acegi.ACLEntryVoter] [LocalFeedGenerator3] Access granted for the system user
2020-12-02 12:13:00,275 DEBUG [org.alfresco.repo.security.permissions.impl.acegi.ACLEntryAfterInvocationProvider] [LocalFeedGenerator2] Method: public abstract org.alfresco.service.cmr.security.AccessStatus org.alfresco.service.cmr.security.PermissionService.hasPermission(org.alfresco.service.cmr.repository.NodeRef,java.lang.String)
2020-12-02 12:13:00,275 DEBUG [org.alfresco.repo.security.permissions.impl.acegi.ACLEntryAfterInvocationProvider] [LocalFeedGenerator2] Uncontrolled object - access allowed for org.springframework.aop.framework.ReflectiveMethodInvocation
2020-12-02 12:13:00,275 DEBUG [org.alfresco.repo.node.MLPropertyInterceptor] [LocalFeedGenerator3] Intercepting method exists using content filter pl_PL
2020-12-02 12:13:00,276 DEBUG [org.alfresco.repo.audit.inbound] [LocalFeedGenerator2] 
Inbound audit values:
	/alfresco-api/post/PermissionService/hasPermission/args/permission=Read
	/alfresco-api/post/PermissionService/hasPermission/args/nodeRef=workspace://SpacesStore/86a45e3f-b662-4caa-8cac-2a94328a18cb
	/alfresco-api/post/PermissionService/hasPermission/result=ALLOWED
	/alfresco-api/post/PermissionService/hasPermission/no-error=null
2020-12-02 12:13:00,275 DEBUG [org.alfresco.util.transaction.SpringAwareUserTransaction] [DefaultScheduler_Worker-9] Exception attempting to pass transaction boundaries.
java.lang.Exception
	at org.alfresco.util.transaction.SpringAwareUserTransaction.rollback(SpringAwareUserTransaction.java:544)
	at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:519)
	at org.alfresco.repo.lock.JobLockServiceImpl.doWithRetry(JobLockServiceImpl.java:546)
	at org.alfresco.repo.lock.JobLockServiceImpl.getLockImpl(JobLockServiceImpl.java:500)
	at org.alfresco.repo.lock.JobLockServiceImpl.getLock(JobLockServiceImpl.java:228)
	at org.alfresco.repo.lock.JobLockServiceImpl.getLock(JobLockServiceImpl.java:218)
	at org.alfresco.repo.activities.feed.AbstractFeedGenerator.acquireLock(AbstractFeedGenerator.java:264)
	at org.alfresco.repo.activities.feed.AbstractFeedGenerator.access$3(AbstractFeedGenerator.java:261)
	at org.alfresco.repo.activities.feed.AbstractFeedGenerator$1.execute(AbstractFeedGenerator.java:193)
	at org.alfresco.repo.activities.feed.AbstractFeedGenerator$1.execute(AbstractFeedGenerator.java:1)
	at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:450)
	at org.alfresco.repo.activities.feed.AbstractFeedGenerator.execute(AbstractFeedGenerator.java:183)
	at org.alfresco.repo.activities.feed.FeedGeneratorJob.execute(FeedGeneratorJob.java:57)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
2020-12-02 12:13:00,276 DEBUG [org.alfresco.util.transaction.TransactionSupportUtil] [DefaultScheduler_Worker-9] Before completion: TransactionSychronizationImpl[ txnId=94a678e3-a93c-4b93-b8a2-c3233c969318]
2020-12-02 12:13:00,276 DEBUG [org.alfresco.repo.service.StoreRedirectorProxyFactory] [LocalFeedGenerator3] Redirecting method public abstract boolean org.alfresco.service.cmr.repository.NodeService.exists(org.alfresco.service.cmr.repository.NodeRef) based on store type workspace://SpacesStore
2020-12-02 12:13:00,277 DEBUG [org.alfresco.util.transaction.TransactionSupportUtil] [DefaultScheduler_Worker-9] After completion (rolled-back): TransactionSychronizationImpl[ txnId=94a678e3-a93c-4b93-b8a2-c3233c969318]
2020-12-02 12:13:00,277 DEBUG [org.alfresco.repo.audit.BeanIdentifierImpl] [LocalFeedGenerator2] Cached look up for NodeService.exists

[upforsin]

Summing everything up:

1. Emails are not coming because Alfresco doesn't see new activities
2.  There are no new activities displayed in the dashlets and the REST API returns empty feed list (or shows only old ones)
3. New feeds are generated correctly and saved in the Database with the POSTED status in the alf_activity_post table, but they are missing in the alf_activity_feed table (I can see only 'documentLibrary' activities)
4. I did not find anything special in logs excluding SpringAwareUserTransaction error ("Exception attempting to pass transaction boundaries"

Does anyone know what else I can check?

[upforsin · Accepted solution]

Alright, sorry guys, it seems like my mistake. I added a few lines to LocalFeedTaskProcessor.java to add parentNodeName to the activityPost. It was working for a while but then it was causing an issue (but why?). After commenting out this code it's working again.

I added this code to the selectPost method:

for(ActivityPostEntity activityPost : activityPosts) {
    try {
     	JSONObject activiyDataJson = new JSONObject(activityPost.getActivityData());
        String parentNodeName = (String) nodeService.getProperty(new NodeRef(activiyDataJson.get("parentNodeRef").toString()), ContentModel.PROP_TITLE);
	if(parentNodeName == null || parentNodeName.length() == 0) {
	    parentNodeName = (String) nodeService.getProperty(new NodeRef(activiyDataJson.get("parentNodeRef").toString()), ContentModel.PROP_NAME);
	}
	activiyDataJson.put("parentTitle", parentNodeName);
	activityPost.setActivityData(activiyDataJson.toString());
    } catch (JSONException e) {
	logger.debug("[LocalFeedTaskProcessor]: could not load JSON while getting parent node!\n");
    } catch (Exception e ) {
        logger.debug("[LocalFeedTaskProcessor]: could not get parent node!\n");
    }
}

(I know it is very inefficient and it should be done in PostLookup but I didn't want to interfere in code too much as I would have to reimplement almost every class connected to the activities)

PS. Merry Christmas! 

[horelvis]

The bug is because some activities type haven't  parentNode.