You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

216 lines
6.6 KiB

  1. # ADR 1: Logging
  2. ## Context
  3. Current logging system in Tendermint is very static and not flexible enough.
  4. Issues: [358](https://github.com/tendermint/tendermint/issues/358), [375](https://github.com/tendermint/tendermint/issues/375).
  5. What we want from the new system:
  6. - per package dynamic log levels
  7. - dynamic logger setting (logger tied to the processing struct)
  8. - conventions
  9. - be more visually appealing
  10. "dynamic" here means the ability to set smth in runtime.
  11. ## Decision
  12. ### 1) An interface
  13. First, we will need an interface for all of our libraries (`tmlibs`, Tendermint, etc.). My personal preference is go-kit `Logger` interface (see Appendix A.), but that is too much a bigger change. Plus we will still need levels.
  14. ```go
  15. # log.go
  16. type Logger interface {
  17. Debug(msg string, keyvals ...interface{}) error
  18. Info(msg string, keyvals ...interface{}) error
  19. Error(msg string, keyvals ...interface{}) error
  20. With(keyvals ...interface{}) Logger
  21. }
  22. ```
  23. On a side note: difference between `Info` and `Notice` is subtle. We probably
  24. could do without `Notice`. Don't think we need `Panic` or `Fatal` as a part of
  25. the interface. These funcs could be implemented as helpers. In fact, we already
  26. have some in `tmlibs/common`.
  27. - `Debug` - extended output for devs
  28. - `Info` - all that is useful for a user
  29. - `Error` - errors
  30. `Notice` should become `Info`, `Warn` either `Error` or `Debug` depending on the message, `Crit` -> `Error`.
  31. This interface should go into `tmlibs/log`. All libraries which are part of the core (tendermint/tendermint) should obey it.
  32. ### 2) Logger with our current formatting
  33. On top of this interface, we will need to implement a stdout logger, which will be used when Tendermint is configured to output logs to STDOUT.
  34. Many people say that they like the current output, so let's stick with it.
  35. ```
  36. NOTE[04-25|14:45:08] ABCI Replay Blocks module=consensus appHeight=0 storeHeight=0 stateHeight=0
  37. ```
  38. Couple of minor changes:
  39. ```
  40. I[04-25|14:45:08.322] ABCI Replay Blocks module=consensus appHeight=0 storeHeight=0 stateHeight=0
  41. ```
  42. Notice the level is encoded using only one char plus milliseconds.
  43. Note: there are many other formats out there like [logfmt](https://brandur.org/logfmt).
  44. This logger could be implemented using any logger - [logrus](https://github.com/sirupsen/logrus), [go-kit/log](https://github.com/go-kit/kit/tree/master/log), [zap](https://github.com/uber-go/zap), log15 so far as it
  45. a) supports coloring output<br>
  46. b) is moderately fast (buffering) <br>
  47. c) conforms to the new interface or adapter could be written for it <br>
  48. d) is somewhat configurable<br>
  49. go-kit is my favorite so far. Check out how easy it is to color errors in red https://github.com/go-kit/kit/blob/master/log/term/example_test.go#L12. Although, coloring could only be applied to the whole string :(
  50. ```
  51. go-kit +: flexible, modular
  52. go-kit “-”: logfmt format https://brandur.org/logfmt
  53. logrus +: popular, feature rich (hooks), API and output is more like what we want
  54. logrus -: not so flexible
  55. ```
  56. ```go
  57. # tm_logger.go
  58. // NewTmLogger returns a logger that encodes keyvals to the Writer in
  59. // tm format.
  60. func NewTmLogger(w io.Writer) Logger {
  61. return &tmLogger{kitlog.NewLogfmtLogger(w)}
  62. }
  63. func (l tmLogger) SetLevel(level string() {
  64. switch (level) {
  65. case "debug":
  66. l.sourceLogger = level.NewFilter(l.sourceLogger, level.AllowDebug())
  67. }
  68. }
  69. func (l tmLogger) Info(msg string, keyvals ...interface{}) error {
  70. l.sourceLogger.Log("msg", msg, keyvals...)
  71. }
  72. # log.go
  73. func With(logger Logger, keyvals ...interface{}) Logger {
  74. kitlog.With(logger.sourceLogger, keyvals...)
  75. }
  76. ```
  77. Usage:
  78. ```go
  79. logger := log.NewTmLogger(os.Stdout)
  80. logger.SetLevel(config.GetString("log_level"))
  81. node.SetLogger(log.With(logger, "node", Name))
  82. ```
  83. **Other log formatters**
  84. In the future, we may want other formatters like JSONFormatter.
  85. ```
  86. { "level": "notice", "time": "2017-04-25 14:45:08.562471297 -0400 EDT", "module": "consensus", "msg": "ABCI Replay Blocks", "appHeight": 0, "storeHeight": 0, "stateHeight": 0 }
  87. ```
  88. ### 3) Dynamic logger setting
  89. https://dave.cheney.net/2017/01/23/the-package-level-logger-anti-pattern
  90. This is the hardest part and where the most work will be done. logger should be tied to the processing struct, or the context if it adds some fields to the logger.
  91. ```go
  92. type BaseService struct {
  93. log log15.Logger
  94. name string
  95. started uint32 // atomic
  96. stopped uint32 // atomic
  97. ...
  98. }
  99. ```
  100. BaseService already contains `log` field, so most of the structs embedding it should be fine. We should rename it to `logger`.
  101. The only thing missing is the ability to set logger:
  102. ```
  103. func (bs *BaseService) SetLogger(l log.Logger) {
  104. bs.logger = l
  105. }
  106. ```
  107. ### 4) Conventions
  108. Important keyvals should go first. Example:
  109. ```
  110. correct
  111. I[04-25|14:45:08.322] ABCI Replay Blocks module=consensus instance=1 appHeight=0 storeHeight=0 stateHeight=0
  112. ```
  113. not
  114. ```
  115. wrong
  116. I[04-25|14:45:08.322] ABCI Replay Blocks module=consensus appHeight=0 storeHeight=0 stateHeight=0 instance=1
  117. ```
  118. for that in most cases you'll need to add `instance` field to a logger upon creating, not when u log a particular message:
  119. ```go
  120. colorFn := func(keyvals ...interface{}) term.FgBgColor {
  121. for i := 1; i < len(keyvals); i += 2 {
  122. if keyvals[i] == "instance" && keyvals[i+1] == "1" {
  123. return term.FgBgColor{Fg: term.Blue}
  124. } else if keyvals[i] == "instance" && keyvals[i+1] == "1" {
  125. return term.FgBgColor{Fg: term.Red}
  126. }
  127. }
  128. return term.FgBgColor{}
  129. }
  130. logger := term.NewLogger(os.Stdout, log.NewTmLogger, colorFn)
  131. c1 := NewConsensusReactor(...)
  132. c1.SetLogger(log.With(logger, "instance", 1))
  133. c2 := NewConsensusReactor(...)
  134. c2.SetLogger(log.With(logger, "instance", 2))
  135. ```
  136. ## Status
  137. proposed
  138. ## Consequences
  139. ### Positive
  140. Dynamic logger, which could be turned off for some modules at runtime. Public interface for other projects using Tendermint libraries.
  141. ### Negative
  142. We may loose the ability to color keys in keyvalue pairs. go-kit allow you to easily change foreground / background colors of the whole string, but not its parts.
  143. ### Neutral
  144. ## Appendix A.
  145. I really like a minimalistic approach go-kit took with his logger https://github.com/go-kit/kit/tree/master/log:
  146. ```
  147. type Logger interface {
  148. Log(keyvals ...interface{}) error
  149. }
  150. ```
  151. See [The Hunt for a Logger Interface](https://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide). The advantage is greater composability (check out how go-kit defines colored logging or log-leveled logging on top of this interface https://github.com/go-kit/kit/tree/master/log).