这两天出现一个小事故,是logstash读取文件信息输出到kafka,因为topic没有创建,而导致所有的topic都没有数据。先将配置文件列出来。

input {
	file {
		path => "/data/xx/log/xsec_anti_cheat_d/xsec_anti_cheat_d.log"
		start_position => "end"
		sincedb_path => "../data/sincedb-access-v1"
	}
}

filter {
	grok {
		match => {
			"message" => ["result\|%{GREEDYDATA:matched_result}"]
		}
		add_tag => ["result"]
		tag_on_failure => []
	}

	grok {
		match => {
			"message" => ["phone_not_found\|%{WORD:appId}\|%{WORD:unmatched_phone}\|%{WORD:uid}"]
		}
		add_tag => ["phone"]
		tag_on_failure => []
	}

	if "result" in [tags] {
		json {
			source => "matched_result"
		}
	}

	mutate {
		"remove_field" => ["logsource", "pid", "program", "@version", "host", "path", "message", "matched_result"]
	}
}

output {
	if "result" in [tags] {
		if [appId] == "xxsignal_joinchan" {
			kafka {
				bootstrap_servers => "kafkasz006-core001.xx.com:8101,kafkasz006-core002.xx.com:8101,kafkasz006-core003.xx.com:8101"
				topic_id => "xsec_anticheat_log_xxsignal_joinchan"
				codec => json
			}
		}else if [appId] == "xxsignal_online" {
			kafka {
				bootstrap_servers =>"kafkasz006-core001.xx.com:8101,kafkasz006-core002.xx.com:8101,kafkasz006-core003.xx.com:8101"
				topic_id => "xsec_anticheat_log_xxsignal_online"
				codec => json
			}
		}
	}
	else if "phone" in [tags] {
		kafka {
			bootstrap_servers => "kafkasz006-core001.xx.com:8101,kafkasz006-core002.xx.com:8101,kafkasz006-core003.xx.com:8101"
			topic_id => "xsec_anticheat_phone_notfound"
			codec => json
		}
	}
}

由于对集群进行迁移,在新的kafka集群中漏创建了一个名为xsec_anticheat_phone_notfound的topic,因为缺乏监控原因,最初并没有发现变更配置后有问题。过了几个小时才发现,所有业务的日志数据全部都没有消费到,于是一步步去查根源。发现logstash的日志里有大量的这样的记录:

[2019-09-29T09:22:27,472][WARN ][org.apache.kafka.clients.NetworkClient] [Producer clientId=producer-48] Error while fetching metadata with correlation id 1204417 : {xsec_anticheat_phone_notfound=UNKNOWN_TOPIC_OR_PARTITION}
[2019-09-29T09:22:27,583][WARN ][logstash.outputs.kafka   ] KafkaProducer.send() failed: org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms. {:exception=>java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.}
[2019-09-29T09:22:27,583][WARN ][logstash.outputs.kafka   ] KafkaProducer.send() failed: org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms. {:exception=>java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.}

从日志上看,是因为xsec_anticheat_phone_notfound的topic没有建立造成的,出错后会sleep 60s,这出现我第一个疑问:为什么一个topic的出错,会造成所有的topic数据都无法写入?我看过logstash的配置,里面的并发应是安装环境的CPU核数,但从这现象上,我却怀疑logstash是单线程的。

第二个疑问:logstash出错后,是否一直等待到消息发送成功为止?从日志看出错后,logstash进入sleep状态,但是苏醒过来后,是重新去尝试发送出错的数据,还是跳过当前消息,如果是跳过当前消息,那下一条消息是没问题的,应是可以发送成功,那不应该所有数据都不会写入Kafka对应的topic中。

发现topic没有创建的问题后,我立刻创建topic,创建topic后,数据立刻恢复正常了,但是有个现象很奇怪的,接到的数据只是当前时间的,前面几个小时都没有了。第三个疑问:在配置中,start_position => "end"是设置是读取文件的最后,但没有任务重启操作,从出错的状态转为正常的状态,数据竟然从end的位置开始生产消息,如果每时每刻都从end去消费数据,那么如果数据量较大量是否会有消息漏掉?但从我观察来看,正常情况下数据并不会漏。

这三个疑问还停留在这里,数据恢复了,后面有空再研究这几个问题,有清楚原理的大牛麻烦回答下。