[Logstash] sincedbファイルに unknown 履歴が挿入されることに関して


#1

■環境
・Windows10
・Logstash6.4.2

Logstashのinput-fileプラグインでファイルの監視中に

[2018-11-09T12:16:50,332][WARN ][filewatch.tailmode.processor] >>> Rotation In Progress - inode change detected and original content is not fully read, file is closed and path points to new content {"watched_file details"=>"<FileWatch::WatchedFile: @filename='4.txt', @state='rotation_in_progress', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='0', current_size='25', last_stat_size='25', file_open?='false', @initial=false, @sincedb_key='unknown 0 0'>"}

という警告が発生することがあります。
何度か検証を繰り返している中で、警告が発生する前にsincedbファイルにsincedb_keyの部分に 'unknown' という履歴が挿入されていることがわかりました。
この状態になるとsincedbファイルが破損している状態になるのかファイルの読み込み位置が正しく判定されないファイルが発生する場合があります。

この問題により不正な情報がElasticsearchに転送される可能性があり情報を集めています。
同様の問題に遭遇した方や原因、解決方法をご存知の方がいましたら情報をお願いします。

検証用に作成したconfファイルと手順です。

■ confファイル

input {
file {
path => "D:/Elastic_Kibana/logstash-6.4.2/_testdata/*.txt"
start_position => beginning
sincedb_path => "./_sincedb/test.db"
}
}
filter {
}
output {
stdout {
codec => line {
format => "event : %{path} => %{message}"
}
}
}

■検証用監視ファイル

ファイル名 : <数字>.txt ※数字の部分を0~ 連番で用意
ファイルの中身 : this file name is <数字>.txt

■手順

  1. cmd or psでlogstash起動 (logstash -f confファイル)
  2. 監視フォルダに作成済みファイルをコピーする
  3. ログに該当の警告"Rotation In Progress - ~"が表示されたらsincedbを確認する
  4. 内部にunknownキーの履歴があることを確認する

■発生時のログ

event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/1.txt => this file name is 1.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/2.txt => this file name is 2.txt
[2018-11-09T12:29:04,151][WARN ][filewatch.tailmode.processor] >>> Rotation In Progress - inode change detected and original content is not fully read, file is closed and path points to new content {"watched_file details"=>"<FileWatch::WatchedFile: @filename='3.txt', @state='rotation_in_progress', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='0', current_size='25', last_stat_size='25', file_open?='false', @initial=false, @sincedb_key='unknown 0 0'>"}
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/3.txt => this file name is 3.txt
[2018-11-09T12:29:34,291][WARN ][filewatch.tailmode.processor] >>> Rotation In Progress - inode change detected and original content is not fully read, file is closed and path points to new content {"watched_file details"=>"<FileWatch::WatchedFile: @filename='4.txt', @state='rotation_in_progress', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='0', current_size='25', last_stat_size='25', file_open?='false', @initial=false, @sincedb_key='unknown 0 0'>"}
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/4.txt => this file name is 4.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/5.txt => this file name is 5.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/6.txt => this file name is 6.txt
[2018-11-09T12:30:19,451][WARN ][filewatch.tailmode.processor] >>> Rotation In Progress - inode change detected and original content is not fully read, file is closed and path points to new content {"watched_file details"=>"<FileWatch::WatchedFile: @filename='8.txt', @state='rotation_in_progress', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='0', current_size='27', last_stat_size='27', file_open?='false', @initial=false, @sincedb_key='unknown 0 0'>"}
[2018-11-09T12:30:19,453][WARN ][filewatch.tailmode.processor] >>> Rotation In Progress - inode change detected and original content is not fully read, file is closed and path points to new content {"watched_file details"=>"<FileWatch::WatchedFile: @filename='9.txt', @state='rotation_in_progress', @recent_states='[:watched, :watched]', @bytes_read='0', @bytes_unread='0', current_size='27', last_stat_size='27', file_open?='false', @initial=false, @sincedb_key='unknown 0 0'>"}
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/7.txt => this file name is 7.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/7.txt =>
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/2.txt => this file name is 2.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/8.txt => this file name is 8.txt
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/8.txt =>
event : D:/Elastic_Kibana/logstash-6.4.2/_testdata/9.txt =>


#2

補足です。

上記再現手順時は、2.txtの履歴がsincedbに書き込まれた時に inode名が 'unknown' となっていました。
その後はログの通りmessageが空のイベントがや重複したイベントがトリガーされます。

英語フォーラム、githubのissueなどを一通り探したのですが解決に至る情報は見つけられませんでした。
(英語フォーラムには同様のトピックがありましたがリプライがないままクローズされていました)

引き続き情報のほどお願いします。


(Jun Ohtani) #3

これは、同じファイルをコピーして、既存のファイルに上書きをしてるということでしょうか?


#4

input-fileプラグインの監視対象パスに
連番で用意した別々のファイルを一つずつコピー(移動)しています
※sincedbファイルは削除して検証しています

また、ファイルは完成済みの状態でコピーされ
監視対象になってから加筆されることはありません