tlogger.go 6.1 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263
  1. /*
  2. *
  3. * Copyright 2020 gRPC authors.
  4. *
  5. * Licensed under the Apache License, Version 2.0 (the "License");
  6. * you may not use this file except in compliance with the License.
  7. * You may obtain a copy of the License at
  8. *
  9. * http://www.apache.org/licenses/LICENSE-2.0
  10. *
  11. * Unless required by applicable law or agreed to in writing, software
  12. * distributed under the License is distributed on an "AS IS" BASIS,
  13. * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  14. * See the License for the specific language governing permissions and
  15. * limitations under the License.
  16. *
  17. */
  18. package grpctest
  19. import (
  20. "errors"
  21. "fmt"
  22. "os"
  23. "path"
  24. "regexp"
  25. "runtime"
  26. "strconv"
  27. "sync"
  28. "testing"
  29. "time"
  30. "google.golang.org/grpc/grpclog"
  31. )
  32. // TLogger serves as the grpclog logger and is the interface through which
  33. // expected errors are declared in tests.
  34. var TLogger *tLogger
  35. const callingFrame = 4
  36. type logType int
  37. func (l logType) String() string {
  38. switch l {
  39. case infoLog:
  40. return "INFO"
  41. case warningLog:
  42. return "WARNING"
  43. case errorLog:
  44. return "ERROR"
  45. case fatalLog:
  46. return "FATAL"
  47. }
  48. return "UNKNOWN"
  49. }
  50. const (
  51. infoLog logType = iota
  52. warningLog
  53. errorLog
  54. fatalLog
  55. )
  56. type tLogger struct {
  57. v int
  58. initialized bool
  59. mu sync.Mutex // guards t, start, and errors
  60. t *testing.T
  61. start time.Time
  62. errors map[*regexp.Regexp]int
  63. }
  64. func init() {
  65. TLogger = &tLogger{errors: map[*regexp.Regexp]int{}}
  66. vLevel := os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL")
  67. if vl, err := strconv.Atoi(vLevel); err == nil {
  68. TLogger.v = vl
  69. }
  70. }
  71. // getCallingPrefix returns the <file:line> at the given depth from the stack.
  72. func getCallingPrefix(depth int) (string, error) {
  73. _, file, line, ok := runtime.Caller(depth)
  74. if !ok {
  75. return "", errors.New("frame request out-of-bounds")
  76. }
  77. return fmt.Sprintf("%s:%d", path.Base(file), line), nil
  78. }
  79. // log logs the message with the specified parameters to the tLogger.
  80. func (g *tLogger) log(ltype logType, depth int, format string, args ...interface{}) {
  81. g.mu.Lock()
  82. defer g.mu.Unlock()
  83. prefix, err := getCallingPrefix(callingFrame + depth)
  84. if err != nil {
  85. g.t.Error(err)
  86. return
  87. }
  88. args = append([]interface{}{ltype.String() + " " + prefix}, args...)
  89. args = append(args, fmt.Sprintf(" (t=+%s)", time.Since(g.start)))
  90. if format == "" {
  91. switch ltype {
  92. case errorLog:
  93. // fmt.Sprintln is used rather than fmt.Sprint because t.Log uses fmt.Sprintln behavior.
  94. if g.expected(fmt.Sprintln(args...)) {
  95. g.t.Log(args...)
  96. } else {
  97. g.t.Error(args...)
  98. }
  99. case fatalLog:
  100. panic(fmt.Sprint(args...))
  101. default:
  102. g.t.Log(args...)
  103. }
  104. } else {
  105. // Add formatting directives for the callingPrefix and timeSuffix.
  106. format = "%v " + format + "%s"
  107. switch ltype {
  108. case errorLog:
  109. if g.expected(fmt.Sprintf(format, args...)) {
  110. g.t.Logf(format, args...)
  111. } else {
  112. g.t.Errorf(format, args...)
  113. }
  114. case fatalLog:
  115. panic(fmt.Sprintf(format, args...))
  116. default:
  117. g.t.Logf(format, args...)
  118. }
  119. }
  120. }
  121. // Update updates the testing.T that the testing logger logs to. Should be done
  122. // before every test. It also initializes the tLogger if it has not already.
  123. func (g *tLogger) Update(t *testing.T) {
  124. g.mu.Lock()
  125. defer g.mu.Unlock()
  126. if !g.initialized {
  127. grpclog.SetLoggerV2(TLogger)
  128. g.initialized = true
  129. }
  130. g.t = t
  131. g.start = time.Now()
  132. g.errors = map[*regexp.Regexp]int{}
  133. }
  134. // ExpectError declares an error to be expected. For the next test, the first
  135. // error log matching the expression (using FindString) will not cause the test
  136. // to fail. "For the next test" includes all the time until the next call to
  137. // Update(). Note that if an expected error is not encountered, this will cause
  138. // the test to fail.
  139. func (g *tLogger) ExpectError(expr string) {
  140. g.ExpectErrorN(expr, 1)
  141. }
  142. // ExpectErrorN declares an error to be expected n times.
  143. func (g *tLogger) ExpectErrorN(expr string, n int) {
  144. g.mu.Lock()
  145. defer g.mu.Unlock()
  146. re, err := regexp.Compile(expr)
  147. if err != nil {
  148. g.t.Error(err)
  149. return
  150. }
  151. g.errors[re] += n
  152. }
  153. // EndTest checks if expected errors were not encountered.
  154. func (g *tLogger) EndTest(t *testing.T) {
  155. g.mu.Lock()
  156. defer g.mu.Unlock()
  157. for re, count := range g.errors {
  158. if count > 0 {
  159. t.Errorf("Expected error '%v' not encountered", re.String())
  160. }
  161. }
  162. g.errors = map[*regexp.Regexp]int{}
  163. }
  164. // expected determines if the error string is protected or not.
  165. func (g *tLogger) expected(s string) bool {
  166. for re, count := range g.errors {
  167. if re.FindStringIndex(s) != nil {
  168. g.errors[re]--
  169. if count <= 1 {
  170. delete(g.errors, re)
  171. }
  172. return true
  173. }
  174. }
  175. return false
  176. }
  177. func (g *tLogger) Info(args ...interface{}) {
  178. g.log(infoLog, 0, "", args...)
  179. }
  180. func (g *tLogger) Infoln(args ...interface{}) {
  181. g.log(infoLog, 0, "", args...)
  182. }
  183. func (g *tLogger) Infof(format string, args ...interface{}) {
  184. g.log(infoLog, 0, format, args...)
  185. }
  186. func (g *tLogger) InfoDepth(depth int, args ...interface{}) {
  187. g.log(infoLog, depth, "", args...)
  188. }
  189. func (g *tLogger) Warning(args ...interface{}) {
  190. g.log(warningLog, 0, "", args...)
  191. }
  192. func (g *tLogger) Warningln(args ...interface{}) {
  193. g.log(warningLog, 0, "", args...)
  194. }
  195. func (g *tLogger) Warningf(format string, args ...interface{}) {
  196. g.log(warningLog, 0, format, args...)
  197. }
  198. func (g *tLogger) WarningDepth(depth int, args ...interface{}) {
  199. g.log(warningLog, depth, "", args...)
  200. }
  201. func (g *tLogger) Error(args ...interface{}) {
  202. g.log(errorLog, 0, "", args...)
  203. }
  204. func (g *tLogger) Errorln(args ...interface{}) {
  205. g.log(errorLog, 0, "", args...)
  206. }
  207. func (g *tLogger) Errorf(format string, args ...interface{}) {
  208. g.log(errorLog, 0, format, args...)
  209. }
  210. func (g *tLogger) ErrorDepth(depth int, args ...interface{}) {
  211. g.log(errorLog, depth, "", args...)
  212. }
  213. func (g *tLogger) Fatal(args ...interface{}) {
  214. g.log(fatalLog, 0, "", args...)
  215. }
  216. func (g *tLogger) Fatalln(args ...interface{}) {
  217. g.log(fatalLog, 0, "", args...)
  218. }
  219. func (g *tLogger) Fatalf(format string, args ...interface{}) {
  220. g.log(fatalLog, 0, format, args...)
  221. }
  222. func (g *tLogger) FatalDepth(depth int, args ...interface{}) {
  223. g.log(fatalLog, depth, "", args...)
  224. }
  225. func (g *tLogger) V(l int) bool {
  226. return l <= g.v
  227. }