Logfile creation error during rotation

D

dduck

Hi,

When logging to a file using FileHandler, we sometimes experience
problems during log rotation. The logger stops writing to the file,
and an exception is thrown (see below). This problem is reproducable,
but does not happen during every rotation.

Suggestions?

Exception trace:

java.util.logging.ErrorManager: 4
java.io.FileNotFoundException: ./log/gatekeeper0.log.0 (No such file
or directory)
at java.io.FileOutputStream.open(Native Method)
at java.io.FileOutputStream.<init>(FileOutputStream.java:179)
at java.io.FileOutputStream.<init>(FileOutputStream.java:102)
at java.util.logging.FileHandler.open(FileHandler.java:156)
at java.util.logging.FileHandler.rotate(FileHandler.java:535)
at java.util.logging.FileHandler.access$100(FileHandler.java:
103)
at java.util.logging.FileHandler$1.run(FileHandler.java:565)
at java.security.AccessController.doPrivileged(Native Method)
at java.util.logging.FileHandler.publish(FileHandler.java:563)
at java.util.logging.Logger.log(Logger.java:452)
at java.util.logging.Logger.doLog(Logger.java:474)
at java.util.logging.Logger.logp(Logger.java:590)
at
dk.kb.doms.framework.logging.JavaLoggingStatusMsgHandler.accept(JavaLoggingStatusMsgHandler.java:
57)
at dk.kb.doms.framework.logging.Alert
$ConcreteAlerter.post(Alert.java:109)
at dk.kb.doms.framework.logging.Alert
$ConcreteAlerter.message(Alert.java:83)
at
dk.kb.doms.components.cumulus.CumulusSipDipServicePoint.processRecordReferenceList(CumulusSipDipServicePoint.java:
174)
at
dk.kb.doms.components.cumulus.CumulusSipDipServicePoint.performOnSipDips(CumulusSipDipServicePoint.java:
395)
at
dk.kb.doms.api.oais.helpers.CmdExecutable.execute(CmdExecutable.java:
69)
at
dk.kb.doms.api.oais.helpers.DecoratingTimedExecutable.execute(DecoratingTimedExecutable.java:
65)
at
dk.kb.doms.api.oais.helpers.DecoratingBlockableExecutable.execute(DecoratingBlockableExecutable.java:
53)
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
com.sun.jmx.mbeanserver.StandardMetaDataImpl.invoke(StandardMetaDataImpl.java:
414)
at javax.management.StandardMBean.invoke(StandardMBean.java:
323)
at
com.sun.jmx.mbeanserver.DynamicMetaDataImpl.invoke(DynamicMetaDataImpl.java:
213)
at
com.sun.jmx.mbeanserver.MetaDataImpl.invoke(MetaDataImpl.java:220)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:
815)
at
com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:784)
at
com.sun.jmx.remote.security.MBeanServerAccessController.invoke(MBeanServerAccessController.java:
429)
at
javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:
1408)
at javax.management.remote.rmi.RMIConnectionImpl.access
$100(RMIConnectionImpl.java:81)
at javax.management.remote.rmi.RMIConnectionImpl
$PrivilegedOperation.run(RMIConnectionImpl.java:1245)
at java.security.AccessController.doPrivileged(Native Method)
at
javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:
1348)
at
javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:
782)
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
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)
at sun.rmi.transport.Transport$1.run(Transport.java:153)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:149)
at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:
466)
at sun.rmi.transport.tcp.TCPTransport
$ConnectionHandler.run(TCPTransport.java:707)
at java.lang.Thread.run(Thread.java:595)
 
D

dduck

Here are the relevant bits of the FileHandler .java file. As far as I
can tell, the problem might be due to the renameTo command being
asynchronous in some cases - I am currently investigating if this
could be the case in our setup.

<...>

private void open(File fname, boolean append) throws IOException {
int len = 0;
if (append) {
len = (int)fname.length();
}
FileOutputStream fout = new FileOutputStream(fname.toString(),
append);
BufferedOutputStream bout = new BufferedOutputStream(fout);
meter = new MeteredStream(bout, len);
setOutputStream(meter);
}

<...>

// Rotate the set of output files
private synchronized void rotate() {
Level oldLevel = getLevel();
setLevel(Level.OFF);

super.close();
for (int i = count-2; i >= 0; i--) {
File f1 = files;
File f2 = files[i+1];
if (f1.exists()) {
if (f2.exists()) {
f2.delete();
}
f1.renameTo(f2);
}
}
try {
open(files[0], false);
} catch (IOException ix) {
// We don't want to throw an exception here, but we
// report the exception to any registered ErrorManager.
reportError(null, ix, ErrorManager.OPEN_FAILURE);

}
setLevel(oldLevel);
}
 
D

dduck

Here are the relevant bits of the FileHandler .java file. As far as I
can tell, the problem might be due to the renameTo command being
asynchronous in some cases - I am currently investigating if this
could be the case in our setup.

Well, the problem is found, and possible solved. It develops that
renameTo does not always work (!!!!) as can be seen here:

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6213298

The suggested workaround may do the trick. Time will tell.
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

No members online now.

Forum statistics

Threads
473,744
Messages
2,569,483
Members
44,903
Latest member
orderPeak8CBDGummies

Latest Threads

Top