0006098: Missing system properties after redeploy/restart - Mantis

Mantis Bugtracker

Viewing Issue Advanced Details [ Jump to Notes ]

[ View Simple ] [ 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

Platform

Status

closed

OS

Projection

none

OS Version

ETA

none

Fixed in Version

4.0.55

Product Version

4.0.53

Product Build

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

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.