Mantis - Resin
Viewing Issue Advanced Details
ID: Category: Severity: Reproducibility: Date Submitted: Last Update:
6098 major sometimes 09-23-17 23:54 11-03-17 13:59
Reporter: mnsh Platform:  
Assigned To: ferg OS:  
Priority: normal OS Version:  
Status: closed Product Version: 4.0.53  
Product Build: Resolution: unable to reproduce  
Projection: none      
ETA: none Fixed in Version: 4.0.55  
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.
Steps To Reproduce:
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
Attached Files:

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.