Log4j日志轮转后Logstash延迟读取旧日志问题排查求助

我有一个metrics.log文件，通过Log4j的RollingFileAppender每天23:59执行日志轮转，轮转后的文件以metrics-$DATE.log的格式存储在其他目录中。文件包含JSON格式的日志数据（每条日志自带生成时的timestamp），每分钟会有一条新日志写入metrics.log。

近期发现大量日志会在早上7点左右批量出现。为排查问题根源，我新增了多个时间戳：

• 在Windows机器上的Logstash中通过Ruby过滤器添加了received时间戳（代码为event.set('received', Time.now.utc)），用于记录Logstash接收日志的时间；
• 在Elastic中添加了ingest pipeline，用于记录日志被Elastic接收的delivered时间戳。

这两个时间戳始终接近，说明ELK栈的传输环节无异常，但日志自带的timestamp与这两个时间戳有时相差数小时甚至数天。我可以通过执行POST /logs-metrics-prod/_search请求，使用查询条件"doc['delivered'].value.getMillis() - doc['timestamp'].value.getMillis() > 10000"筛选出这些时间不匹配的条目，示例结果如下：

{
    "hits": [
      {
          // ...
          "@timestamp": "2024-08-01T22:00:08.515Z",
          "received": "2024-08-02T06:48:55.932Z",
          "delivered": "2024-08-02T06:48:56.470630659Z",
          "timestamp": "2024-08-01T22:00:08.515Z"
        }
      },
      // ...
]

在2024-08-02T06:48:55.933Z时，metrics.log已完成轮转，不应包含"@timestamp": "2024-08-01T22:01:08.519Z"这类旧日志。

我的Logstash管道配置如下：

input {
  file {
    path => ["C:/wms/metrics.log"]
    start_position => "beginning"
    mode => "tail"
    codec => plain { charset => "ISO-8859-1" }
  }
}

filter {
  date {
    match => ["timestamp", "ISO8601"]
    timezone => "Europe/Berlin"
    target => "@timestamp"
  }
  ruby {
   # format: 2024-07-25T06:52:59.493Z
   code => "event.set('received', Time.now.utc)"
  }
  mutate {
    copy => { "@timestamp" => "timestamp" }
    // ...
  }
// ...
}

我复制timestamp是因为metrics.log输出的是本地时间而非UTC。原始日志条目示例如下：

{"timestamp":"2024-08-05T00:12:12.379774800","type":"metric","offenePickauftraege":{"PUPT":0,"GTHY":0},"anzahlPicker":{"PUPT":0,"GTHY":0}}

我已经尝试了start_position => "beginning/end"和mode => "tail/read"的所有组合，且在Logstash日志（即使是INFO级别）中未发现异常信息。每次尝试前，我都会删除logs-metrics-prod数据流并重启Logstash以确保环境干净，运行一天后次日查看问题仍存在。

由于无法修改日志生成程序或日志轮转规则，请问这是否是日志轮转导致的问题？还有其他排查方向吗？

1. 日志轮转是潜在诱因 #

RollingFileAppender在Windows环境下的轮转操作可能触发以下问题：

• 文件句柄未释放：若日志生成程序未及时释放原metrics.log的文件句柄，Log4j的轮转操作可能不彻底，导致Logstash继续读取旧文件的残留内容；
• Windows文件锁定机制：Windows下文件重命名操作可能因文件被占用延迟执行，Logstash在轮转后的一段时间内仍会读取旧文件，直到锁定解除。

2. 其他排查方向 #

（1）重置Logstash的读取位置记录 #

Logstash通过.sincedb文件记录日志读取位置，即使删除数据流重启，该文件可能仍保留旧标记：

• 找到.sincedb文件（默认路径为C:\Users\<用户名>\.sincedb_*或Logstash数据目录），删除所有相关文件后重启Logstash；
• 在file input配置中添加sincedb_path => "NUL"（Windows下禁用sincedb），强制每次启动从指定位置重新读取，验证问题是否复现。

（2）验证日志轮转后的文件状态 #

• 每天23:59轮转完成后，检查metrics.log的文件大小、修改时间，确认无后续写入；
• 查看轮转后的metrics-$DATE.log文件，确认是否包含本该写入新metrics.log的内容，反向验证轮转逻辑是否正常。

（3）优化Logstash的file input配置 #

• 添加discover_interval => 10（缩短文件扫描间隔），让Logstash更快识别文件变更；
• 启用stat_interval => 5，更频繁检查文件的修改时间和大小，避免遗漏更新；
• 添加exclude => "metrics-*.log"，确保Logstash不会误读归档目录中的轮转日志。

（4）修正时间戳处理逻辑 #

• 当前filter中用date插件将本地时间转换为UTC的@timestamp后，又将其复制回timestamp字段，覆盖了原始本地时间，干扰排查。建议保留原始timestamp，新增utc_timestamp字段存储转换后的UTC时间；
• 在date插件中添加tag_on_failure => ["date_parse_fail"]，检查是否存在时间戳解析失败的日志——原始日志的timestamp无时区标识，需确认timezone => "Europe/Berlin"是否正确解析。

（5）排查Windows系统定时任务或资源瓶颈 #

• 检查早上7点左右是否有系统定时任务（如备份、杀毒扫描）访问metrics.log所在目录，这类操作可能导致文件锁定或Logstash读取异常；
• 监控Logstash进程的CPU、内存使用情况，确认是否因资源瓶颈导致日志堆积，在早上7点左右批量发送。

内容的提问来源于stack exchange，提问作者oxoma