Hide Forgot
Date of First Response: 2008-07-07 07:55:01 project_key: SOA The OOTB log4j configuration of the standalone server/default profile results in > 300K messages per hour on an idle server. The majority of these (DEBUG level) messages - see sample below - are generated by hibernate + jBPM. The large number of these messages can make it difficult to find specific log messages. Also - on an idle server - the log grows by ~15 MB per hour. The logging categories listed below might be a better default for this server. CP01 - standalone server - after one hour Total # of lines in server.log: 300919 (15MB) # of lines from hibernate.org: 234846 # of lines from jbpm.org: 36930 After adding this to server/default/conf/jboss-log4j.xml <category name="org.hibernate"> <priority value="INFO"/> </category> <category name="org.jbpm"> <priority value="INFO"/> </category> After one hour: Total # of lines in server.log: 22315 (3MB file) ====================== This pattern is repeated every 5 seconds: 2008-04-29 21:45:03,533 DEBUG [org.jbpm.job.executor.JobExecutorThread] acquiring jobs for execution... 2008-04-29 21:45:03,533 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2008-04-29 21:45:03,533 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@152a84b 2008-04-29 21:45:03,534 DEBUG [org.jbpm.JbpmContext] start user JTA transaction 2008-04-29 21:45:03,545 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-04-29 21:45:03,545 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4954193524920320 2008-04-29 21:45:03,545 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2008-04-29 21:45:03,545 DEBUG [org.jbpm.job.executor.JobExecutorThread] querying for acquirable job... 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-04-29 21:45:03,546 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_22_, job0_.VERSION_ as VERSION3_22_, job0_.DUEDATE_ as DUEDATE4_22_, job0_.PROCESSINSTANCE_ as PROCESSI5_22_, job0_.TOKEN_ as TOKEN6_22_, job0_.TASKINSTANCE_ as TASKINST7_22_, job0_.ISSUSPENDED_ as ISSUSPEN8_22_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_22_, job0_.LOCKOWNER_ as LOCKOWNER10_22_, job0_.LOCKTIME_ as LOCKTIME11_22_, job0_.EXCEPTION_ as EXCEPTION12_22_, job0_.RETRIES_ as RETRIES13_22_, job0_.NAME_ as NAME14_22_, job0_.REPEAT_ as REPEAT15_22_, job0_.TRANSITIONNAME_ as TRANSIT16_22_, job0_.ACTION_ as ACTION17_22_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_22_, job0_.GRAPHELEMENT_ as GRAPHEL19_22_, job0_.NODE_ as NODE20_22_, job0_.CLASS_ as CLASS2_22_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.DUEDATE_<=? and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-04-29 21:45:03,546 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-04-29 21:45:03,546 DEBUG [org.jbpm.job.executor.JobExecutorThread] no acquirable jobs in job table 2008-04-29 21:45:03,546 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@152a84b 2008-04-29 21:45:03,546 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@122b302 2008-04-29 21:45:03,546 DEBUG [org.jbpm.JbpmContext] end user JTA transaction 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] end jta transation with COMMIT 2008-04-29 21:45:03,559 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@815832 2008-04-29 21:45:03,559 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: [] 2008-04-29 21:45:03,559 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1c5472f 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] start user JTA transaction 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-04-29 21:45:03,576 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4954193525047296 2008-04-29 21:45:03,576 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-04-29 21:45:03,577 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_22_, job0_.VERSION_ as VERSION3_22_, job0_.DUEDATE_ as DUEDATE4_22_, job0_.PROCESSINSTANCE_ as PROCESSI5_22_, job0_.TOKEN_ as TOKEN6_22_, job0_.TASKINSTANCE_ as TASKINST7_22_, job0_.ISSUSPENDED_ as ISSUSPEN8_22_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_22_, job0_.LOCKOWNER_ as LOCKOWNER10_22_, job0_.LOCKTIME_ as LOCKTIME11_22_, job0_.EXCEPTION_ as EXCEPTION12_22_, job0_.RETRIES_ as RETRIES13_22_, job0_.NAME_ as NAME14_22_, job0_.REPEAT_ as REPEAT15_22_, job0_.TRANSITIONNAME_ as TRANSIT16_22_, job0_.ACTION_ as ACTION17_22_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_22_, job0_.GRAPHELEMENT_ as GRAPHEL19_22_, job0_.NODE_ as NODE20_22_, job0_.CLASS_ as CLASS2_22_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-04-29 21:45:03,577 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-04-29 21:45:03,577 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@1c5472f 2008-04-29 21:45:03,577 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@1cc042f 2008-04-29 21:45:03,577 DEBUG [org.jbpm.JbpmContext] end user JTA transaction 2008-04-29 21:45:03,579 DEBUG [org.jbpm.JbpmContext] end jta transation with COMMIT 2008-04-29 21:45:03,579 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@dbe4e5
This is probably related to SOA-222. A fix for that took the jboss-log4j.xml from jboss-eap-4.3.0-0.3.rc1.ep1.1.zip and modified it. Our changes should be applied to the current (EAP 4.3.0 CP01) file, e.g. via XSLT. However, we may still have problems if the EAP version changes.
Link: Added: This issue is related to SOA-222
Using XSLT will not detect changes in the upstream file, so replacing the file we get from EAP (as is done for SOA-222) is the best current way forward. This has been done on the 4.3dev branch in revision 1458: Fix for SOA-536: reduce logging output in the standalone default config. For this: move: resource/conf-skeleton/jboss-log4j.xml to: resource/conf-skeleton/jboss-log4j-production.xml for the embedded production config. Move the replacement fail message in builders/eap/build.xml Add the replacement of jboss-log4j.xml in builders/esb/build.xml
Can we move this across into trunk then?
Now merged to trunk. Updated to versions from EAP 4.3.0 CP02 in revision 1586.
Changes also added to 4.2.0 branch in revision 2464 of: builders/eap/build.xml builders/esb/build.xml resource/conf-skeleton/jboss-log4j.xml (deleted) resource/conf-skeleton/jboss-log4j-default.xml (added) resource/conf-skeleton/jboss-log4j-production.xml (added) (this will be in the next CR build of 4.2.0 CP03).
Link: Added: This issue related SOA-1537