二丫讲梵
二丫讲梵
2019-10-18
目录

logstash本地调试日志方法详解

文章发布较早，内容可能过时，阅读注意甄别。

以前在新增项目需要添加日志采集配置的时候，我的操作流程都是filebeat添加配置采集，然后logstash配置中转，接着就创建索引交付了，现在来看，这个流程不无不妥，但是在配置logstash的时候，往往简单化地参考了以往项目的配置，拿着就上了，事实上，这样是有问题的。

因为以往的操作中，忽略了一个重要的环节，那就是将日志当中的时间问题，按照以往的操作，可能日志采集也是通的，看起来似乎没啥问题，但是如果时间格式不注意，可能会出问题，所以这个问题，应该首先在正式上之前，先自行测试齐备。

这篇文章记录一下测试的整个流程以及注意点，而不过度解读时间格式，时间格式这个问题会在另外一篇文章中详细探讨。

# 1，准备。

主机：centos-7.4。

logstash：6.5.4。

在实际生产环境之外，自己搭建专有的elk测试环境，然后进行测试。或者使用如下几条命令，在一台主机安装logstash环境，进行测试。

# 1，安装依赖。

主要是依赖jdk环境。

yum -y install lrzsz vim curl wget java ntpdate && ntpdate -u cn.pool.ntp.org
1

# 2，配置yum源。

添加源：

cat > /etc/yum.repos.d/elk.repo << EOF
[elasticsearch-6.x]
name=Elasticsearch repository for 6.x packages
baseurl=https://artifacts.elastic.co/packages/6.x/yum
gpgcheck=1
gpgkey=https://artifacts.elastic.co/GPG-KEY-elasticsearch
enabled=1
autorefresh=1
type=rpm-md
EOF
1
2
3
4
5
6
7
8
9
10

导入key：

rpm --import https://artifacts.elastic.co/GPG-KEY-elasticsearch
1

如果执行这一步报错，则有可能是主机时间问题，可以同步一下主机时间，在执行！

# 3，安装logstash。

yum -y install logstash-6.5.4
1

安装之后就可以直接进行如下的测试了，不需要配置其他任何东东。

# 2，思路。

这里不搞太过复杂，不需要从头配置走通整个采集流程，主要是为了验证logstash解析的配置，所以直接在配置里读取本地文件，以模拟日志文件，然后通过输出到控制台的方式，进行判断分析。

# 3，两种模式。

先放一个常规配置，然后根据配置来解释含义：

input {
	file {
		path 			=> ["/data/log/test.log"]  # 读取本地日志目录
		start_position 	=> "beginning"  # 每次重新启动从日志的开头读
		sincedb_path 	=> "/dev/null"  # 该参数用来指定sincedb文件名，但是如果我们设置为/dev/null这个linux系统上特殊的空洞文件，那么logstash每次重启进程的时候，尝试读取sincedb内容，都只会读到空洞，也就可以理解为前不有过运行记录，自然就从初始位置开始读取了！
		codec 			=> "json"  # 如果日志格式是json的，可以启动此参数
	}
 }
 
output {
	stdout {
		codec => rubydebug  # 以rubydebug格式在控制台输出
		# codec => json  # 以json格式在控制台输出
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

接下来先分别看一下两个输出模式的内容有什么不一样。

# 1，json格式输出。

使用配置文件如下：

$cat /usr/share/logstash/test.conf  # 因为安装之后在这里，所以测试的配置文件直接放到这里了

input {
	file {
		path 			=> ["/data/log/test.log"]
		start_position 	=> "beginning"
		sincedb_path 	=> "/dev/null"
	 #	codec 			=> "json" # 因为是测试，随便写点数据，因此先注释此配置
	}
 }

output {
	stdout {
		# codec => rubydebug
		codec => json
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

配置完成之后，可用如下命令先检测一下配置有没有问题：

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf -t

WARNING: Could not find logstash.yml which is typically located in $LS_HOME/config or /etc/logstash. You can specify the path using --path.settings. Continuing using the defaults
Could not find log4j2 configuration at path /usr/share/logstash/config/log4j2.properties. Using default config which logs errors to the console
[INFO ] 2019-10-12 17:29:35.035 [main] writabledirectory - Creating directory {:setting=>"path.queue", :path=>"/usr/share/logstash/data/queue"}
[INFO ] 2019-10-12 17:29:35.050 [main] writabledirectory - Creating directory {:setting=>"path.dead_letter_queue", :path=>"/usr/share/logstash/data/dead_letter_queue"}
[WARN ] 2019-10-12 17:29:35.707 [LogStash::Runner] multilocal - Ignoring the 'pipelines.yml' file because modules or command line options are specified
Configuration OK
[INFO ] 2019-10-12 17:29:38.302 [LogStash::Runner] runner - Using config.test_and_exit mode. Config Validation Result: OK. Exiting Logstash
1
2
3
4
5
6
7
8
9

看到了有OK的输出，说明配置没有问题，接下来可以去掉 -t，直接监听测试的日志目录内容：

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf

WARNING: Could not find logstash.yml which is typically located in $LS_HOME/config or /etc/logstash. You can specify the path using --path.settings. Continuing using the defaults
Could not find log4j2 configuration at path /usr/share/logstash/config/log4j2.properties. Using default config which logs errors to the console
[WARN ] 2019-10-12 17:32:18.537 [LogStash::Runner] multilocal - Ignoring the 'pipelines.yml' file because modules or command line options are specified
[INFO ] 2019-10-12 17:32:18.562 [LogStash::Runner] runner - Starting Logstash {"logstash.version"=>"6.5.4"}
[INFO ] 2019-10-12 17:32:18.609 [LogStash::Runner] agent - No persistent UUID file found. Generating new UUID {:uuid=>"9f86b0f6-ea25-476a-b6ad-627f02e0d720", :path=>"/usr/share/logstash/data/uuid"}
[INFO ] 2019-10-12 17:32:22.343 [Converge PipelineAction::Create<main>] pipeline - Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>2, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[INFO ] 2019-10-12 17:32:22.836 [Converge PipelineAction::Create<main>] pipeline - Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x1a225873 run>"}
[INFO ] 2019-10-12 17:32:22.962 [Ruby-0-Thread-1: /usr/share/logstash/lib/bootstrap/environment.rb:6] agent - Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[INFO ] 2019-10-12 17:32:23.172 [[main]<file] observingtail - START, creating Discoverer, Watch with file and sincedb collections
[INFO ] 2019-10-12 17:32:23.688 [Api Webserver] agent - Successfully started Logstash API endpoint {:port=>9600}
1
2
3
4
5
6
7
8
9
10
11
12

启动之后，将会在前台进行监听，现在随便写一条内容放到log里边，看看有什么效果：

$ cat test.log

this is test json
1
2
3

然后看到控制台输出如下：

{"@version":"1","host":"localhost.localdomain","message":"this is test json","tags":["_jsonparsefailure"],"@timestamp":"2019-10-12T09:35:25.836Z","path":"/data/log/test.log"}
1

注意此条内容中，时间是9点，而上边的输出则是当前时间17点，这是因为应用自身的时区问题，logstash采用UTC的时间，比我们当前时间晚8个小时，这个时区问题，会在其他地方细讲，这里不赘述。

# 2，rubydebug格式输出。

同样，还是先调整配置：

$cat /usr/share/logstash/test.conf

input {
	file {
		path 			=> ["/data/log/test.log"]
		start_position 	=> "beginning"
		sincedb_path 	=> "/dev/null"
	 #	codec 			=> "json" # 因为是测试，随便写点数据，因此先注释此配置
	}
 }

output {
	stdout {
		codec => rubydebug
	# codec => json
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

然后启动此条管道。

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf
1

接着写一条日志，可以看到输出如下：

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf

WARNING: Could not find logstash.yml which is typically located in $LS_HOME/config or /etc/logstash. You can specify the path using --path.settings. Continuing using the defaults
Could not find log4j2 configuration at path /usr/share/logstash/config/log4j2.properties. Using default config which logs errors to the console
[WARN ] 2019-10-12 17:40:07.301 [LogStash::Runner] multilocal - Ignoring the 'pipelines.yml' file because modules or command line options are specified
[INFO ] 2019-10-12 17:40:07.332 [LogStash::Runner] runner - Starting Logstash {"logstash.version"=>"6.5.4"}
[INFO ] 2019-10-12 17:40:12.008 [Converge PipelineAction::Create<main>] pipeline - Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>2, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[INFO ] 2019-10-12 17:40:12.555 [Converge PipelineAction::Create<main>] pipeline - Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x2d0a9cba sleep>"}
[INFO ] 2019-10-12 17:40:12.651 [Ruby-0-Thread-1: /usr/share/logstash/lib/bootstrap/environment.rb:6] agent - Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[INFO ] 2019-10-12 17:40:12.680 [[main]<file] observingtail - START, creating Discoverer, Watch with file and sincedb collections
[INFO ] 2019-10-12 17:40:13.350 [Api Webserver] agent - Successfully started Logstash API endpoint {:port=>9600}

{
    "@timestamp" => 2019-10-12T09:40:13.929Z,
          "host" => "localhost.localdomain",
          "path" => "/data/log/test.log",
       "message" => "this is test json",
      "@version" => "1"
}

{
    "@timestamp" => 2019-10-12T09:41:15.295Z,
          "host" => "localhost.localdomain",
          "path" => "/data/log/test.log",
       "message" => "this is test rubydebug",
      "@version" => "1"
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27

可以看到，这种输出能够更加清晰的呈现出日志被解析之后的样式，相当于把上边的json格式化了，从而便于观察，因此接下来的调试就用这种方案了。

当然还有另外两条是否从文件开头读取日志的参数，这个就在此演示了，有兴趣可以自己做实验。

# 4，时间格式调试。

学会了上边的调试方法，接下来就可以进行一波真刀真枪的调试了。

从上到下没少提时间格式这个名词，不过貌似还没有对其进行简单解释，其实很简单，就是我们希望日志在kibana当中呈现的时候，时间戳是与日志当中当条日志记录的时间戳一致，这听起来似乎理所应当，但是如果我们没有用合适的配置对时间格式进行匹配，那么很可能最终结果将不是我们所想要的。

这段话应当反复研读，以认同这一配置细节的重要性，然后才能有信心继续往内部深挖。

举个例子，比如我本条日志里的时间是2019-10-12T09:41:15，我希望写入到elasticsearch的时候，这条日志的时间也是这个，而不是提前或者延后，那么就需要进行严格的时间格式配置，一旦配置是错误的，那么logstash会将采集到日志的时间作为此条日志的时间戳，这个误差，在某些特定搜索场景下，可能会导致结果失准，那么接下来，就来实际验证一下刚刚的这两种情况。

比如我有如下日志一条：

{"timestamp":"2019-10-10T15:37:08+08:00","level":"info","message":"这是一条测试日志","content":"{\"taskId\":\"213292\",\"checkList\":[\"20191012\"],\"userinfoId\":\"28881951\"}","trace_id":"461d7df6633fdebda346d7e73e6813e8"}
1

今天是阳历2019-10-12，我这里为了展示效果，就把日志的时间调整为了两天前2019-10-10，希望日志采集之后写入到es的时间也是2019-10-10，但是如果配置不对，那么时间也将跑偏。

# 1，错误示范。

首先还是写好解析的配置，因为这里需要针对时间进行解析了，就要用到了data关键字，我以往不太注意这个地方，可能随便拷贝了其他类似日志的配置，大概如下：

input {
	file {
		path 			=> ["/data/log/test.log"]
		start_position 	=> "beginning"
		sincedb_path 	=> "/dev/null"
		codec 			=> "json"
	}
}

filter {
	date {
		match => ["time", "yyyy-MM-dd HH:mm:ss"] # 获取time字段的时间戳，作为es的@timestamp
		remove_field => "time"  # 丢弃掉日志中的time字段
	}
}   

output {
	stdout {
		codec => rubydebug
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

现在整条配置的核心是中间的filter，但是不解里边内容的真意，胡乱复制过来，就用上了，但事实是有问题的，具体问题，马上就能看到。

那么，现在继续加载此配置进行监听，看看输出什么，关于日志生成的调试，我个人一个小小心得是，先把日志放到另一个文件中，然后用cat模拟应用将日志写入log文件。

$ cat a
{"timestamp":"2019-10-10T15:37:08+08:00","level":"info","message":"这是一条测试日志","content":"{\"taskId\":\"213292\",\"checkList\":[\"20191012\"],\"userinfoId\":\"28881951\"}","trace_id":"461d7df6633fdebda346d7e73e6813e8"}

$ cat a >> test.log
1
2
3
4

接着可以看到控制台那边的输出：

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf

。。。。。。
打印信息忽略
。。。。。。

{
       "message" => "这是一条测试日志",
    "@timestamp" => 2019-10-12T10:20:14.733Z,
     "timestamp" => "2019-10-10T15:37:08+08:00",
         "level" => "info",
      "@version" => "1",
       "content" => "{\"taskId\":\"213292\",\"checkList\":[\"20191012\"],\"userinfoId\":\"28881951\"}",
      "trace_id" => "461d7df6633fdebda346d7e73e6813e8",
          "host" => "localhost.localdomain",
          "path" => "/data/log/test.log"
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

从这里可以很明显看到，我们日志是10生成的，结果记录到es里边的 @timestamp字段中，确实当前时间，这不是我们想要的。

# 2，正确示范。

现在再来重新审视一下关于时间格式解析的配置文件：

	date {
		match => ["time", "yyyy-MM-dd HH:mm:ss"]
	}
1
2
3

date关键字就是针对时间格式进行处理的，可以将日志当中一些不符合默认标准($time_iso8601)的进行处理，从而让日志以我们想要的效果展示。

match用于配置具体的匹配内容规则，前边的time表示匹配实际日志当中的时间戳的名称，这里用time明显是不对的，因为原始日志里边时间戳的字段名是timestamp，后边的是匹配具体日志时间戳规则的，这个内容，将专门在另外文章讲解，这里不详细展开。

理解了这个地方的要点之后，得出如下配置：

input {
	file {
		path 			=> ["/data/log/test.log"]
		start_position 	=> "beginning"
		sincedb_path 	=> "/dev/null"
		codec 			=> "json"
	}
}

filter {
	date {
		match => [ "timestamp" , "yyyy-MM-dd'T'HH:mm:ss+08:00" ]
		remove_field => "timestamp"
	}
}   

output {
	stdout {
		codec => rubydebug
	}
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

写入到配置中去，然后重复上边的操作，将日志写入，看看控制台输出：

$ /usr/share/logstash/bin/logstash -f /usr/share/logstash/test.conf

。。。。。。
打印信息忽略
。。。。。。

{
          "host" => "localhost.localdomain",
       "message" => "这是一条测试日志",
    "@timestamp" => 2019-10-10T07:37:08.000Z,
      "trace_id" => "461d7df6633fdebda346d7e73e6813e8",
     "timestamp" => "2019-10-10T15:37:08+08:00",
       "content" => "{\"taskId\":\"213292\",\"checkList\":[\"20191012\"],\"userinfoId\":\"28881951\"}",
          "path" => "/data/log/test.log",
      "@version" => "1",
         "level" => "info"
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

可以看到，当我们正确解析了原始日志当中的日志格式之后，写入到es的@timestamp字段就变成了原始日志中的10号了，而这，就是我在本文一开头强调的日志的时间格式问题。

以往的操作当中，因为对这个地方的配置了解不够深入，可能有一些配置就像错误示范的那种情况一样，因为elk采集起来不会延迟太久，最终生成的@timestamp与实际的相差不大，所以一直没有注意到这一点，但是经过了本文操作之后，以后就懂得这个地方的奥妙了。

从此后，新增采集日志的流程中，首先观察日志，然后在自己测试环境进行测试解析，也就变成了第一项要做的事情了。

微信 支付宝
#elk#logstash
上次更新: 2022/08/19, 09:49:20

← logstash采集日志的时间格式探微→

最近更新
01
学习周刊-总第125期-2023年第38周
09-22
02
学习周刊-总第124期-2023年第37周
09-14
03
Jenkins-pipeline之利用activity choice插件对接查询MySQL数据实现动态参数化的功能
09-09
更多文章>
Theme by Vdoing | Copyright © 2017-2023 | 点击查看十年之约 | 浙ICP备18057030号