Logback with prudent mode creates corrupt log file

Question

We run a spring application as a war on a tomcat in a kubernetes cluster with multiple pods. All pods write a statistic log file to an nfs share. All pods should write into the same file. So prudent mode sounded like the thing we should use.

So I defined the following logback appender:

<property name="STATISTIC_LOG_PATTERN" value="%d{yyyy-MM-dd'T'HH:mm:ss:SSSZ},%X{mdc.key1},%X{mdc.key2},%X{mdc.key3},%X{mdc.key4},%X{mdc.key5}, %m %n"/>;

...

<appender name="STATISTIC_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <prudent>true</prudent>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${statistic.log.path}/statistics_yeti-%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
        <pattern>${STATISTIC_LOG_PATTERN}</pattern>
    </encoder>
</appender>
....

But the resulting log file is corrupt. Some lines are not complete and there are a lot of CTRL-@ special chars (nul prompt) in the log file. I could not find any topics on corrupt logback log files, except some recommend to remove the file tag, which I don't have in the configuration.

As far as I understand the documentation prudent mode with no file tag should be sufficent? Logback version is 1.2.3

With just one pod the log file is correct.

I suggest to log per instance and aggregate the logs (for example to elastic). Prudent creates an exclusive lock on file write, which has a huge performance cost. — zlaval, Jun 19 '20 at 06:32

NicholasMarven · Answer 1 · 2020-11-30T03:39:20.970

Since v1.2.0 the safeWrite is almost useless, if you look into the source code, you can figure it out.

OutputStreamAppender.subAppend
protected void subAppend(E event) {
    if (!isStarted()) {
        return;
    }
    try {
        // skip some irrelevant codes...
        byte[] byteArray = this.encoder.encode(event);
        writeBytes(byteArray);
    } catch (IOException ioe) {
        this.started = false;
        addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
}

before v1.2.0 the write logic is like this:

try {
    // skip some irrelevant codes...
    writeOut(event)
} catch (IOException ioe) {
    this.started = false;
    addStatus(new ErrorStatus("IO failure in appender", this, ioe));
}

and the writeOut is Overrided by FileAppender

@Override
protected void writeOut(E event) throws IOException {
    if (prudent) {
        safeWrite(event); // here is the point, it ensure write integrity with file lock
    } else {
        super.writeOut(event);
    }
}

This commit was made on Feb 4 2017, check this out.

It's still now misguided in official manual, maybe you can submit an issue in the github repo

Logback with prudent mode creates corrupt log file

1 Answers1