Switch to structured logging

1 files changed, 104 insertions, 0 deletions

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