Hi all, Thank you for the responses. I'm a little better but still not there. As you can see my log starts off good but once tapestry is initialized there are no more logs generated from hibernate or spring. At the very end you can see where my DAO (SubjectDAO.java) fetches some records from the db, and then only logs from my DAO are generated. Any ideas?
Here is my start up log: launching Jetty webapp: /jpa on address: 0.0.0.0:8080 using dir: [S:\Java\workspaces_eclipse6\companies\jpa-test\src\main\webapp] 22:15:32.312 INFO [main] org.mortbay.log.LogImpl.add(LogImpl.java:109) >16> added [EMAIL PROTECTED] 22:15:32.265 INFO [main] org.mortbay.log.LogImpl.reset(LogImpl.java:228) >11> reset 22:15:32.312 INFO [main] org.mortbay.log.LogImpl.add(LogImpl.java:109) >11> added [EMAIL PROTECTED] 22:15:32.968 INFO [main] org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:178) >09> Root WebApplicationContext: initialization started 22:15:33.046 INFO [main] org.springframework.context.support.AbstractApplicationContext.prepareRefresh(AbstractApplicationContext.java:378) >12> Refreshing [EMAIL PROTECTED]: display name [Root WebApplicationContext]; startup date [Tue Jan 08 22:15:33 PST 2008]; root of context hierarchy 22:15:33.234 INFO [main] org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions(XmlBeanDefinitionReader.java:303) >19> Loading XML bean definitions from class path resource [applicationContext.xml] 22:15:34.109 INFO [main] org.springframework.context.support.AbstractApplicationContext.obtainFreshBeanFactory(AbstractApplicationContext.java:393) >12> Bean factory for application context [EMAIL PROTECTED]: [EMAIL PROTECTED] 22:15:34.359 INFO [main] org.springframework.context.support.AbstractApplicationContext$BeanPostProcessorChecker.postProcessAfterInitialization(AbstractApplicationContext.java:1006) >21> Bean 'org.springframework.aop.config.internalAutoProxyCreator' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying) 22:15:34.390 INFO [main] org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:276) >12> Pre-instantiating singletons in [EMAIL PROTECTED]: defining beans [entityManagerFactory,transactionManager,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.interceptor.TransactionAttributeSourceAdvisor,SubjectDAO,StudentDAO]; root of factory hierarchy 22:15:34.437 INFO [main] org.springframework.orm.jpa.LocalEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalEntityManagerFactoryBean.java:76) >21> Building JPA EntityManagerFactory for persistence unit 'jpaTestPU' 22:15:34.562 INFO [main] org.hibernate.cfg.annotations.Version.<clinit>(Version.java:15) >26> Hibernate Annotations 3.3.0.GA 22:15:34.625 INFO [main] org.hibernate.cfg.Environment.<clinit>(Environment.java:514) >30> Hibernate 3.2.5 22:15:34.656 INFO [main] org.hibernate.cfg.Environment.<clinit>(Environment.java:547) >30> hibernate.properties not found 22:15:34.656 INFO [main] org.hibernate.cfg.Environment.buildBytecodeProvider(Environment.java:681) >31> Bytecode provider name : cglib 22:15:34.671 INFO [main] org.hibernate.cfg.Environment.<clinit>(Environment.java:598) >30> using JDK 1.4 java.sql.Timestamp handling 22:15:34.906 INFO [main] org.hibernate.ejb.Version.<clinit>(Version.java:15) >25> Hibernate EntityManager 3.3.1.GA 22:15:35.515 INFO [main] org.hibernate.cfg.AnnotationBinder.bindClass(AnnotationBinder.java:398) >32> Binding entity from annotated class: com.jpa.db.Subject 22:15:35.656 INFO [main] org.hibernate.cfg.annotations.EntityBinder.bindTable(EntityBinder.java:420) >33> Bind entity com.jpa.db.Subject on table subject 22:15:35.937 INFO [main] org.hibernate.cfg.AnnotationBinder.bindClass(AnnotationBinder.java:398) >32> Binding entity from annotated class: com.jpa.db.Student 22:15:35.937 INFO [main] org.hibernate.cfg.annotations.EntityBinder.bindTable(EntityBinder.java:420) >33> Bind entity com.jpa.db.Student on table student 22:15:36.203 INFO [main] org.hibernate.cfg.annotations.CollectionBinder.bindOneToManySecondPass(CollectionBinder.java:627) >35> Mapping collection: com.jpa.db.Subject.students -> student 22:15:36.234 INFO [main] org.hibernate.validator.Version.<clinit>(Version.java:17) >36> Hibernate Validator 3.0.0.GA 22:15:36.406 INFO [main] org.hibernate.connection.DriverManagerConnectionProvider.configure(DriverManagerConnectionProvider.java:41) >31> Using Hibernate built-in connection pool (not for production use!) 22:15:36.406 INFO [main] org.hibernate.connection.DriverManagerConnectionProvider.configure(DriverManagerConnectionProvider.java:42) >31> Hibernate connection pool size: 20 22:15:36.406 INFO [main] org.hibernate.connection.DriverManagerConnectionProvider.configure(DriverManagerConnectionProvider.java:45) >31> autocommit mode: true 22:15:36.421 INFO [main] org.hibernate.connection.DriverManagerConnectionProvider.configure(DriverManagerConnectionProvider.java:80) >31> using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost/ 22:15:36.421 INFO [main] org.hibernate.connection.DriverManagerConnectionProvider.configure(DriverManagerConnectionProvider.java:86) >31> connection properties: {user=root, autocommit=true, release_mode=auto} 22:15:36.828 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:89) >28> RDBMS: MySQL, version: 4.1.11-nt-max 22:15:36.843 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:90) >28> JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-3.1.8 ( $Date: 2005/04/14 20:36:13 $, $Revision: 1.27.4.64 $ ) 22:15:36.921 INFO [main] org.hibernate.dialect.Dialect.<init>(Dialect.java:152) >40> Using dialect: org.hibernate.dialect.MySQLDialect 22:15:36.937 INFO [main] org.hibernate.transaction.TransactionFactoryFactory.buildTransactionFactory(TransactionFactoryFactory.java:34) >30> Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory 22:15:36.937 INFO [main] org.hibernate.transaction.TransactionManagerLookupFactory.getTransactionManagerLookup(TransactionManagerLookupFactory.java:33) >30> No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended) 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:143) >28> Automatic flush during beforeCompletion(): disabled 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:147) >28> Automatic session close at end of transaction: disabled 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:154) >28> JDBC batch size: 15 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:157) >28> JDBC batch updates for versioned data: disabled 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:162) >28> Scrollable result sets: enabled 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:170) >28> JDBC3 getGeneratedKeys(): enabled 22:15:36.937 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:178) >28> Connection release mode: auto 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:202) >28> Maximum outer join fetch depth: 2 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:205) >28> Default batch fetch size: 1 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:209) >28> Generate SQL with comments: disabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:213) >28> Order SQL updates by primary key: disabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:217) >28> Order SQL inserts for batching: disabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.createQueryTranslatorFactory(SettingsFactory.java:386) >29> Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 22:15:36.953 INFO [main] org.hibernate.hql.ast.ASTQueryTranslatorFactory.<init>(ASTQueryTranslatorFactory.java:24) >36> Using ASTQueryTranslatorFactory 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:225) >28> Query language substitutions: {} 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:230) >28> JPA-QL strict compliance: enabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:235) >28> Second-level cache: enabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:239) >28> Query cache: disabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.createCacheProvider(SettingsFactory.java:373) >29> Cache provider: org.hibernate.cache.NoCacheProvider 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:254) >28> Optimize cache for minimal puts: disabled 22:15:36.953 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:263) >28> Structured second-level cache entries: disabled 22:15:36.984 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:290) >28> Statistics: disabled 22:15:36.984 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:294) >28> Deleted entity synthetic identifier rollback: disabled 22:15:36.984 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:309) >28> Default entity-mode: pojo 22:15:36.984 INFO [main] org.hibernate.cfg.SettingsFactory.buildSettings(SettingsFactory.java:313) >28> Named query checking : enabled 22:15:37.109 INFO [main] org.hibernate.impl.SessionFactoryImpl.<init>(SessionFactoryImpl.java:161) >27> building session factory 22:15:37.953 INFO [main] org.hibernate.impl.SessionFactoryObjectFactory.addInstance(SessionFactoryObjectFactory.java:82) >28> Not binding factory to JNDI, no JNDI name configured 22:15:37.953 INFO [main] org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:115) >28> Running hbm2ddl schema update 22:15:37.968 INFO [main] org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:126) >28> fetching database metadata 22:15:37.984 INFO [main] org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:138) >28> updating schema 22:15:38.000 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:39) >31> table found: school.student 22:15:38.000 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:40) >31> columns: [subject_id, rank, name, id] 22:15:38.000 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:42) >31> foreign keys: [fk8ffe823b765afb37, fk_subject_id, fk8ffe823b643508aa] 22:15:38.000 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:43) >31> indexes: [primary, fk8ffe823b765afb37, fk8ffe823b643508aa] 22:15:38.015 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:39) >31> table found: school.subject 22:15:38.015 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:40) >31> columns: [name, id] 22:15:38.015 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:42) >31> foreign keys: [] 22:15:38.015 INFO [main] org.hibernate.tool.hbm2ddl.TableMetadata.<init>(TableMetadata.java:43) >31> indexes: [primary] 22:15:38.015 INFO [main] org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:160) >28> schema update complete 22:15:38.406 INFO [main] org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:198) >09> Root WebApplicationContext: initialization completed in 5438 ms [INFO] TapestryFilter Startup status: Startup time: 625 ms to build IoC Registry, 2,078 ms overall. Startup services status: AjaxComponentActionRequestHandler: DEFINED AjaxComponentEventResultProcessor: DEFINED AjaxPartialResponseRenderer: DEFINED Alias: REAL AliasOverrides: REAL ApplicationDefaults: VIRTUAL ApplicationGlobals: REAL ApplicationInitializer: REAL ApplicationStateManager: DEFINED ApplicationStatePersistenceStrategySource: DEFINED AssetObjectProvider: REAL AssetSource: VIRTUAL BeanBlockSource: DEFINED BeanModelSource: DEFINED BindingSource: DEFINED ChainBuilder: VIRTUAL ClassFactory: BUILTIN ClassNameLocator: REAL ClasspathAssetAliasManager: DEFINED ClasspathAssetFactory: DEFINED ClientPersistentFieldStorage: DEFINED ClientPersistentFieldStrategy: DEFINED ComponentActionRequestHandler: DEFINED ComponentClassFactory: VIRTUAL ComponentClassResolver: REAL ComponentClassTransformWorker: DEFINED ComponentClassTransformer: VIRTUAL ComponentDefaultProvider: DEFINED ComponentEventResultProcessor: DEFINED ComponentInstanceResultProcessor: DEFINED ComponentInstantiatorSource: REAL ComponentInvocationMap: DEFINED ComponentMessagesSource: DEFINED ComponentSource: DEFINED ComponentTemplateSource: VIRTUAL Context: DEFINED ContextAssetFactory: DEFINED CookieSink: DEFINED CookieSource: DEFINED Cookies: DEFINED DataTypeAnalyzer: DEFINED DefaultDataTypeAnalyzer: DEFINED DefaultImplementationBuilder: VIRTUAL Environment: VIRTUAL EnvironmentalShadowBuilder: DEFINED ExceptionAnalyzer: DEFINED ExceptionTracker: DEFINED FactoryDefaults: VIRTUAL FieldValidationSupport: DEFINED FieldValidatorDefaultSource: DEFINED FieldValidatorSource: DEFINED FormSupport: DEFINED HttpServletRequestHandler: VIRTUAL InjectionProvider: DEFINED LinkFactory: VIRTUAL LocalizationSetter: DEFINED LocationRenderer: DEFINED LoggerSource: BUILTIN LoggingDecorator: DEFINED MarkupRenderer: DEFINED MarkupWriterFactory: DEFINED MasterDispatcher: DEFINED MasterObjectProvider: REAL MetaDataLocator: DEFINED ObjectRenderer: DEFINED PageElementFactory: DEFINED PageLoader: DEFINED PageMarkupRenderer: DEFINED PagePool: DEFINED PageRenderQueue: DEFINED PageRenderRequestHandler: DEFINED PageRenderSupport: DEFINED PageResponseRenderer: DEFINED PageTemplateLocator: DEFINED PartialMarkupRenderer: DEFINED PersistentFieldManager: DEFINED PersistentLocale: DEFINED PipelineBuilder: REAL PropBindingFactory: DEFINED PropertyAccess: VIRTUAL PropertyConduitSource: DEFINED PropertyShadowBuilder: VIRTUAL RegistryShutdownHub: BUILTIN RegistryStartup: REAL Request: VIRTUAL RequestEncodingInitializer: DEFINED RequestExceptionHandler: DEFINED RequestGlobals: VIRTUAL RequestHandler: DEFINED RequestPageCache: VIRTUAL ResourceCache: DEFINED ResourceDigestGenerator: DEFINED ResourceStreamer: DEFINED Response: VIRTUAL ServiceActivityScoreboard: BUILTIN ServiceLifecycleSource: DEFINED ServletApplicationInitializer: REAL StrategyBuilder: VIRTUAL StudentDAO: DEFINED SubjectDAO: DEFINED SymbolSource: REAL TemplateParser: DEFINED ThreadCleanupHub: BUILTIN ThreadLocale: VIRTUAL TimingFilter: DEFINED TranslatorDefaultSource: DEFINED TranslatorSource: DEFINED TypeCoercer: REAL UpdateListenerHub: REAL ValidationConstraintGenerator: DEFINED ValidationMessagesSource: DEFINED ValueEncoderSource: DEFINED WebApplicationContext: DEFINED entityManagerFactory: DEFINED org.springframework.aop.config.internalAutoProxyCreator: DEFINED org.springframework.transaction.interceptor.TransactionAttributeSourceAdvisor: DEFINED transactionManager: DEFINED 82.91% unrealized services (97/117) [INFO] TimingFilter start time: 1199859344109 ms 22:15:46.046 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >52> finding Subject instance with id: 1 [rank: 1 name: Billy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 4 name: Sammy] 22:15:46.218 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.update(SubjectDAO.java:136) >52> updating Subject instance 22:15:46.218 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.update(SubjectDAO.java:139) >52> update successful 22:15:46.218 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.refresh(SubjectDAO.java:255) >52> refreshing Subject instance [rank: 4 name: Billy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 1 name: Sammy] 22:15:46.312 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.refresh(SubjectDAO.java:261) >52> refresh successful 22:15:46.312 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >52> finding Subject instance with id: 1 [rank: 4 name: Billy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 1 name: Sammy] 22:15:46.343 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >52> finding Subject instance with id: 1 [rank: 1 name: Sammy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 4 name: Billy] 22:15:46.718 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >63> finding Subject instance with id: 1 [rank: 1 name: Sammy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 4 name: Billy] 22:15:46.734 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.update(SubjectDAO.java:136) >63> updating Subject instance 22:15:46.734 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.update(SubjectDAO.java:139) >63> update successful [rank: 4 name: Sammy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 1 name: Billy] 22:15:46.734 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.refresh(SubjectDAO.java:255) >63> refreshing Subject instance 22:15:46.734 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.refresh(SubjectDAO.java:261) >63> refresh successful 22:15:46.734 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >63> finding Subject instance with id: 1 [rank: 4 name: Sammy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 1 name: Billy] 22:15:46.765 INFO [SocketListener0-1] com.jpa.db.SubjectDAO.findById(SubjectDAO.java:148) >63> finding Subject instance with id: 1 [rank: 1 name: Billy, rank: 2 name: Bob, rank: 3 name: Farrah, rank: 4 name: Sammy] [INFO] TimingFilter Request time: 2750 ms 127.0.0.1 - - [08/Jan/2008:22:15:43 -0800] "GET /jpa/start HTTP/1.1" 200 521 "http://localhost:8080/jpa/start" "Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.11) Gecko/20071127 Firefox/2.0.0.11" - And here is my log4j.properties file: log4j.rootCategory=WARN, A1 # A1 is set to be a ConsoleAppender. log4j.appender.A1=org.apache.log4j.ConsoleAppender # A1 uses PatternLayout. log4j.appender.A1.layout=org.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern=[%p] %c{1} %m%n log4j.category.org.apache.tapestry.TapestryFilter=info log4j.category.org.apache.tapestry=error log4j.category.tapestry=error log4j.category.com.jpa=error # Service category names are the name of the defining module class # and then the service id. log4j.category.com.jpa.services.AppModule.TimingFilter=info # Turning on debug mode for a page or component will show all of the code changes that occur when the # class is loaded. Turning on debug mode for a page will enable detailed output about # the contruction of the page, including the runtime code modifications that occur. Verbose # mode is rarely used, as it output voluminous details about the rendering of the page. # log4j.category.com.jpa.pages.Start=debug log4j.category.org.springframework=debug log4j.logger.net.sf.hibernate=debug log4j.category.net.sf.hibernate=debug #log4j.category.org.hibernate=info log4j.category.org.hibernate=debug ### log HQL query parser activity #log4j.category.org.hibernate.hql.ast.AST=debug ### log just the SQL log4j.category.org.hibernate.SQL=debug ### log JDBC bind parameters ### log4j.category.org.hibernate.type=debug ### log schema export/update ### log4j.category.org.hibernate.tool.hbm2ddl=debug ### log HQL parse trees #log4j.category.org.hibernate.hql=debug ### log cache activity ### log4j.category.org.hibernate.cache=debug ### log transaction activity log4j.category.org.hibernate.transaction=debug -- View this message in context: http://www.nabble.com/-T5--5.0.7---Help-with-log4j.properties-file-tp14611599p14705979.html Sent from the Tapestry - User mailing list archive at Nabble.com. --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]