Log4j Timer task does not pickup changes to jboss-log4j.xml

[jaikiran]

JBoss-5.0 CR1 with the following system details:

19:42:28,984 INFO [ServerImpl] Home Dir: D:\jboss-5.0.0.CR1
19:42:28,984 INFO [ServerImpl] Home URL: file:/D:/jboss-5.0.0.CR1/
19:42:28,984 INFO [ServerImpl] Library URL: file:/D:/jboss-5.0.0.CR1/lib/
19:42:28,984 INFO [ServerImpl] Patch URL: null
19:42:28,984 INFO [ServerImpl] Server Name: jaikiran
19:42:28,984 INFO [ServerImpl] Server Home Dir: D:\jboss-5.0.0.CR1\server\jaikiran
19:42:28,984 INFO [ServerImpl] Server Home URL: file:/D:/jboss-5.0.0.CR1/server/jaikiran/
19:42:28,984 INFO [ServerImpl] Server Data Dir: D:\jboss-5.0.0.CR1\server\jaikiran\data
19:42:28,984 INFO [ServerImpl] Server Temp Dir: D:\jboss-5.0.0.CR1\server\jaikiran\tmp
19:42:28,984 INFO [ServerImpl] Server Config URL: file:/D:/jboss-5.0.0.CR1/server/jaikiran/conf/
19:42:28,984 INFO [ServerImpl] Server Library URL: file:/D:/jboss-5.0.0.CR1/server/jaikiran/lib/

......


19:42:39,672 INFO [ServerInfo] Java version: 1.5.0_07,Sun Microsystems Inc.
19:42:39,922 INFO [ServerInfo] Java VM: Java HotSpot(TM) Server VM 1.5.0_07-b03,Sun Microsystems Inc.
19:42:39,922 INFO [ServerInfo] OS-System: Windows 2003 5.2,x86

The server boots properly with the following logs in boot.log:

19:42:46,141 DEBUG [ServiceCreator] About to create xmbean object: jboss.system:type=Log4jService,service=Logging with code: org.jboss.logging.Log4jService with descriptor: resource:xmdesc/Log4jService-xmbean.xml
19:42:46,234 DEBUG [ServiceCreator] Created mbean: jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [ServiceConfigurator] ConfigurationURL set to resource:jboss-log4j.xml in jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [ServiceConfigurator] Log4jQuietMode set to true in jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [ServiceConfigurator] RefreshPeriod set to 60 in jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [ServiceController] Creating service jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [Log4jService] Creating jboss.system:type=Log4jService,service=Logging
19:42:46,297 DEBUG [Log4jService$URLWatchTimerTask] Configuring from URL: resource:jboss-log4j.xml

To enable some more verbose logging of some package, i edited and saved the jboss-log4j.xml in D:/jboss-5.0.0.CR1/server/jaikiran/conf/ and saved the file. Waited for more than a minute (default refresh period for the log4j timer task is 60 seconds). The changes were not picked up. Restarted the server, the changes were picked up. To figure out what the issue was, i enabled TRACE level logging of org.jboss.logging, rebooted the server and then tried the same steps of editing the jboss-log4j.xml. Here's what the logs shows:

2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) Checking if configuration changed
2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) Checking if configuration changed
2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) connection: org.jboss.net.protocol.resource.ResourceURLConnection:resource:jboss-log4j.xml{ org.jboss.virtual.plugins.vfs.VirtualFileURLConnection:vfsfile:/D:/jboss-5.0.0.CR1/server/jaikiran/conf/jboss-log4j.xml }
2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) connection: org.jboss.net.protocol.resource.ResourceURLConnection:resource:jboss-log4j.xml{ org.jboss.virtual.plugins.vfs.VirtualFileURLConnection:vfsfile:/D:/jboss-5.0.0.CR1/server/jaikiran/conf/jboss-log4j.xml }
2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) last configured: 1216044766531
 2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) last configured: 1216044766531
 2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) last modified: 0
 2008-07-14 19:50:46,553 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) last modified: 0

For some reason, the last modified timestamp of jboss-log4j.xml is not being read correctly.

[jaikiran]

Based on a bit of debugging, this looks related to the VFS changes that are in 5.0 CR1 and looks more of a generic problem and not just limited to the log4j config file (i might be wrong).

The log4j timer task opens a org.jboss.virtual.plugins.vfs.VirtualFileURLConnection to vfsfile:/D:/jboss-5.0.0.CR1/server/jaikiran/conf/jboss-log4j.xml :

URLConnection conn = configURL.openConnection();

Later on it invokes the getLastModified method on this URLConnection:

long lastModified = conn.getLastModified();

However, the VirtualFileURLConnection has no implementation for getLastModified nor the getHeaderField methods. As a result, the getLastModified call is delegated to the URLConnection implementation of the JDK. The JDK implementation is as follows:

public long getLastModified() {
 return getHeaderFieldDate("last-modified", 0);
}

public long getHeaderFieldDate(String name, long Default) {
 String value = getHeaderField(name);
 try {
 return Date.parse(value);
 } catch (Exception e) { }
 return Default;
}


public String getHeaderField(String name) {
 return null;
}

As can be seen, the getLastModified is always going to return 0 (the default value).

[alesj]

I'm just adding a few overridden methods to VFS.
I'll let you know when I'm done.
Could you try it then?

[jaikiran]

"alesj" wrote:

Could you try it then?

Sure, no problem.

[alesj]

It's in VFS trunk (+ the tests ;-)) - http://jira.jboss.com/jira/browse/JBVFS-46.

[jaikiran]

Thanks!
I'll patch the vfs jar into JBossAS CR1 and try it out. Will let you know how it goes.

[jaikiran]

Works :-)

The getLastModified returns the correct value now:

2008-07-15 15:17:58,297 TRACE [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) last modified: 1216115180702

And the changes to jboss-log4j.xml file are now dynamically picked up. Thanks again.