Eu estou tentando descobrir por que algumas mensagens recebidas pelo logstash têm algum texto faltando delas.
Estou enviando os logs de um Untangle NGFW (11.0 - licensed) para logstash para que eu possa manter registros históricos de logs de filtros da web, etc.
Primeiramente, notei um problema com os logs provenientes do Untangle logo após a configuração do syslog, configurei um filtro que procura mensagens que foram divididas porque eram muito longas, isso as une novamente para que possam ser analisadas por grok & Analisadores json no logstash. A maioria dos eventos foi processada corretamente, incluindo a maioria dos eventos com tags de múltiplas linhas, no entanto, várias mensagens estavam chegando com tags jsonparsefailure. Eu copiei essas mensagens e as coloquei em um analisador json e descobri que elas falhariam porque pequenas partes da mensagem logo após a divisão da mensagem estavam faltando.
Meu primeiro pensamento ao ver o problema foi que meu filtro estava fazendo algo inesperado, mas eu verifiquei e, logicamente, não consegui ver como isso removeria qualquer texto que estivesse faltando aleatoriamente. Então eu removi todos os filtros da configuração do logstash e verifiquei as mensagens que estavam chegando, algumas ainda estavam faltando algum texto. Eu perguntei sobre isso no canal do IRC #logstash e alguém sugeriu clonar todas as mensagens quando elas chegassem, o que me permitiria continuar filtrando todas as mensagens, mas manteria a mensagem original intacta. Eu poderia, então, verificar as mensagens recebidas em relação ao que foi salvo nos arquivos de log de desembaraço. Também criei uma consulta de suporte com o Untangle, que criou um bugzilla, que foi fechado depois do dia como não reproduzível.
Minha configuração do 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" ]
}
}
}
Um exemplo de evento com texto ausente, isso é retirado do arquivo de mensagens clonadas:
{"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"}
Como você pode ver na segunda linha, o timeStam foi cortado, o final da palavra se foi, assim como o fechamento \ "e o:
Em seguida, conectei-me ao servidor Untangle e verifiquei os registros para ver o que foi salvo lá:
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}
O que é salvo na máquina Untangle inclui a mensagem completa, incluindo os caracteres que estavam faltando no ponto de vista do logstashes. Eu sei que isso não é o que é enviado via rsyslog de Untangle, como a prioridade está faltando na frente da entrada de log. No entanto, esta deve ser a mensagem que foi lida pelo rsyslog antes do envio.
O que eu preciso saber é como eu agora descubro onde esse pipeline está quebrando, a mensagem está intacta no início na máquina Untangle, mas no momento em que é recebida e salva no servidor logstash, mensagem está faltando alguns caracteres.
Estou bastante confiante de que a única vez que isso acontece é quando a mensagem é dividida pela parte de envio, não tenho nenhum problema com mensagens de linha única. Isso acontece frequentemente com mensagens que são divididas, mas não todas as vezes, eu consegui obter 3 exemplos de mensagens diferentes onde havia caracteres faltando logo após a divisão, em cerca de 15 minutos em um servidor bastante silencioso (atualmente testando essa nova máquina Untangle antes rolar para a produção).
Pensei em configurar um tcpdump para capturar todo o tráfego do servidor de desequilíbrio para logstash, o que posso fazer bem, mas não tenho certeza sobre como encontrar as mensagens que estou procurando no arquivo PCAP para provar que as informações enviadas estavam com / sem os caracteres que desapareceram.
Estou usando o rsyslogd 5.8.11 e o logstash 1.5.0RC2 (eu estava usando o 1.4.2 mas atualizado porque o clone - > filter não funcionava no 1.4.2)
Qualquer sugestão sobre a melhor forma de investigar isso para que eu possa encontrar a causa do problema seria muito apreciada.
EDITAR:
Hoje fiz mais algumas investigações, fiz uma captura de pacotes e, em seguida, passei pela captura após um evento que faltava algum texto. Eu achei que o texto está faltando no pacote recebido pelo servidor, então eu acredito que o problema é com o rsyslog. Eu também achei que o rsyslog não faz a divisão (até onde eu sei) parece ser feito pelo logger.