[GLASSFISH-16162] Cannot start standalone instance Created: 04/Mar/11  Updated: 09/Jan/13  Resolved: 10/Apr/11

Status: Closed
Project: glassfish
Component/s: logging
Affects Version/s: 3.1_b43
Fix Version/s: 3.1.1_b01

Type: Bug Priority: Major
Reporter: lidiam Assignee: naman_mehta
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

solaris sparc


Attachments: HTML File 8691     HTML File 8743     File server.log.started-notrunning    

 Description   

I'm trying to start a standalone instance but the action hangs from both Admin Console and CLI. After trying with --verbose, with Joe's advice, here is what I see:

tuppy(j2eetest):/export/home/j2eetest/v3.1/glassfish3/glassfish# a start-local-instance --verbose in1
CLI801 Instance is already synchronized
Mar 4, 2011 5:52:23 PM com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: JVM invocation command line:
/export/home/j2eetest/jdk/bin/java
-cp
/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/glassfish.jar
-XX:+UnlockDiagnosticVMOptions
-XX:MaxPermSize=192m
-XX:NewRatio=2
-Xmx512m
-javaagent:/export/home/j2eetest/v3.1/glassfish3/glassfish/lib/monitor/btrace-agent.jar=unsafe=true,noServer=true
-server
-Dosgi.shell.telnet.maxconn=1
-Dfelix.fileinstall.disableConfigSave=false
-Djdbc.drivers=org.apache.derby.jdbc.ClientDriver
-Dfelix.fileinstall.dir=/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/autostart/
-Djavax.net.ssl.keyStore=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/keystore.jks
-Dosgi.shell.telnet.port=26666
-Djava.security.policy=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/server.policy
-Dfelix.fileinstall.log.level=3
-Dfelix.fileinstall.poll=5000
-Dcom.sun.aas.instanceRoot=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1
-Dosgi.shell.telnet.ip=127.0.0.1
-Dcom.sun.enterprise.config.config_environment_factory_class=com.sun.enterprise.config.serverbeans.AppserverConfigEnvironmentFactory
-Djava.endorsed.dirs=/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/endorsed:/export/home/j2eetest/v3.1/glassfish3/glassfish/lib/endorsed
-Dcom.sun.aas.installRoot=/export/home/j2eetest/v3.1/glassfish3/glassfish
-Dfelix.fileinstall.bundles.startTransient=true
-Djava.ext.dirs=/export/home/j2eetest/jdk/lib/ext:/export/home/j2eetest/jdk/jre/lib/ext:/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/lib/ext
-Dfelix.fileinstall.bundles.new.start=true
-Djavax.net.ssl.trustStore=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/cacerts.jks
-Dorg.glassfish.additionalOSGiBundlesToStart=org.apache.felix.shell,org.apache.felix.gogo.runtime,org.apache.felix.gogo.shell,org.apache.felix.gogo.command
-Dcom.sun.enterprise.security.httpsOutboundKeyAlias=s1as
-Djava.security.auth.login.config=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/login.conf
-DANTLR_USE_DIRECT_CLASS_LOADING=true
Dgosh.args=-noshutdown -c noop=true
-Djava.library.path=/export/home/j2eetest/v3.1/glassfish3/glassfish/lib:/export/home/j2eetest/jdk/jre/lib/sparc/server:/export/home/j2eetest/jdk/jre/lib/sparc:/export/home/j2eetest/jdk/lib/sparc:/usr/jdk/packages/lib/sparc:/lib:/usr/lib
com.sun.enterprise.glassfish.bootstrap.ASMain
-asadmin-args
-host,,,localhost,,,port,,,4848,,,secure=false,,,terse=false,,,echo=false,,,interactive=false,,,start-local-instance,,,verbose=true,,,-debug=false,,,in1
-instancename
in1
-verbose
true
-debug
false
-asadmin-classpath
/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/admin-cli.jar
-asadmin-classname
com.sun.enterprise.admin.cli.AsadminMain
-upgrade
false
-type
INSTANCE
-instancedir
/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1
-read-stdin
true
Mar 4, 2011 5:52:23 PM com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: Successfully launched in 100 msec.
Launching GlassFish on Felix platform
Exception in thread "main" java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.enterprise.glassfish.bootstrap.GlassFishMain.main(GlassFishMain.java:97)
at com.sun.enterprise.glassfish.bootstrap.ASMain.main(ASMain.java:55)
Caused by: java.lang.NullPointerException
at com.sun.enterprise.server.logging.SyslogHandler.postConstruct(SyslogHandler.java:88)
at com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
at com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:91)
at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
at org.jvnet.hk2.component.Habitat$5.get(Habitat.java:701)
at java.util.AbstractList$Itr.next(AbstractList.java:345)
at com.sun.enterprise.server.logging.LogManagerService.postConstruct(LogManagerService.java:263)
at com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
at com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:91)
at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
at com.sun.enterprise.v3.server.AppServerStartup.run(AppServerStartup.java:219)
at com.sun.enterprise.v3.server.AppServerStartup.start(AppServerStartup.java:135)
at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.start(GlassFishImpl.java:79)
at com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:117)
... 6 more

The exception seems to come from logging, hence I'm logging this bug under this module.

A little background: I've been using this solaris system for verifying 3.1 bugs for the past week or so. I encountered this issue yesterday. The last thing I did was undeploy a hello.war application from this instance while it was stopped (didn't actually mean to do this). When I went to the standalone instance's page and clicked on Start button. The "processing, please wait" message was displayed and never went away. I checked CLI and it reported this instance as stopped but with odd status:

tuppy(j2eetest):/export/home/j2eetest/v3.1/glassfish3/glassfish/domains/domain1/logs# a list-instances
in1 not running [pending config changes are: _get-runtime-info; _get-runtime-info; ]
c1in1 running
in2 not running
Command list-instances executed successfully.

After reloading Admin Console, the instance was reported as stopped there too.

I checked jps -v and it looked like there were two in1 processes running:

tuppy(j2eetest):/export/home/j2eetest/v3.1/glassfish3/glassfish/domains/domain1/logs# jps -v
8743 ASMain -XX:+UnlockDiagnosticVMOptions -XX:MaxPermSize=192m -XX:NewRatio=2 -Xmx512m -javaagent:/export/home/j2eetest/v3.1/glassfish3/glassfish/lib/monitor/btrace-agent.jar=unsafe=true,noServer=true -Dosgi.shell.telnet.maxconn=1 -Dfelix.fileinstall.disableConfigSave=false -Djdbc.drivers=org.apache.derby.jdbc.ClientDriver -Dfelix.fileinstall.dir=/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/autostart/ -Djavax.net.ssl.keyStore=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/keystore.jks -Dosgi.shell.telnet.port=26666 -Djava.security.policy=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/server.policy -Dfelix.fileinstall.log.level=3 -Dfelix.fileinstall.poll=5000 -Dcom.sun.aas.instanceRoot=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1 -Dosgi.shell.telnet.ip=127.0.0.1 -Dcom.sun.enterprise.config.config_environment_factory_class=com.sun.enterprise.config.serverbeans.AppserverConfigEnvironmentFactory -Djava.endorsed.
...
8691 ASMain -XX:+UnlockDiagnosticVMOptions -XX:MaxPermSize=192m -XX:NewRatio=2 -Xmx512m -javaagent:/export/home/j2eetest/v3.1/glassfish3/glassfish/lib/monitor/btrace-agent.jar=unsafe=true,noServer=true -Dosgi.shell.telnet.maxconn=1 -Dfelix.fileinstall.disableConfigSave=false -Djdbc.drivers=org.apache.derby.jdbc.ClientDriver -Dfelix.fileinstall.dir=/export/home/j2eetest/v3.1/glassfish3/glassfish/modules/autostart/ -Djavax.net.ssl.keyStore=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/keystore.jks -Dosgi.shell.telnet.port=26666 -Djava.security.policy=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1/config/server.policy -Dfelix.fileinstall.log.level=3 -Dfelix.fileinstall.poll=5000 -Dcom.sun.aas.instanceRoot=/export/home/j2eetest/v3.1/glassfish3/glassfish/nodes/localhost-domain1/in1 -Dosgi.shell.telnet.ip=127.0.0.1 -Dcom.sun.enterprise.config.config_environment_factory_class=com.sun.enterprise.config.serverbeans.AppserverConfigEnvironmentFactory -Djava.endorsed.

At this point I asked Joe for help and he confirmed that indeed there were two in1 processes on the system. I'm attaching thread dump for both of them. I also checked instance's server.log and it looks like the shutdown from that day was not clean. Here is the output of the shutdown from a couple days earlier on the same instance that completed:

[#|2011-02-23T19:04:20.327-0800|INFO|oracle-glassfish3.1|javax.enterprise.system
.tools.admin.org.glassfish.server|_ThreadID=79;_ThreadName=Thread-2;|JMXStartupS
ervice: Stopped JMXConnectorServer: null|#]

[#|2011-02-23T19:04:20.329-0800|INFO|oracle-glassfish3.1|javax.enterprise.system
.tools.admin.org.glassfish.server|_ThreadID=79;_ThreadName=Thread-2;|JMXStartupS
ervice and JMXConnectors have been shut down.|#]

[#|2011-02-23T19:04:20.330-0800|INFO|oracle-glassfish3.1|javax.enterprise.system
.core.com.sun.enterprise.v3.server|_ThreadID=79;_ThreadName=Thread-2;|Shutdown p
rocedure finished|#]

Feb 25, 2011 12:13:58 PM com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: JVM invocation command line:
/export/home/j2eetest/jdk/bin/java

While the latest shutdown is missing the "Shutdown procedure finished" line:

[#|2011-03-03T15:49:31.811-0800|INFO|oracle-glassfish3.1|javax.enterprise.system
.tools.admin.org.glassfish.server|_ThreadID=1120;_ThreadName=Thread-2;|JMXStartu
pService: Stopped JMXConnectorServer: null|#]

[#|2011-03-03T15:49:31.813-0800|INFO|oracle-glassfish3.1|javax.enterprise.system
.tools.admin.org.glassfish.server|_ThreadID=1120;_ThreadName=Thread-2;|JMXStartu
pService and JMXConnectors have been shut down.|#]

Mar 3, 2011 3:51:25 PM com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: JVM invocation command line:
/export/home/j2eetest/jdk/bin/java

At this point, I killed both processes and tried to start the instance again - it would still hang and the output of the verbose option is listed at the top (hence we came the full circle). I'm attaching server.log from the start of testing till the initial startup hang and thread dumps of both processes that belonged to the instance. The machine is still available for debugging.



 Comments   
Comment by naman_mehta [ 07/Mar/11 ]

Don't able to reproduce the same. Please provide me the exact steps to reproduce.

Looks like it's machine specific issue.

Comment by naman_mehta [ 21/Mar/11 ]

hi lidia,

Wouldn't able to reproduce the same. Assigning this issue in your name. If still reproducible by you then give me exact steps and machine details.

Comment by lidiam [ 22/Mar/11 ]

It is not an issue that can be easily reproduced. I do not know what caused it in the first place, however, since the outcome was quite severe, I was asked to log an issue. You can close it if you want. If anybody encounters it in the future, we can reopen.

Comment by lidiam [ 22/Mar/11 ]

One more note, Joe Di Pol was helping debug this issue and this is how far we got. I kept the machine intact for a couple of days for debugging, but Glassfish has been reinstalled since. Glassfish worked flawlessly on this machine for months, so it's not necessarily a machine specific issue. After reinstall everything is working fine again. Series of many steps got Glassfish in this situation and unfortunately can't be reproduced.

Comment by naman_mehta [ 22/Mar/11 ]

As per the comments by lidia this issue is not reproducible.

But to avoid NPE in the code made some changes to catch the same. Committed revision 45678.

Comment by Matthias Wimmer [ 14/Apr/11 ]

Same problem existed here today. I found the reason for this to be some configuration properties missing in the file logging.properties in the config directory within the domain.
The first missing properties, causing this exception was "com.sun.enterprise.server.logging.SyslogHandler.useSystemLogging". After I have added this property, glassfish did not catch a NullPointerException in line 88 of SyslogHandler.java. But I got the next exception for the property "com.sun.enterprise.server.logging.GFFileHandler.file", which was missing as well.
As I expected even more properties would miss, I then copied a logging.properties file from a working domain on an other server. With the new logging.properties glassfish did start again.

Probably the broken logging.properties file was produced by editing a log level setting using the web interface by one of my coleagues last night.

The broken logging.properties file produced by the web interface we had, solely contains the following content:

#GlassFish logging.properties list
#Wed Apr 13 22:02:29 UTC 2011
javax.enterprise.system.tools.admin.level=INFO
javax.enterprise.system.ssl.security.level=OFF
org.apache.jasper.level=INFO
javax.enterprise.system.tools.backup.level=INFO
javax.enterprise.resource.corba.level=INFO
javax.enterprise.resource.webcontainer.jsf.resource.level=INFO
javax.enterprise.system.core.classloading.level=INFO
javax.enterprise.resource.jta.level=INFO
java.util.logging.ConsoleHandler.level=FINEST
javax.enterprise.system.webservices.saaj.level=INFO
javax.enterprise.system.tools.deployment.level=INFO
javax.enterprise.system.container.ejb.level=INFO
javax.enterprise.system.core.transaction.level=INFO
org.apache.catalina.level=INFO
javax.enterprise.resource.webcontainer.jsf.lifecycle.level=INFO
javax.enterprise.resource.webcontainer.jsf.config.level=INFO
javax.enterprise.system.container.ejb.mdb.level=INFO
javax.enterprise.resource.webcontainer.jsf.timing.level=INFO
javax.enterprise.system.core.level=INFO
org.apache.coyote.level=INFO
javax.level=INFO
javax.enterprise.resource.webcontainer.jsf.taglib.level=INFO
com.nicbase.server.infra.keyvalue.level=FINEST
javax.enterprise.resource.javamail.level=INFO
javax.enterprise.system.webservices.rpc.level=INFO
javax.enterprise.system.container.web.level=INFO
javax.enterprise.system.util.level=INFO
javax.enterprise.resource.webcontainer.jsf.facelets.level=INFO
javax.enterprise.resource.resourceadapter.level=INFO
javax.org.glassfish.persistence.level=INFO
javax.enterprise.resource.webcontainer.jsf.context.level=INFO
javax.enterprise.resource.webcontainer.jsf.application.level=INFO
javax.enterprise.resource.jms.level=INFO
javax.enterprise.system.core.config.level=INFO
org.jvnet.hk2.osgiadapter.level=INFO
javax.enterprise.system.level=INFO
javax.enterprise.system.core.security.level=INFO
javax.enterprise.resource.sqltrace.level=FINE
javax.enterprise.resource.webcontainer.jsf.renderkit.level=INFO
javax.enterprise.system.webservices.registry.level=INFO
javax.enterprise.system.core.selfmanagement.level=INFO
javax.enterprise.resource.webcontainer.jsf.managedbean.level=INFO
org.glassfish.admingui.level=INFO
javax.enterprise.resource.jdo.level=INFO
javax.enterprise.system.core.naming.level=INFO

Comment by naman_mehta [ 14/Apr/11 ]

We added code for checking that properties is present or not so NPE is avoided now.

Tried to made changes under Logger Settings page from admin GUI but couldn't reproduce broken logging.properties file. So question is how to reproduce broken logging.properties file from web interface. Let me know if it's reproducible.

Comment by juergenschmied [ 22/Feb/12 ]

Same problem. Rebuilding logging.properties helped.

Comment by roinou [ 06/Apr/12 ]

Same problem here.

It happened in our PRODUCTION environment this morning. After a routine restart, it was no longer possible to restart the server. Thanks to this issue, we reconstructed the "logging.properties" from our ACCEPTANCE and it fixed the problem.

The question is, HOW did this file get corrupted? last modification date stated 2012/03/29, today is 2012/04/06. This is a serious issue, we lost 3 hours of working time this morning.

Comment by cobre420 [ 09/Jan/13 ]

Same trouble today (9.1.2013) with glassfish 3.1.2.2. end of stacktrace
at com.sun.enterprise.server.logging.SyslogHandler.postConstruct(SyslogHandler.java:86)
at com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
at com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:91)
at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:78)
at org.jvnet.hk2.component.Habitat$5.get(Habitat.java:703)
at java.util.AbstractList$Itr.next(AbstractList.java:345)
at com.sun.enterprise.server.logging.LogManagerService.postConstruct(LogManagerService.java:374)
at com.sun.hk2.component.AbstractCreatorImpl.inject(AbstractCreatorImpl.java:131)
at com.sun.hk2.component.ConstructorCreator.initialize(ConstructorCreator.java:91)
at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:82)
at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:78)
at com.sun.enterprise.v3.server.AppServerStartup.run(AppServerStartup.java:229)
at com.sun.enterprise.v3.server.AppServerStartup.doStart(AppServerStartup.java:145)
at com.sun.enterprise.v3.server.AppServerStartup.start(AppServerStartup.java:136)
at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.start(GlassFishImpl.java:79)
at com.sun.enterprise.glassfish.bootstrap.GlassFishDecorator.start(GlassFishDecorator.java:63)
at com.sun.enterprise.glassfish.bootstrap.osgi.OSGiGlassFishImpl.start(OSGiGlassFishImpl.java:69)
at com.sun.enterprise.glassfish.bootstrap.GlassFishMain$Launcher.launch(GlassFishMain.java:117)

Replacing the logging.properties helped.. Any advice or help, how to prevent from this behavior?

Generated at Sat Feb 28 15:53:38 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.