Merge pull request #473 from bkeepers/log-everything

Log all changes to ENV

lib/dotenv.rb

@@ -1,6 +1,7 @@
 require "dotenv/parser"
 require "dotenv/environment"
 require "dotenv/missing_keys"
+require "dotenv/diff"
 
 # The top level Dotenv module. The entrypoint for the application logic.
 module Dotenv
@@ -13,7 +14,12 @@ class << self
   # Loads environment variables from one or more `.env` files. See `#parse` for more details.
   def load(*filenames, **kwargs)
     parse(*filenames, **kwargs) do |env|
-      instrument("dotenv.load", env: env) { env.apply }
+      instrument(:load, env: env) do |payload|
+        env_before = ENV.to_h
+        env.apply
+        payload[:diff] = Dotenv::Diff.new(env_before, ENV.to_h)
+        env
+      end
     end
   end
 
@@ -61,9 +67,9 @@ def parse(*filenames, overwrite: false, ignore: true, &block)
 
   def instrument(name, payload = {}, &block)
     if instrumenter
-      instrumenter.instrument(name, payload, &block)
+      instrumenter.instrument("#{name}.dotenv", payload, &block)
     else
-      block&.call
+      block&.call payload
     end
   end
 
@@ -76,12 +82,12 @@ def require_keys(*keys)
   # Save a snapshot of the current `ENV` to be restored later
   def save
     @snapshot = ENV.to_h.freeze
-    instrument("dotenv.save", env: @snapshot)
+    instrument(:save, snapshot: @snapshot)
   end
 
   # Restore the previous snapshot of `ENV`
   def restore
-    instrument("dotenv.restore", env: @snapshot) { ENV.replace(@snapshot) }
+    instrument(:restore, diff: Dotenv::Diff.new(ENV.to_h, @snapshot)) { ENV.replace(@snapshot) }
   end
 end
 

lib/dotenv/diff.rb

@@ -0,0 +1,27 @@
+module Dotenv
+  # Compare two hashes and return the differences
+  class Diff
+    attr_reader :a, :b
+
+    def initialize(a, b)
+      @a, @b = a, b
+    end
+
+    # Return a Hash of keys added with their new values
+    def added
+      @added ||= b.slice(*(b.keys - a.keys))
+    end
+
+    # Returns a Hash of keys removed with their previous values
+    def removed
+      @removed ||= a.slice(*(a.keys - b.keys))
+    end
+
+    # Returns of Hash of keys changed with an array of their previous and new values
+    def changed
+      @changed ||= (b.slice(*a.keys).to_a - a.to_a).map do |(k, v)|
+        [k, [a[k], v]]
+      end.to_h
+    end
+  end
+end

lib/dotenv/log_subscriber.rb

@@ -0,0 +1,52 @@
+require "active_support/log_subscriber"
+
+module Dotenv
+  class LogSubscriber < ActiveSupport::LogSubscriber
+    attach_to :dotenv
+
+    def logger
+      Dotenv::Rails.logger
+    end
+
+    def load(event)
+      diff = event.payload[:diff]
+      env = event.payload[:env]
+
+      # Only show the keys that were added or changed
+      changed = env.slice(*(diff.added.keys + diff.changed.keys)).keys.map { |key| color_var(key) }
+
+      info "Set #{changed.to_sentence} from #{color_filename(env.filename)}" if changed.any?
+    end
+
+    def save(event)
+      info "Saved a snapshot of #{color_env_constant}"
+    end
+
+    def restore(event)
+      diff = event.payload[:diff]
+
+      removed = diff.removed.keys.map { |key| color(key, :RED) }
+      restored = (diff.changed.keys + diff.added.keys).map { |key| color_var(key) }
+
+      if removed.any? || restored.any?
+        info "Restored snapshot of #{color_env_constant}"
+        debug "Unset #{removed.to_sentence}" if removed.any?
+        debug "Restored #{restored.to_sentence}" if restored.any?
+      end
+    end
+
+    private
+
+    def color_filename(filename)
+      color(Pathname.new(filename).relative_path_from(Dotenv::Rails.root.to_s).to_s, :YELLOW)
+    end
+
+    def color_var(name)
+      color(name, :CYAN)
+    end
+
+    def color_env_constant
+      color("ENV", :GREEN)
+    end
+  end
+end

lib/dotenv/rails.rb

@@ -1,11 +1,13 @@
 require "dotenv"
+require "dotenv/replay_logger"
+require "dotenv/log_subscriber"
 
 Dotenv.instrumenter = ActiveSupport::Notifications
 
 # Watch all loaded env files with Spring
 begin
   require "spring/commands"
-  ActiveSupport::Notifications.subscribe("dotenv.load") do |*args|
+  ActiveSupport::Notifications.subscribe("load.dotenv") do |*args|
     event = ActiveSupport::Notifications::Event.new(*args)
     Spring.watch event.payload[:env].filename if Rails.application
   end
@@ -16,11 +18,13 @@
 module Dotenv
   # Rails integration for using Dotenv to load ENV variables from a file
   class Rails < ::Rails::Railtie
-    delegate :files, :files=, :overwrite, :overwrite=, :autorestore, :autorestore=, to: "config.dotenv"
+    delegate :files, :files=, :overwrite, :overwrite=, :autorestore, :autorestore=, :logger, :logger=, to: "config.dotenv"
 
     def initialize
       super()
       config.dotenv = ActiveSupport::OrderedOptions.new.update(
+        # Rails.logger is not available yet, so we'll save log messages and replay them when it is
+        logger: Dotenv::ReplayLogger.new,
         overwrite: false,
         files: [
           root.join(".env.#{env}.local"),
@@ -78,10 +82,11 @@ def self.load
       instance.load
     end
 
-    # Rails.logger was not intialized when dotenv loaded. Wait until it is and log what happened.
     initializer "dotenv", after: :initialize_logger do |app|
-      loaded_files = files.select(&:exist?).map { |p| p.relative_path_from(root).to_s }
-      ::Rails.logger.debug "dotenv loaded ENV from #{loaded_files.to_sentence}"
+      # Set up a new logger once Rails has initialized the logger and replay logs
+      new_logger = ActiveSupport::TaggedLogging.new(::Rails.logger).tagged("dotenv")
+      logger.replay new_logger if logger.respond_to?(:replay)
+      self.logger = new_logger
     end
 
     initializer "dotenv.deprecator" do |app|

lib/dotenv/replay_logger.rb

@@ -0,0 +1,20 @@
+module Dotenv
+  # A logger that can be used before the apps real logger is initialized.
+  class ReplayLogger
+    def initialize
+      @logs = []
+    end
+
+    def method_missing(name, *args, &block)
+      @logs.push([name, args, block])
+    end
+
+    def respond_to_missing?(name, include_private = false)
+      (include_private ? Logger.instance_methods : Logger.public_instance_methods).include?(name) || super
+    end
+
+    def replay(logger)
+      @logs.each { |name, args, block| logger.send(name, *args, &block) }
+    end
+  end
+end

spec/dotenv/diff_spec.rb

@@ -0,0 +1,41 @@
+require "spec_helper"
+
+describe Dotenv::Diff do
+  let(:before) { {} }
+  let(:after) { {} }
+  subject { Dotenv::Diff.new(before, after) }
+
+  context "no changes" do
+    let(:before) { {"A" => 1} }
+    let(:after) { {"A" => 1} }
+
+    it { expect(subject.added).to eq({}) }
+    it { expect(subject.removed).to eq({}) }
+    it { expect(subject.changed).to eq({}) }
+  end
+
+  context "key added" do
+    let(:after) { {"A" => 1} }
+
+    it { expect(subject.added).to eq("A" => 1) }
+    it { expect(subject.removed).to eq({}) }
+    it { expect(subject.changed).to eq({}) }
+  end
+
+  context "key removed" do
+    let(:before) { {"A" => 1} }
+
+    it { expect(subject.added).to eq({}) }
+    it { expect(subject.removed).to eq("A" => 1) }
+    it { expect(subject.changed).to eq({}) }
+  end
+
+  context "key changed" do
+    let(:before) { {"A" => 1} }
+    let(:after) { {"A" => 2} }
+
+    it { expect(subject.added).to eq({}) }
+    it { expect(subject.removed).to eq({}) }
+    it { expect(subject.changed).to eq("A" => [1, 2]) }
+  end
+end

spec/dotenv/log_subscriber_spec.rb

@@ -0,0 +1,73 @@
+require "spec_helper"
+require "active_support/all"
+require "rails"
+require "dotenv/rails"
+
+describe Dotenv::LogSubscriber do
+  let(:logs) { StringIO.new }
+
+  before do
+    Dotenv.instrumenter = ActiveSupport::Notifications
+    Dotenv::Rails.logger = Logger.new(logs)
+  end
+
+  context "set" do
+    it "logs when a new instance variable is set" do
+      Dotenv.load(fixture_path("plain.env"))
+      expect(logs.string).to match(/Set.*PLAIN.*from.*plain.env/)
+    end
+
+    it "logs when an instance variable is overwritten" do
+      ENV["PLAIN"] = "nope"
+      Dotenv.load(fixture_path("plain.env"), overwrite: true)
+      expect(logs.string).to match(/Set.*PLAIN.*from.*plain.env/)
+    end
+
+    it "does not log when an instance variable is not overwritten" do
+      # load everything once and clear the logs
+      Dotenv.load(fixture_path("plain.env"))
+      logs.truncate(0)
+
+      # load again
+      Dotenv.load(fixture_path("plain.env"))
+      expect(logs.string).not_to match(/Set.*plain.env/i)
+    end
+
+    it "does not log when an instance variable is unchanged" do
+      ENV["PLAIN"] = "true"
+      Dotenv.load(fixture_path("plain.env"), overwrite: true)
+      expect(logs.string).not_to match(/PLAIN/)
+    end
+  end
+
+  context "save" do
+    it "logs when a snapshot is saved" do
+      Dotenv.save
+      expect(logs.string).to match(/Saved/)
+    end
+  end
+
+  context "restore" do
+    it "logs restored keys" do
+      previous_value = ENV["PWD"]
+      ENV["PWD"] = "/tmp"
+      Dotenv.restore
+
+      expect(logs.string).to match(/Restored.*PWD/)
+
+      # Does not log value
+      expect(logs.string).not_to include(previous_value)
+    end
+
+    it "logs unset keys" do
+      ENV["DOTENV_TEST"] = "LogSubscriber"
+      Dotenv.restore
+      expect(logs.string).to match(/Unset.*DOTENV_TEST/)
+    end
+
+    it "does not log if no keys unset or restored" do
+      Dotenv.restore
+      expect(logs.string).not_to match(/Restored|Unset/)
+    end
+  end
+end

spec/dotenv/rails_spec.rb

@@ -32,11 +32,13 @@
     Rails.env = "test"
     Rails.application = nil
     Spring.watcher = Set.new # Responds to #add
-  end
 
-  after do
-    # Remove the singleton instance if it exists
-    Dotenv::Rails.remove_instance_variable(:@instance)
+    begin
+      # Remove the singleton instance if it exists
+      Dotenv::Rails.remove_instance_variable(:@instance)
+    rescue
+      nil
+    end
   end
 
   describe "files" do

spec/dotenv_spec.rb

@@ -199,7 +199,7 @@
     describe "load" do
       it "instruments if the file exists" do
         expect(instrumenter).to receive(:instrument) do |name, payload|
-          expect(name).to eq("dotenv.load")
+          expect(name).to eq("load.dotenv")
           expect(payload[:env]).to be_instance_of(Dotenv::Environment)
           {}
         end