topic Re: AbstractFeedGenerator warning in Alfresco Archive

AbstractFeedGenerator warning

dullaertd — Mon, 27 Apr 2009 10:15:24 GMT

hello,I have a freshly deployed alfresco 3.0.1 running on Weblogic, that was installed on solaris. For the backend we use Oracle 10g2When I look in the log files, i keep getting the same warning (shown below). Could some one tell me what this means and perhaps how to resolve it?10:43:12,912 WARN [o

Re: AbstractFeedGenerator warning

compaqnx7300 — Thu, 27 May 2010 08:00:09 GMT

Did you resolved this problem? I have similar situation. My Alfresco (v. 3.3.0) starts correctly and work correctly for some time. After a few hours two warnings appears:\


WARN  [activities.feed.AbstractFeedGenerator] Still busy …
WARN  [activities.feed.AbstractFeedGenerator] Still busy …
‍‍‍‍

and Alfresco does not respond. It even does not close correctly (I have to force it)

Re: AbstractFeedGenerator warning

svast — Fri, 04 Jun 2010 07:47:31 GMT

+1… I am facing the same issue, after some load test.
Is Alfresco experiencing some dead lock in its transactions?

@developers: On what kind of events this message is thrown?

Re: AbstractFeedGenerator warning

kahya — Fri, 11 Jun 2010 15:12:51 GMT

The same here, but i get the bug only when i use a benchmark tool, not in a comon usage..

Re: AbstractFeedGenerator warning

compaqnx7300 — Fri, 18 Jun 2010 09:05:08 GMT

For what is responsible AbstractFeedGenerator?
I noticed, that it happens when system is not used too. I start system, wait about 6-7 hours, warning on console appears and it is not possible to do anything in system

Re: AbstractFeedGenerator warning

kpacierpnik — Wed, 23 Jun 2010 11:40:45 GMT

Hi,
I have the same problem with Alfresco 3.3. My suspicion is that it's database "deadlock" or "unclosed connections" issue. Did anybody submit it in JIRA?

Re: AbstractFeedGenerator warning

kpacierpnik — Wed, 23 Jun 2010 13:20:36 GMT

I discovered that some threads are waiting infinitely while having transaction opened or opening transaction. In my case this situation happens when creating a lot of workflows (10 users creating 1 workflow per 2 seconds).I think that all connections from database connection pool are used, because they are not closed properly.

Example threads:

——————————————————————————————————————————————————————————————-
Name: AlfrescoJbpmJobExecutor:10.0.1.96:1
State: WAITING on org.apache.commons.pool.impl.GenericObjectPool@36961
Total blocked: 0 Total waited: 4

Stack trace:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:942)
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:336)
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:293)
org.alfresco.util.transaction.SpringAwareUserTransaction.begin(SpringAwareUserTransaction.java:411)
- locked org.alfresco.util.transaction.SpringAwareUserTransaction@bbe1a4
org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:310)
org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:228)
org.alfresco.repo.workflow.jbpm.AlfrescoJobExecutorThread.acquireJobs(AlfrescoJobExecutorThread.java:95)
org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:54)
——————————————————————————————————————————————————————————————-

——————————————————————————————————————————————————————————————-
Name: http-8080-47
State: WAITING on org.apache.commons.pool.impl.GenericObjectPool@36961
Total blocked: 994 Total waited: 995

Stack trace:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:942)
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:336)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:102)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
$Proxy39.validate(Unknown Source)
org.alfresco.web.app.servlet.AuthenticationHelper.getUser(AuthenticationHelper.java:487)
org.alfresco.web.app.servlet.AuthenticationHelper.authenticate(AuthenticationHelper.java:173)
org.alfresco.web.app.servlet.AuthenticationHelper.authenticate(AuthenticationHelper.java:154)
org.alfresco.web.app.servlet.AuthenticationFilter.doFilter(AuthenticationFilter.java:99)
sun.reflect.GeneratedMethodAccessor411.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.alfresco.repo.management.subsystems.ChainingSubsystemProxyFactory$1.invoke(ChainingSubsystemProxyFactory.java:116)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
$Proxy206.doFilter(Unknown Source)
org.alfresco.repo.web.filter.beans.BeanProxyFilter.doFilter(BeanProxyFilter.java:82)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
org.alfresco.repo.web.filter.beans.NullFilter.doFilter(NullFilter.java:68)
sun.reflect.GeneratedMethodAccessor411.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.alfresco.repo.management.subsystems.ChainingSubsystemProxyFactory$1.invoke(ChainingSubsystemProxyFactory.java:116)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
$Proxy206.doFilter(Unknown Source)
org.alfresco.repo.web.filter.beans.BeanProxyFilter.doFilter(BeanProxyFilter.java:82)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:852)
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
java.lang.Thread.run(Thread.java:619)
——————————————————————————————————————————————————————————————-

Re: AbstractFeedGenerator warning

luisalves00 — Thu, 22 Jul 2010 15:41:15 GMT

I have the same problem…

How to make sure the transactions are properly closed?

Re: AbstractFeedGenerator warning

svast — Thu, 22 Jul 2010 19:16:19 GMT

May it be related to the database layer?

By default Alfresco recommands MySQL. Has everyone here encountered that issue on MySQL also?
Is it occurring on PostgreSQL, or other RDBMS?

Thanks a lot for your feedbacks.

Re: AbstractFeedGenerator warning

svast — Tue, 27 Jul 2010 13:24:55 GMT

FYI : This issue has been reproduced also with postgreSQL backend.

Re: AbstractFeedGenerator warning

svast — Fri, 13 Aug 2010 08:45:00 GMT

Looks like the quartz jobs are blocked somehow…

FYI: Luis Alves reported a JIRA issue about it
http://issues.alfresco.com/jira/browse/ALF-4020?page=com.atlassian.streams.streams-jira-plugin%3Aactivity-stream-issue-tab

Re: AbstractFeedGenerator warning

janv — Thu, 16 Sep 2010 15:18:48 GMT

This warning message is mostly likely to be a symptom rather than the underlying cause, which could be exhausted DB connections. Disabling the feed generator may simply shift the symptom elsewhere.

For this particular warning message the FeedGenerator job (used to generate Share Activity Feeds) could be hanging when simply trying to query the DB, even if the activity tables are empty. Hence the next iteration of the FeedGenerator job will see that the previous iteration has not yet completed (even if there is no work to do) and issue the warning.

Please double-check your DB configuration to ensure it is configured appropriately for the expected level of concurrency / load. For example:

- for Alfresco you may need to increase the "db.pool.max" which is currently set to 40 by default
- it is also important to check (and if necessary, reconfigure) your DB server to handle at least 10 more connections than the total number of pool connections expected … taking into account all client/node pools that access the DB server (which may included multiple Alfresco nodes in a clustered setup)

In a dev/test environment, you can also check for leaked DB connections by custom overriding the "defaultDataSource" bean and adding the following property:

       <property name="logAbandoned" >
            <value>true</value>
        </property>

Hope this helps.

Re: AbstractFeedGenerator warning

svast — Wed, 29 Sep 2010 12:37:31 GMT

@janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

I can read in https://issues.alfresco.com/jira/browse/ALF-4020 that you just set the issue at "won't fix".
Can you explain why this won't be fixed?

I don't understand the benefit of 'Hiding the issue by leveraging the logging level' as a solution.
Is it the warning message that causes the application to dead-lock ? meaning that no warn message may lead to no deadlock?

Re: AbstractFeedGenerator warning

janv — Wed, 29 Sep 2010 15:21:46 GMT

>> @janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

What do you mean by "help a little" ?

>> Can you explain why this won't be fixed?

"Won't fix" simply means that we will leave the warning message as-is for the time being (rather than remove or hide it).

>> Is it the warning message that causes the application to dead-lock ?

The warning message does not cause the deadlock. As per earlier post, it appears to be a symptom (not the underlying cause). It simply indicates that the previous execution of the activities feed generator job is still busy for some reason. That particular job runs regularly (by default, every 30 secs) hence might already be busy processing a large number of Share activities *or* waiting for a DB connection (even if the queries will be against an empty "alf_activity_post" table). The latter seems to be the case here. You can confirm this (ie. empty table) by temporarily adding the following debug:


log4j.logger.org.alfresco.repo.activities.feed.local.LocalFeedGenerator=debug
‍‍‍

If you're not causing Share activities to be posted (hence the table is empty) then you will see debug approx every 30 secs, such as:


15:58:25,611  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:58:55,609  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:59:25,610  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
15:59:55,609  DEBUG [feed.local.LocalFeedGenerator] >>> No work to be done for this job cycle: local
‍‍‍‍‍‍

If you *also* still see the warning message intermittently:


11:13:12,920 WARN [org.alfresco.repo.activities.feed.AbstractFeedGenerator] Still busy …
‍‍‍

then it implies that it (ie. previous job iteration) is still waiting to get a DB connection.

If you hide the warning message or even explicitly disable the activities feed generator job then it is still possible that other threads could hang due to an exhausted DB connection pool.

Regards,
Jan

Re: AbstractFeedGenerator warning

svast — Wed, 29 Sep 2010 16:13:33 GMT

>> @janv: All right, thank you very much for the tip. Increasing db.pool.max did help a little.

What do you mean by "help a little" ?

I mean that I don't have that message as often as before. I've just realized the db.pool.max was not high enough.
Now it works flawlessly, with db.pool.max=350

>> Is it the warning message that causes the application to dead-lock ?

The warning message does not cause the deadlock. As per earlier post, it appears to be a symptom (not the underlying cause). It simply indicates that the previous execution of the activities feed generator job is still busy for some reason. That particular job runs regularly (by default, every 30 secs) hence might already be busy processing a large number of Share activities *or* waiting for a DB connection (even if the queries will be against an empty "alf_activity_post" table). The latter seems to be the case here. You can confirm this (ie. empty table) by temporarily adding the following debug:

If you're not causing Share activities to be posted (hence the table is empty) then you will see debug approx every 30 secs, such as:

I don't use Share at all, so my guess is the table will remain empty.

If you hide the warning message or even explicitly disable the activities feed generator job then it is still possible that other threads could hang due to an exhausted DB connection pool.

Regards,
Jan

Now I understand much better the whole picture, thank you for the time spent.

Re: AbstractFeedGenerator warning

svast — Mon, 03 Jan 2011 22:55:24 GMT

So after digging a while about that "Still busy…" issue, I saw that it was supposed to be fixed in v3.4a onwards.
But it seems to be back again as http://issues.alfresco.com/jira/browse/ALF-5837

I can confirm the issue is still here when using Alfresco v3.4.c, unfortunately.