磁盘满了对日志打印(Logback)的影响

news2024/9/25 3:19:45

背景

我们生产环境有一个服务半夜报警：磁盘剩余空间不足10%，请及时处理。排查后发现是新上线的一个功能，日志打太多导致的，解决方法有很多，就不赘述了。领导担心报警不及时、或者报警遗漏，担心磁盘满了对线上业务有负面影响，甚至不可用，令我研究一下该情况下对服务的影响。

正文

注：我们线上的应用使用Logback日志框架进行打印，所以log4j、log4j2或其它日志框架不在本次研究的范围。

实验研究

实验步骤

启动服务，观察各项指标正常（模拟正常工作的服务以及环境状态）
将磁盘写满
观察应用服务、宿主机各项指标，查看服务响应是否正常（包括功能以及性能）
将大文件删除（恢复）
重复第3步

实验过程

第1、3、5步重在观测，不赘述。

第2步的模拟磁盘写满，使用linux的fallocate命令。

将磁盘写满的方式如下有几种：

自己写文件，写满为止，速度较慢，有开发（写脚本）成本
使用dd命令，但是比较慢，取决于磁盘的速度
~~使用truncate命令，但是该命令操作的结果并不占用实际的磁盘空间~~
使用fallocate命令，fallocate -l {size} {fileName}，如fallocate -l 20G text1

我选择了方式4，很快就写满了磁盘

验证方式：vim {xxx}，进入文件编辑，写入任意内容，保存失败并提示：Can’t open file for writing(No space left on device)

实验结果

磁盘写满前、后，应用服务各项指标均正常（功能、性能）
磁盘写满后，服务器磁盘空间报警（无可用空间），删除文件后报警恢复
磁盘写满后，应用日志停止打印，删除文件后应用日志恢复打印

即，磁盘满了对于使用logback日志框架的应用，并不会造成影响。

实验结果令人诧异，按正常理解，磁盘满了之后再写入，会报No space left on device异常，进而影响到应用程序的功能。

原理分析

logback配置文件里的文件appender如下（RollingFileAppender同理）：

<appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>${LOG_HOME}/${APP_NAME}.log</file>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

把关注点放到appender即可，因为最终的日志输出是由appender控制的：它控制写在哪个文件里，格式是怎样的，滚动策略又是怎样的。

通过IDEA查看RollingFileAppender的继承关系如下下示：

在这里插入图片描述

将视线聚焦到ch.qos.logback.core.OutputStreamAppender#writeBytes，代码如下：

private void writeBytes(byte[] byteArray) throws IOException {
    if(byteArray == null || byteArray.length == 0)
        return;
    
    lock.lock();
    try {
        this.outputStream.write(byteArray);
        if (immediateFlush) {
            this.outputStream.flush();
        }
    } finally {
        lock.unlock();
    }
}

由上可知，写日志时会加锁，避免资源竞争，然后通过outputStream写出，接着马上刷盘（默认情况）。

这里的outputStream可了不得，是个ResilientFileOutputStream实例，顾名思议，【弹性的】FileOutputStream。它是个子类，核心逻辑在父类ResilientOutputStreamBase上，看看write方法：

public void write(byte b[], int off, int len) {
    if (isPresumedInError()) {
        if (!recoveryCoordinator.isTooSoon()) {
            attemptRecovery();
        }
        return; // return regardless of the success of the recovery attempt
    }

    try {
        os.write(b, off, len);
        postSuccessfulWrite();
    } catch (IOException e) {
        postIOFailure(e);
    }
}

这个write方法隐藏着【即使磁盘满了也不影响业务】的秘密！它的核心逻辑是：如果能正常写文件，就写；如果写入失败（出现了IO异常），就抓住异常并切换至失败状态，接下来的一段时间都不再继续写文件，直接返回。

而此处所有的IO异常，就包含了No space left on device，因此，此处便是磁盘满了之后继续日志写入，却不会抛出No space left on device异常进而影响业务的原因。

还有一个问题，待磁盘有剩余空间后，如何恢复日志写入？上面实验结果提到，磁盘写满后，应用日志停止打印，删除文件后应用日志恢复打印。因此必然会有一个策略，能够在磁盘空间恢复后，继续进行日志写入。

再仔细查看看write方法，方法首先判断当前状态是否为“失败”。若是，接着检查自上次失败至今的时间。如果已经经过了很长时间，就【尝试恢复】。

void attemptRecovery() {
    try {
        close();
    } catch (IOException e) {
    }

    addStatusIfCountNotOverLimit(new InfoStatus("Attempting to recover from IO failure on " + getDescription(), this));

    // subsequent writes must always be in append mode
    try {
        os = openNewOutputStream();
        presumedClean = true;
    } catch (IOException e) {
        addStatusIfCountNotOverLimit(new ErrorStatus("Failed to open " + getDescription(), this, e));
    }
}

尝试恢复的逻辑是：关闭旧文件流并重新打开文件流，将【失败】状态切换至【半恢复】状态，此处并未完全进入【正常】状态，而是立即返回，即是说当次的日志记录请求并不会写文件。

下次的日志写入，才会尝试将日志写入文件

若日志成功写入文件，就将状态切换至【正常】状态。
若日志写入文件失败，就将状态切换至【失败】状态。

此处的失败以及恢复逻辑非常像Hystrix断路器，即经历一个正常→失败→半通路状态，通过下次请求的结果来决定是恢复正常还是保持失败。

上面提到若经过很长时间，就尝试恢复，这里的【很长时间】其实是一个泛指，它有自己的时间计算逻辑，此处采用了类似于RocketMQ在消费失败时的重试策略，即采用指数退避逻辑来控制重试时间间隔。

每次【半恢复】状态下写文件失败时，会保持【失败】状态，且每一次的失败写入都会指数级延长【失败】状态保持的时间。

public boolean isTooSoon() {
    long now = getCurrentTime();
    if (now > next) {
        next = now + getBackoffCoefficient();
        return false;
    } else {
        return true;
    }
}

private long getBackoffCoefficient() {
    long currentCoeff = backOffCoefficient;
    if (backOffCoefficient < BACKOFF_COEFFICIENT_MAX) {
        backOffCoefficient *= BACKOFF_MULTIPLIER;
    }
    return currentCoeff;
}