lib/awetestlib/logging.rb in awetestlib-0.1.28 vs lib/awetestlib/logging.rb in awetestlib-0.1.29pre1

- old
+ new

@@ -1,366 +1,366 @@ -module Awetestlib - # Logging and reporting. - module Logging - - # @deprecated - def self.included(mod) - # puts "RegressionSupport::Logging extended by #{mod}" - end - - # Format log message and write to STDOUT. Write to physical log if indicated. - # @private - # @param [Fixnum] severity Severity level of message. Use constants DEBUG, INFO, WARN, ERROR, FATAL, or UNKNOWN - # @param [String] message The message to be placed in the log. - # @param [String, Fixnum] tag Indicates the type of message. Valid string values are 'FAIL' and 'PASS'. - # Valid number values are 0 to 9. - # @param [Fixnum] lnbr the line number in the calling script - # @param [Fixnum] addts Obsolete, no longer used. - # @param [String] exception Obsolete, no longer used. - def log_message(severity, message, tag = '', lnbr = nil, addts = 1, exception=nil) - # caller = get_caller(lnbr, exception) - - # @sequence ||= log_properties ? log_properties.fetch('sequence', 0) : 0 - # @sequence += 1 - - t = Time.now.utc - @last_t ||= t - @last_t = t - dt = t.strftime("%H%M%S") - mySev = translate_severity(severity) - myCaller = get_caller(lnbr) || 'unknown' - - myMsg = "%-8s" % mySev - myMsg << '[' + dt + ']:' - if tag - if tag.is_a? Fixnum - tag = '-LVL' + tag.to_s - end - end - myMsg << "[%-5s]:" % tag - #myMsg << '[' + t.to_f.to_s + ']:' - #myMsg << '[' + myCaller + ']:' - #myMsg << "#{get_call_list[-1]}#{get_call_list[-2]} " - myMsg << get_call_list_new.to_s - myMsg << ' '+message - myMsg << " [#{lnbr}] " if lnbr - - @myLog.add(severity, myMsg) if @myLog # add persistent logging for awetestlib. pmn 05jun2012 - puts myMsg+"\n" - - nil # so method doesn't return whole @output. - end - - #private log_message - - # Translates tag value to corresponding value for +pass+ column in database. - # @private - # @param [String, Fixnum] tag - # @return [String] Single character - def pass_code_for(tag) - case - when tag =~ /PASS/ - 'P' - when tag =~ /FAIL/ - 'F' - #when tag =~ /\d+/ # avoid having to require andand for awetestlib. pmn 05jun2012 - when tag.andand.is_a?(Fixnum) - 'H' - when tag =~ /DONE/ - 'D' - when tag =~ /role/ - 'R' - end - end - - # @private - def log_sikuli_output(output_file, passed) - output_lines = File.open(output_file, 'r') { |f| f.readlines } - puts "IM FAILING?! #{passed}" - - # if passed - - log_messages = ['[log]', '[error]'] - output_lines = output_lines.select { |l| log_messages } #.detect{|msg| l.include?(msg)} } - while line = output_lines.shift do - puts "line to be logged: #{line}" - if line.include? '[log]' - passed_to_log line - elsif line.include? '[error]' - failed_to_log line - elsif line.match /\s*Exception/ - failed_to_log output_lines.join("\n") - break - else - debug_tolog line - end - end - - # else - # failed_to_log "SIKULI LOG:\n\n #{output_lines.join('\n')}" - # end - - return { :result => passed, :msg => output_str } - end - - - # Write a status message to the log and report indicating location or activity - # in the script. mark_test_level automatically determines the call hierarchy level - # of the calling method within the script and project utility methods. The top level - # method of the script is always level 1. The method also prefixes the calling method - # name (titleized) to the message to be placed in the log. - # @param [String] message The text to place in the log and report after the titleized - # calling method name. - # @param [Fixnum] lvl '0' forces a message to the report without a specific level - # attached. Any other integer is ignored in favor of the calculated level - # @param [String] desc Any additional information to add to the message. - # @param [Boolean] dbg When set to true adds a trace to the message. - # @return [void] - def mark_test_level(message = '', lvl = nil, desc = '', dbg = nil) - call_arr = get_call_array() - #debug_to_log("#{call_arr.to_yaml}") - strg = '' - call_script, call_line, call_meth = parse_caller(call_arr[1]) - if not lvl or lvl > 1 - lvl, list = get_test_level - strg << "#{call_meth.titleize}" - end - strg << " #{message}" if message.length > 0 - strg << " (#{desc})" if desc.length > 0 - strg << " [#{call_line}]" - strg << "\n#{list.to_yaml}" if dbg or @debug_calls - @report_class.add_to_report(strg, "&nbsp", lvl || 1) unless Awetestlib::Runner.nil? - log_message(INFO, strg, lvl, nil, 1) - rescue - failed_to_log("#{__method__}: #{$!}") - end - - alias mark_testlevel mark_test_level - - # @param [String] message The text to place in the log - # @return [void] - def info_to_log(message, lnbr = nil) - log_message(INFO, message, 0, lnbr) - end - - alias message_tolog info_to_log - alias message_to_log info_to_log - alias info_tolog info_to_log - - # @param [String] message The text to place in the log and report - # @return [void] - def debug_to_log(message, lnbr = nil, dbg = false) - message << "\n#{get_debug_list}" if dbg or @debug_calls # and not @debug_calls_fail_only) - log_message(DEBUG, "#{message}", nil, lnbr) - end - - alias debug_tolog debug_to_log - - # @note Do not use for failed validations. Use only for serious error conditions. - # @return [void] - # @param [String] message The text to place in the log and report - def error_to_log(message, lnbr = nil) - log_message(ERROR, message, nil, lnbr) - end - - alias error_tolog error_to_log - - # @param [String] message The text to place in the log and report - # @return [void] - def passed_to_log(message, lnbr = nil, dbg = false) - message << " \n#{get_debug_list}" if dbg or @debug_calls # and not @debug_calls_fail_only) - @my_passed_count += 1 if @my_passed_count - parse_error_references(message) - @report_class.add_to_report(message, "PASSED") unless Awetestlib::Runner.nil? - log_message(INFO, "#{message}", PASS, lnbr) - end - - alias validate_passed_tolog passed_to_log - alias validate_passed_to_log passed_to_log - alias passed_tolog passed_to_log - alias pass_tolog passed_to_log - alias pass_to_log passed_to_log - - # @param [String] message The text to place in the log and report - # @return [void] - def failed_to_log(message, lnbr = nil, dbg = false) - message << " \n#{get_debug_list}" if dbg or @debug_calls or @debug_calls_fail_only - @my_failed_count += 1 if @my_failed_count - parse_error_references(message, true) - @report_class.add_to_report("#{message}" + " [#{get_caller(lnbr)}]", "FAILED") unless Awetestlib::Runner.nil? - log_message(WARN, "#{message}", FAIL, lnbr) - end - - alias validate_failed_tolog failed_to_log - alias validate_failed_to_log failed_to_log - alias failed_tolog failed_to_log - alias fail_tolog failed_to_log - alias fail_to_log failed_to_log - - # @param [String] message The text to place in the log and report - # @return [void] - def fatal_to_log(message, lnbr = nil, dbg = false) - message << " \n#{get_debug_list}" if dbg or (@debug_calls and not @debug_calls_fail_only) - @my_failed_count += 1 if @my_failed_count - parse_error_references(message, true) - @report_class.add_to_report("#{message}" + " [#{get_caller(lnbr)}]", "FAILED") unless Awetestlib::Runner.nil? - debug_to_report("#{__method__}:\n#{dump_caller(lnbr)}") - log_message(FATAL, "#{message} (#{lnbr})", FAIL, lnbr) - end - - alias fatal_tolog fatal_to_log - - # @param [String] message The text to place in the log and report - # @return [void] - def message_to_report(message, dbg = false) - mark_testlevel(message, 0, '', dbg) - end - - # @param [String] message The text to place in the log and report - # @return [void] - def debug_to_report(message, dbg = false) - mark_testlevel("(DEBUG): ", 0, "#{message}", dbg) - end - - # @private - # @return [Fixnum] required by logger. - def translate_severity(severity) - mySev = '' - case - when severity == 0 - mySev = 'DEBUG' - when severity == 1 - mySev = 'INFO' - when severity == 2 - mySev = 'WARN' - when severity == 3 - mySev = 'ERROR' - when severity == 4 - mySev = 'FATAL' - when severity > 4 - mySev = 'UNKNOWN' - end - mySev - end - - # @private - def get_caller(lnbr=nil, exception=nil) - script_name ||= File.basename(script_file) - if lnbr && script_type.eql?("Selenium") - [script_name, lnbr, 'in run()'].join(":") - elsif lnbr && script_type.eql?("MobileNativeApp") - [script_name, lnbr, 'in scenario()'].join(":") - else - caller_object = exception ? exception.backtrace : Kernel.caller - call_frame = caller_object.detect do |frame| - frame.match(/#{script_name}/) or (library && frame.match(/#{library}/)) - end - unless call_frame.nil? - call_frame.gsub!(/^C:/, '') - file, line, method = call_frame.split(":") - [File.basename(file), line, method].join(":") - else - 'unknown' - end - end - end - - # @private - def init_logger(logFile, scriptName = nil) - if File.exist?(logFile) - puts "==> Logfile already exists: #{logFile}. Replacing it." - begin - File.delete(logFile) - rescue - puts "#{scriptName}: init_logger RESCUE: #{$!}" - end - end - logger = ActiveSupport::BufferedLogger.new(logFile) - logger.level = ActiveSupport::BufferedLogger::DEBUG - logger.auto_flushing = (true) - logger.add(INFO, "#{logFile}\n#{ENV["OS"]}") - logger - end - - #private init_logger - - # @private - def start_run(ts = nil) - @start_timestamp = Time.now unless ts - utc_ts = @start_timestamp.getutc - loc_tm = "#{@start_timestamp.strftime("%H:%M:%S")} #{@start_timestamp.zone}" - message_to_report(">> Starting #{@myName.titleize} #{utc_ts} (#{loc_tm})") - end - - alias start_to_log start_run - - # @private - # Tally and report duration, validation and failure counts, and end time for the script. - # @param [DateTime] ts Time stamp indicating the time the script completed. - def finish_run(ts = Time.now) - tally_error_references - message_to_report( - ">> #{@myName.titleize} duration: #{sec2hms(ts - @start_timestamp)}") - message_to_report(">> #{@myName.titleize} validations: #{@my_passed_count + @my_failed_count} "+ - "fail: #{@my_failed_count}]") if @my_passed_count and @my_failed_count - utc_ts = ts.getutc - loc_tm = "#{ts.strftime("%H:%M:%S")} #{ts.zone}" - message_to_report(">> End #{@myName.titleize} #{utc_ts} (#{loc_tm})") - end - - alias finish_to_log finish_run - - # @private - def tally_error_references(list_tags = @report_all_refs) - tags_tested = 0 - tags_hit = 0 - if @my_error_hits and @my_error_hits.length > 0 - message_to_report(">> Tagged Error Hits:") - tags_hit = @my_error_hits.length - @my_error_hits.each_key do |ref| - message_to_report("#{ref} - #{@my_error_hits[ref]}") - end - end - if list_tags - if @my_error_references and @my_error_references.length > 0 - message_to_report(">> Error and Test Case Tags:") - tags_tested = @my_error_references.length - @my_error_references.each_key do |ref| - message_to_report("#{ref} - #{@my_error_references[ref]}") - end - message_to_report(">> Fails were hit on #{tags_hit} of #{tags_tested} error/test case references") - else - message_to_report(">> No Error or Test Case References found.") - end - end - end - - # @private - def parse_error_references(message, fail = false) - msg = message.dup - while msg =~ /(\*\*\*\s+[\w\d_\s,-:;\?]+\s+\*\*\*)/ - capture_error_reference($1, fail) - msg.sub!($1, '') - end - end - - # @private - def capture_error_reference(ref, fail) - if fail - @my_error_hits = Hash.new unless @my_error_hits - if @my_error_hits[ref] - @my_error_hits[ref] += 1 - else - @my_error_hits[ref] = 1 - end - #debug_to_report("#{__method__}: error hits:\n#{@my_error_hits.to_yaml}") - end - @my_error_references = Hash.new unless @my_error_references - if @my_error_references[ref] - @my_error_references[ref] += 1 - else - @my_error_references[ref] = 1 - end - end - - end -end +module Awetestlib + # Logging and reporting. + module Logging + + # @deprecated + def self.included(mod) + # puts "RegressionSupport::Logging extended by #{mod}" + end + + # Format log message and write to STDOUT. Write to physical log if indicated. + # @private + # @param [Fixnum] severity Severity level of message. Use constants DEBUG, INFO, WARN, ERROR, FATAL, or UNKNOWN + # @param [String] message The message to be placed in the log. + # @param [String, Fixnum] tag Indicates the type of message. Valid string values are 'FAIL' and 'PASS'. + # Valid number values are 0 to 9. + # @param [Fixnum] lnbr the line number in the calling script + # @param [Fixnum] addts Obsolete, no longer used. + # @param [String] exception Obsolete, no longer used. + def log_message(severity, message, tag = '', lnbr = nil, addts = 1, exception=nil) + # caller = get_caller(lnbr, exception) + + # @sequence ||= log_properties ? log_properties.fetch('sequence', 0) : 0 + # @sequence += 1 + + t = Time.now.utc + @last_t ||= t + @last_t = t + dt = t.strftime("%H%M%S") + mySev = translate_severity(severity) + myCaller = get_caller(lnbr) || 'unknown' + + myMsg = "%-8s" % mySev + myMsg << '[' + dt + ']:' + if tag + if tag.is_a? Fixnum + tag = '-LVL' + tag.to_s + end + end + myMsg << "[%-5s]:" % tag + #myMsg << '[' + t.to_f.to_s + ']:' + #myMsg << '[' + myCaller + ']:' + #myMsg << "#{get_call_list[-1]}#{get_call_list[-2]} " + myMsg << get_call_list_new.to_s + myMsg << ' '+message + myMsg << " [#{lnbr}] " if lnbr + + @myLog.add(severity, myMsg) if @myLog # add persistent logging for awetestlib. pmn 05jun2012 + puts myMsg+"\n" + + nil # so method doesn't return whole @output. + end + + #private log_message + + # Translates tag value to corresponding value for +pass+ column in database. + # @private + # @param [String, Fixnum] tag + # @return [String] Single character + def pass_code_for(tag) + case + when tag =~ /PASS/ + 'P' + when tag =~ /FAIL/ + 'F' + #when tag =~ /\d+/ # avoid having to require andand for awetestlib. pmn 05jun2012 + when tag.andand.is_a?(Fixnum) + 'H' + when tag =~ /DONE/ + 'D' + when tag =~ /role/ + 'R' + end + end + + # @private + def log_sikuli_output(output_file, passed) + output_lines = File.open(output_file, 'r') { |f| f.readlines } + puts "IM FAILING?! #{passed}" + + # if passed + + log_messages = ['[log]', '[error]'] + output_lines = output_lines.select { |l| log_messages } #.detect{|msg| l.include?(msg)} } + while line = output_lines.shift do + puts "line to be logged: #{line}" + if line.include? '[log]' + passed_to_log line + elsif line.include? '[error]' + failed_to_log line + elsif line.match /\s*Exception/ + failed_to_log output_lines.join("\n") + break + else + debug_tolog line + end + end + + # else + # failed_to_log "SIKULI LOG:\n\n #{output_lines.join('\n')}" + # end + + return { :result => passed, :msg => output_str } + end + + + # Write a status message to the log and report indicating location or activity + # in the script. mark_test_level automatically determines the call hierarchy level + # of the calling method within the script and project utility methods. The top level + # method of the script is always level 1. The method also prefixes the calling method + # name (titleized) to the message to be placed in the log. + # @param [String] message The text to place in the log and report after the titleized + # calling method name. + # @param [Fixnum] lvl '0' forces a message to the report without a specific level + # attached. Any other integer is ignored in favor of the calculated level + # @param [String] desc Any additional information to add to the message. + # @param [Boolean] dbg When set to true adds a trace to the message. + # @return [void] + def mark_test_level(message = '', lvl = nil, desc = '', dbg = nil) + call_arr = get_call_array() + #debug_to_log("#{call_arr.to_yaml}") + strg = '' + call_script, call_line, call_meth = parse_caller(call_arr[1]) + if not lvl or lvl > 1 + lvl, list = get_test_level + strg << "#{call_meth.titleize}" + end + strg << " #{message}" if message.length > 0 + strg << " (#{desc})" if desc.length > 0 + strg << " [#{call_line}]" if dbg or @debug_calls + strg << "\n#{list.to_yaml}" if dbg or @debug_calls + @report_class.add_to_report(strg, "&nbsp", lvl || 1) unless Awetestlib::Runner.nil? + log_message(INFO, strg, lvl, nil, 1) + rescue + failed_to_log("#{__method__}: #{$!}") + end + + alias mark_testlevel mark_test_level + + # @param [String] message The text to place in the log + # @return [void] + def info_to_log(message, lnbr = nil) + log_message(INFO, message, 0, lnbr) + end + + alias message_tolog info_to_log + alias message_to_log info_to_log + alias info_tolog info_to_log + + # @param [String] message The text to place in the log and report + # @return [void] + def debug_to_log(message, lnbr = nil, dbg = false) + message << "\n#{get_debug_list}" if dbg or @debug_calls # and not @debug_calls_fail_only) + log_message(DEBUG, "#{message}", nil, lnbr) + end + + alias debug_tolog debug_to_log + + # @note Do not use for failed validations. Use only for serious error conditions. + # @return [void] + # @param [String] message The text to place in the log and report + def error_to_log(message, lnbr = nil) + log_message(ERROR, message, nil, lnbr) + end + + alias error_tolog error_to_log + + # @param [String] message The text to place in the log and report + # @return [void] + def passed_to_log(message, lnbr = nil, dbg = false) + message << " \n#{get_debug_list}" if dbg or @debug_calls # and not @debug_calls_fail_only) + @my_passed_count += 1 if @my_passed_count + parse_error_references(message) + @report_class.add_to_report(message, "PASSED") unless Awetestlib::Runner.nil? + log_message(INFO, "#{message}", PASS, lnbr) + end + + alias validate_passed_tolog passed_to_log + alias validate_passed_to_log passed_to_log + alias passed_tolog passed_to_log + alias pass_tolog passed_to_log + alias pass_to_log passed_to_log + + # @param [String] message The text to place in the log and report + # @return [void] + def failed_to_log(message, lnbr = nil, dbg = false) + message << " \n#{get_debug_list}" if dbg or @debug_calls or @debug_calls_fail_only + @my_failed_count += 1 if @my_failed_count + parse_error_references(message, true) + @report_class.add_to_report("#{message}" + " [#{get_caller(lnbr)}]", "FAILED") unless Awetestlib::Runner.nil? + log_message(WARN, "#{message}", FAIL, lnbr) + end + + alias validate_failed_tolog failed_to_log + alias validate_failed_to_log failed_to_log + alias failed_tolog failed_to_log + alias fail_tolog failed_to_log + alias fail_to_log failed_to_log + + # @param [String] message The text to place in the log and report + # @return [void] + def fatal_to_log(message, lnbr = nil, dbg = false) + message << " \n#{get_debug_list}" if dbg or (@debug_calls and not @debug_calls_fail_only) + @my_failed_count += 1 if @my_failed_count + parse_error_references(message, true) + @report_class.add_to_report("#{message}" + " [#{get_caller(lnbr)}]", "FAILED") unless Awetestlib::Runner.nil? + debug_to_report("#{__method__}:\n#{dump_caller(lnbr)}") + log_message(FATAL, "#{message} (#{lnbr})", FAIL, lnbr) + end + + alias fatal_tolog fatal_to_log + + # @param [String] message The text to place in the log and report + # @return [void] + def message_to_report(message, dbg = false) + mark_testlevel(message, 0, '', dbg) + end + + # @param [String] message The text to place in the log and report + # @return [void] + def debug_to_report(message, dbg = false) + mark_testlevel("(DEBUG): ", 0, "#{message}", dbg) + end + + # @private + # @return [Fixnum] required by logger. + def translate_severity(severity) + mySev = '' + case + when severity == 0 + mySev = 'DEBUG' + when severity == 1 + mySev = 'INFO' + when severity == 2 + mySev = 'WARN' + when severity == 3 + mySev = 'ERROR' + when severity == 4 + mySev = 'FATAL' + when severity > 4 + mySev = 'UNKNOWN' + end + mySev + end + + # @private + def get_caller(lnbr=nil, exception=nil) + script_name ||= File.basename(script_file) + if lnbr && script_type.eql?("Selenium") + [script_name, lnbr, 'in run()'].join(":") + elsif lnbr && script_type.eql?("MobileNativeApp") + [script_name, lnbr, 'in scenario()'].join(":") + else + caller_object = exception ? exception.backtrace : Kernel.caller + call_frame = caller_object.detect do |frame| + frame.match(/#{script_name}/) or (library && frame.match(/#{library}/)) + end + unless call_frame.nil? + call_frame.gsub!(/^C:/, '') + file, line, method = call_frame.split(":") + [File.basename(file), line, method].join(":") + else + 'unknown' + end + end + end + + # @private + def init_logger(logFile, scriptName = nil) + if File.exist?(logFile) + puts "==> Logfile already exists: #{logFile}. Replacing it." + begin + File.delete(logFile) + rescue + puts "#{scriptName}: init_logger RESCUE: #{$!}" + end + end + logger = ActiveSupport::BufferedLogger.new(logFile) + logger.level = ActiveSupport::BufferedLogger::DEBUG + logger.auto_flushing = (true) + logger.add(INFO, "#{logFile}\n#{ENV["OS"]}") + logger + end + + #private init_logger + + # @private + def start_run(ts = nil) + @start_timestamp = Time.now unless ts + utc_ts = @start_timestamp.getutc + loc_tm = "#{@start_timestamp.strftime("%H:%M:%S")} #{@start_timestamp.zone}" + message_to_report(">> Starting #{@myName.titleize} #{utc_ts} (#{loc_tm})") + end + + alias start_to_log start_run + + # @private + # Tally and report duration, validation and failure counts, and end time for the script. + # @param [DateTime] ts Time stamp indicating the time the script completed. + def finish_run(ts = Time.now) + tally_error_references + message_to_report( + ">> #{@myName.titleize} duration: #{sec2hms(ts - @start_timestamp)}") + message_to_report(">> #{@myName.titleize} validations: #{@my_passed_count + @my_failed_count} "+ + "fail: #{@my_failed_count}]") if @my_passed_count and @my_failed_count + utc_ts = ts.getutc + loc_tm = "#{ts.strftime("%H:%M:%S")} #{ts.zone}" + message_to_report(">> End #{@myName.titleize} #{utc_ts} (#{loc_tm})") + end + + alias finish_to_log finish_run + + # @private + def tally_error_references(list_tags = @report_all_refs) + tags_tested = 0 + tags_hit = 0 + if @my_error_hits and @my_error_hits.length > 0 + message_to_report(">> Tagged Error Hits:") + tags_hit = @my_error_hits.length + @my_error_hits.each_key do |ref| + message_to_report("#{ref} - #{@my_error_hits[ref]}") + end + end + if list_tags + if @my_error_references and @my_error_references.length > 0 + message_to_report(">> Error and Test Case Tags:") + tags_tested = @my_error_references.length + @my_error_references.each_key do |ref| + message_to_report("#{ref} - #{@my_error_references[ref]}") + end + message_to_report(">> Fails were hit on #{tags_hit} of #{tags_tested} error/test case references") + else + message_to_report(">> No Error or Test Case References found.") + end + end + end + + # @private + def parse_error_references(message, fail = false) + msg = message.dup + while msg =~ /(\*\*\*\s+[\w\d_\s,-:;\?]+\s+\*\*\*)/ + capture_error_reference($1, fail) + msg.sub!($1, '') + end + end + + # @private + def capture_error_reference(ref, fail) + if fail + @my_error_hits = Hash.new unless @my_error_hits + if @my_error_hits[ref] + @my_error_hits[ref] += 1 + else + @my_error_hits[ref] = 1 + end + #debug_to_report("#{__method__}: error hits:\n#{@my_error_hits.to_yaml}") + end + @my_error_references = Hash.new unless @my_error_references + if @my_error_references[ref] + @my_error_references[ref] += 1 + else + @my_error_references[ref] = 1 + end + end + + end +end