草庐IT

替换jar包未重启引起的系统宕机事件

y-h-c 2023-05-14 原文

一、事件背景：

某天凌晨，一阵急促的铃声将我从周公那里拉了过来，接听电话后，一脸懵逼。

什么情况？XX后台宕机了？当日日志也不打印了，前端发起的请求，都报超时，重启后又恢复了，不清楚会不会再次宕机。

出现这种情况，我第一时间想的是为什么是00:00:00宕机？难道后台嫌我这个大龄程序员睡得早了？

然后是通过远程视频，看日志，排查了凌晨之前的日志里的所有异常，均无有效的线索，毫无头绪。

这就大半夜的见鬼了，看来一时半会搞不定，看来得心爱的野摩托出马了，匆匆赶到客户现场，然后巴拉巴拉小魔仙，各种猜测、验证。

 

二、项目情况说明：

根据问题现象，最明显的地方是出现了日志打印异常，怀疑日志打印那块的功能导致的宕机。

于是，我静下心来研究下该后台使用的日志架构。

先看pom.xml文件，然后找日志相关组件，

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-logging</artifactId>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>log4j-over-slf4j</artifactId>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jcl-over-slf4j</artifactId>
</dependency>

最后在某jar包里，发现了这个配置：logback-spring.xml

 

三、问题分析思路：

logback-spring.xml关键配置：

<appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文件的路径及文件名 -->
<file>${log.path}/dev.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- 日志归档 -->
<fileNamePattern>${log.path}/dev/dev-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>1000MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文件保留天数-->
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>

从问题现象来看，凌晨以后，../dev/dev-2023-04-13.0.log能够正常生成，而dev.log不行。

说明宕机可能出现的地方在这个环节之间。那就先分析代码吧。

四、宕机原因分析：

看上述配置文件中，有个比较关键的日志策略类：TimeBasedRollingPolicy，没说的，先找api文档吧。具体见下。

https://logback.qos.ch/apidocs/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.html

其中有一行比较关键：

void rollover() Rolls over log files according to implementation policy.（根据实施策略滚动日志文件。）
就他了，看样子是这个方法里出现异常了，反编译瞅瞅吧，试试水有多深。
源码分析：
public void rollover() throws RolloverFailure {
　　 //timeBasedFileNamingAndTriggeringPolicy有两个实现类：
　　 //DefaultTimeBasedFileNamingAndTriggeringPolicy.java、SizeAndTimeBasedFNATP.java。
    // 对照下logback-spring.xml中的配置，使用的是后者SizeAndTimeBasedFNATP.java，elapsedPeriodsFileName 
　  //再看这个类里这个字段的初始化，很容易猜出来，elapsedPeriodsFileName 
    //就是用来生成上一天的日志文件的，此处是：elapsedPeriodsFileName="dev-2023-04-13.0.log"
    String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();
　　//此处是去掉结尾的"/"，对文件名进行合法性处理
    String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);
　　 // compressionMode:NONE, GZ, ZIP 有此推测如下IF-ELSE用来实现文件写入，dev-2023-04-13.0.log就是在这个里面完成写入的。
    if (compressionMode == CompressionMode.NONE) {
        if (getParentsRawFileProperty() != null) {
            renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
        } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }
    } else {
        if (getParentsRawFileProperty() == null) {
            compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
        } else {
            compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
        }
    }
　　 //看来问题最容易出现的地方是这里：下面应该是要生成dev.log文件，而实际没有生成
    if (archiveRemover != null) {
　　　　 //此变量的生成应该不容易引起宕机，推测是下下一步导致的宕机
        Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
        this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);
    }
}

TimeBasedArchiveRemover.java
public Future<?> cleanAsynchronously(Date now) {
    ArhiveRemoverRunnable runnable = new ArhiveRemoverRunnable(now);
    ExecutorService executorService = context.getScheduledExecutorService();
    Future<?> future = executorService.submit(runnable);
    return future;
}
重点在这里：ArhiveRemoverRunnable。
这个类是内部类，用途是实现了个线程类，初看没啥问题，仔细想想，类的加载是有顺序的，有没有可能是这个内部类加载的时候，报错了？
好好的为啥加载不上了呢？谁动了他的奶酪？
各种检查、分析，发现了个奇怪的现象：
日志中打印的jar启动的时间是10点，然后jar包的最后修改时间是17点。什么鬼？难道是替换了新包没有重启，导致这个内部类加载有问题，系统宕机了？
抓紧验证一下，构造一个类似的场景：
1.修改系统时间为23:55:00.使用java -jar ***.jar启动服务。
2.准备个微调的jar包，待之前的服务启动好后，替换掉他，然后坐等零点到来。
3.激动人心的时刻到了，零点后，dev.log不见了，dev-2023-04-13.0.log有生成。抓紧看下控制台。一堆报错，最关键的信息也打印了。

　　到此，本次系统宕机的根因找到了，是jar包替换没有重启，导致日志打印那块出现中断，最后跟实时的同事要求升级包要规范，不能这样随意的操作。

五、总结：

这个问题太邪门了，尤其是凌晨暴雷，简直是要了程序员的老命，果然不管什么问题，重启试试是最有效的武器。

本次系统宕机的问题就分享到这里，谢谢大家批评指正。

 

timeBasedFileNamingAndTriggeringPolicy
jar替换brspanstyleJava

有关替换jar包未重启引起的系统宕机事件的更多相关文章

  1. ruby-on-rails - rails 目前在重启后没有安装 - 2

    我有一个奇怪的问题:我在rvm上安装了ruby​​onrails。一切正常，我可以创建项目。但是在我输入“railsnew”时重新启动后，我有“程序'rails'当前未安装。”。SystemUbuntu12.04ruby-v"1.9.3p194"gemlistactionmailer(3.2.5)actionpack(3.2.5)activemodel(3.2.5)activerecord(3.2.5)activeresource(3.2.5)activesupport(3.2.5)arel(3.0.2)builder(3.0.0)bundler(1.1.4)coffee-rails(

  2. ruby-on-rails - 如何优雅地重启 thin + nginx？ - 2

    我的瘦服务器配置了nginx，我的ROR应用程序正在它们上运行。在我发布代码更新时运行thinrestart会给我的应用程序带来一些停机时间。我试图弄清楚如何优雅地重启正在运行的Thin实例，但找不到好的解决方案。有没有人能做到这一点？ 最佳答案 #Restartjustthethinserverdescribedbythatconfigsudothin-C/etc/thin/mysite.ymlrestartNginx将继续运行并代理请求。如果您将Nginx设置为使用多个上游服务器，例如server{listen80;server

  3. ruby 正则表达式 - 如何替换字符串中匹配项的第 n 个实例 - 2

    在我的应用程序中，我需要能够找到所有数字子字符串，然后扫描每个子字符串，找到第一个匹配范围(例如5到15之间)的子字符串，并将该实例替换为另一个字符串“X”。我的测试字符串s="1foo100bar10gee1"我的初始模式是1个或多个数字的任何字符串，例如，re=Regexp.new(/\d+/)matches=s.scan(re)给出["1","100","10","1"]如果我想用“X”替换第N个匹配项，并且只替换第N个匹配项，我该怎么做？例如，如果我想替换第三个匹配项“10”(匹配项[2])，我不能只说s[matches[2]]="X"因为它做了两次替换“1fooX0barXg

  4. ruby-on-rails - 在 ruby​​ 中使用 gsub 函数替换单词 - 2

    我正在尝试用ruby​​中的gsub函数替换字符串中的某些单词，但有时效果很好，在某些情况下会出现此错误？这种格式有什么问题吗NoMethodError(undefinedmethod`gsub!'fornil:NilClass):模型.rbclassTest"replacethisID1",WAY=>"replacethisID2andID3",DELTA=>"replacethisID4"}end另一个模型.rbclassCheck 最佳答案 啊，我找到了!gsub!是一个非常奇怪的方法。首先，它替换了字符串，所以它实际上修改了

  5. ruby-on-rails - 事件管理员日期过滤器日期格式自定义 - 2

    是否有简单的方法来更改默认ISO格式(yyyy-mm-dd)的ActiveAdmin日期过滤器显示格式？ 最佳答案 您可以像这样为日期选择器提供额外的选项，而不是覆盖js:=f.input:my_date,as::datepicker,datepicker_options:{dateFormat:"mm/dd/yy"} 关于ruby-on-rails-事件管理员日期过滤器日期格式自定义，我们在StackOverflow上找到一个类似的问题： https://s

  6. 电脑0x0000001A蓝屏错误怎么U盘重装系统教学 - 2

    　　电脑0x0000001A蓝屏错误怎么U盘重装系统教学分享。有用户电脑开机之后遇到了系统蓝屏的情况。系统蓝屏问题很多时候都是系统bug，只有通过重装系统来进行解决。那么蓝屏问题如何通过U盘重装新系统来解决呢？来看看以下的详细操作方法教学吧。　　准备工作：　　1、U盘一个（尽量使用8G以上的U盘）。　　2、一台正常联网可使用的电脑。　　3、ghost或ISO系统镜像文件（Win10系统下载_Win10专业版_windows10正式版下载-系统之家）。　　4、在本页面下载U盘启动盘制作工具：系统之家U盘启动工具。　　U盘启动盘制作步骤：　　注意：制作期间，U盘会被格式化，因此U盘中的重要文件请注

  7. 【鸿蒙应用开发系列】- 获取系统设备信息以及版本API兼容调用方式 - 2

    在应用开发中，有时候我们需要获取系统的设备信息，用于数据上报和行为分析。那在鸿蒙系统中，我们应该怎么去获取设备的系统信息呢，比如说获取手机的系统版本号、手机的制造商、手机型号等数据。1、获取方式这里分为两种情况，一种是设备信息的获取，一种是系统信息的获取。1.1、获取设备信息获取设备信息，鸿蒙的SDK包为我们提供了DeviceInfo类，通过该类的一些静态方法，可以获取设备信息，DeviceInfo类的包路径为：ohos.system.DeviceInfo.具体的方法如下：ModifierandTypeMethodDescriptionstatic StringgetAbiList​()Obt

  8. kvm虚拟机安装centos7基于ubuntu20.04系统 - 2

    需求：要创建虚拟机，就需要给他提供一个虚拟的磁盘，我们就在/opt目录下创建一个10G大小的raw格式的虚拟磁盘CentOS-7-x86_64.raw命令格式：qemu-imgcreate-f磁盘格式磁盘名称磁盘大小qemu-imgcreate-f磁盘格式-o?1.创建磁盘qemu-imgcreate-fraw/opt/CentOS-7-x86_64.raw10G执行效果#ls/opt/CentOS-7-x86_64.raw2.安装虚拟机使用virt-install命令，基于我们提供的系统镜像和虚拟磁盘来创建一个虚拟机，另外在创建虚拟机之前，提前打开vnc客户端，在创建虚拟机的时候，通过vnc

  9. ruby-on-rails - 事件记录 : Select max of limit - 2

    我正在尝试将以下SQL查询转换为ActiveRecord，它正在融化我的大脑。deletefromtablewhereid有什么想法吗？我想做的是限制表中的行数。所以，我想删除少于最近10个条目的所有内容。编辑:通过结合以下几个答案找到了解决方案。Temperature.where('id这给我留下了最新的10个条目。 最佳答案 从您的SQL来看，您似乎想要从表中删除前10条记录。我相信到目前为止的大多数答案都会如此。这里有两个额外的选择:基于MurifoX的版本:Table.where(:id=>Table.order(:id).

  10. ruby - Ruby gsub 替换中的行为不一致？ - 2

    两个gsub产生不同的结果。谁能解释一下为什么？代码也可在https://gist.github.com/franklsf95/6c0f8938f28706b5644d获得.ver=9999str="\tCFBundleDevelopmentRegion\n\ten\n\tCFBundleVersion\n\t0.1.190\n\tAppID\n\t000000000000000"putsstr.gsub/(CFBundleVersion\n\t.*\.).*()/,"#{$1}#{ver}#{$2}"puts'--------'putsstr.gsub/(CFBundleVersio

随机推荐