admin@glassfish.java.net

Re: QL logging errors

From: Byron Nevins <byron.nevins_at_oracle.com>
Date: Thu, 28 Apr 2011 16:36:55 -0700

+1

On 4/28/2011 3:59 PM, Bill Shannon wrote:
> I'd definitely like to see more automated checking of error and log
> messages, although I was envisioning doing that at the source code or
> class file level.
>
> I'm a bit worried that, even if we clean up all the known problems,
> there's enough uncertainty in the behavior of quicklook that we'll
> expose a lot of errors that aren't caused by what any person is changing.
>
> Here's what I think we should do...
>
> We should clean up all the errors currently found by this test.
>
> We should set up a couple of Hudson jobs that run quicklook on
> different platforms and *fail* if this test finds any errors. (Maybe
> an environment variable could control whether these errors cause
> failure or not?) Let's run those jobs for a few weeks and see what
> kind of failures we see. If we only ever see real failures, we should
> make this be the default behavior.
>
> Does that seem reasonable?
>
>
> Koper, Dies wrote on 04/25/2011 08:39 PM:
>>
>> Hi Byron, Bill,
>>
>> I’ve created GLASSFISH-16450 for the issue with the first message.
>>
>> ØIs there a point to doing this in the Quick Look Tests? I never see
>> it change. It seems to be ignored. Or am I missing something? E.g.
>> does it send badgering emails to the authors of code that have
>> logging problems?
>>
>> It seems you are right.
>>
>> As it checks messages in server.log, it needs to be run after GF has
>> been used at runtime.
>>
>> Running it in a svn commit hook is not an option.
>>
>> So I thought it would be good to have it run automatically at the end
>> of the Quicklook tests and cause it to fail the tests, thereby
>> failing the build, which in turn would cause authors who introduced
>> the issues to be badgered by hudson e-mails.
>>
>> I was hoping once we had that in place, we could have something
>> similar done for CTS, as that would catch many more broken messages.
>>
>> Unfortunately Naman and I couldn’t get Ming’s permission to include
>> the change to make it fail the QL tests.
>>
>> Clearly, without having a way of enforcement new broken messages will
>> be introduced.
>>
>> Bill, just like raising the bar on Findbugs, can’t we raise the bar
>> on messages?
>>
>> All we need is someone who can convince Ming, or come up with another
>> solution.
>>
>> FYI, this is how I envisioned the target would work:
>>
>> 1.Before introducing the change to fail the QL, we’ll need to address
>> the current issues.
>>
>> 2.As soon as we have 0 message issues, make the change to let it fail
>> the QL tests.
>>
>> 3.Next time a committer makes a change that causes the task to fail
>> due to:
>>
>> a.a message with logging problems
>>
>> b.a message that is excluded from the requirement to have a message ID
>>
>> c.logging a stacktrace
>>
>> d.adding a new VM option or other string mistaken to be a message
>>
>> this person would have to fix it by e.g.:
>>
>> a.fixing the message or stacktrace
>>
>> b.adding the string to the exclude list
>>
>> Depending on how it goes we could reconsider for a next release to
>> reduce the types of messages that do not get assigned message IDs.
>>
>> Regards,
>>
>> Dies
>>
>> *From:*Byron Nevins [mailto:byron.nevins_at_oracle.com]
>> *Sent:* Tuesday, 26 April 2011 04:48
>> *To:* Naman Mehta; admin_at_glassfish.java.net
>> *Subject:* QL logging errors
>>
>> Is there a point to doing this in the Quick Look Tests? I never see
>> it change. It seems to be ignored. Or am I missing something? E.g.
>> does it send badgering emails to the authors of code that have
>> logging problems?
>>
>> check-logged-messages:
>> [echo] Checking messages in:
>> [echo] c:\Hudson\BUILD_AREA\workspace\gf-trunk-build-windows\gfv3-gp\glassfish3\glassfish\domains\domain1\logs\server.log
>> [echo]
>> [copy] Copying 1 file to C:\Hudson\BUILD_AREA\workspace\gf-trunk-build-windows\v3\tests\test-output
>> [echo]
>> [echo] * Message keys logged instead of message:
>> [echo] (none)
>> [echo]
>> [echo] * Parameter marker not substituted with value:
>> [echo] [#|2011-04-25T12:51:19.015-0500|INFO|glassfish3.2|javax.enterprise.resource.jms.com.sun.enterprise.connectors.jms.system|_ThreadID=48;_ThreadName=Thread-1;|end point determine destionation name, Res name: javax.jms.Queue, JNDI name: MessageBean descriptor name : {3}|#]
>> [echo]
>> [echo]
>> [echo] * Bundle not found:
>> [echo] (none)
>> [echo]
>> [echo] * Messages not found in message bundle:
>> [echo] (none)
>> [echo]
>> [echo] * No message:
>> [echo] (none)
>> [echo]
>> [echo] * Messages with common typo's ('occured' with one 'r', 'dont' missing apostrophe, etc.):
>> [echo] (none)
>> [echo]
>> [echo] * Messages with double apostrophes:
>> [echo] (none)
>> [echo]
>> [echo] * Messages with no proper message Id:
>> [echo] -Dgosh.args=--nointeractive
>> [echo] -Dorg.glassfish.additionalOSGiBundlesToStart=org.apache.felix.shell,org.apache.felix.gogo.runtime,org.apache.felix.gogo.shell,org.apache.felix.gogo.command,org.apache.felix.shell.remote,org.apache.felix.fileinstall
>> [echo] [#|2011-04-25T12:40:07.359-0500|INFO|glassfish3.2|javax.enterprise.system.core.com.sun.enterprise.v3.admin.adapter|_ThreadID=20;_ThreadName=Thread-1;|The Admin Console is starting. Please wait.|#]
>> [echo] -Dgosh.args=--nointeractive
>> [echo] -Dorg.glassfish.additionalOSGiBundlesToStart=org.apache.felix.shell,org.apache.felix.gogo.runtime,org.apache.felix.gogo.shell,org.apache.felix.gogo.command,org.apache.felix.shell.remote,org.apache.felix.fileinstall
>> [echo] -Djava.security.manager
>> [echo] Apr 25, 2011 12:40:21 PM null
>> [echo] -Dgosh.args=--nointeractive
>> [echo] -Dorg.glassfish.additionalOSGiBundlesToStart=org.apache.felix.shell,org.apache.felix.gogo.runtime,org.apache.felix.gogo.shell,org.apache.felix.gogo.command,org.apache.felix.shell.remote,org.apache.felix.fileinstall
>> [echo] -Djava.security.manager
>> [echo] Apr 25, 2011 12:40:53 PM null
>> [echo] [#|2011-04-25T12:43:49.687-0500|WARNING|glassfish3.2|org.jboss.interceptor.reader.InterceptorMetadataUtils|_ThreadID=21;_ThreadName=Thread-1;|Method init defined on class numberguess.InterceptorB will not be used for interception, since it is not defined according to the specification. It is annotated with @javax.annotation.PostConstruct, but is defined on the target class and does not have 0 arguments|#]
>> [echo] [#|2011-04-25T12:43:49.687-0500|WARNING|glassfish3.2|org.jboss.interceptor.reader.InterceptorMetadataUtils|_ThreadID=21;_ThreadName=Thread-1;|Method destroy defined on class numberguess.InterceptorB will not be used for interception, since it is not defined according to the specification. It is annotated with @javax.annotation.PreDestroy, but is defined on the target class and does not have 0 arguments|#]
>> [echo] [#|2011-04-25T12:45:27.484-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=17;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(null)- permission((java.lang.RuntimePermission createClassLoader))|#]
>> [echo] [#|2011-04-25T12:46:55.968-0500|INFO|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=22;_ThreadName=Thread-1;|Initialized AMXStartupServiceNew in 12 ms, registered as amx-support:type=amx-loader,name=startup|#]
>> [echo] [#|2011-04-25T12:46:56.062-0500|INFO|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=23;_ThreadName=Thread-1;|In AMXConfigLoader : loader == null|#]
>> [echo] [#|2011-04-25T12:46:56.546-0500|INFO|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=23;_ThreadName=Thread-1;|AMX config read, domain config registered as amx:pp=/,type=domain|#]
>> [echo] [#|2011-04-25T12:46:57.000-0500|INFO|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=24;_ThreadName=Thread-1;|J2EEDomain registered at amx:pp=/,type=J2EEDomain,j2eeType=J2EEDomain,name=amx|#]
>> [echo] [#|2011-04-25T12:46:57.000-0500|INFO|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=22;_ThreadName=Thread-1;|AMXStartupServiceNew: AMX ready for use, DomainRoot = amx:pp=,type=domain-root|#]
>> [echo] [#|2011-04-25T12:47:16.500-0500|WARNING|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=26;_ThreadName=Thread-1;|Non-singleton ConfigBean com.sun.enterprise.config.serverbeans.Config has empty key value (name), supplying MISSING_NAME-1|#]
>> [echo] [#|2011-04-25T12:48:11.515-0500|WARNING|glassfish3.2|null|_ThreadID=19;_ThreadName=Thread-1;|config.getHttpService() null for config 'AMXConfigProxyTests.TEST'|#]
>> [echo] [#|2011-04-25T12:48:11.640-0500|INFO|glassfish3.2|javax.enterprise.system.core.com.sun.enterprise.v3.admin.adapter|_ThreadID=32;_ThreadName=Thread-1;|The Admin Console is starting. Please wait.|#]
>> [echo] [#|2011-04-25T12:50:04.765-0500|INFO|glassfish3.2|org.glassfish.admingui|_ThreadID=21;_ThreadName=Thread-1;|Admin Console: Initializing Session Attributes...|#]
>> [echo] [#|2011-04-25T12:50:32.000-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(jdbcusertx/jdbcusertx)- permission((java.lang.RuntimePermission getenv.AS_DEBUG))|#]
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 104 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 106 more
>> [echo] [#|2011-04-25T12:50:33.296-0500|SEVERE|glassfish3.2|javax.enterprise.system.tools.monitor.org.glassfish.admin.monitor|_ThreadID=37;_ThreadName=Thread-1;|MNTG0205:Gmbal registration failed
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 104 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 106 more
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 128 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 130 more
>> [echo] [#|2011-04-25T12:50:33.890-0500|SEVERE|glassfish3.2|javax.enterprise.system.tools.monitor.org.glassfish.admin.monitor|_ThreadID=35;_ThreadName=Thread-1;|MNTG0205:Gmbal registration failed
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 128 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 130 more
>> [echo] [#|2011-04-25T12:50:36.046-0500|WARNING|glassfish3.2|javax.enterprise.system.container.web.com.sun.web.security|_ThreadID=38;_ThreadName=Thread-1;|Exception
>> [echo] com.sun.enterprise.security.auth.login.common.LoginException: Login failed: Failed file login for j2ee.
>> [echo] Caused by: javax.security.auth.login.LoginException: Failed file login for j2ee.
>> [echo] ... 29 more
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 110 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 112 more
>> [echo] [#|2011-04-25T12:50:42.578-0500|SEVERE|glassfish3.2|javax.enterprise.system.tools.monitor.org.glassfish.admin.monitor|_ThreadID=35;_ThreadName=Thread-1;|MNTG0205:Gmbal registration failed
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 110 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 112 more
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 92 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 94 more
>> [echo] [#|2011-04-25T12:50:43.625-0500|SEVERE|glassfish3.2|javax.enterprise.system.tools.monitor.org.glassfish.admin.monitor|_ThreadID=37;_ThreadName=Thread-1;|MNTG0205:Gmbal registration failed
>> [echo] Caused by: java.lang.RuntimeException: Can't add NotificationListener
>> [echo] ... 92 more
>> [echo] Caused by: java.security.AccessControlException: access denied (javax.management.MBeanPermission javax.management.MBeanServerDelegate#-[JMImplementation:type=MBeanServerDelegate] addNotificationListener)
>> [echo] ... 94 more
>> [echo] [#|2011-04-25T12:50:43.734-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=37;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(RosterApp/RosterAppEJB_jar)- permission((org.osgi.framework.AdminPermission (id=154) resolve,resource))|#]
>> [echo] [#|2011-04-25T12:50:44.171-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=37;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(RosterApp/RosterAppEJB_jar)- permission((org.osgi.framework.AdminPermission (id=154) resolve,resource))|#]
>> [echo] [#|2011-04-25T12:50:44.750-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=37;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(RosterApp/RosterAppEJB_jar)- permission((org.osgi.framework.AdminPermission (id=154) resolve,resource))|#]
>> [echo] [#|2011-04-25T12:50:49.156-0500|INFO|glassfish3.2|javax.enterprise.resource.jms.com.sun.enterprise.connectors.jms.system|_ThreadID=47;_ThreadName=Thread-1;|ADDRESSLIST in setJmsServiceProvider: mq://localhost:7676/|#]
>> [echo] [#|2011-04-25T12:51:19.015-0500|INFO|glassfish3.2|javax.enterprise.resource.jms.com.sun.enterprise.connectors.jms.system|_ThreadID=48;_ThreadName=Thread-1;|end point determine destionation name, Res name: javax.jms.Queue, JNDI name: MessageBean descriptor name : {3}|#]
>> [echo] [#|2011-04-25T12:51:48.078-0500|WARNING|glassfish3.2|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=46;_ThreadName=Thread-1;|
>> [echo] [#|2011-04-25T12:51:48.093-0500|WARNING|glassfish3.2|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=49;_ThreadName=Thread-1;|
>> [echo] [#|2011-04-25T12:51:49.062-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=49;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(ejb-ejb30-hello-mdbApp/ejb-ejb30-hello-mdb-ejb_jar)- permission((java.lang.RuntimePermission getenv.AS_DEBUG))|#]
>> [echo] [#|2011-04-25T12:51:55.953-0500|WARNING|glassfish3.2|javax.faces|_ThreadID=36;_ThreadName=Thread-1;|Multiple JSF Applications found on same ClassLoader. Unable to safely determine which FactoryManager instance to use. Defaulting to first match.|#]
>> [echo] [#|2011-04-25T12:51:55.953-0500|WARNING|glassfish3.2|javax.faces|_ThreadID=36;_ThreadName=Thread-1;|Multiple JSF Applications found on same ClassLoader. Unable to safely determine which FactoryManager instance to use. Defaulting to first match.|#]
>> [echo] [#|2011-04-25T12:52:04.484-0500|INFO|glassfish3.2|javax.enterprise.system.core.security|_ThreadID=34;_ThreadName=Thread-1;|JACC Policy Provider: Failed Permission Check, context(jaxbosgi/jaxbosgi)- permission((org.osgi.framework.AdminPermission (id=154) resolve,resource))|#]
>> [echo] FAILURE_DETECT_TCP_RETRANSMIT_TIMEOUT(ms):10000
>> [echo] START_TIMEOUT(ms):15000 WRITE_TIMEOUT(ms):10000
>> [echo] /0.0.0.0;
>> [echo] multicast address:/228.9.28.49 timeToLive=4|#]
>> [echo] [#|2011-04-25T12:54:10.453-0500|WARNING|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=66;_ThreadName=Thread-1;|Can't unregister MBean: amx:pp=/domain/clusters/cluster[eec1],type=application-ref,name=helloworld
>> [echo] javax.management.InstanceNotFoundException: amx:pp=/J2EEDomain/J2EEServer[eein1-with-a-very-very-very-long-name],type=WebModule,name=helloworld,j2eeType=WebModule,J2EEServer=eein1-with-a-very-very-very-long-name,J2EEApplication=null
>> [echo] [#|2011-04-25T12:54:10.453-0500|WARNING|glassfish3.2|javax.enterprise.system.tools.admin.org.glassfish.admin.amx.impl.util|_ThreadID=66;_ThreadName=Thread-1;|Can't unregister MBean: amx:pp=/domain/clusters/cluster[eec1],type=application-ref,name=helloworld
>> [echo] javax.management.InstanceNotFoundException: amx:pp=/J2EEDomain/J2EEServer[eein2],type=WebModule,name=helloworld,j2eeType=WebModule,J2EEServer=eein2,J2EEApplication=null
>> [echo] [#|2011-04-25T12:54:22.906-0500|SEVERE|glassfish3.2|null|_ThreadID=70;_ThreadName=Thread-1;|Config Listener notification got interrupted
>> [echo] java.util.concurrent.ExecutionException: java.lang.NullPointerException
>> [echo] Caused by: java.lang.NullPointerException
>> [echo] ... 5 more
>> [echo] [#|2011-04-25T12:54:31.984-0500|SEVERE|glassfish3.2|null|_ThreadID=66;_ThreadName=Thread-1;|Config Listener notification got interrupted
>> [echo] java.util.concurrent.ExecutionException: java.lang.NullPointerException
>> [echo] Caused by: java.lang.NullPointerException
>> [echo] ... 5 more
>> [echo] [#|2011-04-25T12:54:50.640-0500|WARNING|glassfish3.2|javax.management.remote.misc|_ThreadID=78;_ThreadName=Thread-1;|Failed to restart: java.io.IOException: Failed to get a RMI stub: javax.naming.ServiceUnavailableException [Root exception is java.rmi.ConnectException: Connection refused to host: localhost; nested exception is:
>> [echo] java.net.ConnectException: Connection refused: connect]|#]
>> [echo] [#|2011-04-25T12:54:51.625-0500|WARNING|glassfish3.2|javax.management.remote.rmi|_ThreadID=78;_ThreadName=Thread-1;|Failed to call the method close():java.rmi.ConnectException: Connection refused to host: 10.232.128.191; nested exception is:
>> [echo] java.net.ConnectException: Connection refused: connect|#]
>> [echo] [#|2011-04-25T12:54:51.625-0500|WARNING|glassfish3.2|javax.management.remote.misc|_ThreadID=78;_ThreadName=Thread-1;|Failed to check connection: java.net.ConnectException: Connection refused: connect|#]
>> [echo] [#|2011-04-25T12:54:51.625-0500|WARNING|glassfish3.2|javax.management.remote.misc|_ThreadID=78;_ThreadName=Thread-1;|stopping|#]
>> [echo]
>> [echo]
>>
>> pass:
>>
>> fail:
>> [echo] ======================================================================
>> [echo] FAILED: check-logged-messages
>> [echo] Issues found in one or more messages (see results above).
>> [echo] Please address them, or if the message should be left as-is,
>> [echo] add it to the exclusion list with details why it should be excluded:
>> [echo] C:\Hudson\BUILD_AREA\workspace\gf-trunk-build-windows\v3\tests\quicklook\gfproject\log_msg_excl.txt
>> [echo] ======================================================================
>>
>>
>> --
>> Oracle <http://www.oracle.com/>
>> Byron Nevins | Principal MTS
>> Phone: +1 6503958992 <tel:+1%206503958992>
>>
>> Green Oracle <http://www.oracle.com/commitment>Oracle is committed to
>> developing practices and products that help protect the environment
>>
>

-- 
Oracle <http://www.oracle.com>
Byron Nevins | Principal MTS
Phone: +1 6503958992 <tel:+1%206503958992>
Green Oracle <http://www.oracle.com/commitment> Oracle is committed to 
developing practices and products that help protect the environment