summaryrefslogtreecommitdiff
path: root/spec/gitlab_logger_spec.rb
blob: eec6648db8da6ad0bf3a7ce7028a2448bf46ad91 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
require_relative 'spec_helper'
require_relative '../lib/gitlab_logger'
require 'securerandom'

describe :convert_log_level do
  subject { convert_log_level :extreme }

  it "converts invalid log level to Logger::INFO" do
    $stderr.should_receive(:puts).at_least(:once)
    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

  describe 'log flushing' do
    it 'logs get written even when calling Kernel.exec' do
      msg = SecureRandom.hex(12)
      test_logger_status = system('bin/test-logger', msg)
      expect(test_logger_status).to eq(true)

      grep_status = system('grep', '-q', '-e', msg, GitlabConfig.new.log_file)
      expect(grep_status).to eq(true)
    end
  end
end