1package hclog 2 3import ( 4 "bytes" 5 "encoding/json" 6 "fmt" 7 "runtime" 8 "strings" 9 "testing" 10 11 "github.com/stretchr/testify/assert" 12 "github.com/stretchr/testify/require" 13) 14 15func TestInterceptLogger(t *testing.T) { 16 t.Run("sends output to registered sinks", func(t *testing.T) { 17 var buf bytes.Buffer 18 var sbuf bytes.Buffer 19 20 intercept := NewInterceptLogger(&LoggerOptions{ 21 Level: Info, 22 Output: &buf, 23 }) 24 25 sink := NewSinkAdapter(&LoggerOptions{ 26 Level: Debug, 27 Output: &sbuf, 28 }) 29 30 intercept.RegisterSink(sink) 31 defer intercept.DeregisterSink(sink) 32 33 intercept.Debug("test log", "who", "programmer") 34 35 str := sbuf.String() 36 dataIdx := strings.IndexByte(str, ' ') 37 rest := str[dataIdx+1:] 38 39 assert.Equal(t, "[DEBUG] test log: who=programmer\n", rest) 40 41 }) 42 43 t.Run("sink includes with arguments", func(t *testing.T) { 44 var buf bytes.Buffer 45 var sbuf bytes.Buffer 46 47 intercept := NewInterceptLogger(&LoggerOptions{ 48 Name: "with_test", 49 Level: Info, 50 Output: &buf, 51 }) 52 53 sink := NewSinkAdapter(&LoggerOptions{ 54 Level: Debug, 55 Output: &sbuf, 56 }) 57 intercept.RegisterSink(sink) 58 defer intercept.DeregisterSink(sink) 59 60 derived := intercept.With("a", 1, "b", 2) 61 derived = derived.With("c", 3) 62 63 derived.Info("test1") 64 output := buf.String() 65 dataIdx := strings.IndexByte(output, ' ') 66 rest := output[dataIdx+1:] 67 68 assert.Equal(t, "[INFO] with_test: test1: a=1 b=2 c=3\n", rest) 69 70 // Ensure intercept works 71 output = sbuf.String() 72 dataIdx = strings.IndexByte(output, ' ') 73 rest = output[dataIdx+1:] 74 75 assert.Equal(t, "[INFO] with_test: test1: a=1 b=2 c=3\n", rest) 76 }) 77 78 t.Run("sink includes name", func(t *testing.T) { 79 var buf bytes.Buffer 80 var sbuf bytes.Buffer 81 82 intercept := NewInterceptLogger(&LoggerOptions{ 83 Name: "with_test", 84 Level: Info, 85 Output: &buf, 86 }) 87 88 sink := NewSinkAdapter(&LoggerOptions{ 89 Level: Debug, 90 Output: &sbuf, 91 }) 92 intercept.RegisterSink(sink) 93 defer intercept.DeregisterSink(sink) 94 95 httpLogger := intercept.Named("http") 96 97 httpLogger.Info("test1") 98 output := buf.String() 99 dataIdx := strings.IndexByte(output, ' ') 100 rest := output[dataIdx+1:] 101 102 assert.Equal(t, "[INFO] with_test.http: test1\n", rest) 103 104 // Ensure intercept works 105 output = sbuf.String() 106 dataIdx = strings.IndexByte(output, ' ') 107 rest = output[dataIdx+1:] 108 109 assert.Equal(t, "[INFO] with_test.http: test1\n", rest) 110 }) 111 112 t.Run("intercepting logger can create logger with reset name", func(t *testing.T) { 113 var buf bytes.Buffer 114 var sbuf bytes.Buffer 115 116 intercept := NewInterceptLogger(&LoggerOptions{ 117 Name: "with_test", 118 Level: Info, 119 Output: &buf, 120 }) 121 122 sink := NewSinkAdapter(&LoggerOptions{ 123 Level: Debug, 124 Output: &sbuf, 125 }) 126 intercept.RegisterSink(sink) 127 defer intercept.DeregisterSink(sink) 128 129 httpLogger := intercept.ResetNamed("http") 130 131 httpLogger.Info("test1") 132 output := buf.String() 133 dataIdx := strings.IndexByte(output, ' ') 134 rest := output[dataIdx+1:] 135 136 assert.Equal(t, "[INFO] http: test1\n", rest) 137 138 // Ensure intercept works 139 output = sbuf.String() 140 dataIdx = strings.IndexByte(output, ' ') 141 rest = output[dataIdx+1:] 142 143 assert.Equal(t, "[INFO] http: test1\n", rest) 144 }) 145 146 t.Run("Intercepting logger sink can deregister itself", func(t *testing.T) { 147 var buf bytes.Buffer 148 var sbuf bytes.Buffer 149 150 intercept := NewInterceptLogger(&LoggerOptions{ 151 Name: "with_test", 152 Level: Info, 153 Output: &buf, 154 }) 155 156 sink := NewSinkAdapter(&LoggerOptions{ 157 Level: Debug, 158 Output: &sbuf, 159 }) 160 intercept.RegisterSink(sink) 161 intercept.DeregisterSink(sink) 162 163 intercept.Info("test1") 164 165 assert.Equal(t, "", sbuf.String()) 166 }) 167 168 t.Run("Sinks accept different log formats", func(t *testing.T) { 169 var buf bytes.Buffer 170 var sbuf bytes.Buffer 171 172 intercept := NewInterceptLogger(&LoggerOptions{ 173 Level: Info, 174 Output: &buf, 175 IncludeLocation: true, 176 }) 177 178 sink := NewSinkAdapter(&LoggerOptions{ 179 Level: Debug, 180 Output: &sbuf, 181 JSONFormat: true, 182 IncludeLocation: true, 183 }) 184 185 intercept.RegisterSink(sink) 186 defer intercept.DeregisterSink(sink) 187 188 intercept.Info("this is a test", "who", "caller") 189 _, file, line, ok := runtime.Caller(0) 190 require.True(t, ok) 191 192 output := buf.String() 193 dataIdx := strings.IndexByte(output, ' ') 194 rest := output[dataIdx+1:] 195 196 expected := fmt.Sprintf("[INFO] go-hclog/interceptlogger_test.go:%d: this is a test: who=caller\n", line-1) 197 assert.Equal(t, expected, rest) 198 199 b := sbuf.Bytes() 200 201 var raw map[string]interface{} 202 if err := json.Unmarshal(b, &raw); err != nil { 203 t.Fatal(err) 204 } 205 206 assert.Equal(t, "this is a test", raw["@message"]) 207 assert.Equal(t, "caller", raw["who"]) 208 assert.Equal(t, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"]) 209 }) 210 211 t.Run("handles parent with arguments and log level args", func(t *testing.T) { 212 var buf bytes.Buffer 213 var sbuf bytes.Buffer 214 215 intercept := NewInterceptLogger(&LoggerOptions{ 216 Name: "with_test", 217 Level: Debug, 218 Output: &buf, 219 }) 220 221 sink := NewSinkAdapter(&LoggerOptions{ 222 Level: Debug, 223 Output: &sbuf, 224 }) 225 intercept.RegisterSink(sink) 226 defer intercept.DeregisterSink(sink) 227 228 named := intercept.Named("sub_logger") 229 named = named.With("parent", "logger") 230 subNamed := named.Named("http") 231 232 subNamed.Debug("test1", "path", "/some/test/path", "args", []string{"test", "test"}) 233 234 output := buf.String() 235 dataIdx := strings.IndexByte(output, ' ') 236 rest := output[dataIdx+1:] 237 assert.Equal(t, "[DEBUG] with_test.sub_logger.http: test1: parent=logger path=/some/test/path args=[\"test\", \"test\"]\n", rest) 238 }) 239 240 t.Run("derived standard loggers send output to sinks", func(t *testing.T) { 241 var buf bytes.Buffer 242 var sbuf bytes.Buffer 243 244 intercept := NewInterceptLogger(&LoggerOptions{ 245 Name: "with_name", 246 Level: Debug, 247 Output: &buf, 248 }) 249 250 standard := intercept.StandardLogger(&StandardLoggerOptions{InferLevels: true}) 251 252 sink := NewSinkAdapter(&LoggerOptions{ 253 Level: Debug, 254 Output: &sbuf, 255 }) 256 intercept.RegisterSink(sink) 257 defer intercept.DeregisterSink(sink) 258 259 standard.Println("[DEBUG] test log") 260 261 output := buf.String() 262 dataIdx := strings.IndexByte(output, ' ') 263 rest := output[dataIdx+1:] 264 assert.Equal(t, "[DEBUG] with_name: test log\n", rest) 265 266 output = sbuf.String() 267 dataIdx = strings.IndexByte(output, ' ') 268 rest = output[dataIdx+1:] 269 assert.Equal(t, "[DEBUG] with_name: test log\n", rest) 270 }) 271 272 t.Run("includes the caller location", func(t *testing.T) { 273 var buf bytes.Buffer 274 var sbuf bytes.Buffer 275 276 logger := NewInterceptLogger(&LoggerOptions{ 277 Name: "test", 278 Output: &buf, 279 IncludeLocation: true, 280 }) 281 282 sink := NewSinkAdapter(&LoggerOptions{ 283 IncludeLocation: true, 284 Level: Debug, 285 Output: &sbuf, 286 }) 287 logger.RegisterSink(sink) 288 defer logger.DeregisterSink(sink) 289 290 logger.Info("this is test", "who", "programmer", "why", "testing is fun") 291 _, _, line, ok := runtime.Caller(0) 292 require.True(t, ok) 293 294 str := buf.String() 295 dataIdx := strings.IndexByte(str, ' ') 296 rest := str[dataIdx+1:] 297 298 expected := fmt.Sprintf("[INFO] go-hclog/interceptlogger_test.go:%d: test: this is test: who=programmer why=\"testing is fun\"\n", line-1) 299 assert.Equal(t, expected, rest) 300 301 str = sbuf.String() 302 dataIdx = strings.IndexByte(str, ' ') 303 rest = str[dataIdx+1:] 304 assert.Equal(t, expected, rest) 305 }) 306 307 t.Run("supports resetting the output", func(t *testing.T) { 308 var first, second bytes.Buffer 309 310 logger := NewInterceptLogger(&LoggerOptions{ 311 Output: &first, 312 }) 313 314 logger.Info("this is test", "production", Fmt("%d beans/day", 12)) 315 316 str := first.String() 317 dataIdx := strings.IndexByte(str, ' ') 318 rest := str[dataIdx+1:] 319 320 assert.Equal(t, "[INFO] this is test: production=\"12 beans/day\"\n", rest) 321 322 logger.(OutputResettable).ResetOutput(&LoggerOptions{ 323 Output: &second, 324 }) 325 326 logger.Info("this is another test", "production", Fmt("%d beans/day", 13)) 327 328 str = first.String() 329 dataIdx = strings.IndexByte(str, ' ') 330 rest = str[dataIdx+1:] 331 assert.Equal(t, "[INFO] this is test: production=\"12 beans/day\"\n", rest) 332 333 str = second.String() 334 dataIdx = strings.IndexByte(str, ' ') 335 rest = str[dataIdx+1:] 336 assert.Equal(t, "[INFO] this is another test: production=\"13 beans/day\"\n", rest) 337 }) 338 339 t.Run("supports resetting the output with flushing", func(t *testing.T) { 340 var first bufferingBuffer 341 var second bytes.Buffer 342 343 logger := NewInterceptLogger(&LoggerOptions{ 344 Output: &first, 345 }) 346 347 logger.Info("this is test", "production", Fmt("%d beans/day", 12)) 348 349 str := first.String() 350 assert.Empty(t, str) 351 352 logger.(OutputResettable).ResetOutputWithFlush(&LoggerOptions{ 353 Output: &second, 354 }, &first) 355 356 logger.Info("this is another test", "production", Fmt("%d beans/day", 13)) 357 358 str = first.String() 359 dataIdx := strings.IndexByte(str, ' ') 360 rest := str[dataIdx+1:] 361 assert.Equal(t, "[INFO] this is test: production=\"12 beans/day\"\n", rest) 362 363 str = second.String() 364 dataIdx = strings.IndexByte(str, ' ') 365 rest = str[dataIdx+1:] 366 assert.Equal(t, "[INFO] this is another test: production=\"13 beans/day\"\n", rest) 367 }) 368} 369