Tests automatisés des patterns Grok pour le plugin Logstash
Quand on souhaite analyser l’usage d’une API REST, la suite logicielle ELK se révèle être un outil simple et extrêmement puissant. Elle permet de suivre en temps réel l’usage des APIs, détecter des régressions suite à un déploiement, détecter les problèmes de performances, détecter des erreurs d’implémentation ou d’algorithmie dans les applications clientes, de retracer une activité utilisateur, etc…
Même si les logs d’accès HTTP sont supportés en standard, il est intéressant de les personnaliser pour obtenir un niveau de détail permettant une analyse plus fine (en ajoutant quelques champs dans les logs et en découpant plus finement les URIs).
Le découpage des trames se configure au travers d’un pattern Grok. Ce pattern peut être assez complexe si l’on tente de gérer une variété importante de type d’URIs1. Or à chaque modification, il y a un risque de casser l’analyse des logs.
Heureusement pour nous, il existe une application en ligne très pratique qui permet de tester un pattern avec un jeu de données de logs :
Il existe des outils en ligne pour valider ses patterns Grok : Grok Constructor ou Grok Debugger. Il est très pratique en phase de développement. Mais il n’est pas adapté pour l’automatisation et assurer la non-régression. Pour cela, il faut écrire un script Ruby.
Sommaire
Installation
Le script dépend du composant grok-pure et des patterns par défaut de grok qu’il faut installer de cette façon :
$ gem install jls-grok json Fetching: cabin-0.9.0.gem (100%) Successfully installed cabin-0.9.0 Fetching: jls-grok-0.11.4.gem (100%) Successfully installed jls-grok-0.11.4 Parsing documentation for cabin-0.9.0 Installing ri documentation for cabin-0.9.0 Parsing documentation for jls-grok-0.11.4 Installing ri documentation for jls-grok-0.11.4 Done installing documentation for cabin, jls-grok after 0 seconds 2 gems installed $ curl -ks https://raw.githubusercontent.com/logstash-plugins/logstash-patterns-core/master/patterns/grok-patterns -o grok/patterns/grok-patterns
Mon pattern personnalisé se trouve dans le fichier /grok/patterns/extra :
CUSTOM_UUID urn\:uuid\:%{UUID}
CUSTOM_COMMONAPACHELOG (%{IPORHOST:clientipforwarded} )?%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] "(?:%{WORD:verb} /%{USERNAME:apiname}(?:/%{WORD:apiversion}/%{USERNAME:resource}(/%{CUSTOM_UUID:uuid})?(/%{USERNAME:subressurce})?|%{URIPATH:path})(\?%{NOTSPACE:request})?(?: HTTP/%{NUMBER:httpversion})?|%{DATA:rawrequest})" %{NUMBER:response} (?:%{NUMBER:bytes}|-)
CUSTOM_COMBINEDAPACHELOG %{CUSTOM_COMMONAPACHELOG} %{QS:referrer} %{QS:agent}
Le jeu de données
Le jeu de données à utiliser pour valider le pattern se trouve dans examples.log :
- 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts?alt=json HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts/urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121 HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts/urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121?alt=json HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts/urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121/customer HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.128 - - [25/Jun/2017:21:09:29 +0200] "PUT /core-api/v1/contracts/urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121/customer?alt=json HTTP/1.1" 200 666 "-" "ReconciliationBatch" **0/19733** - 10.112.0.127 - - [27/Jun/2017:15:53:47 +0200] "GET /admin/logout HTTP/1.1" 302 - "https://mycompany.com/admin" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36" **0/3806** - 10.112.0.204 - - [27/Jun/2017:15:45:14 +0200] "GET /admin/js/angular/contracts/services/ContractsService.js HTTP/1.1" 304 - "https://mycompany.com/admin/contracts/urn:uuid:e8a80824-4647-4bbf-953e-bb017bb4be38" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36" **0/562** - 10.112.0.223 - - [07/Jul/2017:10:47:32 +0200] "GET /portal/ HTTP/1.1" 200 1752 "-" "python-requests/2.13.0" **0/440** - 10.112.0.223 - - [07/Jul/2017:10:47:32 +0200] "GET /portal/ HTTP/1.1" 200 1752 "-" "python-requests/2.13.0" **0/440**
En complément du jeu de données, il est nécessaire de définir le résultat attendu. Par simplicité, j’ai utilisé un fichier JSON définissant la liste des champs et leur valeur pour chaque ligne de log. Tout ceci dans un fichier expected.json :
{
"0": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts"
},
"1": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts",
"request": "alt=json"
},
"2": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts",
"uuid": "urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121"
},
"3": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts",
"uuid": "urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121",
"request": "alt=json"
},
"4": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts",
"uuid": "urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121",
"subressource": "customer"
},
"5": {
"apiversion": "v1",
"httpversion": "1.1",
"timestamp": "25/Jun/2017:21:09:29 +0200",
"agent": "\"ReconciliationBatch\"",
"clientip": "10.112.0.128",
"bytes": "666",
"response": "200",
"ident": "-",
"apiname": "core-api",
"verb": "PUT",
"responsetimemic": "19733",
"referrer": "\"-\"",
"ressource": "contracts",
"uuid": "urn:uuid:195e2dc2-214b-49fe-9bbc-490e709f5121",
"subressource": "customer",
"request": "alt=json"
},
"6": {
"apiversion": null,
"httpversion": "1.1",
"timestamp": "27/Jun/2017:15:53:47 +0200",
"agent": "\"Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36\"",
"clientip": "10.112.0.127",
"bytes": null,
"response": "302",
"ident": "-",
"apiname": "admin",
"verb": "GET",
"responsetimemic": "3806",
"referrer": "\"https://mycompany.com/admin\"",
"ressource": null,
"uuid": null,
"subressource": null,
"request": null,
"path": "/logout"
},
"7": {
"apiversion": null,
"httpversion": "1.1",
"timestamp": "27/Jun/2017:15:45:14 +0200",
"agent": "\"Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36\"",
"clientip": "10.112.0.204",
"bytes": null,
"response": "304",
"ident": "-",
"apiname": "admin",
"verb": "GET",
"responsetimemic": "562",
"referrer": "\"https://mycompany.com/admin/contracts/urn:uuid:e8a80824-4647-4bbf-953e-bb017bb4be38\"",
"ressource": null,
"uuid": null,
"subressource": null,
"request": null,
"path": "/js/angular/contracts/services/ContractsService.js"
},
"8": {
"apiversion": null,
"httpversion": "1.1",
"timestamp": "07/Jul/2017:10:47:32 +0200",
"agent": "\"python-requests/2.13.0\"",
"clientip": "10.112.0.223",
"bytes": "1752",
"response": "200",
"ident": "-",
"apiname": "portal",
"verb": "GET",
"responsetimemic": "440",
"referrer": "\"-\"",
"ressource": null,
"uuid": null,
"subressource": null,
"request": null,
"path": "/"
}
}
Le script de validation
N’étant pas un développeur Ruby, veuillez ne pas tenir rigueur de la qualité du code2 de groktest.rb3 :
#!/usr/local/bin/ruby
require 'rubygems'
require 'grok-pure'
require 'pp'
require 'json'
# define somes constants
module GrokTest
class << self
attr_accessor :display_warn
attr_accessor :blacklist
end
@blacklist = []
end
# old check function from result
def check_expected_from_result(expected, result, context)
result.each_capture do |key, value|
# puts "#{key}: #{value} == #{expected[key]} ?"
if expected.key?(key)
if value == expected[key]
# puts 'success: #{key} => #{value} == #{expected[key]}'
else
puts "failure at line #{context}: #{key} => #{value} != #{expected[key]}"
return false
end
elsif GrokTest.display_warn && (!GrokTest.blacklist.include? key)
puts "ignore field at line #{context}: #{key} => #{value}"
end
end
true
end
# new check function from expected
def check_result_from_expected(result, expected, context)
expected.each do |(key, value)|
# puts "#{key} => #{value}"
if result.key?(key)
if value == result[key][0]
# puts "success: #{key} => #{value} == #{result[key]}"
else
puts "failure at line #{context}: #{key} => #{value} != #{result[key][0]}"
return false
end
end
end
true
end
# the assert function for a single parsed log
def assert_fields(expected, result, context)
is_valid = true
# check if all results are OK
is_valid = false unless check_expected_from_result(expected, result, context)
# check if all excepted are OK
is_valid = false unless check_result_from_expected(result.captures, expected, context)
is_valid
end
grok = Grok.new
# Make sure these point to your pattern files
grok.add_patterns_from_file('./grok/patterns/grok-patterns')
grok.add_patterns_from_file('./grok/patterns/extra')
# blacklist all defined grok patterns
Dir.glob('./grok/patterns/*') do |grok_file|
File.open(grok_file, 'r') do |file|
file.each_line do |line|
line_data = line.split(' ')
reserved_word = line_data[0]
if !reserved_word.nil? && reserved_word != '#'
GrokTest.blacklist.push(reserved_word)
end
end
end
end
# load the assertion file
file = File.read('expected.json')
expected = JSON.parse(file)
# define and load the pattern to test
first_arg, *the_rest = ARGV
pattern = first_arg.dup
GrokTest.display_warn = the_rest.include? '--warn=yes'
grok.compile(pattern)
puts "PATTERN: #{pattern}"
puts 'Checking logs:'
total = 0
ok = 0
ko = 0
ignored = 0
$stdin.each_with_index do |line, index|
total += 1
m = grok.match(line)
# puts "IN(#{index}): #{line}"
if m
if expected.key?(index.to_s)
if assert_fields(expected[index.to_s], m, index)
ok += 1
else
ko += 1
end
else
warn "ignore line #{index}" if GrokTest.display_warn
ignored += 1
end
else
puts "failure: unable to parse message \"#{line}\""
exit
end
print '.'
STDOUT.flush
end
puts "\nResult (OK/KO/ignored/total): #{ok}/#{ko}/#{ignored}/#{total} OK"
Utilisation
$ cat examples.log | ruby groktest.rb '%{MORE_COMBINEDAPACHELOG}( \*\*%{NUMBER:responsetimesec}/%{POSINT:responsetimemic}\*\*)?'
PATTERN: %{MORE_COMBINEDAPACHELOG}( \*\*%{NUMBER:responsetimesec}/%{POSINT:responsetimemic}\*\*)?
Checking logs:
..........
Result (OK/KO/ignored/total): 9/0/1/10 OK
Nous pouvons voir que 9 lignes ont passées les tests et une a été ignorée car aucun résultat attendu n’a été configurée pour cette dernière.
Conclusion
Nous avons donc un outil en ligne de commande qui permet non seulement de tester nos patterns Grok mais surtout s’assurer la non-régression sur un jeu de données pré-défini.
L’écriture de cet outil s’est révélée intéressante sur bien des points :
- écrire un script d’une centaine de lignes pour valider la configuration d’un outil tiers mais central à une architecture
- augmenter la productivité lors de l’ajout de nouveau champs
- assurer la non-régression (et donc ne plus avoir besoin de croiser les doigts lors d’un changement de configuration)
- découvrir le Ruby (même si j’avais déjà fait une PR sur un projet en Ruby)
Il est également possible d’améliorer ce script en rendant paramétrable :
- le chemin de configuration des patterns Grok
- le fichier définissant le résultat attendu
- le niveau de détail des informations à afficher sur la sortie standard ou erreur
- Ce n’est sûrement pas la bonne approche. Il faudrait plutôt typer les logs et avoir un pattern par type de log. Mais ce n’est pas le sujet ici. ↩
- J’ai tout de même fait un petit
gem install rubocop ruby-lintpour lever les erreurs de base… ↩ - On pourrait supprimer la fonction
check_expected_from_resultqui est inutile suite à l’ajout de la fonctioncheck_result_from_expected↩
Laisser un commentaire