9 Replies Latest reply on Jun 26, 2006 9:10 AM by Scott Stark

    Logging screwed up ?

    Jens Elkner Apprentice

      Hmmm, just testing 4.0.4GA and it seems, that logging is screwed up - grrr. E.g.:

      2006-05-20 19:49:11,640 INFO [ScannerThread:org.apache.commons.logging.impl.Log4JLogger:94] - found EJB3 Entity bean: foo.bar.Article
      ...
      2006-05-20 21:21:50,609 DEBUG [SocketServerInvokerThread-192.168.21.1-0:org.apache.commons.logging.impl.Log4JLogger:84] - select a_user0_.uid as uid1_, a_user0_.max as max1_, a_user0_.min as min1_, a_user0_.email as email1_, a_user0_.firstname as firstname1_, a_user0_.lastname as lastname1_, a_user0_.login as login1_, a_user0_.middlename as middlename1_, a_user0_.passwd as passwd1_, a_user0_.expire as expire1_, a_user0_.lastChange as lastChange1_, a_user0_.warn as warn1_ from users a_user0_ where a_user0_.login=?

      Actually it tells me not what I wanna known aka is at least for me more or less useless. In 4.0.4CR2 it was ok. E.g.:

      2006-04-23 19:54:00,586 INFO [main:org.hibernate.ejb.Ejb3Configuration:365] - found EJB3 Entity bean: foo.bar.Article

      Is there any magic to obtain the old behavior ? I guess it is a hibernate problem, since the usual jboss log infos seem to be ok...

      BTW: Is it possible to consider slf4j[.org] as a replacement for all the more or less senseless "logging-plugin back-and-forward [loop]" chaos ?

        • 1. Re: Logging screwed up ?
          Jens Elkner Apprentice

          BTW: Since logging does not work correctly, is somebody able to explain:

          2006-05-21 01:41:18,545 FATAL [SocketServerInvokerThread-192.168.21.1-34:org.apache.commons.logging.impl.Log4JLogger:124] - META-INF/INDEX.LISTO-:-Ofalse

          ???

          • 2. Re: Logging screwed up ?
            Scott Stark Master

            I don't see either with the jboss-4.0.4.GA-Patch1-installer.jar so details are needed:

            06:24:19,500 INFO [Ejb3Deployment] EJB3 deployment time took: 735
            06:24:19,515 INFO [JmxKernelAbstraction] installing MBean: persistence.units:jar=entity-test.jar,unitName=tempdb with dependencies:
            06:24:19,515 INFO [JmxKernelAbstraction] jboss.jca:name=DefaultDS,service=ManagedConnectionFactory
            06:24:19,562 INFO [Version] Hibernate EntityManager 3.2.0.CR1
            06:24:19,578 INFO [Version] Hibernate Annotations 3.2.0.CR1
            06:24:19,593 INFO [Environment] Hibernate 3.2 cr2
            06:24:19,609 INFO [Environment] hibernate.properties not found
            06:24:19,609 INFO [Environment] Bytecode provider name : javassist
            06:24:19,609 INFO [Environment] using JDK 1.4 java.sql.Timestamp handling
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Address
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Airport
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Company
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Customer
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldAddress
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldAirport
            06:24:19,781 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldCompany
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldCustomer
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldFlight
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.FieldTicket
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Flight
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.MyResource
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Resource
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.Ticket
            06:24:19,796 INFO [Ejb3Configuration] found EJB3 Entity bean: org.jboss.ejb3.test.entity.User
            06:24:19,796 WARN [Ejb3Configuration] Persistence provider caller does not impl
            ements the EJB3 spec correctly. PersistenceUnitInfo.getNewTempClassLoader() is n
            ull.06:24:19,890 INFO [Configuration] Reading mappings from resource: META-INF/orm.xml
            06:24:19,906 INFO [Ejb3Configuration] [PersistenceUnit: tempdb] no META-INF/orm.xml found
            06:24:20,046 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Address
            06:24:20,109 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Address on table EJB3TEST_ADDRESS
            06:24:20,171 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Airport
            06:24:20,171 INFO [QueryBinder] Binding Named query: allAirports => from Airport
            06:24:20,171 INFO [QueryBinder] Binding Named query: airportById => from Airport a where a.id=:id
            06:24:20,171 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Airport on table Airport
            06:24:20,171 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Company
            06:24:20,171 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Company on table Company
            06:24:20,218 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Customer
            06:24:20,218 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Customer on table Customer
            06:24:20,234 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldAddress
            06:24:20,234 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldAddress on table EJB3TEST_FIELD_ADDRESS
            06:24:20,250 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldAirport
            06:24:20,250 INFO [QueryBinder] Binding Named query: airportByCode => from FieldAirport a where a.code=:code
            06:24:20,250 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldAirport on table FieldAirport
            06:24:20,250 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldCompany
            06:24:20,250 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldCompany on table FieldCompany
            06:24:20,250 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldCustomer
            06:24:20,250 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldCustomer on table FieldCustomer
            06:24:20,250 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldFlight
            06:24:20,250 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldFlight on table FieldFlight
            06:24:20,390 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.FieldTicket
            06:24:20,390 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.FieldTicket on table FieldTicket
            06:24:20,406 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Flight
            06:24:20,406 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Flighton table Flight
            06:24:20,421 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Resource
            06:24:20,421 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Resource on table TBRESOURCE
            06:24:20,421 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.MyResource
            06:24:20,421 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.MyResource on table TBRESOURCE2
            06:24:20,437 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.Ticket
            06:24:20,437 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.Ticketon table Ticket
            06:24:20,453 INFO [AnnotationBinder] Binding entity from annotated class: org.jboss.ejb3.test.entity.User
            06:24:20,453 INFO [EntityBinder] Bind entity org.jboss.ejb3.test.entity.User on table TBUSER
            06:24:20,546 INFO [CollectionBinder] Mapping collection: org.jboss.ejb3.test.entity.Company.flights -> Flight
            06:24:20,546 INFO [CollectionBinder] Mapping collection: org.jboss.ejb3.test.entity.Customer.tickets -> Ticket
            06:24:20,546 INFO [CollectionBinder] Mapping collection: org.jboss.ejb3.test.entity.FieldCompany.flights -> FieldFlight
            06:24:20,562 INFO [CollectionBinder] Mapping collection: org.jboss.ejb3.test.entity.FieldCustomer.tickets -> FieldTicket
            06:24:20,921 INFO [ConnectionProviderFactory] Initializing connection provider:
             org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
            06:24:20,921 INFO [InjectedDataSourceConnectionProvider] Using provided datasource
            06:24:20,937 INFO [SettingsFactory] RDBMS: HSQL Database Engine, version: 1.8.0
            
            06:24:20,937 INFO [SettingsFactory] JDBC driver: HSQL Database Engine Driver, version: 1.8.006:24:20,953 INFO [Dialect] Using dialect: org.hibernate.dialect.HSQLDialect
            06:24:20,968 INFO [TransactionFactoryFactory] Transaction strategy: org.hiberna
            te.ejb.transaction.JoinableCMTTransactionFactory
            06:24:20,968 INFO [TransactionManagerLookupFactory] instantiating TransactionManagerLookup: org.hibernate.transaction.JBossTransactionManagerLookup
            06:24:20,968 INFO [TransactionManagerLookupFactory] instantiated TransactionMan
            agerLookup
            06:24:20,968 INFO [SettingsFactory] Automatic flush during beforeCompletion():
            disabled
            06:24:20,968 INFO [SettingsFactory] Automatic session close at end of transacti
            on: disabled
            06:24:20,968 INFO [SettingsFactory] JDBC batch size: 15
            06:24:20,968 INFO [SettingsFactory] JDBC batch updates for versioned data: disabled
            06:24:20,968 INFO [SettingsFactory] Scrollable result sets: enabled
            06:24:20,968 INFO [SettingsFactory] JDBC3 getGeneratedKeys(): disabled
            06:24:20,984 INFO [SettingsFactory] Connection release mode: auto
            06:24:20,984 INFO [SettingsFactory] Default batch fetch size: 1
            06:24:20,984 INFO [SettingsFactory] Generate SQL with comments: disabled
            06:24:20,984 INFO [SettingsFactory] Order SQL updates by primary key: disabled
            06:24:20,984 INFO [SettingsFactory] Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
            06:24:20,984 INFO [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory
            06:24:20,984 INFO [SettingsFactory] Query language substitutions: {}
            06:24:20,984 INFO [SettingsFactory] Second-level cache: enabled
            06:24:20,984 INFO [SettingsFactory] Query cache: disabled
            06:24:20,984 INFO [SettingsFactory] Cache provider: org.hibernate.cache.Hashtab
            leCacheProvider
            06:24:20,984 INFO [SettingsFactory] Optimize cache for minimal puts: disabled
            06:24:20,984 INFO [SettingsFactory] Structured second-level cache entries: disabled
            06:24:21,000 INFO [SettingsFactory] Statistics: disabled
            06:24:21,000 INFO [SettingsFactory] Deleted entity synthetic identifier rollback: disabled
            06:24:21,000 INFO [SettingsFactory] Default entity-mode: pojo
            06:24:21,046 INFO [SessionFactoryImpl] building session factory
            06:24:21,875 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured
            06:24:21,906 INFO [SchemaExport] Running hbm2ddl schema export
            06:24:21,906 INFO [SchemaExport] exporting generated schema to database
            06:24:21,953 INFO [SchemaExport] schema export complete
            06:24:22,046 INFO [NamingHelper] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.p
            kgs=org.jboss.naming:org.jnp.interfaces}
            06:24:22,484 INFO [JmxKernelAbstraction] installing MBean: jboss.j2ee:jar=entity-test.jar,name=EntityTestBean,service=EJB3 with dependencies:
            06:24:22,484 INFO [JmxKernelAbstraction] persistence.units:jar=entity-test.jar,unitName=tempdb
            06:24:22,890 INFO [EJBContainer] STARTED EJB: org.jboss.ejb3.test.entity.EntityTestBean ejbName: EntityTestBean
            06:24:22,937 INFO [EJB3Deployer] Deployed: file:/C:/tmp/jboss-4.0.x-ejb3/server/default/deploy/entity-test.jar
            



            • 3. Re: Logging screwed up ?
              Emmanuel Bernard Master

               

              "elkner" wrote:
              BTW: Since logging does not work correctly, is somebody able to explain:

              2006-05-21 01:41:18,545 FATAL [SocketServerInvokerThread-192.168.21.1-34:org.apache.commons.logging.impl.Log4JLogger:124] - META-INF/INDEX.LISTO-:-Ofalse

              ???


              I removed this log. I thought I did before releasing.

              • 4. Re: Logging screwed up ?
                Jens Elkner Apprentice

                Hi Scott,

                sorry for forgetting to say, that I'm always build the server from source available via sourceforge and creating a package from the output/*-ejb3. So is it possible, that the sf sources do not include the changes made for the patch1 installer? If so, is there a patchset available, which I can apply?

                Hi Emmanuel,

                so it will go away and has no special meaning. OK - thanx for the info.

                • 5. Re: Logging screwed up ?
                  Jens Elkner Apprentice

                  BTW: Is it possible to review the following files wrt. commons-logging?:

                  ./aspects/src/main/org/jboss/aspects/asynchronous/aspects/jboss/TraceThreadAspect.java
                  ./ejb3/src/main/org/jboss/ejb3/entity/JTATableIdGenerator.java
                  ./jaxrpc/src/main/org/jboss/axis/components/logger/LogFactory.java
                  ./system/src/main/org/jboss/system/server/ServerLoader.java
                  ./tomcat/src/main/org/jboss/web/tomcat/security/FormAuthenticator.java
                  ./tomcat/src/main/org/jboss/web/tomcat/tc5/session/JBossCacheCluster.java
                  ./tomcat/src/main/org/jboss/web/tomcat/tc5/WebAppClassLoader.java
                  ./tomcat/src/main/org/jboss/web/tomcat/tc5/WebAppLoader.java
                  ./tomcat/src/main/org/jboss/web/tomcat/tc5/WebCtxLoader.java
                  ./varia/src/main/org/jboss/jaxr/juddi/axis/JBossJuddiAxisProcessor.java
                  ./varia/src/main/org/jboss/jaxr/juddi/axis/JBossJuddiAxisTransport.java
                  ./varia/src/main/org/jboss/jaxr/juddi/transport/SaajTransport.java
                  ./varia/src/main/org/jboss/jaxr/juddi/transport/WS4EESaajTransport.java

                  • 6. Re: Logging screwed up ?
                    M Cantrell Newbie

                    We had the same issue. We resolved the problem by removing the log4j.jar deployed w/ our webapp.

                    • 7. Re: Logging screwed up ?
                      Jens Elkner Apprentice

                      Ehmmm nope. No app comes or gets installed with a log4j.jar and there is only one log4j archive on the server.

                      • 8. Re: Logging screwed up ?
                        Jens Elkner Apprentice

                        Hmmm, seems to be a [n]log4j problem - see http://bugzilla.slf4j.org/show_bug.cgi?id=23.

                        Fixed it by a small modification/extension to Category, SLF4JLog and Logger (so no more apache commons-logging anywhere - hurray ;-)).

                        BTW: jboss-4.0.4.GA-src/thirdparty/apache-logging/component-info.xml states, that the
                        commons-logging.jar is a patched version. Is this patch somewhere available?

                        • 9. Re: Logging screwed up ?
                          Scott Stark Master

                          Its in the cvs repository (http://wiki.jboss.org/wiki/Wiki.jsp?page=CVSRepository) under apache/commons-logging

                          cvs co -r Apache_Common_Logging_1_0_5_JBoss apache/commons-logging

                          Fisheye:
                          http://fisheye.jboss.org/viewrep/JBoss/apache/commons-logging