vendor/github.com/hashicorp/go-hclog/logger_test.go

   1 package hclog
   2
   3 import (
   4         "bytes"
   5         "encoding/json"
   6         "errors"
   7         "fmt"
   8         "strconv"
   9         "strings"
  10         "testing"
  11         "time"
  12
  13         "github.com/stretchr/testify/assert"
  14         "github.com/stretchr/testify/require"
  15 )
  16
  17 func TestLogger(t *testing.T) {
  18         t.Run("formats log entries", func(t *testing.T) {
  19                 var buf bytes.Buffer
  20
  21                 logger := New(&LoggerOptions{
  22                         Name:   "test",
  23                         Output: &buf,
  24                 })
  25
  26                 logger.Info("this is test", "who", "programmer", "why", "testing")
  27
  28                 str := buf.String()
  29
  30                 dataIdx := strings.IndexByte(str, ' ')
  31
  32                 // ts := str[:dataIdx]
  33                 rest := str[dataIdx+1:]
  34
  35                 assert.Equal(t, "[INFO ] test: this is test: who=programmer why=testing\n", rest)
  36         })
  37
  38         t.Run("quotes values with spaces", func(t *testing.T) {
  39                 var buf bytes.Buffer
  40
  41                 logger := New(&LoggerOptions{
  42                         Name:   "test",
  43                         Output: &buf,
  44                 })
  45
  46                 logger.Info("this is test", "who", "programmer", "why", "testing is fun")
  47
  48                 str := buf.String()
  49
  50                 dataIdx := strings.IndexByte(str, ' ')
  51
  52                 // ts := str[:dataIdx]
  53                 rest := str[dataIdx+1:]
  54
  55                 assert.Equal(t, "[INFO ] test: this is test: who=programmer why=\"testing is fun\"\n", rest)
  56         })
  57
  58         t.Run("outputs stack traces", func(t *testing.T) {
  59                 var buf bytes.Buffer
  60
  61                 logger := New(&LoggerOptions{
  62                         Name:   "test",
  63                         Output: &buf,
  64                 })
  65
  66                 logger.Info("who", "programmer", "why", "testing", Stacktrace())
  67
  68                 lines := strings.Split(buf.String(), "\n")
  69
  70                 require.True(t, len(lines) > 1)
  71
  72                 assert.Equal(t, "github.com/hashicorp/go-hclog.Stacktrace", lines[1])
  73         })
  74
  75         t.Run("outputs stack traces with it's given a name", func(t *testing.T) {
  76                 var buf bytes.Buffer
  77
  78                 logger := New(&LoggerOptions{
  79                         Name:   "test",
  80                         Output: &buf,
  81                 })
  82
  83                 logger.Info("who", "programmer", "why", "testing", "foo", Stacktrace())
  84
  85                 lines := strings.Split(buf.String(), "\n")
  86
  87                 require.True(t, len(lines) > 1)
  88
  89                 assert.Equal(t, "github.com/hashicorp/go-hclog.Stacktrace", lines[1])
  90         })
  91
  92         t.Run("includes the caller location", func(t *testing.T) {
  93                 var buf bytes.Buffer
  94
  95                 logger := New(&LoggerOptions{
  96                         Name:            "test",
  97                         Output:          &buf,
  98                         IncludeLocation: true,
  99                 })
 100
 101                 logger.Info("this is test", "who", "programmer", "why", "testing is fun")
 102
 103                 str := buf.String()
 104
 105                 dataIdx := strings.IndexByte(str, ' ')
 106
 107                 // ts := str[:dataIdx]
 108                 rest := str[dataIdx+1:]
 109
 110                 // This test will break if you move this around, it's line dependent, just fyi
 111                 assert.Equal(t, "[INFO ] go-hclog/logger_test.go:101: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
 112         })
 113
 114         t.Run("prefixes the name", func(t *testing.T) {
 115                 var buf bytes.Buffer
 116
 117                 logger := New(&LoggerOptions{
 118                         // No name!
 119                         Output: &buf,
 120                 })
 121
 122                 logger.Info("this is test")
 123                 str := buf.String()
 124                 dataIdx := strings.IndexByte(str, ' ')
 125                 rest := str[dataIdx+1:]
 126                 assert.Equal(t, "[INFO ] this is test\n", rest)
 127
 128                 buf.Reset()
 129
 130                 another := logger.Named("sublogger")
 131                 another.Info("this is test")
 132                 str = buf.String()
 133                 dataIdx = strings.IndexByte(str, ' ')
 134                 rest = str[dataIdx+1:]
 135                 assert.Equal(t, "[INFO ] sublogger: this is test\n", rest)
 136         })
 137
 138         t.Run("use a different time format", func(t *testing.T) {
 139                 var buf bytes.Buffer
 140
 141                 logger := New(&LoggerOptions{
 142                         Name:       "test",
 143                         Output:     &buf,
 144                         TimeFormat: time.Kitchen,
 145                 })
 146
 147                 logger.Info("this is test", "who", "programmer", "why", "testing is fun")
 148
 149                 str := buf.String()
 150
 151                 dataIdx := strings.IndexByte(str, ' ')
 152
 153                 assert.Equal(t, str[:dataIdx], time.Now().Format(time.Kitchen))
 154         })
 155
 156         t.Run("use with", func(t *testing.T) {
 157                 var buf bytes.Buffer
 158
 159                 rootLogger := New(&LoggerOptions{
 160                         Name:   "with_test",
 161                         Output: &buf,
 162                 })
 163
 164                 // Build the root logger in two steps, which triggers a slice capacity increase
 165                 // and is part of the test for inadvertant slice aliasing.
 166                 rootLogger = rootLogger.With("a", 1, "b", 2)
 167                 rootLogger = rootLogger.With("c", 3)
 168
 169                 // Derive two new loggers which should be completely independent
 170                 derived1 := rootLogger.With("cat", 30)
 171                 derived2 := rootLogger.With("dog", 40)
 172
 173                 derived1.Info("test1")
 174                 output := buf.String()
 175                 dataIdx := strings.IndexByte(output, ' ')
 176                 assert.Equal(t, "[INFO ] with_test: test1: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
 177
 178                 buf.Reset()
 179
 180                 derived2.Info("test2")
 181                 output = buf.String()
 182                 dataIdx = strings.IndexByte(output, ' ')
 183                 assert.Equal(t, "[INFO ] with_test: test2: a=1 b=2 c=3 dog=40\n", output[dataIdx+1:])
 184         })
 185
 186         t.Run("unpaired with", func(t *testing.T) {
 187                 defer func() {
 188                         if r := recover(); r == nil {
 189                                 t.Fatal("expected panic")
 190                         }
 191                 }()
 192
 193                 var buf bytes.Buffer
 194
 195                 rootLogger := New(&LoggerOptions{
 196                         Name:   "with_test",
 197                         Output: &buf,
 198                 })
 199
 200                 rootLogger = rootLogger.With("a")
 201         })
 202
 203         t.Run("use with and log", func(t *testing.T) {
 204                 var buf bytes.Buffer
 205
 206                 rootLogger := New(&LoggerOptions{
 207                         Name:   "with_test",
 208                         Output: &buf,
 209                 })
 210
 211                 // Build the root logger in two steps, which triggers a slice capacity increase
 212                 // and is part of the test for inadvertant slice aliasing.
 213                 rootLogger = rootLogger.With("a", 1, "b", 2)
 214                 // This line is here to test that when calling With with the same key,
 215                 // only the last value remains (see issue #21)
 216                 rootLogger = rootLogger.With("c", 4)
 217                 rootLogger = rootLogger.With("c", 3)
 218
 219                 // Derive another logger which should be completely independent of rootLogger
 220                 derived := rootLogger.With("cat", 30)
 221
 222                 rootLogger.Info("root_test", "bird", 10)
 223                 output := buf.String()
 224                 dataIdx := strings.IndexByte(output, ' ')
 225                 assert.Equal(t, "[INFO ] with_test: root_test: a=1 b=2 c=3 bird=10\n", output[dataIdx+1:])
 226
 227                 buf.Reset()
 228
 229                 derived.Info("derived_test")
 230                 output = buf.String()
 231                 dataIdx = strings.IndexByte(output, ' ')
 232                 assert.Equal(t, "[INFO ] with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
 233         })
 234
 235         t.Run("use with and log and change levels", func(t *testing.T) {
 236                 var buf bytes.Buffer
 237
 238                 rootLogger := New(&LoggerOptions{
 239                         Name:   "with_test",
 240                         Output: &buf,
 241                         Level:  Warn,
 242                 })
 243
 244                 // Build the root logger in two steps, which triggers a slice capacity increase
 245                 // and is part of the test for inadvertant slice aliasing.
 246                 rootLogger = rootLogger.With("a", 1, "b", 2)
 247                 rootLogger = rootLogger.With("c", 3)
 248
 249                 // Derive another logger which should be completely independent of rootLogger
 250                 derived := rootLogger.With("cat", 30)
 251
 252                 rootLogger.Info("root_test", "bird", 10)
 253                 output := buf.String()
 254                 if output != "" {
 255                         t.Fatalf("unexpected output: %s", output)
 256                 }
 257
 258                 buf.Reset()
 259
 260                 derived.Info("derived_test")
 261                 output = buf.String()
 262                 if output != "" {
 263                         t.Fatalf("unexpected output: %s", output)
 264                 }
 265
 266                 derived.SetLevel(Info)
 267
 268                 rootLogger.Info("root_test", "bird", 10)
 269                 output = buf.String()
 270                 dataIdx := strings.IndexByte(output, ' ')
 271                 assert.Equal(t, "[INFO ] with_test: root_test: a=1 b=2 c=3 bird=10\n", output[dataIdx+1:])
 272
 273                 buf.Reset()
 274
 275                 derived.Info("derived_test")
 276                 output = buf.String()
 277                 dataIdx = strings.IndexByte(output, ' ')
 278                 assert.Equal(t, "[INFO ] with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
 279         })
 280
 281         t.Run("supports Printf style expansions when requested", func(t *testing.T) {
 282                 var buf bytes.Buffer
 283
 284                 logger := New(&LoggerOptions{
 285                         Name:   "test",
 286                         Output: &buf,
 287                 })
 288
 289                 logger.Info("this is test", "production", Fmt("%d beans/day", 12))
 290
 291                 str := buf.String()
 292
 293                 dataIdx := strings.IndexByte(str, ' ')
 294
 295                 // ts := str[:dataIdx]
 296                 rest := str[dataIdx+1:]
 297
 298                 assert.Equal(t, "[INFO ] test: this is test: production=\"12 beans/day\"\n", rest)
 299         })
 300 }
 301
 302 func TestLogger_JSON(t *testing.T) {
 303         t.Run("json formatting", func(t *testing.T) {
 304                 var buf bytes.Buffer
 305                 logger := New(&LoggerOptions{
 306                         Name:       "test",
 307                         Output:     &buf,
 308                         JSONFormat: true,
 309                 })
 310
 311                 logger.Info("this is test", "who", "programmer", "why", "testing is fun")
 312
 313                 b := buf.Bytes()
 314
 315                 var raw map[string]interface{}
 316                 if err := json.Unmarshal(b, &raw); err != nil {
 317                         t.Fatal(err)
 318                 }
 319
 320                 assert.Equal(t, "this is test", raw["@message"])
 321                 assert.Equal(t, "programmer", raw["who"])
 322                 assert.Equal(t, "testing is fun", raw["why"])
 323         })
 324
 325         t.Run("json formatting with", func(t *testing.T) {
 326                 var buf bytes.Buffer
 327                 logger := New(&LoggerOptions{
 328                         Name:       "test",
 329                         Output:     &buf,
 330                         JSONFormat: true,
 331                 })
 332                 logger = logger.With("cat", "in the hat", "dog", 42)
 333
 334                 logger.Info("this is test", "who", "programmer", "why", "testing is fun")
 335
 336                 b := buf.Bytes()
 337
 338                 var raw map[string]interface{}
 339                 if err := json.Unmarshal(b, &raw); err != nil {
 340                         t.Fatal(err)
 341                 }
 342
 343                 assert.Equal(t, "this is test", raw["@message"])
 344                 assert.Equal(t, "programmer", raw["who"])
 345                 assert.Equal(t, "testing is fun", raw["why"])
 346                 assert.Equal(t, "in the hat", raw["cat"])
 347                 assert.Equal(t, float64(42), raw["dog"])
 348         })
 349
 350         t.Run("json formatting error type", func(t *testing.T) {
 351                 var buf bytes.Buffer
 352
 353                 logger := New(&LoggerOptions{
 354                         Name:       "test",
 355                         Output:     &buf,
 356                         JSONFormat: true,
 357                 })
 358
 359                 errMsg := errors.New("this is an error")
 360                 logger.Info("this is test", "who", "programmer", "err", errMsg)
 361
 362                 b := buf.Bytes()
 363
 364                 var raw map[string]interface{}
 365                 if err := json.Unmarshal(b, &raw); err != nil {
 366                         t.Fatal(err)
 367                 }
 368
 369                 assert.Equal(t, "this is test", raw["@message"])
 370                 assert.Equal(t, "programmer", raw["who"])
 371                 assert.Equal(t, errMsg.Error(), raw["err"])
 372         })
 373
 374         t.Run("json formatting custom error type json marshaler", func(t *testing.T) {
 375                 var buf bytes.Buffer
 376
 377                 logger := New(&LoggerOptions{
 378                         Name:       "test",
 379                         Output:     &buf,
 380                         JSONFormat: true,
 381                 })
 382
 383                 errMsg := &customErrJSON{"this is an error"}
 384                 rawMsg, err := errMsg.MarshalJSON()
 385                 if err != nil {
 386                         t.Fatal(err)
 387                 }
 388                 expectedMsg, err := strconv.Unquote(string(rawMsg))
 389                 if err != nil {
 390                         t.Fatal(err)
 391                 }
 392
 393                 logger.Info("this is test", "who", "programmer", "err", errMsg)
 394
 395                 b := buf.Bytes()
 396
 397                 var raw map[string]interface{}
 398                 if err := json.Unmarshal(b, &raw); err != nil {
 399                         t.Fatal(err)
 400                 }
 401
 402                 assert.Equal(t, "this is test", raw["@message"])
 403                 assert.Equal(t, "programmer", raw["who"])
 404                 assert.Equal(t, expectedMsg, raw["err"])
 405         })
 406
 407         t.Run("json formatting custom error type text marshaler", func(t *testing.T) {
 408                 var buf bytes.Buffer
 409
 410                 logger := New(&LoggerOptions{
 411                         Name:       "test",
 412                         Output:     &buf,
 413                         JSONFormat: true,
 414                 })
 415
 416                 errMsg := &customErrText{"this is an error"}
 417                 rawMsg, err := errMsg.MarshalText()
 418                 if err != nil {
 419                         t.Fatal(err)
 420                 }
 421                 expectedMsg := string(rawMsg)
 422
 423                 logger.Info("this is test", "who", "programmer", "err", errMsg)
 424
 425                 b := buf.Bytes()
 426
 427                 var raw map[string]interface{}
 428                 if err := json.Unmarshal(b, &raw); err != nil {
 429                         t.Fatal(err)
 430                 }
 431
 432                 assert.Equal(t, "this is test", raw["@message"])
 433                 assert.Equal(t, "programmer", raw["who"])
 434                 assert.Equal(t, expectedMsg, raw["err"])
 435         })
 436
 437         t.Run("supports Printf style expansions when requested", func(t *testing.T) {
 438                 var buf bytes.Buffer
 439
 440                 logger := New(&LoggerOptions{
 441                         Name:       "test",
 442                         Output:     &buf,
 443                         JSONFormat: true,
 444                 })
 445
 446                 logger.Info("this is test", "production", Fmt("%d beans/day", 12))
 447
 448                 b := buf.Bytes()
 449
 450                 var raw map[string]interface{}
 451                 if err := json.Unmarshal(b, &raw); err != nil {
 452                         t.Fatal(err)
 453                 }
 454
 455                 assert.Equal(t, "this is test", raw["@message"])
 456                 assert.Equal(t, "12 beans/day", raw["production"])
 457         })
 458 }
 459
 460 type customErrJSON struct {
 461         Message string
 462 }
 463
 464 // error impl.
 465 func (c *customErrJSON) Error() string {
 466         return c.Message
 467 }
 468
 469 // json.Marshaler impl.
 470 func (c customErrJSON) MarshalJSON() ([]byte, error) {
 471         return []byte(strconv.Quote(fmt.Sprintf("json-marshaler: %s", c.Message))), nil
 472 }
 473
 474 type customErrText struct {
 475         Message string
 476 }
 477
 478 // error impl.
 479 func (c *customErrText) Error() string {
 480         return c.Message
 481 }
 482
 483 // text.Marshaler impl.
 484 func (c customErrText) MarshalText() ([]byte, error) {
 485         return []byte(fmt.Sprintf("text-marshaler: %s", c.Message)), nil
 486 }
 487
 488 func BenchmarkLogger(b *testing.B) {
 489         b.Run("info with 10 pairs", func(b *testing.B) {
 490                 var buf bytes.Buffer
 491
 492                 logger := New(&LoggerOptions{
 493                         Name:            "test",
 494                         Output:          &buf,
 495                         IncludeLocation: true,
 496                 })
 497
 498                 for i := 0; i < b.N; i++ {
 499                         logger.Info("this is some message",
 500                                 "name", "foo",
 501                                 "what", "benchmarking yourself",
 502                                 "why", "to see what's slow",
 503                                 "k4", "value",
 504                                 "k5", "value",
 505                                 "k6", "value",
 506                                 "k7", "value",
 507                                 "k8", "value",
 508                                 "k9", "value",
 509                                 "k10", "value",
 510                         )
 511                 }
 512         })
 513 }