On Debian : LogConfigurationException on Tomcat deploy

[liotier]

Hi, I am encountering this exception on the deployment of Alfresco by Tomcat :

Oct 27, 2006 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
SEVERE: Error deploying web application archive alfresco.war
org.apache.commons.logging.LogConfigurationException: java.lang.ExceptionInInitializerError (Caused by java.lang.ExceptionInInitializerError)

I am very novice with Java. I have understood this may have something to do with Log4J but I do not know how to get any further.

I am using Debian with the following packages :

- Tomcat 5.5.20-1
- Liblog4j 1.2.13-1
- Alfresco Community war 1.4.0
- Sun Java 5 JRE & JDK 1.5.0-08-1

It seems they are fine versions that are supposed to work together…

Would anybody here have a clue about what might be failing ?


The full startup log follows :

Using CATALINA_BASE:   /var/lib/tomcat5.5
Using CATALINA_HOME:   /usr/share/tomcat5.5
Using CATALINA_TMPDIR: /var/lib/tomcat5.5/temp
Using JRE_HOME:       /usr/lib/jvm/java-1.5.0-sun
Using Security Manager
Oct 27, 2006 6:56:41 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
INFO: The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/lib/jvm/java-1.5.0-sun-1.5.0.08/jre/lib/i386/client:/usr/lib/jvm/java-1.5.0-sun-1.5.0.08/jre/lib/i386:/usr/lib/jvm/java-1.5.0-sun-1.5.0.08/jre/../lib/i386
Oct 27, 2006 6:56:41 PM org.apache.coyote.http11.Http11BaseProtocol init
INFO: Initializing Coyote HTTP/1.1 on http-8180
Oct 27, 2006 6:56:41 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 940 ms
Oct 27, 2006 6:56:41 PM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Oct 27, 2006 6:56:41 PM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/5.5
Oct 27, 2006 6:56:41 PM org.apache.catalina.core.StandardHost start
INFO: XML validation disabled
Oct 27, 2006 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive alfresco.war
Oct 27, 2006 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
SEVERE: Error deploying web application archive alfresco.war
org.apache.commons.logging.LogConfigurationException: java.lang.ExceptionInInitializerError (Caused by java.lang.ExceptionInInitializerError)
        at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:538)
        at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:235)
        at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:370)
        at org.apache.catalina.core.ContainerBase.getLogger(ContainerBase.java:380)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4114)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:759)
        at org.apache.catalina.core.ContainerBase.access$0(ContainerBase.java:743)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:143)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:737)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:524)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:809)
        at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:698)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:472)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1122)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:310)
        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1021)
        at org.apache.catalina.core.StandardHost.start(StandardHost.java:718)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013)
        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442)
        at org.apache.catalina.core.StandardService.start(StandardService.java:450)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:709)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:551)
        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:585)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:294)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:432)
Caused by: java.lang.ExceptionInInitializerError
        at org.apache.log4j.Logger.getLogger(Logger.java:85)
        at org.apache.commons.logging.impl.Log4JLogger.<init>(Log4JLogger.java:102)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:494)
        at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:529)
        … 29 more
Caused by: java.security.AccessControlException: access denied (java.io.FilePermission alfresco.log write)
        at java.security.AccessControlContext.checkPermission(AccessControlContext.java:264)
        at java.security.AccessController.checkPermission(AccessController.java:427)
        at java.lang.SecurityManager.checkPermission(SecurityManager.java:532)
        at java.lang.SecurityManager.checkWrite(SecurityManager.java:962)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:169)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:102)
        at org.apache.log4j.FileAppender.setFile(FileAppender.java:272)
        at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:151)
        at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:206)
        at org.apache.log4j.config.PropertySetter.activate(PropertySetter.java:247)
        at org.apache.log4j.config.PropertySetter.setProperties(PropertySetter.java:123)
        at org.apache.log4j.config.PropertySetter.setProperties(PropertySetter.java:87)
        at org.apache.log4j.PropertyConfigurator.parseAppender(PropertyConfigurator.java:645)
        at org.apache.log4j.PropertyConfigurator.parseCategory(PropertyConfigurator.java:603)
        at org.apache.log4j.PropertyConfigurator.configureRootCategory(PropertyConfigurator.java:500)
        at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:406)
        at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:432)
        at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:460)
        at org.apache.log4j.LogManager.<clinit>(LogManager.java:113)
        … 36 more
Oct 27, 2006 6:56:42 PM org.apache.coyote.http11.Http11BaseProtocol start
INFO: Starting Coyote HTTP/1.1 on http-8180
Oct 27, 2006 6:56:43 PM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8009
Oct 27, 2006 6:56:43 PM org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/28  config=null
Oct 27, 2006 6:56:43 PM org.apache.catalina.storeconfig.StoreLoader load
INFO: Find registry server-registry.xml at classpath resource
Oct 27, 2006 6:56:43 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 1860 ms

[liotier]

How did you solve the permission conflict with the log file?

- I gave ownership of /var/log/tomcat5.5/alfresco.log to the tomcat55 user.
- I added TOMCAT5_SECURITY=no to /etc/default/tomtom5.5

[jml75]

Here is how i fixed this problem:

In "/etc/tomcat5.5/policy.d/40webapps.policy"

I added the following line at the end :

grant codeBase "file:/var/lib/tomcat5.5/webapps/alfresco/-" {
  permission java.io.FilePermission "/var/log/tomcat5.5/alfresco.log", "read,write";
};

and it fixed the permission problem for file /var/log/tomcat5.5/alfresco.log without turning tomcat5.5's security.

But then I have new problems regarding security.

So I think that this shows the right direction for the config of Tomcat. I just have to fond the rest of the changes I have to do.

I'll keep you guys posted!

Thanx!

[jlhenry]

Hello,

Thanks for this help!

I tried it and it works for me too. I'm no trying to resolve the other errors but stop on one quite difficult.

First this error does not seems to be tomcat_security related (as there is no "denied" message), but when I use "TOMCAT5_SECURITY=no" alfresco works like a charm and there is no error!

First here is the result of my work trying to complete this file: /etc/tomcat5.5/policy.d/40webapps.policy :

grant codeBase "file:/var/lib/tomcat5.5/webapps/alfresco/-" {
        permission java.io.FilePermission "/var/log/tomcat5.5/alfresco.log", "read,write";
        permission java.net.SocketPermission "java.sun.com:80", "connect,resolve";
        permission java.lang.RuntimePermission "shutdownHooks";
        permission java.security.SecurityPermission "putProviderProperty.CryptixCrypto";
        permission java.security.SecurityPermission "insertProvider.CryptixCrypto";
        permission java.util.PropertyPermission "alfresco.jmx.dir", "read,write";
        permission java.util.PropertyPermission "form.name", "read";
        permission java.util.PropertyPermission "avm.remote.port", "read";
        permission java.util.PropertyPermission "source", "read";
        permission java.util.PropertyPermission "options", "read";
        permission java.util.PropertyPermission "target", "read";
        permission java.util.PropertyPermission "cache.strategy", "read";
        permission java.util.PropertyPermission "db.script.dialect", "read";
        permission java.lang.RuntimePermission "accessDeclaredMembers";
        permission java.lang.reflect.ReflectPermission "suppressAccessChecks";
        permission java.util.PropertyPermission "user.home", "read";
        permission java.util.PropertyPermission "user.dir", "read";
        permission java.util.PropertyPermission "java.io.tmpdir", "read";
        permission java.util.PropertyPermission "net.sf.ehcache.disabled", "read";
        permission java.util.PropertyPermission "net.sf.ehcache.useLRUMap", "read";
};

As you can see, I've resolved a certain number of issues.

But it seems that there is more to be done as my file is full of error. I'll not dump it all here, but there are error lines like this one:
14:34:52,862 ERROR [org.hibernate.proxy.BasicLazyInitializer] CGLIB Enhancement failed: org.alfresco.repo.avm.MergeLinkImpl

It's not always "org.alfresco.repo.avm.MergeLinkImpl", it's also "org.jbpm.graph.exe.ProcessInstance", "org.jbpm.context.log.VariableLog"…. In fact, I have 117 lines like this one!…

Looks like this error, but it's not exactly the same: http://www.hibernate.org/116.html#A5

Any idea here ????

…. I definitely do not like using "TOMCAT5_SECURITY=no"

Jluc

[jml75]

Hi jlhenry,

I'm at the same point than you now.

I found out the same as you, the same twenty permissions are granted on my server and now I too have errors in the alfresco.log file.

I'll keep on looking on my side and keep you posted with my findings.

Please do the same to.

Jonathan

[jml75]

How can I make an equivalent change in tomcat5.5/shared/classes/alfresco/extension/ instead of tomcat5.5/webapps/alfresco/WEB-INF/classes/?

I can't find where log4j.properties is imported.

/m

I finally found a way to bypass this!!!

Simply copy the file "/var/lib/tomcat5.5/webapps/alfresco/WEB-INF/classes/log4j.properties" in "/usr/share/tomcat5.5/common/classes" and edit it there.

After just restart tomcat server!

P.S.: I don't know thought if this will interfere with any other tomcat apps…

[jml75]

Sorry for editing again my post.

Actually, my trick works only intermittently. Some times it works, some times it does not work.

I just don't get it.

Any one has an other idea else than turning off tomcat security?

[fms]

… is to grant Alfresco all permissions; in /etc/tomcat5.5/policy.d/04webapps.policy (this is the file I have in unstable):

grant codeBase "file:/var/lib/tomcat5.5/webapps/alfresco/-" {
permission java.security.AllPermission;
};

Just to clarify things, this is rather different than turning security off: it simply means that I trust this application. Also, keep in mind that if you don't play to have developers deploying applications on your server, and you simply need to run Alfresco, there is little point in turning tomcat security on.

I should also mention that, in my experience, on top of the packages mentioned in the first post, you also need tomcat5.5-admin, otherwise Alfresco (and I'd suppose, any application) will not deploy. I didn't check whether it starts when tomcat is started, since I didn't care much.

There has always been a short period when I got this error when deploying Alfresco:

INFO: Deploying web application archive alfresco.war
4-lug-2007 23.03.11 org.apache.catalina.core.StandardContext start
GRAVE: Error listenerStart

(I got it again today by trying to use the list of permissions mentioned in the forum). I solved it by binding Tomcat to port 8080, which Alfresco tries to use, rather than the default of 8180; this is changed in the file /etc/tomcat5.5/server.xml, find the section that reads

<!– Define a non-SSL HTTP/1.1 Connector on port 8180 –>
    <Connector port="8180" maxHttpHeaderSize="8192"
               maxThreads="150" minSpareThreads="25" maxSpareThreads="75"
               enableLookups="false" redirectPort="8443" acceptCount="100"
               connectionTimeout="20000" disableUploadTimeout="true" />

and change 8180 to 8080. I don't know how, but this issue disappeared: today, if I give Alfresco all permissions, I can have Tomcat on 8180 and Alfresco on 8080 - as it is reasonable, since "all permissions" should allow to bind to a port.

Another issue I had was that sometimes Alfresco deployment starts before Tomcat startup is complete. In this situation, I undeploy and redeploy Alfresco- this is ugly, I'm looking for a better solution. Anyway, this is a potential source of intermittent errors.

I'll be glad to help if anybody has further problems. Keep in mind that I am on a costantly upgraded "unstable" Debian machine.