Class: KitchenBlame::Blame

Inherits:
Object
  • Object
show all
Defined in:
lib/kitchen_blame.rb

Overview

Main class

Constant Summary collapse

LOG_DIR = 
(Pathname.getwd + Pathname.new('.kitchen/logs')).freeze

Class Method Summary collapse

Class Method Details

.analyze_create(key_path, log) ⇒ Object 



76
77
78
79
80
81
82
83
84
85
86
87
 
# File 'lib/kitchen_blame.rb', line 76

def self.analyze_create(key_path, log)
  log = resolve_log(log)
  server_log_entries = server_log_entries(key_path, log)
  create_duration = image_create(log, server_log_entries)
  startup_finished_entry = server_log_entries.find { |entry| entry['MESSAGE'].include?('Startup finished') }
  boot_start = extract_syslog_time(server_log_entries.first)
  boot_finish = extract_syslog_time(startup_finished_entry)
  boot_duration = measure_duration(boot_start, boot_finish)
  puts "Image create took #{create_duration} seconds"
  puts "Boot took #{boot_duration} seconds"
  puts "Systemd timing: #{startup_finished_entry['MESSAGE']}"
end

.analyze_duration(log) ⇒ Object

rubocop:disable MethodLength



123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
 
# File 'lib/kitchen_blame.rb', line 123

def self.analyze_duration(log)
  log = resolve_log(log)
  log_lines = IO.readlines(log).map do |line|
    match_data = /.,\s\[(?<time>.*)\]\s+[^:]+:(?<log>.*)$/.match(line)
    next unless match_data
    time = extract_time(match_data)
    log = match_data[:log]
    { log: log, time: time }
  end
  max_duration = log_lines.compact.each_cons(2).map {|pair| measure_pair(pair)}.max
  puts max_duration
  log_lines.compact.each_cons(2) do |pair|
    log = pair.first[:log]
    duration = measure_pair(pair)
    puts "#{duration.to_s.ljust(max_duration.to_s.length)} seconds for entry #{log}"
  end
end

.analyze_recipe(log) ⇒ Object

rubocop:disable MethodLength



104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
 
# File 'lib/kitchen_blame.rb', line 104

def self.analyze_recipe(log)
  log = resolve_log(log)
  recipe_lines = IO.readlines(log).grep(/Recipe:/).map do |line|
    match_data = /\[(?<time>.*)\].*Recipe:\s(?<recipe>.*)$/.match(line)
    next unless match_data
    time = extract_time(match_data)
    recipe = match_data[:recipe]
    { recipe: recipe, time: time }
  end
  max_duration = recipe_lines.compact.each_cons(2).map {|pair| measure_pair(pair)}.max
  recipe_lines.compact.each_cons(2) do |pair|
    recipe = pair.first[:recipe]
    duration = measure_pair(pair)
    puts "#{duration.to_s.ljust(max_duration.to_s.length)} seconds for recipe #{recipe}"
  end
end

.extract_syslog_time(entry) ⇒ Object

Return the DateTime object from a regex match with a named capture of ‘time’



34
35
36
37
38
 
# File 'lib/kitchen_blame.rb', line 34

def self.extract_syslog_time(entry)
  time = entry['__REALTIME_TIMESTAMP']
  time = (time.to_f / 1_000_000).to_s
  DateTime.strptime(time, '%s')
end

.extract_time(match) ⇒ Object

Return the DateTime object from a regex match with a named capture of ‘time’



27
28
29
30
31
 
# File 'lib/kitchen_blame.rb', line 27

def self.extract_time(match)
  time = match[:time]
  time = time.split('.').first
  DateTime.strptime("#{time} #{Time.now.getlocal.zone}", '%Y-%m-%dT%H:%M:%S %Z')
end

.image_create(log, server_log_entries) ⇒ Object 



95
96
97
98
99
100
101
 
# File 'lib/kitchen_blame.rb', line 95

def self.image_create(log, server_log_entries)
  boot_start = extract_syslog_time(server_log_entries.first)
  create_line = File.foreach(log).grep(/Creating/).first
  match_data = /.,\s\[(?<time>.*)\]\s+[^:]+:(?<log>.*)$/.match(create_line)
  create_time = extract_time(match_data)
  measure_duration(create_time, boot_start)
end

.list(dir) ⇒ Object 



50
51
52
53
54
55
56
57
 
# File 'lib/kitchen_blame.rb', line 50

def self.list(dir)
  return unless File.exist? dir
  Pathname.new(dir).each_child.select(&:file?).each do |log_dir_entry|
    next if log_dir_entry.basename.to_s == 'kitchen.log'
    next unless log_dir_entry.extname == '.log'
    puts log_dir_entry.basename('.log')
  end
end

.measure_duration(start, finish) ⇒ Object

Return the duration for two Datetime objects



41
42
43
 
# File 'lib/kitchen_blame.rb', line 41

def self.measure_duration(start, finish)
  ((finish - start) * 24 * 60 * 60).to_i
end

.measure_pair(pair) ⇒ Object

Return the duration for two objects that both have time fields in a hash



46
47
48
 
# File 'lib/kitchen_blame.rb', line 46

def self.measure_pair(pair)
  ((pair.last[:time] - pair.first[:time]) * 24 * 60 * 60).to_i
end

.resolve_log(log) ⇒ Object

Determine the appropriate log file or raise an error



60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
 
# File 'lib/kitchen_blame.rb', line 60

def self.resolve_log(log)
  log_path = Pathname.new(log)
  return log_path.to_path if log_path.exist? && log_path.file?
  log_path = LOG_DIR + log_path
  return log_path.to_path if log_path.exist? && log_path.file?
  fail "#{LOG_DIR} does not exist.  Cannot find log file matching '#{log}'" unless LOG_DIR.exist?
  LOG_DIR.each_child.select(&:file?).each do |log_dir_entry|
    return log_dir_entry.to_path if log_dir_entry.basename.fnmatch("*#{log}*")
  end
  if log == 'latest'
    latest = LOG_DIR.each_child.select(&:file?).sort_by(&:mtime).last
    return latest if latest
  end
  fail "Unable to fully qualify or find test kitchen log #{log}"
end

.server_log_entries(key_path, log) ⇒ Object 



89
90
91
92
93
 
# File 'lib/kitchen_blame.rb', line 89

def self.server_log_entries(key_path, log)
  ip = File.foreach(log).grep(/Attaching floating IP </).first[/\<(?<ip>.*)\>/, 'ip']
  server_log_entries = `ssh -i #{key_path} -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no vagrant@#{ip} 'sudo journalctl -o json --no-pager' 2>/dev/null`.split("\n")
  server_log_entries.map { |entry| JSON.parse(entry) }
end