Switch to structured logging

5 files changed, 156 insertions, 32 deletions

diff --git a/spec/gitlab_config_spec.rb b/spec/gitlab_config_spec.rb
index 63cb2b3..a1c52a0 100644
--- a/spec/gitlab_config_spec.rb
+++ b/spec/gitlab_config_spec.rb
@@ -24,4 +24,12 @@ describe GitlabConfig do
 
     it("returns false by default") { should eq(false) }
   end
+
+  describe :log_format do
+    subject { config.log_format }
+
+    it 'returns "text" by default' do
+      should eq('text')
+    end
+  end
 end
diff --git a/spec/gitlab_keys_spec.rb b/spec/gitlab_keys_spec.rb
index b9f2f87..c4e617c 100644
--- a/spec/gitlab_keys_spec.rb
+++ b/spec/gitlab_keys_spec.rb
@@ -57,7 +57,7 @@ describe GitlabKeys do
       before { create_authorized_keys_fixture }
 
       it "should log an add-key event" do
-        $logger.should_receive(:info).with('Adding key key-741 => "ssh-rsa AAAAB3NzaDAxx2E"')
+        $logger.should_receive(:info).with("Adding key", {:key_id=>"key-741", :public_key=>"ssh-rsa AAAAB3NzaDAxx2E"})
         gitlab_keys.send :add_key
       end
 
@@ -127,8 +127,8 @@ describe GitlabKeys do
       end
 
       it "should log an add-key event" do
-        $logger.should_receive(:info).with('Adding key key-12 => "ssh-dsa ASDFASGADG"')
-        $logger.should_receive(:info).with('Adding key key-123 => "ssh-rsa GFDGDFSGSDFG"')
+        $logger.should_receive(:info).with("Adding key", key_id: 'key-12', public_key: "ssh-dsa ASDFASGADG")
+        $logger.should_receive(:info).with("Adding key", key_id: 'key-123', public_key: "ssh-rsa GFDGDFSGSDFG")
         gitlab_keys.send :batch_add_keys
       end
 
@@ -169,7 +169,7 @@ describe GitlabKeys do
       end
 
       it "should log an rm-key event" do
-        $logger.should_receive(:info).with('Removing key key-741')
+        $logger.should_receive(:info).with("Removing key", key_id: "key-741")
         gitlab_keys.send :rm_key
       end
 
@@ -266,7 +266,7 @@ describe GitlabKeys do
     it 'should log a warning on unknown commands' do
       gitlab_keys = build_gitlab_keys('nooope')
       gitlab_keys.stub(puts: nil)
-      $logger.should_receive(:warn).with('Attempt to execute invalid gitlab-keys command "nooope".')
+      $logger.should_receive(:warn).with("Attempt to execute invalid gitlab-keys command", command: '"nooope"')
       gitlab_keys.exec
     end
   end
diff --git a/spec/gitlab_logger_spec.rb b/spec/gitlab_logger_spec.rb
index 7d8df76..741ee13 100644
--- a/spec/gitlab_logger_spec.rb
+++ b/spec/gitlab_logger_spec.rb
@@ -9,3 +9,107 @@ describe :convert_log_level do
     should eq(Logger::INFO)
   end
 end
+
+describe GitlabLogger do
+  subject { described_class.new(level, '/dev/null', format) }
+  let(:format) { 'text' }
+  let(:output) { StringIO.new }
+  let(:level) { Logger::INFO }
+  let(:time) { Time.at(123_456_789).utc } # '1973-11-29T21:33:09+00:00'
+  let(:pid) { 1234 }
+
+  before do
+    allow(subject).to receive(:log_file).and_return(output)
+    allow(subject).to receive(:time_now).and_return(time)
+    allow(subject).to receive(:pid).and_return(pid)
+  end
+
+  def first_line
+    output.string.lines.first.chomp
+  end
+
+  describe 'field sorting' do
+    it 'sorts fields, except time, level, msg' do
+      # Intentionally put 'foo' before 'baz' to see the effect of sorting
+      subject.info('hello world', foo: 'bar', baz: 'qux')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=info msg="hello world" baz=qux foo=bar pid=1234')
+    end
+  end
+
+  describe '#info' do
+    context 'when the log level is too high' do
+      let(:level) { Logger::ERROR }
+
+      it 'does nothing' do
+        subject.info('hello world')
+
+        expect(output.string).to eq('')
+      end
+    end
+
+    it 'logs data' do
+      subject.info('hello world', foo: 'bar')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=info msg="hello world" foo=bar pid=1234')
+    end
+  end
+
+  describe '#warn' do
+    context 'when the log level is too high' do
+      let(:level) { Logger::ERROR }
+
+      it 'does nothing' do
+        subject.warn('hello world')
+
+        expect(output.string).to eq('')
+      end
+    end
+
+    it 'logs data' do
+      subject.warn('hello world', foo: 'bar')
+
+      expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=warn msg="hello world" foo=bar pid=1234')
+    end
+  end
+
+  describe '#debug' do
+    it 'does nothing' do
+      subject.debug('hello world')
+
+      expect(output.string).to eq('')
+    end
+
+    context 'when the log level is low enough' do
+      let(:level) { Logger::DEBUG }
+
+      it 'logs data' do
+        subject.debug('hello world', foo: 'bar')
+
+        expect(first_line).to eq('time="1973-11-29T21:33:09+00:00" level=debug msg="hello world" foo=bar pid=1234')
+      end
+    end
+  end
+
+  describe 'json logging' do
+    let(:format) { 'json' }
+
+    it 'writes valid JSON data' do
+      subject.info('hello world', foo: 'bar')
+
+      expect(JSON.parse(first_line)).to eq(
+        'foo' => 'bar',
+        'level' => 'info',
+        'msg' => 'hello world',
+        'pid' => 1234,
+        'time' => '1973-11-29T21:33:09+00:00'
+      )
+    end
+
+    it 'handles non-UTF8 string values' do
+      subject.info("hello\x80world")
+
+      expect(JSON.parse(first_line)).to include('msg' => '"hello\x80world"')
+    end
+  end
+end
diff --git a/spec/gitlab_metrics_spec.rb b/spec/gitlab_metrics_spec.rb
index 07be670..024a85a 100644
--- a/spec/gitlab_metrics_spec.rb
+++ b/spec/gitlab_metrics_spec.rb
@@ -11,7 +11,7 @@ describe GitlabMetrics do
 
     it 'writes the metrics data to a log file' do
       expect(described_class.logger).to receive(:debug).
-        with(/metrics: name=\"foo\" wall_time=\d+ cpu_time=\d+/)
+        with('metrics', a_metrics_log_message('foo'))
 
       described_class.measure('foo') { 10 }
     end
@@ -24,3 +24,13 @@ describe GitlabMetrics do
     end
   end
 end
+
+RSpec::Matchers.define :a_metrics_log_message do |x|
+  match do |actual|
+    [
+      actual.fetch(:name) == x,
+      actual.fetch(:wall_time).is_a?(Numeric),
+      actual.fetch(:cpu_time).is_a?(Numeric),
+    ].all?
+  end
+end
diff --git a/spec/gitlab_shell_spec.rb b/spec/gitlab_shell_spec.rb
index a71e2d0..82db0cf 100644
--- a/spec/gitlab_shell_spec.rb
+++ b/spec/gitlab_shell_spec.rb
@@ -160,15 +160,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<git-upload-pack #{repo_path}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "git-upload-pack #{repo_path}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info).with(/for John Doe/)
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -196,15 +195,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<gitaly-upload-pack unix:gitaly.socket #{gitaly_message}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "gitaly-upload-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info) { |msg| msg.should =~ /for John Doe/ }
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -221,10 +219,9 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<git-receive-pack #{repo_path}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "git-receive-pack #{repo_path}", user: user_string)
       end
     end
 
@@ -244,15 +241,14 @@ describe GitlabShell do
       end
 
       it "should log the command execution" do
-        message = "gitlab-shell: executing git command "
-        message << "<gitaly-receive-pack unix:gitaly.socket #{gitaly_message}> "
-        message << "for user with key #{key_id}."
-        $logger.should_receive(:info).with(message)
+        message = "executing git command"
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:info).with(message, command: "gitaly-receive-pack unix:gitaly.socket #{gitaly_message}", user: user_string)
       end
 
       it "should use usernames if configured to do so" do
         GitlabConfig.any_instance.stub(audit_usernames: true)
-        $logger.should_receive(:info).with(/for John Doe/)
+        $logger.should_receive(:info).with("executing git command", hash_including(user: 'John Doe'))
       end
     end
 
@@ -269,8 +265,9 @@ describe GitlabShell do
       end
 
       it "should log the attempt" do
-        message = "gitlab-shell: Attempt to execute disallowed command <arbitrary command> by user with key #{key_id}."
-        $logger.should_receive(:warn).with(message)
+        message = 'Denied disallowed command'
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:warn).with(message, command: 'arbitrary command', user: user_string)
       end
     end
 
@@ -356,9 +353,9 @@ describe GitlabShell do
                   gl_username: nil,
                   repository_path: nil,
                   gitaly: nil))
-        message = "gitlab-shell: Access denied for git command <git-upload-pack gitlab-ci.git> "
-        message << "by user with key #{key_id}."
-        $logger.should_receive(:warn).with(message)
+        message = 'Access denied'
+        user_string = "user with key #{key_id}"
+        $logger.should_receive(:warn).with(message, command: 'git-upload-pack gitlab-ci.git', user: user_string)
       end
     end
 
@@ -450,8 +447,10 @@ describe GitlabShell do
         end
 
         it "writes an entry on the log" do
+          message = 'git trace log path must be absolute, ignoring'
+
           expect($logger).to receive(:warn).
-            with("gitlab-shell: is configured to trace git commands with #{git_trace_log_file.inspect} but an absolute path needs to be provided")
+            with(message, git_trace_log_file: git_trace_log_file)
 
           Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
           shell.send :exec_cmd, [1, 2]
@@ -474,8 +473,11 @@ describe GitlabShell do
         end
 
         it "writes an entry on the log" do
+          message = 'Failed to open git trace log file'
+          error = 'Permission denied'
+
           expect($logger).to receive(:warn).
-            with("gitlab-shell: is configured to trace git commands with #{git_trace_log_file.inspect} but it's not possible to write in that path Permission denied")
+            with(message, git_trace_log_file: git_trace_log_file, error: error)
 
           Kernel.should_receive(:exec).with(env, [1, 2], exec_options).once
           shell.send :exec_cmd, [1, 2]