Я пытаюсь понять, почему в некоторых сообщениях, полученных logstash, отсутствует какой-то текст.
Я отправляю журналы из Untangle NGFW (11.0 - с лицензией) в logstash, чтобы я мог вести исторические записи журналов веб-фильтров и т. Д.
Я впервые заметил проблему с журналами, поступающими из Untangle вскоре после настройки syslog, я установил фильтр, который ищет сообщения, которые были разделены, потому что они были слишком длинными, это объединяет их вместе, чтобы их можно было проанализировать с помощью grok & json парсеры в logstash. Большинство событий обрабатывались нормально, включая большинство событий с многострочными тегами, однако ряд сообщений также проходил с тегами jsonparsefailure. Я скопировал эти сообщения и поместил их в парсер json и обнаружил, что они не будут работать, потому что небольшие части сообщения вскоре после разделения сообщения отсутствовали.
Когда я впервые увидел проблему, я подумал, что мой фильтр делает что-то неожиданное, но я проверил его и логически не мог понять, как он удалит какой-либо текст, который случайно пропал. Затем я удалил все фильтры из конфигурации logstash и проверил приходящие сообщения, в некоторых все еще отсутствовал какой-то текст. Я спросил об этом в IRC-канале #logstash, и кто-то предложил клонировать все сообщения по мере их поступления, что позволило бы мне продолжить фильтрацию всех сообщений, но сохранило бы исходное сообщение без изменений. Затем я мог сравнивать полученные сообщения с тем, что было сохранено в файлах журналов распутывания. Я также обратился в службу поддержки с Untangle, который поднял bugzilla, который был закрыт позже дня как невоспроизводимый.
Моя конфигурация из logstash:
input {
tcp {
port => 15005
type => "untangle-syslog"
}
}
filter {
#looks for messages from untangle input, then clones every one, some to be saved in a file for future reference, some to be proces
sed by following filters
if [type] == "untangle-syslog" {
clone {
#"cant_touch_this" will be saved to file "modify_this" will be filtered below
clones => [ "cant_touch_this", "modify_this" ]
}
}
if [type] == "modify_this" {
#look for any lines that end with ... this would be a multiline message split by rsyslog when untangle NGFW sends the message
multiline {
pattern => "\.\.\.$"
what => "next"
}
#remove the part between the ... delimiters with nothing, this should return the message to it's starting format
if "multiline" in [tags] {
mutate {
gsub => [ "message", "\.\.\.\n.*\.\.\.", "" ]
}
}
grok {
match => { "message" => "<%{POSINT:priority}>%{SYSLOGTIMESTAMP:syslogtimestamp} localhost node-17: \[SyslogManagerImpl\] <(?:%
{WORD:Protocol}|)> %{WORD:Severity}\s*uvm\[0\]:\s*%{GREEDYDATA:jsonmessage}" }
add_tag => "untangle-syslog"
tag_on_failure => "untangle_syslog_grok_failure"
}
mutate {
gsub => [ "jsonmessage", '"host"', '"websiteHost"' ]
}
json {
source => "jsonmessage"
}
date {
match => [ "timeStamp", "yyyy-MM-dd HH:mm:ss.SSS" ]
}
}
}
Пример события с отсутствующим текстом, это взято из файла клонированных сообщений:
{"message":"<142>Apr 7 11:01:52 localhost node-17: [SyslogManagerImpl] <TCP93307337353045> INFO uvm[0]: {\"requestUri\":\"/pixel.gif?e=34&ud=0&up=0&qa=1366&qb=768&qc=0&qd=0&qf=1366&qe=643&qh=1349&qg=1652&qi=1366&qj=728&qk=0&ql=%3B%5BpwxnRd%7Dt%3Aa%5DmJVOG)%2C~%405%2F%5BGI%3Fi64CE)4b%3DhSIpIm%7C%7CXIN%26JZFEYooWU!%5BFZKU37xWzi%2BGr1VsEkeSKx%26aRo.)%3FJX%5E%255uA%5D%5BC%2BQVo7X%3Ch%2CeI%7C9x%5ELmFLBJIbEBE)8%25S%40xN~ReUobxEsct!6AMCaUw_N%5BoUz%2FAbi%5DpRAJa%3Ci6ikhMn%3CRRHj%5BG%2B1ck9Ln%3AA.eqRB4%2530980o(I%7DY(T0cC%236%3AOtNCp%2F%5B*bT1(ADac8.KG%26JaybqP%23Y%25a%2FqujM37rYgq%7B!%3Dy3mG%2BQV77zANVitbKxpwoFKL3l9EU%22y%2F.D%5BIAby)rx(%40J%3A%3AsLeLG)%3B.o%5DE%24d!L2HyXLy!%7DbSqVB4%25S%40%5EXYq4%3Cc3%2B%7BE%24C%23XGmuGTtDZF%5Eh...","@version":"1","@timestamp":"2015-04-07T10:01:54.569Z","host":"10.0.0.1","type":"cant_touch_this"}
{"message":"<142>Apr 7 11:01:52 localhost ...\"pixel.moatads.com\",\"timeStam \"2015-04-07 11:01:52.447\",\"sessionId\":93307337353045,\"requestId\":93307337050879,\"tag\":\"uvm[0]: \",\"class\":\"class com.untangle.node.http.HttpRequestEvent\",\"method\":\"GET\",\"sessionEvent\":{\"protocol\":6,\"timeStamp\":\"2015-04-07 11:01:52.356\",\"SClientAddr\":\"/192.168.1.11\",\"tag\":\"uvm[0]: \",\"CServerAddr\":\"/54.237.114.13\",\"protocolName\":\"TCP\",\"CClientAddr\":\"/10.0.248.31\",\"class\":\"class com.untangle.uvm.node.SessionEvent\",\"hostname\":\"10.0.248.31\",\"SClientPort\":38237,\"serverIntf\":1,\"CServerPort\":80,\"username\":\"USER\",\"clientIntf\":2,\"sessionId\":93307337353045,\"policyId\":14,\"SServerPort\":80,\"SServerAddr\":\"/54.237.114.13\",\"CClientPort\":22810},\"contentLength\":0}","@version":"1","@timestamp":"2015-04-07T10:01:54.570Z","host":"10.0.0.1","type":"cant_touch_this"}
Как вы можете видеть во второй строке, timeStam был отключен, конец слова исчез, а также закрывающая \ "и:
Затем я подключился к серверу Untangle и проверил журналы, чтобы увидеть, что там было сохранено:
Apr 7 11:01:52 localhost node-17: [SyslogManagerImpl] <TCP93307337353045> INFO uvm[0]: {"requestUri":"/pixel.gif?e=34&ud=0&up=0&qa=1366&qb=768&qc=0&qd=0&qf=1366&qe=643&qh=1349&qg=1652&qi=1366&qj=728&qk=0&ql=%3B%5BpwxnRd%7Dt%3Aa%5DmJVOG)%2C~%405%2F%5BGI%3Fi64CE)4b%3DhSIpIm%7C%7CXIN%26JZFEYooWU!%5BFZKU37xWzi%2BGr1VsEkeSKx%26aRo.)%3FJX%5E%255uA%5D%5BC%2BQVo7X%3Ch%2CeI%7C9x%5ELmFLBJIbEBE)8%25S%40xN~ReUobxEsct!6AMCaUw_N%5BoUz%2FAbi%5DpRAJa%3Ci6ikhMn%3CRRHj%5BG%2B1ck9Ln%3AA.eqRB4%2530980o(I%7DY(T0cC%236%3AOtNCp%2F%5B*bT1(ADac8.KG%26JaybqP%23Y%25a%2FqujM37rYgq%7B!%3Dy3mG%2BQV77zANVitbKxpwoFKL3l9EU%22y%2F.D%5BIAby)rx(%40J%3A%3AsLeLG)%3B.o%5DE%24d!L2HyXLy!%7DbSqVB4%25S%40%5EXYq4%3Cc3%2B%7BE%24C%23XGmuGTtDZF%5Eh...
Apr 7 11:01:52 localhost ..."pixel.moatads.com","timeStamp": "2015-04-07 11:01:52.447","sessionId":93307337353045,"requestId":93307337050879,"tag":"uvm[0]: ","class":"class com.untangle.node.http.HttpRequestEvent","method":"GET","sessionEvent":{"protocol":6,"timeStamp":"2015-04-07 11:01:52.356","SClientAddr":"/192.168.1.11","tag":"uvm[0]: ","CServerAddr":"/54.237.114.13","protocolName":"TCP","CClientAddr":"/10.0.248.31","class":"class com.untangle.uvm.node.SessionEvent","hostname":"10.0.248.31","SClientPort":38237,"serverIntf":1,"CServerPort":80,"username":"USER","clientIntf":2,"sessionId":93307337353045,"policyId":14,"SServerPort":80,"SServerAddr":"/54.237.114.13","CClientPort":22810},"contentLength":0}
То, что сохраняется на машине Untangle, включает в себя полное сообщение, включая символы, которые отсутствовали с точки зрения журналов. Я знаю, что это не то, что отправляется через rsyslog из Untangle, поскольку приоритет отсутствует в начале записи журнала. Однако это должно быть сообщение, которое rsyslog прочитал перед отправкой.
Что мне нужно знать, так это то, как я теперь выясняю, где этот конвейер выходит из строя, сообщение не повреждено в начале на машине Untangle, но к тому времени, когда оно получено и сохранено на сервере logstash, в сообщении отсутствуют некоторые символы.
Я почти уверен, что это происходит только тогда, когда сообщение разделяется отправляющей стороной, у меня вообще нет проблем с однострочными сообщениями. Это часто случается с сообщениями, которые разделены, но не каждый раз, мне удалось получить 3 примера из разных сообщений, в которых отсутствовали символы вскоре после разделения, примерно за 15 минут на довольно тихом сервере (в настоящее время тестируется эта новая машина Untangle до выкатка в производство).
Я подумал о настройке tcpdump для захвата всего трафика с сервера UnTangle в logstash, с чем я могу справиться, но я не уверен, как тогда найти сообщения, которые я ищу, в файле PCAP, чтобы доказать, что отправленная информация содержала / не содержала пропавших без вести символов.
Я использую rsyslogd 5.8.11 и logstash 1.5.0RC2 (я использовал 1.4.2, но обновился, потому что фильтр clone -> не работал в 1.4.2)
Будем очень признательны за любые предложения относительно того, как лучше всего исследовать это, чтобы я мог найти причину проблемы.
РЕДАКТИРОВАТЬ:
Сегодня я провел дополнительное расследование, я сделал захват пакета, а затем прошел захват после того, как произошло событие, в котором отсутствовал какой-то текст. Я обнаружил, что текст отсутствует в пакете, полученном сервером, поэтому я считаю, что проблема связана с rsyslog. Я также обнаружил, что rsyslog не выполняет разбиение (насколько я могу судить), похоже, это выполняется регистратором.