Add a better logger that shows timing diffs (#629)

Been meaning to do this - hopefully this better-formatted logging is easier to see where the performance bottlenecks are.

lib/event_generators/similar_events.rb

@@ -1,17 +1,18 @@
 require_relative '../../app/helpers/application_helper'
+require 'timing_logger'
 
 class SimilarEvents
   include ApplicationHelper
 
-  def initialize(project)
+  def initialize(project, log = TimingLogger.new(STDOUT, 'data:events:similar'))
     @project = project
+    @log = log
   end
 
   def generate
-    log = Logger.new(STDOUT, progname: 'data:events:similar')
-    log.info "Same CWE events"
+    @log.info "Same CWE events"
     cwe_events()
-    log.info "Same directory events"
+    @log.info "Same directory events"
     similar_directory_events()
   end
 
@@ -85,16 +86,16 @@ def similar_directory_events()
     results = ActiveRecord::Base.connection.execute(query)
     results.each do |vuln|
       dir = vuln['fp'].split('/')[0...-1].join('/')
+      cve_link = "<a href=\"/cves/#{vuln['cve']}\"><i class=\"vhp-icon-vulnerability\"></i>#{vuln['cve']}</a>"
       e = Event.new(
         style: dir_style,
         event_type: 'same directory',
-        title: markdown("#{vuln['cve']} fixed in same directory #{dir}"),
+        title: "#{cve_link} fixed in same directory #{dir}",
         date:  vuln['announced'],
-        description: markdown(<<~EOSTR
-            A vulnerability, #{vuln['cve']} that was also fixed in this
-            vulnerability's directory (*#{dir}*) was announced.
+        description: <<~EOSTR
+            A vulnerability, #{cve_link} that was also fixed in this
+            vulnerability's directory (#{dir}) was announced.
           EOSTR
-        )
       )
       events << e
       vuln_events << VulnerabilityEvent.new(vulnerability_id: vuln['vuln1_id'], event: e)

lib/event_generators/weekly_report_events.rb

@@ -2,6 +2,7 @@
 require 'json'
 require 'date'
 require 'writing'
+require 'timing_logger'
 
 class WeeklyReportEvents
   include ApplicationHelper
@@ -19,7 +20,7 @@ def cve_from_filename(f)
   end
 
   def generate(repo_path)
-    logger = Logger.new(STDOUT, progname: 'data:events:weeklies')
+    logger = TimingLogger.new(STDOUT, 'data:events:weeklies')
     events = []
     tags =   []
     vuln_events = []

lib/loaders/article_loader.rb

@@ -1,11 +1,12 @@
 require_relative '../../app/helpers/application_helper'
+require 'timing_logger'
 
 class ArticleLoader
   include ApplicationHelper
 
   def load_data(repo_path)
     Dir["#{repo_path}/articles/*.md"].each do |file|
-      logger = Logger.new(STDOUT, progname: 'data:load:articles')
+      logger = TimingLogger.new(STDOUT, 'data:load:articles')
       content = File.read(file)
       md = YAML.load(content)
 

lib/loaders/git_loader.rb

@@ -1,13 +1,14 @@
 require 'oj'
 require_relative '../nicknames/namer'
 require_relative '../../app/helpers/application_helper'
+require 'timing_logger'
 
 class GitLoader
   include Nicknamer
   include ApplicationHelper
 
   def load_data(repo_path, project)
-    @log = Logger.new(STDOUT, progname: "data:#{project.subdomain}:gitloader")
+    @log = TimingLogger.new(STDOUT, "data:#{project.subdomain}:gitloader")
     @files = {} # maps filepath string to a Filepath model
     @devs  = {} # maps emails to Developer model
     @commits = [] # List of Commit objects with associated stuff

lib/loaders/vulnerability_loader.rb

@@ -1,7 +1,9 @@
+require 'timing_logger'
+
 class VulnerabilityLoader
 
   def initialize
-    @log = Logger.new(STDOUT, progname: 'data:load:vulnerabilities')
+    @log = TimingLogger.new(STDOUT, 'data:load:vulns')
   end
 
   def load_data(repo_path, project)

lib/taggers/lifetime_tagger.rb

@@ -1,4 +1,5 @@
 require_relative '../writing'
+require_relative '../timing_logger'
 
 class LifetimeTagger
 
@@ -39,7 +40,7 @@ def compute_importance(duration_s)
     Math.log(duration_s) / @@LIFETIME_SCALE
   end
 
-  def apply_tags(logger = Logger.new(STDOUT, progname: 'data:taggers:lifetime'))
+  def apply_tags(logger = TimingLogger.new(STDOUT, 'data:taggers:lifetime'))
     tags = []
     query = "SELECT  v.id, v.cve,
               MAX(fix_commit.date_created) fix_date,

lib/tasks/chromium.rake

@@ -3,11 +3,12 @@ require 'yaml'
 require 'fileutils'
 require 'find'
 require 'git'
+require 'timing_logger'
 require_all 'lib/event_generators/*.rb'
 require_all 'lib/loaders/*.rb'
 require_all 'lib/taggers/*.rb'
 
-logger = Logger.new(STDOUT, progname: 'data:chromium')
+logger = TimingLogger.new(STDOUT, 'data:chromium')
 
 desc 'Clean rebuild of Chromium data.'
 namespace :data do
@@ -102,6 +103,7 @@ namespace :data do
       end
       logger.info "Generating weekly report events and tags"
       WeeklyReportEvents.new.generate(repo_dir)
+
     end
 
     desc 'Generate and apply tags'

lib/tasks/clear.rake

@@ -1,4 +1,6 @@
-logger = Logger.new(STDOUT, progname: 'data')
+require 'timing_logger'
+
+logger = TimingLogger.new(STDOUT, 'data')
 
 desc 'Clear the database. Be CAREFUL!!'
 namespace 'data' do

lib/tasks/httpd.rake

@@ -2,11 +2,12 @@ require 'git'
 require 'yaml'
 require 'fileutils'
 require 'find'
+require 'timing_logger'
 require_all 'lib/event_generators/*.rb'
 require_all 'lib/loaders/*.rb'
 require_all 'lib/taggers/*.rb'
 
-logger = Logger.new(STDOUT, progname: 'data:httpd')
+logger = TimingLogger.new(STDOUT, 'data:httpd')
 
 desc 'Clean rebuild of HTTPD data.'
 namespace :data do

lib/tasks/optimize.rake

@@ -1,4 +1,6 @@
-logger = Logger.new(STDOUT, progname: 'data')
+require 'timing_logger'
+
+logger = TimingLogger.new(STDOUT, 'data')
 
 namespace 'data' do
   desc 'Optimize tables '

lib/tasks/struts.rake

@@ -2,11 +2,12 @@ require 'git'
 require 'yaml'
 require 'fileutils'
 require 'find'
+require 'timing_logger'
 require_all 'lib/event_generators/*.rb'
 require_all 'lib/loaders/*.rb'
 require_all 'lib/taggers/*.rb'
 
-logger = Logger.new(STDOUT, progname: 'data:struts')
+logger = TimingLogger.new(STDOUT, 'data:struts')
 
 desc 'Clean rebuild of HTTPD data.'
 namespace :data do

lib/tasks/tomcat.rake

@@ -2,11 +2,12 @@ require 'git'
 require 'yaml'
 require 'fileutils'
 require 'find'
+require 'timing_logger'
 require_all 'lib/event_generators/*.rb'
 require_all 'lib/loaders/*.rb'
 require_all 'lib/taggers/*.rb'
 
-logger = Logger.new(STDOUT, progname: 'data:tomcat')
+logger = TimingLogger.new(STDOUT, 'data:tomcat')
 
 desc 'Clean rebuild of HTTPD data.'
 namespace :data do

lib/tasks/writing.rake

@@ -1,8 +1,9 @@
 require 'git'
 require 'yaml'
 require 'fileutils'
+require 'timing_logger'
 
-logger = Logger.new(STDOUT, progname: 'data:writing')
+logger = TimingLogger.new(STDOUT, 'data:writing')
 
 namespace :data do
 

lib/timing_logger.rb

@@ -0,0 +1,36 @@
+require 'logger'
+require 'forwardable'
+
+# This is a wrapper around the regular Ruby logger
+# It allows us to keep track of how long a task took since its last invocation
+class TimingLogger
+  extend Forwardable
+
+  attr_accessor :logger
+
+  def_delegators :logger, # <-- inner object, v-- delegated methods --v
+   :<<, :add, :close, :datetime_format, :datetime_format=, :debug, :debug?,
+   :error, :error?, :fatal, :fatal?, :info?, :level=, :log, :reopen,
+   :sev_threshold=, :unknown, :warn, :warn?
+
+  def initialize(out = STDOUT, progname = '')
+    @logger = Logger.new(out, progname: progname)
+    @last_info = Time.current
+    @logger.formatter = proc do |severity, _datetime, progname, msg|
+      severity =  "\e[31mWARN\e[0m" if severity == 'WARN'
+      t = Time.current.strftime("%Y-%m-%d %T")
+      preamble = '%-50s' % "[#{severity} #{t} #{progname}]"
+      "#{preamble} #{msg}\n"
+    end
+
+  end
+
+  def info(msg = '')
+    now = Time.current
+    time_took = now - @last_info
+    time_took_str = "%2d" % time_took.seconds
+    @logger.info " #{time_took_str}s | #{msg}"
+    @last_info = now
+  end
+
+end

test/lib/event_generators/similar_events_test.rb

@@ -3,22 +3,25 @@
 require 'writing'
 
 class SimilarEventsTest < ActiveSupport::TestCase
-  test 'same directory generated properly' do
 
+  setup do
+    @silent_logger = TimingLogger.new(StringIO.new, '')
+  end
+
+  test 'same directory generated properly' do
     expected = [
-      "<p><a href=\"/cves/CVE-2011-3092\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory this/is/a/test</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3092\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory this/is/a/test</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3092\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory webkit/port</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3092\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3093\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory this/is/a/test</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3093\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory this/is/a/test</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3093\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory webkit/port</p>\n",
-      "<p><a href=\"/cves/CVE-2011-3093\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory</p>\n",
-      "<p><a href=\"/cves/CVE-2016-1676\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2016-1676</a> fixed in same directory this/is/a/test</p>\n",
-      "<p><a href=\"/cves/CVE-2016-1676\" rel=\"nofollow\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2016-1676</a> fixed in same directory this/is/a/test</p>\n"
+      "<a href=\"/cves/CVE-2011-3092\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory ",
+        "<a href=\"/cves/CVE-2011-3092\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory this/is/a/test",
+        "<a href=\"/cves/CVE-2011-3092\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory this/is/a/test",
+        "<a href=\"/cves/CVE-2011-3092\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3092</a> fixed in same directory webkit/port",
+        "<a href=\"/cves/CVE-2011-3093\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory ",
+        "<a href=\"/cves/CVE-2011-3093\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory this/is/a/test",
+        "<a href=\"/cves/CVE-2011-3093\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory this/is/a/test",
+        "<a href=\"/cves/CVE-2011-3093\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2011-3093</a> fixed in same directory webkit/port",
+        "<a href=\"/cves/CVE-2016-1676\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2016-1676</a> fixed in same directory this/is/a/test",
+        "<a href=\"/cves/CVE-2016-1676\"><i class=\"vhp-icon-vulnerability\"></i>CVE-2016-1676</a> fixed in same directory this/is/a/test"
     ]
-
-    SimilarEvents.new(projects(:one)).generate
+    SimilarEvents.new(projects(:one), @silent_logger).generate
     actual = Event.where("title LIKE '%fixed in same directory%'")
                   .pluck(:title).sort
     assert_equal expected, actual
@@ -29,7 +32,7 @@ class SimilarEventsTest < ActiveSupport::TestCase
       "<p>Another <em>Example</em> vulnerability announced</p>\n",
       "<p>Another <em>Example</em> vulnerability announced</p>\n"
     ]
-    SimilarEvents.new(projects(:one)).generate
+    SimilarEvents.new(projects(:one), @silent_logger).generate
     actual = Event.where("title LIKE '%Another % vulnerability announced%'")
                   .pluck(:title).sort
     assert_equal expected, actual

test/timing_logger_test.rb

@@ -0,0 +1,45 @@
+require 'test_helper'
+require 'timing_logger'
+
+class TimingLoggerTest < ActiveSupport::TestCase
+
+  test 'log once' do
+    out = StringIO.new
+    travel_to Time.zone.parse('1984-05-19 07:35:03')
+    log = TimingLogger.new(out, 'prog')
+    travel_to Time.zone.parse('1984-05-19 07:35:13') # 10s later
+    log.info "log once"
+
+    expected = <<~EOS
+[INFO 1984-05-19 07:35:13 prog]                     10s | log once
+    EOS
+
+    assert_equal expected, out.string
+  end
+
+  test 'log with warnings in between' do
+    out = StringIO.new
+
+    travel_to Time.zone.parse('1984-05-19 07:35:03')
+    log = TimingLogger.new(out, 'prog')
+
+    travel_to Time.zone.parse('1984-05-19 07:35:13') # 10s later
+    log.info "info first"
+
+    travel_to Time.zone.parse('1984-05-19 07:35:15') # 10s later
+    log.warn "WARNING"
+
+    travel_to Time.zone.parse('1984-05-19 07:37:13') # 120s since last info
+    log.info "info second blah blah"
+
+    expected = <<~EOS
+[INFO 1984-05-19 07:35:13 prog]                     10s | info first
+[\e[31mWARN\e[0m 1984-05-19 07:35:15 prog]           WARNING
+[INFO 1984-05-19 07:37:13 prog]                     120s | info second blah blah
+EOS
+
+
+    assert_equal expected, out.string
+  end
+
+end