Logfile creation error during rotation

Thread view:

dduck - 07 May 2007 12:20 GMT

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)

Reply to this Message

dduck - 07 May 2007 13:56 GMT

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[i];
    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);
}

Reply to this Message

dduck - 07 May 2007 14:35 GMT

> 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.

Reply to this Message

Logfile creation error during rotation

Free Magazines