0006098: Missing system properties after redeploy/restart - Mantis

Mantis Bugtracker

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ Issue History ] [ Print ]

ID

Category

Severity

Reproducibility

Date Submitted

Last Update

0006098

[Resin]

major

sometimes

09-23-17 23:54

11-03-17 13:59

Reporter

mnsh

View Status

public

Assigned To

ferg

Priority

normal

Resolution

unable to reproduce

Status

closed

Product Version

4.0.53

Summary

0006098: Missing system properties after redeploy/restart

Description

We have a number of webapps logging using log4j, which is configured like this:

Resin's app-default.xml:
...
<web-app-default>
<prologue>
  <system-property host.logDir="${host.rootDir}/logs"/>
  ...
</prologue>
</web-app-default>

Then, in the webapp's WEB-INF/classes/log4j.xml:
...
<appender name="xyz" class="...">
   <param name="File" value="${host.logDir}/xyz.log"/>
   ...
</appender>

This has worked flawlessly for a number of years.

After upgrading a webapp from hibernate-5.1 to hibernate-5.2, it started misbehaving. Every now and then, log4j logging breaks after a redeploy. The webapp itself works fine.

Looking at stderr after such a redeploy, I see that the log4j init has failed with errors like:

2017-09-24 07:48:31.246 log4j:ERROR setFile(null,true) call failed.
2017-09-24 07:48:31.247 java.io.FileNotFoundException: /logs/xyz.log (No such file or directory)

This happens after a redeploy (maybe 1 of 3 times); a fresh resin restart never fails.

It seems that one of the stop->redeploy->start paths resin can take after "xyz.war length is modified (x -> y) ..." ends up triggering the log4j initialization without the "host.logDir" system property being available.

Additional Information

The full stacktrace logged to stderr when the above happens:
------------------------------------------------------------
log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: /logs/xyz.log (No such file or directory)
        at java.io.FileOutputStream.open0(Native Method)
        at java.io.FileOutputStream.open(FileOutputStream.java:270)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:133)
        at org.apache.log4j.FileAppender.setFile(FileAppender.java:294)
        at org.apache.log4j.RollingFileAppender.setFile(RollingFileAppender.java:207)
        at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:165)
        at org.apache.log4j.config.PropertySetter.activate(PropertySetter.java:307)
        at org.apache.log4j.xml.DOMConfigurator.parseAppender(DOMConfigurator.java:295)
        at org.apache.log4j.xml.DOMConfigurator.findAppenderByName(DOMConfigurator.java:176)
        at org.apache.log4j.xml.DOMConfigurator.findAppenderByReference(DOMConfigurator.java:191)
        at org.apache.log4j.xml.DOMConfigurator.parseChildrenOfLoggerElement(DOMConfigurator.java:523)
        at org.apache.log4j.xml.DOMConfigurator.parseCategory(DOMConfigurator.java:436)
        at org.apache.log4j.xml.DOMConfigurator.parse(DOMConfigurator.java:1004)
        at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:872)
        at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:778)
        at org.apache.log4j.helpers.OptionConverter.selectAndConfigure(OptionConverter.java:526)
        at org.apache.log4j.LogManager.<clinit>(LogManager.java:127)
        at org.slf4j.impl.Log4jLoggerFactory.<init>(Log4jLoggerFactory.java:66)
        at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:72)
        at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:45)
        at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
        at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
        at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412)
        at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:357)
        at org.jboss.logging.Slf4jLoggerProvider.getLogger(Slf4jLoggerProvider.java:31)
        at org.jboss.logging.LoggerProviders.logProvider(LoggerProviders.java:156)
        at org.jboss.logging.LoggerProviders.trySlf4j(LoggerProviders.java:118)
        at org.jboss.logging.LoggerProviders.findProvider(LoggerProviders.java:59)
        at org.jboss.logging.LoggerProviders.find(LoggerProviders.java:34)
        at org.jboss.logging.LoggerProviders.<clinit>(LoggerProviders.java:31)
        at org.jboss.logging.Logger.getLogger(Logger.java:2465)
        at org.jboss.logging.Logger.getLogger(Logger.java:2490)
        at org.hibernate.jpa.HibernatePersistenceProvider.<clinit>(HibernatePersistenceProvider.java:38)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at java.lang.Class.newInstance(Class.java:442)
        at com.caucho.env.jpa.PersistenceUnitManager.createDelegate(PersistenceUnitManager.java:421)
        at com.caucho.env.jpa.PersistenceUnitManager.start(PersistenceUnitManager.java:386)
        at com.caucho.env.jpa.PersistenceManager.startPersistenceUnits(PersistenceManager.java:367)
        at com.caucho.env.jpa.PersistenceManager.environmentConfigureEnhancer(PersistenceManager.java:638)
        at com.caucho.loader.EnvironmentClassLoader.config(EnvironmentClassLoader.java:933)
        at com.caucho.loader.EnvironmentClassLoader.bind(EnvironmentClassLoader.java:951)
        at com.caucho.loader.EnvironmentClassLoader.start(EnvironmentClassLoader.java:978)
        at com.caucho.server.webapp.WebApp.startImpl(WebApp.java:3792)
        at com.caucho.server.webapp.WebApp.access$700(WebApp.java:209)
        at com.caucho.server.webapp.WebApp$StartupTask.run(WebApp.java:5370)
        at com.caucho.env.thread2.ResinThread2.runTasks(ResinThread2.java:173)
        at com.caucho.env.thread2.ResinThread2.run(ResinThread2.java:118)
------------------------------------------------------------

Manually pointing a log4j appender to a file resin can't write to and a resin restart gives the exact same stacktrace after properly configuring log4j in the webapp.

So, some kind of a timing issue maybe?

Relationships

Notes
(0006792) mnsh 09-26-17 02:58	Update: this might not have to do with the hibernate upgrade at all. Right before the problem appeared, we added a second instance of the same webapp under the same Resin instance. A successful build of the webapp would then deploy the war to both vhosts. Yesterday, I disabled the auto post-build deploy to one of the vhosts and.. the problem disappeared. So, my new description of this would be: when 2+ webapps are being redeployed simultaneously, they might end up without configured <system-property .../> sysprops.

(0006799) ferg 10-18-17 16:03	I'm having trouble reproducing this. How are the virtual hosts configured? From your description, the system-properties looks it's getting set (because of "/logs" in the FileNotFound), but the ${host.rootDir} is returning null (probably because ${host} is null, which shouldn't happen).

(0006808) ferg 11-03-17 13:59	server/144b There may be some additional requirement to reproduce this that I'm unable to find.

Issue History
Date Modified	Username	Field	Change
09-23-17 23:54	mnsh	New Issue
09-24-17 00:00	mnsh	Issue Monitored: mnsh
09-26-17 02:58	mnsh	Note Added: 0006792
10-18-17 16:03	ferg	Note Added: 0006799
11-03-17 13:59	ferg	Note Added: 0006808
11-03-17 13:59	ferg	Assigned To	=> ferg
11-03-17 13:59	ferg	Status	new => closed
11-03-17 13:59	ferg	Resolution	open => unable to reproduce
11-03-17 13:59	ferg	Fixed in Version	=> 4.0.55

Mantis 1.0.0rc3[^]

Copyright © 2000 - 2005 Mantis Group

34 total queries executed.
28 unique queries executed.