Class: Toaster::ChefListener

Inherits:
Object
  • Object
show all
Defined in:
lib/toaster/chef/chef_listener.rb

Overview

Performs AOP-based instrumentation of the Chef runtime and registers listeners for lifecycle events during Chef automations.

Author: Waldemar Hummer ([email protected])

Class Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Class Attribute Details

.active_listeners ⇒ Object

Returns the value of attribute active_listeners.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def active_listeners
  @active_listeners
end

.chef_log_level ⇒ Object

Returns the value of attribute chef_log_level.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def chef_log_level
  @chef_log_level
end

.current_task_exec_uuid ⇒ Object

Returns the value of attribute current_task_exec_uuid.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def current_task_exec_uuid
  @current_task_exec_uuid
end

.initialized ⇒ Object

Returns the value of attribute initialized.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def initialized
  @initialized
end

.max_task_exec_retries ⇒ Object

Returns the value of attribute max_task_exec_retries.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def max_task_exec_retries
  @max_task_exec_retries
end

.repeat_resource_classes ⇒ Object

Returns the value of attribute repeat_resource_classes.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def repeat_resource_classes
  @repeat_resource_classes
end

.repeated_tasks_running ⇒ Object

Returns the value of attribute repeated_tasks_running.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def repeated_tasks_running
  @repeated_tasks_running
end

.task_exec_error ⇒ Object

Returns the value of attribute task_exec_error.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def task_exec_error
  @task_exec_error
end

.task_exec_timeout_repeated ⇒ Object

Returns the value of attribute task_exec_timeout_repeated.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def task_exec_timeout_repeated
  @task_exec_timeout_repeated
end

.task_exec_uuid_to_task ⇒ Object

Returns the value of attribute task_exec_uuid_to_task.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def task_exec_uuid_to_task
  @task_exec_uuid_to_task
end

.task_execution_timeout ⇒ Object

Returns the value of attribute task_execution_timeout.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def task_execution_timeout
  @task_execution_timeout
end

.task_parameters ⇒ Object

Returns the value of attribute task_parameters.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def task_parameters
  @task_parameters
end

.tasks_by_resource ⇒ Object

Returns the value of attribute tasks_by_resource.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def tasks_by_resource
  @tasks_by_resource
end

.tasks_by_uuid ⇒ Object

Returns the value of attribute tasks_by_uuid.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def tasks_by_uuid
  @tasks_by_uuid
end

.toaster_chef_imported ⇒ Object

Returns the value of attribute toaster_chef_imported.



77
78
79
 
# File 'lib/toaster/chef/chef_listener.rb', line 77

def toaster_chef_imported
  @toaster_chef_imported
end

Class Method Details

.add_listener(listener) ⇒ Object 



47
48
49
50
 
# File 'lib/toaster/chef/chef_listener.rb', line 47

def self.add_listener(listener)
  register_aop_hook()
  self.active_listeners.push(listener)
end

.close_task_exec(task, execution_uuid, error = nil, run = nil) ⇒ Object 



353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
 
# File 'lib/toaster/chef/chef_listener.rb', line 353

def self.close_task_exec(task, execution_uuid, error=nil, run=nil)

  run = AutomationRun.get_current() if !run

  # get output string
  script_output = $output_io.string
  # reset STDOUT and STDERR
  $stderr = $previous_stderr
  $stdout = $previous_stdout
  # print output
  puts script_output
  ChefUtil.set_chef_log_level($chef_log_level)

  # notify listeners
  self.active_listeners.each do |l|
    begin
      l.after_run_action(task, execution_uuid, error, script_output)
    rescue Exception => ex
      puts "Error in listener method 'after_run_action': #{ex}"
      puts ex.backtrace
    end
  end

end

.get_task_from_sourcecode_line(resource, action, start_source_line) ⇒ Object 



84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
 
# File 'lib/toaster/chef/chef_listener.rb', line 84

def self.get_task_from_sourcecode_line(resource, action, start_source_line)
  sourcecode = nil
  sourcefile = nil
  sourceline = nil
  if start_source_line
    # parse static resource definition source code
    sourcecode = ChefUtil.read_sourcecode(start_source_line)
    sourcefile = ChefUtil.get_sourcefile(start_source_line)
    begin sourcefile = sourcefile[(sourcefile.index("/")+1)..-1] end while sourcefile.scan("/").size > 2
    sourceline = ChefUtil.get_sourceline(start_source_line)
  end
  # get or create task
  task = Task.load_from_chef_source(resource, action, sourcecode, sourcefile, sourceline)
  return task
end

.get_task_list(chef_resource_list) ⇒ Object 



100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
 
# File 'lib/toaster/chef/chef_listener.rb', line 100

def self.get_task_list(chef_resource_list)
  list = []
  chef_resource_list.each do |r|
    resource = r.to_s
    action = r.action
    action = action[0] if action.kind_of?(Array)
    action = action.to_s if action.kind_of?(Symbol)
    start_source_line = r.source_line
    if !start_source_line
      puts "WARN: Could not read source_line from resource #{r}"
    end
    task = get_task_from_sourcecode_line(resource,action,start_source_line)
    list << task
  end
  return list
end

.prepare_task_exec(task, execution_uuid) ⇒ Object 



321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
 
# File 'lib/toaster/chef/chef_listener.rb', line 321

def self.prepare_task_exec(task, execution_uuid)

  #puts "TRACE: Prepare task execution, task '#{task.name}', #{task.uuid}, execution #{execution_uuid}"

  # notify listeners
  do_continue = false
  self.active_listeners.each do |l|
    begin
      do_continue ||= l.before_run_action(task, execution_uuid)
    rescue Exception => ex
      puts "Error in listener method 'before_run_action': #{ex}"
      puts ex.backtrace
    end
  end

  return false if !do_continue

  # TODO: turn globals into class variables!
  $chef_log_level = ChefUtil.get_chef_log_level
  # redirect/capture STDOUT and STDERR!
  $output_io = StringIO.open('','w')
  $previous_stderr = $stderr
  $previous_stdout = $stdout
  $stdout.sync = true
  $stderr.sync = true
  $stderr = $output_io
  $stdout = $output_io
  script_output = nil

  return true
end

.proceed_joinpoint_method(jp, task) ⇒ Object 



242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
 
# File 'lib/toaster/chef/chef_listener.rb', line 242

def self.proceed_joinpoint_method(jp, task)

  # 16-characters short random ID should be enough for our purposes..
  execution_uuid = Util.generate_short_uid
  run = AutomationRun.get_current()

  # prepare task execution
  do_continue = prepare_task_exec(task, execution_uuid)

  if !do_continue

    puts "Skipping execution of task #{task.uuid} in automation run #{run.uuid}"

  else

    error = nil
    # we have to set the class-wide error variable as well,
    # because we need it later on to get the error of a
    # chef resource notification run  (TODO: revise)
    ChefListener.task_exec_error = nil # TODO

    begin
      ChefUtil.set_chef_log_level(self.chef_log_level)

      ################################
      # EXECUTE RESOURCE, WITH RETRIES
      ################################

      resource_to_exec = jp.context.parameters[0]
      resource_class = resource_to_exec.class
      exec_timeout = ChefListener.task_execution_timeout
      num_retries = 0
      if ChefListener.repeat_resource_classes.include?(resource_class)
        # set task execution timeout and retries
        exec_timeout = ChefListener.task_exec_timeout_repeated
        num_retries = ChefListener.max_task_exec_retries
      end
      (0..num_retries).each do |iter|
        begin 
          Util.exec_timeout(exec_timeout, ::Chef::Exceptions::CommandTimeout) do
            begin
              self.current_task_exec_uuid = execution_uuid
              self.task_exec_uuid_to_task[execution_uuid] = task
              jp.proceed
            rescue Object => exc1
              puts "WARN: Exception in resource execution: #{exc1} - backtrace (last 10 lines): #{exc1.backtrace[0..10]}"
              raise exc1
            ensure
              self.current_task_exec_uuid = nil
            end
          end
          break
        rescue ::Chef::Exceptions::CommandTimeout => exc
          # timeout occurred, start next try
          remaining = num_retries-iter
          if remaining > 0
            puts "WARN: Chef resource #{resource_to_exec} timed out, remaining retries: #{remaining}" 
            sleep 5 # sleep a bit before the next retry
          end
        end
      end

    rescue Object => ex
      error = ex
      puts "INFO: Error in Chef automation method. Adding details to testing log."
      run = AutomationRun.get_current()
      run.success = false
      run.end_time = TimeStamp.now().to_i
      run.error_details = "#{error}\n#{error.backtrace}"
      run.save()
    end

    # post-process task execution
    close_task_exec(task, execution_uuid, error, run)

    raise error if error
  end
end

.register_aop_hook ⇒ Object 



390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
 
# File 'lib/toaster/chef/chef_listener.rb', line 390

def self.register_aop_hook()

  return if self.initialized
  self.initialized = true

  register_aop_hook1()

  Aspect.new :around, :calls_to => /^run_action/,
  :for_types => [Chef::Runner],
  :method_options => :exclude_ancestor_methods do |jp, obj, *args|
    begin

      if jp.method_name.to_s == "run_action"

        # check to see if we need to update the 'current automation' object
        run = AutomationRun.get_current()
        if run && !run.automation
          ctx = obj.run_context
          ChefListener.update_current_automation_info(run, ctx)
        end

        # TODO: remove as soon as AOP pointcut for Chef::Runner.converge is working..
        ChefListener.save_current_run_details()

        resource = args[0]
        action = args[1]
        task = nil
        if ChefListener.tasks_by_resource[resource]
          task = ChefListener.tasks_by_resource[resource]
        else
          source_line_spec = ""
          args.each do |c| 
            if c.respond_to?("source_line")
              #puts "DEBUG: AOP args in run_action: #{args}"
              source_line_spec = c.source_line 
              # this break here is vital!, because multiple source_line_spec's
              # are read in this loop sometimes (in a Chef notifications context)
              # and the FIRST element on the "args" array is the right resource
              # we are looking for! For instance, we have seen arrays like the 
              # following: [<notified_resource>, :run, :immediate, <notifying_resource>]
              # TODO: check again, not sure if the statement above is true :/
              break
            end
          end
          task = get_task_from_sourcecode_line(resource, action, source_line_spec)
          #puts "get task #{resource} #{action} #{source_line_spec}: #{task}"
        end

        # check if we execute within an "immediate notification"
        if ChefListener.current_task_exec_uuid

          old_task = ChefListener.task_exec_uuid_to_task[ChefListener.current_task_exec_uuid]

          puts "INFO: Apparently we are running within a notification context; " + 
            "closing task execution (to re-open a new execution). " +
            "Old task: name '#{old_task.name}', uuid '#{old_task.uuid}'. " +
            "New task: name '#{task.name}', uuid '#{task.uuid}'."

          # close old/current task execution - a new one will be opened later in the process...
          close_task_exec(old_task, ChefListener.current_task_exec_uuid)

        end

        ChefListener.tasks_by_uuid[task.uuid] = task
        ChefListener.tasks_by_resource[resource] = task
        ChefListener.task_parameters[task] = jp.context.parameters

        num_executions = 1
        if !self.active_listeners.empty?
          num_executions = self.active_listeners[0].num_requested_task_executions(task)
        end

        # execute task, possibly multiple times...
        (1..num_executions).each do

          # run the actual Chef method that was intercepted by AOP..
          proceed_joinpoint_method(jp, task)

        end

        if !self.repeated_tasks_running
          # repeat sequences of tasks, as specified in repeat_tasks=[..] Chef configuration
          tasks_to_repeat = self.active_listeners[0].tasks_to_repeat_now(task)
          if tasks_to_repeat
            puts "INFO: List of tasks to repeat: #{tasks_to_repeat}"
            # temporarily disable interception (otherwise we end up in an infinite loop!)
            self.repeated_tasks_running = true
            tasks_to_repeat.each do |t_uuid|
              task_to_run = self.tasks_by_uuid[t_uuid]
              puts "INFO: Proceeding old joinpoint of task with uuid #{t_uuid}"
              chef_runner = jp.context.advised_object
              params = self.task_parameters[task_to_run]
              # invoke method
              begin
                # this call will again be intercepted by AOP and we will 
                # eventually end up in self.proceed_joinpoint_method(...)
                # Hence, no exec_timeout block is required for this call.
                chef_runner.run_action(params[0], params[1])
              rescue Object => exc
                puts "Error when repeating Chef resource: #{exc} - #{exc.backtrace}"
              end
            end
            # re-activate interception
            self.repeated_tasks_running = false
          end
        end

      else

        begin
          jp.proceed
        rescue Object => ex
          puts "Error in Chef automation: #{ex}"
        end

      end
    rescue Object => ex1
      puts "Error occurred: #{ex1}"
      puts ex1.backtrace.join("\n") + "\n..."
    end
  end
end

.register_aop_hook1 ⇒ Object 



378
379
380
381
382
383
384
385
386
387
388
 
# File 'lib/toaster/chef/chef_listener.rb', line 378

def self.register_aop_hook1()
  Aspect.new :around, :calls_to => /^converge/,
  # :method_options => :exclude_ancestor_methods,
  :for_types => [Chef::Runner] do |jp, obj, *args|
    begin
      #puts "!!!!!!!!!!!!! AOP Chef::Runner::converge !!!!!!!!!!!!!!!!!!"
      # TODO FIXME uncomment as soon as this pointcut is fixed
      #ChefListener.save_current_run_details()
    end
  end
end

.save_current_run_details ⇒ Object 



220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
 
# File 'lib/toaster/chef/chef_listener.rb', line 220

def self.save_current_run_details()
  run = AutomationRun.get_current()
  if run
    run.end_time = TimeStamp.now().to_i
    run.save

    # check if all executed tasks are also included
    # in the associated automation entity
    auto = run.automation
    if auto
      changed = false
      run.get_executed_tasks.each do |t|
        if !auto.get_task_ids.include?(t.uuid)
          auto.tasks << t
          changed = true
        end
      end
      auto.save if changed
    end
  end
end

.update_current_automation_info(run, ctx) ⇒ Object

this method is called ONCE, in the context of executing the first task of the automation under test



119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
 
# File 'lib/toaster/chef/chef_listener.rb', line 119

def self.update_current_automation_info(run, ctx)
  node_name = nil

  # get run_list
  run_list = []
  ctx.node.run_list.each do |n|
    run_list << n.to_s
  end
  run_list = ChefUtil.get_reduced_run_list(run_list)

  # try to determine node name (cookbook name)
  chef_cfg = Chef::Config
  if chef_cfg[:json_attribs]
    json_file = chef_cfg[:json_attribs]
    if json_file.match(/.*\/[^\/]+_node\.json/).to_s == json_file
      node_name = json_file.gsub(/.*\/([^\/]+)_node\.json/, '\1')
      node_name = ChefUtil.wrap_node_name(node_name)
    end
  else
    puts "WARN: Chef::Config[:json_attribs] is not available: '#{chef_cfg[:json_attribs]}'"
    node_name = chef_cfg[:node_name]
  end

  if !node_name
    node_name = ChefUtil.guess_cookbook_from_runlist(run_list)
  end
  node_name = ctx.node.to_s if !node_name
  node_name = node_name.gsub(/.*node\[(.+)\]/, '\1') if node_name.include?("node[")

  # try to retrieve automation from DB, if it exists..
  if File.exist?(json_file)
    attribs = JSON.parse(File.read(json_file))
    if attribs["toaster"] && attribs["toaster"]["automation_uuid"]
      autos = Toaster::Automation.find(
        :uuid => attribs["toaster"]["automation_uuid"]).to_a
      if !autos.empty?
        run.automation = autos[0]
        return
      end
    end
  end
  if !run.automation
    run.automation = Automation.find_by_cookbook_and_runlist(node_name, run_list)[0]
  end

  puts "TRACE: automation run #{run.uuid}, automation #{run.automation ? run.automation.uuid : 'nil'}"

  # create new automation if we cannot find existing one...
  if !run.automation

    config_dir = File.join(File.dirname(__FILE__),"..")
    config_json = ::Toaster::Config.values()
    dirs = []
    config_json["chef"]["cookbook_dirs"].each do |dir|
      dir = File.expand_path(File.join(config_dir, dir)) if dir[0] != "/"
      dirs << dir
    end

    # important: due to possible name conflicts, all Chef related 
    # files apparently need to be loaded before chef_node_inspector, 
    # hence we put this require statement here.
    if !self.toaster_chef_imported
      require 'toaster/chef/chef_node_inspector'
      self.toaster_chef_imported = true
    end

    node_values = config_json["chef"]["node_values"]
    insp = Toaster::ChefNodeInspector.new(dirs,
            Toaster::DefaultProcessorRecursive.new(node_values) {
          |level, msg| puts "WARN: #{msg}" }) {
          |level, msg| puts "WARN: #{msg}"}
    recipe = ChefUtil.guess_recipe_from_runlist(run_list)
    params = {}
    begin
      params = insp.get_defaults(node_name, recipe)
      puts "params: #{params}"
      # make sure we make the hash MongoDB-compatible 
      # (i.e., remove special characters in keys):
      MarkupUtil.rectify_keys(params)
    rescue Object => exc
      puts "WARN: Unable to get default parameters for recipe '#{node_name}'-'#{recipe}': #{exc} - #{exc.backtrace}"
    end

    task_list = ChefListener.get_task_list(ctx.resource_collection.all_resources)
    run.automation = Automation.load_for_chef(node_name, task_list, params, run_list)
    #puts "TRACE: automation 1: #{node_name}, #{task_list}, #{params}, #{run_list}"
    #puts "TRACE: automation run 1: #{run.uuid}, automation #{run.automation ? run.automation.uuid : 'nil'}"

  end

  # determine active parameter values for the current automation run
  Automation.get_attribute_array_names(params, "").each do |param_array_path|
    val = nil
    if "#{param_array_path}" != ""
      eval("val = ctx.node#{param_array_path}")
      eval("params#{param_array_path} = val")
    end
  end
  run.run_attributes = RunAttribute.from_hash(params)
end

Instance Method Details

#after_run_action(task, execution_uuid, error = nil, script_output = nil) ⇒ Object

Informs about an automation task that has just been executed.

  • Args :

    • task -> A Toaster::Task representing the executed task

    • execution_uuid -> String that identifies the automation run this task is part of

    • error -> Contains details (usually an Exception object) in case an error has occurred

    • script_output -> Contains output (stdout+stderr) of the script that executed the task



43
44
45
 
# File 'lib/toaster/chef/chef_listener.rb', line 43

def after_run_action(task, execution_uuid, error = nil, script_output = nil)
  # should be overridden by subclasses
end

#before_run_action(task, execution_uuid) ⇒ Object

Informs about an automation task that is about to be executed.

  • Args :

    • task -> A Toaster::Task representing the currently executing task

    • execution_uuid -> String that identifies the automation run this task is part of



31
32
33
 
# File 'lib/toaster/chef/chef_listener.rb', line 31

def before_run_action(task, execution_uuid)
  # should be overridden by subclasses
end