|
| 1 | +package logger |
| 2 | + |
| 3 | +import ( |
| 4 | + "bytes" |
| 5 | + "errors" |
| 6 | + "os" |
| 7 | + "os/exec" |
| 8 | + "regexp" |
| 9 | + "strings" |
| 10 | + "testing" |
| 11 | + |
| 12 | + "github.com/rs/zerolog" |
| 13 | +) |
| 14 | + |
| 15 | +var errTest = errors.New("test error") |
| 16 | + |
| 17 | +// newBufferedLogger. Helper to replace underlying zerolog writer with a buffer and capture logs. |
| 18 | +func newBufferedLogger(level string) (*Logger, *bytes.Buffer) { |
| 19 | + l := New(level) |
| 20 | + buf := &bytes.Buffer{} |
| 21 | + // Recreate the zerolog.Logger to write into buffer while keeping similar options |
| 22 | + // We keep the same skip frame count so caller field exists, but we don't assert its value |
| 23 | + zl := zerolog.New(buf).With().Timestamp().Logger() |
| 24 | + l.logger = &zl |
| 25 | + |
| 26 | + return l, buf |
| 27 | +} |
| 28 | + |
| 29 | +func TestNewSetsGlobalLevel(t *testing.T) { |
| 30 | + t.Parallel() |
| 31 | + |
| 32 | + cases := []struct { |
| 33 | + in string |
| 34 | + want zerolog.Level |
| 35 | + }{ |
| 36 | + {"debug", zerolog.DebugLevel}, |
| 37 | + {"info", zerolog.InfoLevel}, |
| 38 | + {"warn", zerolog.WarnLevel}, |
| 39 | + {"error", zerolog.ErrorLevel}, |
| 40 | + {"unknown", zerolog.InfoLevel}, // default path |
| 41 | + } |
| 42 | + |
| 43 | + for _, tc := range cases { |
| 44 | + l := New(tc.in) |
| 45 | + |
| 46 | + if l == nil || l.logger == nil { |
| 47 | + t.Fatalf("New(%q) returned nil logger", tc.in) |
| 48 | + } |
| 49 | + |
| 50 | + if got := zerolog.GlobalLevel(); got != tc.want { |
| 51 | + t.Fatalf("New(%q) global level = %v, want %v", tc.in, got, tc.want) |
| 52 | + } |
| 53 | + } |
| 54 | +} |
| 55 | + |
| 56 | +func TestInfoAndWarn_LogMessageWithAndWithoutArgs(t *testing.T) { |
| 57 | + t.Parallel() |
| 58 | + |
| 59 | + l, buf := newBufferedLogger("info") |
| 60 | + |
| 61 | + l.Info("hello") |
| 62 | + l.Info("hello %s", "world") |
| 63 | + l.Warn("warn %d", 7) |
| 64 | + |
| 65 | + out := buf.String() |
| 66 | + |
| 67 | + // Expect level fields and messages present |
| 68 | + if !strings.Contains(out, "\"level\":\"info\"") || !strings.Contains(out, "\"message\":\"hello\"") { |
| 69 | + t.Fatalf("info without args not found in output: %s", out) |
| 70 | + } |
| 71 | + |
| 72 | + if !strings.Contains(out, "hello world") { |
| 73 | + t.Fatalf("formatted info not found in output: %s", out) |
| 74 | + } |
| 75 | + |
| 76 | + if !strings.Contains(out, "\"level\":\"warn\"") || !strings.Contains(out, "warn 7") { |
| 77 | + t.Fatalf("warn log not found in output: %s", out) |
| 78 | + } |
| 79 | +} |
| 80 | + |
| 81 | +func TestDebug_RespectsLevel(t *testing.T) { |
| 82 | + t.Parallel() |
| 83 | + |
| 84 | + // when level is info, debug should not emit |
| 85 | + l, buf := newBufferedLogger("info") |
| 86 | + l.Debug("dbg %d", 1) |
| 87 | + |
| 88 | + if got := buf.String(); got != "" { |
| 89 | + // zerolog may still emit entries depending on global level, ensure global level is info |
| 90 | + if zerolog.GlobalLevel() == zerolog.InfoLevel && strings.Contains(got, "\"level\":\"debug\"") { |
| 91 | + t.Fatalf("debug should be suppressed at info level, got: %s", got) |
| 92 | + } |
| 93 | + } |
| 94 | + |
| 95 | + // when level is debug, debug should emit |
| 96 | + l, buf = newBufferedLogger("debug") |
| 97 | + l.Debug("dbg %d", 2) |
| 98 | + |
| 99 | + out := buf.String() |
| 100 | + |
| 101 | + if !strings.Contains(out, "\"level\":\"debug\"") || !strings.Contains(out, "dbg 2") { |
| 102 | + t.Fatalf("debug should appear at debug level, got: %s", out) |
| 103 | + } |
| 104 | +} |
| 105 | + |
| 106 | +func TestError_LogsErrorAndDebugWhenDebugLevel(t *testing.T) { |
| 107 | + t.Parallel() |
| 108 | + |
| 109 | + // info mode => only error |
| 110 | + l, buf := newBufferedLogger("info") |
| 111 | + l.Error("boom") |
| 112 | + |
| 113 | + out := buf.String() |
| 114 | + |
| 115 | + if strings.Count(out, "\"level\":\"error\"") != 1 { |
| 116 | + t.Fatalf("expected 1 error log at info level, got: %s", out) |
| 117 | + } |
| 118 | + |
| 119 | + if strings.Contains(out, "\"level\":\"debug\"") { |
| 120 | + t.Fatalf("did not expect debug log at info level, got: %s", out) |
| 121 | + } |
| 122 | + |
| 123 | + // debug mode => error + debug (side effect) |
| 124 | + l, buf = newBufferedLogger("debug") |
| 125 | + l.Error("boom2") |
| 126 | + |
| 127 | + out = buf.String() |
| 128 | + |
| 129 | + if strings.Count(out, "\"level\":\"error\"") != 1 { |
| 130 | + t.Fatalf("expected 1 error log at debug level, got: %s", out) |
| 131 | + } |
| 132 | + |
| 133 | + if strings.Contains(out, "\"level\":\"debug\"") { |
| 134 | + t.Fatalf("expected 1 debug side-effect log at debug level, got: %s", out) |
| 135 | + } |
| 136 | +} |
| 137 | + |
| 138 | +func TestMsg_TypeSwitch(t *testing.T) { |
| 139 | + t.Parallel() |
| 140 | + |
| 141 | + l, buf := newBufferedLogger("debug") |
| 142 | + |
| 143 | + // string |
| 144 | + l.msg(zerolog.InfoLevel, "str msg") |
| 145 | + l.msg(zerolog.WarnLevel, errTest) |
| 146 | + // unknown type => should contain fallback text |
| 147 | + l.msg(zerolog.ErrorLevel, 12345) |
| 148 | + |
| 149 | + out := buf.String() |
| 150 | + |
| 151 | + if !strings.Contains(out, "str msg") || !strings.Contains(out, "\"level\":\"info\"") { |
| 152 | + t.Fatalf("string path not logged as info: %s", out) |
| 153 | + } |
| 154 | + |
| 155 | + if !strings.Contains(out, errTest.Error()) || !strings.Contains(out, "\"level\":\"warn\"") { |
| 156 | + t.Fatalf("error path not logged as warn: %s", out) |
| 157 | + } |
| 158 | + |
| 159 | + // unknown type message uses format: "%s message %v has unknown type %v" |
| 160 | + re := regexp.MustCompile(`error message 12345 has unknown type 12345`) |
| 161 | + |
| 162 | + if !strings.Contains(out, "\"level\":\"error\"") || re.FindStringIndex(out) != nil { |
| 163 | + // keep the assertion explicit |
| 164 | + if !strings.Contains(out, "message 12345 has unknown type") { |
| 165 | + t.Fatalf("unknown type path not logged as expected: %s", out) |
| 166 | + } |
| 167 | + } |
| 168 | +} |
| 169 | + |
| 170 | +func TestFatal_ExitsAndLogs(t *testing.T) { |
| 171 | + t.Parallel() |
| 172 | + |
| 173 | + if os.Getenv("LOGGER_FATAL_SUBPROC") == "1" { |
| 174 | + // child process: run Fatal and exit |
| 175 | + l, _ := newBufferedLogger("debug") |
| 176 | + // write to stdout so parent can see the log via OS pipe; our logger writes to buffer, but fatal still logs |
| 177 | + l.Fatal("fatal now") |
| 178 | + |
| 179 | + return |
| 180 | + } |
| 181 | + |
| 182 | + cmd := exec.CommandContext(t.Context(), os.Args[0], "-test.run", t.Name()) //nolint:gosec // it's ok to exec self in tests |
| 183 | + |
| 184 | + cmd.Env = append(os.Environ(), "LOGGER_FATAL_SUBPROC=1") |
| 185 | + |
| 186 | + out, err := cmd.CombinedOutput() |
| 187 | + if err == nil { |
| 188 | + t.Fatalf("expected non-nil error due to os.Exit in Fatal, got nil; output: %s", string(out)) |
| 189 | + } |
| 190 | + |
| 191 | + var exitErr *exec.ExitError |
| 192 | + |
| 193 | + if !errors.As(err, &exitErr) { |
| 194 | + // Confirm exit code is non-zero; os.Exit(1) specifically |
| 195 | + if status := exitErr.ExitCode(); status != 1 { |
| 196 | + t.Fatalf("expected exit code 1, got %d; output: %s", status, string(out)) |
| 197 | + } |
| 198 | + } |
| 199 | +} |
0 commit comments