klog_test.go 45 KB

1234567891011121314151617181920212223242526272829303132333435363738394041424344454647484950515253545556575859606162636465666768697071727374757677787980818283848586878889909192939495969798991001011021031041051061071081091101111121131141151161171181191201211221231241251261271281291301311321331341351361371381391401411421431441451461471481491501511521531541551561571581591601611621631641651661671681691701711721731741751761771781791801811821831841851861871881891901911921931941951961971981992002012022032042052062072082092102112122132142152162172182192202212222232242252262272282292302312322332342352362372382392402412422432442452462472482492502512522532542552562572582592602612622632642652662672682692702712722732742752762772782792802812822832842852862872882892902912922932942952962972982993003013023033043053063073083093103113123133143153163173183193203213223233243253263273283293303313323333343353363373383393403413423433443453463473483493503513523533543553563573583593603613623633643653663673683693703713723733743753763773783793803813823833843853863873883893903913923933943953963973983994004014024034044054064074084094104114124134144154164174184194204214224234244254264274284294304314324334344354364374384394404414424434444454464474484494504514524534544554564574584594604614624634644654664674684694704714724734744754764774784794804814824834844854864874884894904914924934944954964974984995005015025035045055065075085095105115125135145155165175185195205215225235245255265275285295305315325335345355365375385395405415425435445455465475485495505515525535545555565575585595605615625635645655665675685695705715725735745755765775785795805815825835845855865875885895905915925935945955965975985996006016026036046056066076086096106116126136146156166176186196206216226236246256266276286296306316326336346356366376386396406416426436446456466476486496506516526536546556566576586596606616626636646656666676686696706716726736746756766776786796806816826836846856866876886896906916926936946956966976986997007017027037047057067077087097107117127137147157167177187197207217227237247257267277287297307317327337347357367377387397407417427437447457467477487497507517527537547557567577587597607617627637647657667677687697707717727737747757767777787797807817827837847857867877887897907917927937947957967977987998008018028038048058068078088098108118128138148158168178188198208218228238248258268278288298308318328338348358368378388398408418428438448458468478488498508518528538548558568578588598608618628638648658668678688698708718728738748758768778788798808818828838848858868878888898908918928938948958968978988999009019029039049059069079089099109119129139149159169179189199209219229239249259269279289299309319329339349359369379389399409419429439449459469479489499509519529539549559569579589599609619629639649659669679689699709719729739749759769779789799809819829839849859869879889899909919929939949959969979989991000100110021003100410051006100710081009101010111012101310141015101610171018101910201021102210231024102510261027102810291030103110321033103410351036103710381039104010411042104310441045104610471048104910501051105210531054105510561057105810591060106110621063106410651066106710681069107010711072107310741075107610771078107910801081108210831084108510861087108810891090109110921093109410951096109710981099110011011102110311041105110611071108110911101111111211131114111511161117111811191120112111221123112411251126112711281129113011311132113311341135113611371138113911401141114211431144114511461147114811491150115111521153115411551156115711581159116011611162116311641165116611671168116911701171117211731174117511761177117811791180118111821183118411851186118711881189119011911192119311941195119611971198119912001201120212031204120512061207120812091210121112121213121412151216121712181219122012211222122312241225122612271228122912301231123212331234123512361237123812391240124112421243124412451246124712481249125012511252125312541255125612571258125912601261126212631264126512661267126812691270127112721273127412751276127712781279128012811282128312841285128612871288128912901291129212931294129512961297129812991300130113021303130413051306130713081309131013111312131313141315131613171318131913201321132213231324132513261327132813291330133113321333133413351336133713381339134013411342134313441345134613471348134913501351135213531354135513561357135813591360136113621363136413651366136713681369137013711372137313741375137613771378137913801381138213831384138513861387138813891390139113921393139413951396139713981399140014011402140314041405140614071408140914101411141214131414141514161417141814191420142114221423142414251426142714281429143014311432143314341435143614371438143914401441144214431444144514461447144814491450145114521453145414551456145714581459146014611462146314641465146614671468146914701471147214731474147514761477147814791480148114821483148414851486148714881489149014911492149314941495149614971498149915001501150215031504150515061507150815091510151115121513151415151516151715181519152015211522152315241525152615271528152915301531153215331534153515361537153815391540154115421543154415451546154715481549155015511552155315541555155615571558155915601561156215631564156515661567156815691570157115721573157415751576157715781579158015811582158315841585158615871588158915901591159215931594159515961597159815991600160116021603160416051606160716081609161016111612161316141615161616171618161916201621162216231624162516261627162816291630163116321633163416351636163716381639164016411642164316441645164616471648164916501651165216531654165516561657165816591660166116621663166416651666166716681669167016711672167316741675167616771678167916801681168216831684168516861687168816891690169116921693169416951696169716981699170017011702170317041705170617071708170917101711171217131714171517161717171817191720172117221723172417251726172717281729173017311732173317341735173617371738173917401741174217431744174517461747174817491750175117521753175417551756175717581759176017611762176317641765176617671768176917701771177217731774177517761777177817791780178117821783178417851786178717881789179017911792179317941795179617971798179918001801180218031804180518061807180818091810181118121813181418151816181718181819182018211822182318241825182618271828182918301831183218331834
  1. // Go support for leveled logs, analogous to https://code.google.com/p/google-glog/
  2. //
  3. // Copyright 2013 Google Inc. All Rights Reserved.
  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. package log
  17. import (
  18. "bytes"
  19. "errors"
  20. "flag"
  21. "fmt"
  22. "io"
  23. stdLog "log"
  24. "os"
  25. "path/filepath"
  26. "reflect"
  27. "regexp"
  28. "runtime"
  29. "strconv"
  30. "strings"
  31. "sync"
  32. "testing"
  33. "time"
  34. "github.com/go-logr/logr"
  35. )
  36. // TODO: This test package should be refactored so that tests cannot
  37. // interfere with each-other.
  38. // Test that shortHostname works as advertised.
  39. func TestShortHostname(t *testing.T) {
  40. for hostname, expect := range map[string]string{
  41. "": "",
  42. "host": "host",
  43. "host.google.com": "host",
  44. } {
  45. if got := shortHostname(hostname); expect != got {
  46. t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got)
  47. }
  48. }
  49. }
  50. // flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter.
  51. type flushBuffer struct {
  52. bytes.Buffer
  53. }
  54. func (f *flushBuffer) Flush() error {
  55. return nil
  56. }
  57. func (f *flushBuffer) Sync() error {
  58. return nil
  59. }
  60. // swap sets the log writers and returns the old array.
  61. func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity]flushSyncWriter) {
  62. l.mu.Lock()
  63. defer l.mu.Unlock()
  64. old = l.file
  65. for i, w := range writers {
  66. logging.file[i] = w
  67. }
  68. return
  69. }
  70. // newBuffers sets the log writers to all new byte buffers and returns the old array.
  71. func (l *loggingT) newBuffers() [numSeverity]flushSyncWriter {
  72. return l.swap([numSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)})
  73. }
  74. // contents returns the specified log value as a string.
  75. func contents(s severity) string {
  76. return logging.file[s].(*flushBuffer).String()
  77. }
  78. // contains reports whether the string is contained in the log.
  79. func contains(s severity, str string, t *testing.T) bool {
  80. return strings.Contains(contents(s), str)
  81. }
  82. // setFlags configures the logging flags how the test expects them.
  83. func setFlags() {
  84. logging.toStderr = false
  85. logging.addDirHeader = false
  86. }
  87. // Test that Info works as advertised.
  88. func TestInfo(t *testing.T) {
  89. setFlags()
  90. defer logging.swap(logging.newBuffers())
  91. Info("test")
  92. if !contains(infoLog, "I", t) {
  93. t.Errorf("Info has wrong character: %q", contents(infoLog))
  94. }
  95. if !contains(infoLog, "test", t) {
  96. t.Error("Info failed")
  97. }
  98. }
  99. func TestInfoDepth(t *testing.T) {
  100. setFlags()
  101. defer logging.swap(logging.newBuffers())
  102. f := func() { InfoDepth(1, "depth-test1") }
  103. // The next three lines must stay together
  104. _, _, wantLine, _ := runtime.Caller(0)
  105. InfoDepth(0, "depth-test0")
  106. f()
  107. msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n")
  108. if len(msgs) != 2 {
  109. t.Fatalf("Got %d lines, expected 2", len(msgs))
  110. }
  111. for i, m := range msgs {
  112. if !strings.HasPrefix(m, "I") {
  113. t.Errorf("InfoDepth[%d] has wrong character: %q", i, m)
  114. }
  115. w := fmt.Sprintf("depth-test%d", i)
  116. if !strings.Contains(m, w) {
  117. t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m)
  118. }
  119. // pull out the line number (between : and ])
  120. msg := m[strings.LastIndex(m, ":")+1:]
  121. x := strings.Index(msg, "]")
  122. if x < 0 {
  123. t.Errorf("InfoDepth[%d]: missing ']': %q", i, m)
  124. continue
  125. }
  126. line, err := strconv.Atoi(msg[:x])
  127. if err != nil {
  128. t.Errorf("InfoDepth[%d]: bad line number: %q", i, m)
  129. continue
  130. }
  131. wantLine++
  132. if wantLine != line {
  133. t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine)
  134. }
  135. }
  136. }
  137. func init() {
  138. CopyStandardLogTo("INFO")
  139. }
  140. // Test that CopyStandardLogTo panics on bad input.
  141. func TestCopyStandardLogToPanic(t *testing.T) {
  142. defer func() {
  143. if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") {
  144. t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s)
  145. }
  146. }()
  147. CopyStandardLogTo("LOG")
  148. }
  149. // Test that using the standard log package logs to INFO.
  150. func TestStandardLog(t *testing.T) {
  151. setFlags()
  152. defer logging.swap(logging.newBuffers())
  153. stdLog.Print("test")
  154. if !contains(infoLog, "I", t) {
  155. t.Errorf("Info has wrong character: %q", contents(infoLog))
  156. }
  157. if !contains(infoLog, "test", t) {
  158. t.Error("Info failed")
  159. }
  160. }
  161. // Test that the header has the correct format.
  162. func TestHeader(t *testing.T) {
  163. setFlags()
  164. defer logging.swap(logging.newBuffers())
  165. defer func(previous func() time.Time) { timeNow = previous }(timeNow)
  166. timeNow = func() time.Time {
  167. return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  168. }
  169. pid = 1234
  170. Info("test")
  171. var line int
  172. format := "I0102 15:04:05.067890 1234 klog_test.go:%d] test\n"
  173. n, err := fmt.Sscanf(contents(infoLog), format, &line)
  174. if n != 1 || err != nil {
  175. t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
  176. }
  177. // Scanf treats multiple spaces as equivalent to a single space,
  178. // so check for correct space-padding also.
  179. want := fmt.Sprintf(format, line)
  180. if contents(infoLog) != want {
  181. t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want)
  182. }
  183. }
  184. func TestHeaderWithDir(t *testing.T) {
  185. setFlags()
  186. logging.addDirHeader = true
  187. defer logging.swap(logging.newBuffers())
  188. defer func(previous func() time.Time) { timeNow = previous }(timeNow)
  189. timeNow = func() time.Time {
  190. return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  191. }
  192. pid = 1234
  193. Info("test")
  194. re := regexp.MustCompile(`I0102 15:04:05.067890 1234 (klog|v2)/klog_test.go:(\d+)] test\n`)
  195. if !re.MatchString(contents(infoLog)) {
  196. t.Errorf("log format error: line does not match regex:\n\t%q\n", contents(infoLog))
  197. }
  198. }
  199. // Test that an Error log goes to Warning and Info.
  200. // Even in the Info log, the source character will be E, so the data should
  201. // all be identical.
  202. func TestError(t *testing.T) {
  203. setFlags()
  204. defer logging.swap(logging.newBuffers())
  205. Error("test")
  206. if !contains(errorLog, "E", t) {
  207. t.Errorf("Error has wrong character: %q", contents(errorLog))
  208. }
  209. if !contains(errorLog, "test", t) {
  210. t.Error("Error failed")
  211. }
  212. str := contents(errorLog)
  213. if !contains(warningLog, str, t) {
  214. t.Error("Warning failed")
  215. }
  216. if !contains(infoLog, str, t) {
  217. t.Error("Info failed")
  218. }
  219. }
  220. // Test that an Error log does not goes to Warning and Info.
  221. // Even in the Info log, the source character will be E, so the data should
  222. // all be identical.
  223. func TestErrorWithOneOutput(t *testing.T) {
  224. setFlags()
  225. logging.oneOutput = true
  226. buf := logging.newBuffers()
  227. defer func() {
  228. logging.swap(buf)
  229. logging.oneOutput = false
  230. }()
  231. Error("test")
  232. if !contains(errorLog, "E", t) {
  233. t.Errorf("Error has wrong character: %q", contents(errorLog))
  234. }
  235. if !contains(errorLog, "test", t) {
  236. t.Error("Error failed")
  237. }
  238. str := contents(errorLog)
  239. if contains(warningLog, str, t) {
  240. t.Error("Warning failed")
  241. }
  242. if contains(infoLog, str, t) {
  243. t.Error("Info failed")
  244. }
  245. }
  246. // Test that a Warning log goes to Info.
  247. // Even in the Info log, the source character will be W, so the data should
  248. // all be identical.
  249. func TestWarning(t *testing.T) {
  250. setFlags()
  251. defer logging.swap(logging.newBuffers())
  252. Warning("test")
  253. if !contains(warningLog, "W", t) {
  254. t.Errorf("Warning has wrong character: %q", contents(warningLog))
  255. }
  256. if !contains(warningLog, "test", t) {
  257. t.Error("Warning failed")
  258. }
  259. str := contents(warningLog)
  260. if !contains(infoLog, str, t) {
  261. t.Error("Info failed")
  262. }
  263. }
  264. // Test that a Warning log does not goes to Info.
  265. // Even in the Info log, the source character will be W, so the data should
  266. // all be identical.
  267. func TestWarningWithOneOutput(t *testing.T) {
  268. setFlags()
  269. logging.oneOutput = true
  270. buf := logging.newBuffers()
  271. defer func() {
  272. logging.swap(buf)
  273. logging.oneOutput = false
  274. }()
  275. Warning("test")
  276. if !contains(warningLog, "W", t) {
  277. t.Errorf("Warning has wrong character: %q", contents(warningLog))
  278. }
  279. if !contains(warningLog, "test", t) {
  280. t.Error("Warning failed")
  281. }
  282. str := contents(warningLog)
  283. if contains(infoLog, str, t) {
  284. t.Error("Info failed")
  285. }
  286. }
  287. // Test that a V log goes to Info.
  288. func TestV(t *testing.T) {
  289. setFlags()
  290. defer logging.swap(logging.newBuffers())
  291. logging.verbosity.Set("2")
  292. defer logging.verbosity.Set("0")
  293. V(2).Info("test")
  294. if !contains(infoLog, "I", t) {
  295. t.Errorf("Info has wrong character: %q", contents(infoLog))
  296. }
  297. if !contains(infoLog, "test", t) {
  298. t.Error("Info failed")
  299. }
  300. }
  301. // Test that a vmodule enables a log in this file.
  302. func TestVmoduleOn(t *testing.T) {
  303. setFlags()
  304. defer logging.swap(logging.newBuffers())
  305. logging.vmodule.Set("klog_test=2")
  306. defer logging.vmodule.Set("")
  307. if !V(1).Enabled() {
  308. t.Error("V not enabled for 1")
  309. }
  310. if !V(2).Enabled() {
  311. t.Error("V not enabled for 2")
  312. }
  313. if V(3).Enabled() {
  314. t.Error("V enabled for 3")
  315. }
  316. V(2).Info("test")
  317. if !contains(infoLog, "I", t) {
  318. t.Errorf("Info has wrong character: %q", contents(infoLog))
  319. }
  320. if !contains(infoLog, "test", t) {
  321. t.Error("Info failed")
  322. }
  323. }
  324. // Test that a vmodule of another file does not enable a log in this file.
  325. func TestVmoduleOff(t *testing.T) {
  326. setFlags()
  327. defer logging.swap(logging.newBuffers())
  328. logging.vmodule.Set("notthisfile=2")
  329. defer logging.vmodule.Set("")
  330. for i := 1; i <= 3; i++ {
  331. if V(Level(i)).Enabled() {
  332. t.Errorf("V enabled for %d", i)
  333. }
  334. }
  335. V(2).Info("test")
  336. if contents(infoLog) != "" {
  337. t.Error("V logged incorrectly")
  338. }
  339. }
  340. func TestSetOutputDataRace(t *testing.T) {
  341. setFlags()
  342. defer logging.swap(logging.newBuffers())
  343. var wg sync.WaitGroup
  344. for i := 1; i <= 50; i++ {
  345. go func() {
  346. logging.flushDaemon()
  347. }()
  348. }
  349. for i := 1; i <= 50; i++ {
  350. wg.Add(1)
  351. go func() {
  352. defer wg.Done()
  353. SetOutput(io.Discard)
  354. }()
  355. }
  356. for i := 1; i <= 50; i++ {
  357. go func() {
  358. logging.flushDaemon()
  359. }()
  360. }
  361. for i := 1; i <= 50; i++ {
  362. wg.Add(1)
  363. go func() {
  364. defer wg.Done()
  365. SetOutputBySeverity("INFO", io.Discard)
  366. }()
  367. }
  368. for i := 1; i <= 50; i++ {
  369. go func() {
  370. logging.flushDaemon()
  371. }()
  372. }
  373. wg.Wait()
  374. }
  375. func TestLogToOutput(t *testing.T) {
  376. logging.toStderr = true
  377. defer logging.swap(logging.newBuffers())
  378. buf := new(bytes.Buffer)
  379. SetOutput(buf)
  380. LogToStderr(false)
  381. Info("Does logging to an output work?")
  382. str := buf.String()
  383. if !strings.Contains(str, "Does logging to an output work?") {
  384. t.Fatalf("Expected %q to contain \"Does logging to an output work?\"", str)
  385. }
  386. }
  387. // vGlobs are patterns that match/don't match this file at V=2.
  388. var vGlobs = map[string]bool{
  389. // Easy to test the numeric match here.
  390. "klog_test=1": false, // If -vmodule sets V to 1, V(2) will fail.
  391. "klog_test=2": true,
  392. "klog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed.
  393. // These all use 2 and check the patterns. All are true.
  394. "*=2": true,
  395. "?l*=2": true,
  396. "????_*=2": true,
  397. "??[mno]?_*t=2": true,
  398. // These all use 2 and check the patterns. All are false.
  399. "*x=2": false,
  400. "m*=2": false,
  401. "??_*=2": false,
  402. "?[abc]?_*t=2": false,
  403. }
  404. // Test that vmodule globbing works as advertised.
  405. func testVmoduleGlob(pat string, match bool, t *testing.T) {
  406. setFlags()
  407. defer logging.swap(logging.newBuffers())
  408. defer logging.vmodule.Set("")
  409. logging.vmodule.Set(pat)
  410. if V(2).Enabled() != match {
  411. t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match)
  412. }
  413. }
  414. // Test that a vmodule globbing works as advertised.
  415. func TestVmoduleGlob(t *testing.T) {
  416. for glob, match := range vGlobs {
  417. testVmoduleGlob(glob, match, t)
  418. }
  419. }
  420. func TestRollover(t *testing.T) {
  421. setFlags()
  422. var err error
  423. defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
  424. logExitFunc = func(e error) {
  425. err = e
  426. }
  427. defer func(previous uint64) { MaxSize = previous }(MaxSize)
  428. MaxSize = 512
  429. Info("x") // Be sure we have a file.
  430. info, ok := logging.file[infoLog].(*syncBuffer)
  431. if !ok {
  432. t.Fatal("info wasn't created")
  433. }
  434. if err != nil {
  435. t.Fatalf("info has initial error: %v", err)
  436. }
  437. fname0 := info.file.Name()
  438. Info(strings.Repeat("x", int(MaxSize))) // force a rollover
  439. if err != nil {
  440. t.Fatalf("info has error after big write: %v", err)
  441. }
  442. // Make sure the next log file gets a file name with a different
  443. // time stamp.
  444. //
  445. // TODO: determine whether we need to support subsecond log
  446. // rotation. C++ does not appear to handle this case (nor does it
  447. // handle Daylight Savings Time properly).
  448. time.Sleep(1 * time.Second)
  449. Info("x") // create a new file
  450. if err != nil {
  451. t.Fatalf("error after rotation: %v", err)
  452. }
  453. fname1 := info.file.Name()
  454. if fname0 == fname1 {
  455. t.Errorf("info.f.Name did not change: %v", fname0)
  456. }
  457. if info.nbytes >= info.maxbytes {
  458. t.Errorf("file size was not reset: %d", info.nbytes)
  459. }
  460. }
  461. func TestOpenAppendOnStart(t *testing.T) {
  462. const (
  463. x string = "xxxxxxxxxx"
  464. y string = "yyyyyyyyyy"
  465. )
  466. setFlags()
  467. var err error
  468. defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
  469. logExitFunc = func(e error) {
  470. err = e
  471. }
  472. f, err := os.CreateTemp("", "test_klog_OpenAppendOnStart")
  473. if err != nil {
  474. t.Fatalf("unexpected error: %v", err)
  475. }
  476. defer os.Remove(f.Name())
  477. logging.logFile = f.Name()
  478. // Erase files created by prior tests,
  479. for i := range logging.file {
  480. logging.file[i] = nil
  481. }
  482. // Logging creates the file
  483. Info(x)
  484. _, ok := logging.file[infoLog].(*syncBuffer)
  485. if !ok {
  486. t.Fatal("info wasn't created")
  487. }
  488. // ensure we wrote what we expected
  489. logging.flushAll()
  490. b, err := os.ReadFile(logging.logFile)
  491. if err != nil {
  492. t.Fatalf("unexpected error: %v", err)
  493. }
  494. if !strings.Contains(string(b), x) {
  495. t.Fatalf("got %s, missing expected Info log: %s", string(b), x)
  496. }
  497. // Set the file to nil so it gets "created" (opened) again on the next write.
  498. for i := range logging.file {
  499. logging.file[i] = nil
  500. }
  501. // Logging again should open the file again with O_APPEND instead of O_TRUNC
  502. Info(y)
  503. // ensure we wrote what we expected
  504. logging.lockAndFlushAll()
  505. b, err = os.ReadFile(logging.logFile)
  506. if err != nil {
  507. t.Fatalf("unexpected error: %v", err)
  508. }
  509. if !strings.Contains(string(b), y) {
  510. t.Fatalf("got %s, missing expected Info log: %s", string(b), y)
  511. }
  512. // The initial log message should be preserved across create calls.
  513. logging.lockAndFlushAll()
  514. b, err = os.ReadFile(logging.logFile)
  515. if err != nil {
  516. t.Fatalf("unexpected error: %v", err)
  517. }
  518. if !strings.Contains(string(b), x) {
  519. t.Fatalf("got %s, missing expected Info log: %s", string(b), x)
  520. }
  521. }
  522. func TestLogBacktraceAt(t *testing.T) {
  523. setFlags()
  524. defer logging.swap(logging.newBuffers())
  525. // The peculiar style of this code simplifies line counting and maintenance of the
  526. // tracing block below.
  527. var infoLine string
  528. setTraceLocation := func(file string, line int, ok bool, delta int) {
  529. if !ok {
  530. t.Fatal("could not get file:line")
  531. }
  532. _, file = filepath.Split(file)
  533. infoLine = fmt.Sprintf("%s:%d", file, line+delta)
  534. err := logging.traceLocation.Set(infoLine)
  535. if err != nil {
  536. t.Fatal("error setting log_backtrace_at: ", err)
  537. }
  538. }
  539. {
  540. // Start of tracing block. These lines know about each other's relative position.
  541. _, file, line, ok := runtime.Caller(0)
  542. setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls.
  543. Info("we want a stack trace here")
  544. }
  545. numAppearances := strings.Count(contents(infoLog), infoLine)
  546. if numAppearances < 2 {
  547. // Need 2 appearances, one in the log header and one in the trace:
  548. // log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here
  549. // ...
  550. // k8s.io/klog/klog_test.go:280 (0x41ba91)
  551. // ...
  552. // We could be more precise but that would require knowing the details
  553. // of the traceback format, which may not be dependable.
  554. t.Fatal("got no trace back; log is ", contents(infoLog))
  555. }
  556. }
  557. func BenchmarkHeader(b *testing.B) {
  558. for i := 0; i < b.N; i++ {
  559. buf, _, _ := logging.header(infoLog, 0)
  560. logging.putBuffer(buf)
  561. }
  562. }
  563. func BenchmarkHeaderWithDir(b *testing.B) {
  564. logging.addDirHeader = true
  565. for i := 0; i < b.N; i++ {
  566. buf, _, _ := logging.header(infoLog, 0)
  567. logging.putBuffer(buf)
  568. }
  569. }
  570. // Ensure that benchmarks have side effects to avoid compiler optimization
  571. var result ObjectRef
  572. func BenchmarkKRef(b *testing.B) {
  573. var r ObjectRef
  574. for i := 0; i < b.N; i++ {
  575. r = KRef("namespace", "name")
  576. }
  577. result = r
  578. }
  579. func BenchmarkKObj(b *testing.B) {
  580. a := kMetadataMock{name: "a", ns: "a"}
  581. var r ObjectRef
  582. for i := 0; i < b.N; i++ {
  583. r = KObj(&a)
  584. }
  585. result = r
  586. }
  587. func BenchmarkLogs(b *testing.B) {
  588. setFlags()
  589. defer logging.swap(logging.newBuffers())
  590. testFile, err := os.CreateTemp("", "test.log")
  591. if err != nil {
  592. b.Fatal("unable to create temporary file")
  593. }
  594. defer os.Remove(testFile.Name())
  595. logging.verbosity.Set("0")
  596. logging.toStderr = false
  597. logging.alsoToStderr = false
  598. logging.stderrThreshold = fatalLog
  599. logging.logFile = testFile.Name()
  600. logging.swap([numSeverity]flushSyncWriter{nil, nil, nil, nil})
  601. for i := 0; i < b.N; i++ {
  602. Error("error")
  603. Warning("warning")
  604. Info("info")
  605. }
  606. logging.flushAll()
  607. }
  608. // Test the logic on checking log size limitation.
  609. func TestFileSizeCheck(t *testing.T) {
  610. setFlags()
  611. testData := map[string]struct {
  612. testLogFile string
  613. testLogFileMaxSizeMB uint64
  614. testCurrentSize uint64
  615. expectedResult bool
  616. }{
  617. "logFile not specified, exceeds max size": {
  618. testLogFile: "",
  619. testLogFileMaxSizeMB: 1,
  620. testCurrentSize: 1024 * 1024 * 2000, //exceeds the maxSize
  621. expectedResult: true,
  622. },
  623. "logFile not specified, not exceeds max size": {
  624. testLogFile: "",
  625. testLogFileMaxSizeMB: 1,
  626. testCurrentSize: 1024 * 1024 * 1000, //smaller than the maxSize
  627. expectedResult: false,
  628. },
  629. "logFile specified, exceeds max size": {
  630. testLogFile: "/tmp/test.log",
  631. testLogFileMaxSizeMB: 500, // 500MB
  632. testCurrentSize: 1024 * 1024 * 1000, //exceeds the logFileMaxSizeMB
  633. expectedResult: true,
  634. },
  635. "logFile specified, not exceeds max size": {
  636. testLogFile: "/tmp/test.log",
  637. testLogFileMaxSizeMB: 500, // 500MB
  638. testCurrentSize: 1024 * 1024 * 300, //smaller than the logFileMaxSizeMB
  639. expectedResult: false,
  640. },
  641. }
  642. for name, test := range testData {
  643. logging.logFile = test.testLogFile
  644. logging.logFileMaxSizeMB = test.testLogFileMaxSizeMB
  645. actualResult := test.testCurrentSize >= CalculateMaxSize()
  646. if test.expectedResult != actualResult {
  647. t.Fatalf("Error on test case '%v': Was expecting result equals %v, got %v",
  648. name, test.expectedResult, actualResult)
  649. }
  650. }
  651. }
  652. func TestInitFlags(t *testing.T) {
  653. fs1 := flag.NewFlagSet("test1", flag.PanicOnError)
  654. InitFlags(fs1)
  655. fs1.Set("log_dir", "/test1")
  656. fs1.Set("log_file_max_size", "1")
  657. fs2 := flag.NewFlagSet("test2", flag.PanicOnError)
  658. InitFlags(fs2)
  659. if logging.logDir != "/test1" {
  660. t.Fatalf("Expected log_dir to be %q, got %q", "/test1", logging.logDir)
  661. }
  662. fs2.Set("log_file_max_size", "2048")
  663. if logging.logFileMaxSizeMB != 2048 {
  664. t.Fatal("Expected log_file_max_size to be 2048")
  665. }
  666. }
  667. func TestInfoObjectRef(t *testing.T) {
  668. setFlags()
  669. defer logging.swap(logging.newBuffers())
  670. tests := []struct {
  671. name string
  672. ref ObjectRef
  673. want string
  674. }{
  675. {
  676. name: "with ns",
  677. ref: ObjectRef{
  678. Name: "test-name",
  679. Namespace: "test-ns",
  680. },
  681. want: "test-ns/test-name",
  682. },
  683. {
  684. name: "without ns",
  685. ref: ObjectRef{
  686. Name: "test-name",
  687. Namespace: "",
  688. },
  689. want: "test-name",
  690. },
  691. {
  692. name: "empty",
  693. ref: ObjectRef{},
  694. want: "",
  695. },
  696. }
  697. for _, tt := range tests {
  698. t.Run(tt.name, func(t *testing.T) {
  699. Info(tt.ref)
  700. if !contains(infoLog, tt.want, t) {
  701. t.Errorf("expected %v, got %v", tt.want, contents(infoLog))
  702. }
  703. })
  704. }
  705. }
  706. type kMetadataMock struct {
  707. name, ns string
  708. }
  709. func (m kMetadataMock) GetName() string {
  710. return m.name
  711. }
  712. func (m kMetadataMock) GetNamespace() string {
  713. return m.ns
  714. }
  715. type ptrKMetadataMock struct {
  716. name, ns string
  717. }
  718. func (m *ptrKMetadataMock) GetName() string {
  719. return m.name
  720. }
  721. func (m *ptrKMetadataMock) GetNamespace() string {
  722. return m.ns
  723. }
  724. func TestKObj(t *testing.T) {
  725. tests := []struct {
  726. name string
  727. obj KMetadata
  728. want ObjectRef
  729. }{
  730. {
  731. name: "nil passed as pointer KMetadata implementation",
  732. obj: (*ptrKMetadataMock)(nil),
  733. want: ObjectRef{},
  734. },
  735. {
  736. name: "empty struct passed as non-pointer KMetadata implementation",
  737. obj: kMetadataMock{},
  738. want: ObjectRef{},
  739. },
  740. {
  741. name: "nil pointer passed to non-pointer KMetadata implementation",
  742. obj: (*kMetadataMock)(nil),
  743. want: ObjectRef{},
  744. },
  745. {
  746. name: "nil",
  747. obj: nil,
  748. want: ObjectRef{},
  749. },
  750. {
  751. name: "with ns",
  752. obj: &kMetadataMock{"test-name", "test-ns"},
  753. want: ObjectRef{
  754. Name: "test-name",
  755. Namespace: "test-ns",
  756. },
  757. },
  758. {
  759. name: "without ns",
  760. obj: &kMetadataMock{"test-name", ""},
  761. want: ObjectRef{
  762. Name: "test-name",
  763. },
  764. },
  765. }
  766. for _, tt := range tests {
  767. t.Run(tt.name, func(t *testing.T) {
  768. if KObj(tt.obj) != tt.want {
  769. t.Errorf("expected %v, got %v", tt.want, KObj(tt.obj))
  770. }
  771. })
  772. }
  773. }
  774. func TestKRef(t *testing.T) {
  775. tests := []struct {
  776. testname string
  777. name string
  778. namespace string
  779. want ObjectRef
  780. }{
  781. {
  782. testname: "with ns",
  783. name: "test-name",
  784. namespace: "test-ns",
  785. want: ObjectRef{
  786. Name: "test-name",
  787. Namespace: "test-ns",
  788. },
  789. },
  790. {
  791. testname: "without ns",
  792. name: "test-name",
  793. want: ObjectRef{
  794. Name: "test-name",
  795. },
  796. },
  797. }
  798. for _, tt := range tests {
  799. t.Run(tt.testname, func(t *testing.T) {
  800. if KRef(tt.namespace, tt.name) != tt.want {
  801. t.Errorf("expected %v, got %v", tt.want, KRef(tt.namespace, tt.name))
  802. }
  803. })
  804. }
  805. }
  806. // Test that InfoS and InfoSDepth work as advertised.
  807. func TestInfoS(t *testing.T) {
  808. setFlags()
  809. defer logging.swap(logging.newBuffers())
  810. timeNow = func() time.Time {
  811. return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  812. }
  813. pid = 1234
  814. var testDataInfo = []struct {
  815. msg string
  816. format string
  817. keysValues []interface{}
  818. }{
  819. {
  820. msg: "test",
  821. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n",
  822. keysValues: []interface{}{"pod", "kubedns"},
  823. },
  824. {
  825. msg: "test",
  826. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" replicaNum=20\n",
  827. keysValues: []interface{}{"replicaNum", 20},
  828. },
  829. {
  830. msg: "test",
  831. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  832. keysValues: []interface{}{"err", errors.New("test error")},
  833. },
  834. {
  835. msg: "test",
  836. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  837. keysValues: []interface{}{"err", errors.New("test error")},
  838. },
  839. }
  840. functions := []func(msg string, keyAndValues ...interface{}){
  841. InfoS,
  842. myInfoS,
  843. }
  844. for _, f := range functions {
  845. for _, data := range testDataInfo {
  846. logging.file[infoLog] = &flushBuffer{}
  847. f(data.msg, data.keysValues...)
  848. var line int
  849. n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
  850. if n != 1 || err != nil {
  851. t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
  852. }
  853. want := fmt.Sprintf(data.format, line)
  854. if contents(infoLog) != want {
  855. t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want)
  856. }
  857. }
  858. }
  859. }
  860. // Test that Verbose.InfoS works as advertised.
  861. func TestVInfoS(t *testing.T) {
  862. setFlags()
  863. defer logging.swap(logging.newBuffers())
  864. timeNow = func() time.Time {
  865. return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  866. }
  867. pid = 1234
  868. var testDataInfo = []struct {
  869. msg string
  870. format string
  871. keysValues []interface{}
  872. }{
  873. {
  874. msg: "test",
  875. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" pod=\"kubedns\"\n",
  876. keysValues: []interface{}{"pod", "kubedns"},
  877. },
  878. {
  879. msg: "test",
  880. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" replicaNum=20\n",
  881. keysValues: []interface{}{"replicaNum", 20},
  882. },
  883. {
  884. msg: "test",
  885. format: "I0102 15:04:05.067890 1234 klog_test.go:%d] \"test\" err=\"test error\"\n",
  886. keysValues: []interface{}{"err", errors.New("test error")},
  887. },
  888. }
  889. logging.verbosity.Set("2")
  890. defer logging.verbosity.Set("0")
  891. for l := Level(0); l < Level(4); l++ {
  892. for _, data := range testDataInfo {
  893. logging.file[infoLog] = &flushBuffer{}
  894. V(l).InfoS(data.msg, data.keysValues...)
  895. var want string
  896. var line int
  897. if l <= 2 {
  898. n, err := fmt.Sscanf(contents(infoLog), data.format, &line)
  899. if n != 1 || err != nil {
  900. t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
  901. }
  902. want = fmt.Sprintf(data.format, line)
  903. } else {
  904. want = ""
  905. }
  906. if contents(infoLog) != want {
  907. t.Errorf("V(%d).InfoS has unexpected output: \n got:\t%s\nwant:\t%s", l, contents(infoLog), want)
  908. }
  909. }
  910. }
  911. }
  912. // Test that ErrorS and ErrorSDepth work as advertised.
  913. func TestErrorS(t *testing.T) {
  914. setFlags()
  915. defer logging.swap(logging.newBuffers())
  916. timeNow = func() time.Time {
  917. return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
  918. }
  919. logging.logFile = ""
  920. pid = 1234
  921. functions := []func(err error, msg string, keyAndValues ...interface{}){
  922. ErrorS,
  923. myErrorS,
  924. }
  925. for _, f := range functions {
  926. var errorList = []struct {
  927. err error
  928. format string
  929. }{
  930. {
  931. err: fmt.Errorf("update status failed"),
  932. format: "E0102 15:04:05.067890 1234 klog_test.go:%d] \"Failed to update pod status\" err=\"update status failed\" pod=\"kubedns\"\n",
  933. },
  934. {
  935. err: nil,
  936. format: "E0102 15:04:05.067890 1234 klog_test.go:%d] \"Failed to update pod status\" pod=\"kubedns\"\n",
  937. },
  938. }
  939. for _, e := range errorList {
  940. logging.file[errorLog] = &flushBuffer{}
  941. f(e.err, "Failed to update pod status", "pod", "kubedns")
  942. var line int
  943. n, err := fmt.Sscanf(contents(errorLog), e.format, &line)
  944. if n != 1 || err != nil {
  945. t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog))
  946. }
  947. want := fmt.Sprintf(e.format, line)
  948. if contents(errorLog) != want {
  949. t.Errorf("ErrorS has wrong format: \n got:\t%s\nwant:\t%s", contents(errorLog), want)
  950. }
  951. }
  952. }
  953. }
  954. // Test that kvListFormat works as advertised.
  955. func TestKvListFormat(t *testing.T) {
  956. var testKVList = []struct {
  957. keysValues []interface{}
  958. want string
  959. }{
  960. {
  961. keysValues: []interface{}{"pod", "kubedns"},
  962. want: " pod=\"kubedns\"",
  963. },
  964. {
  965. keysValues: []interface{}{"pod", "kubedns", "update", true},
  966. want: " pod=\"kubedns\" update=true",
  967. },
  968. {
  969. keysValues: []interface{}{"pod", "kubedns", "spec", struct {
  970. X int
  971. Y string
  972. N time.Time
  973. }{X: 76, Y: "strval", N: time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.UTC)}},
  974. want: " pod=\"kubedns\" spec={X:76 Y:strval N:2006-01-02 15:04:05.06789 +0000 UTC}",
  975. },
  976. {
  977. keysValues: []interface{}{"pod", "kubedns", "values", []int{8, 6, 7, 5, 3, 0, 9}},
  978. want: " pod=\"kubedns\" values=[8 6 7 5 3 0 9]",
  979. },
  980. {
  981. keysValues: []interface{}{"pod", "kubedns", "values", []string{"deployment", "svc", "configmap"}},
  982. want: " pod=\"kubedns\" values=[deployment svc configmap]",
  983. },
  984. {
  985. keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("test case for byte array")},
  986. want: " pod=\"kubedns\" bytes=\"test case for byte array\"",
  987. },
  988. {
  989. keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("��=� ⌘")},
  990. want: " pod=\"kubedns\" bytes=\"\\ufffd\\ufffd=\\ufffd \\u2318\"",
  991. },
  992. {
  993. keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}},
  994. want: " pod=\"kubedns\" maps=map[three:4]",
  995. },
  996. {
  997. keysValues: []interface{}{"pod", KRef("kube-system", "kubedns"), "status", "ready"},
  998. want: " pod=\"kube-system/kubedns\" status=\"ready\"",
  999. },
  1000. {
  1001. keysValues: []interface{}{"pod", KRef("", "kubedns"), "status", "ready"},
  1002. want: " pod=\"kubedns\" status=\"ready\"",
  1003. },
  1004. {
  1005. keysValues: []interface{}{"pod", KObj(kMetadataMock{"test-name", "test-ns"}), "status", "ready"},
  1006. want: " pod=\"test-ns/test-name\" status=\"ready\"",
  1007. },
  1008. {
  1009. keysValues: []interface{}{"pod", KObj(kMetadataMock{"test-name", ""}), "status", "ready"},
  1010. want: " pod=\"test-name\" status=\"ready\"",
  1011. },
  1012. {
  1013. keysValues: []interface{}{"pod", KObj(nil), "status", "ready"},
  1014. want: " pod=\"\" status=\"ready\"",
  1015. },
  1016. {
  1017. keysValues: []interface{}{"pod", KObj((*ptrKMetadataMock)(nil)), "status", "ready"},
  1018. want: " pod=\"\" status=\"ready\"",
  1019. },
  1020. {
  1021. keysValues: []interface{}{"pod", KObj((*kMetadataMock)(nil)), "status", "ready"},
  1022. want: " pod=\"\" status=\"ready\"",
  1023. },
  1024. }
  1025. for _, d := range testKVList {
  1026. b := &bytes.Buffer{}
  1027. kvListFormat(b, d.keysValues...)
  1028. if b.String() != d.want {
  1029. t.Errorf("kvlist format error:\n got:\n\t%s\nwant:\t%s", b.String(), d.want)
  1030. }
  1031. }
  1032. }
  1033. func createTestValueOfLoggingT() *loggingT {
  1034. l := new(loggingT)
  1035. l.toStderr = true
  1036. l.alsoToStderr = false
  1037. l.stderrThreshold = errorLog
  1038. l.verbosity = Level(0)
  1039. l.skipHeaders = false
  1040. l.skipLogHeaders = false
  1041. l.addDirHeader = false
  1042. return l
  1043. }
  1044. func createTestValueOfModulePat(p string, li bool, le Level) modulePat {
  1045. m := modulePat{}
  1046. m.pattern = p
  1047. m.literal = li
  1048. m.level = le
  1049. return m
  1050. }
  1051. func compareModuleSpec(a, b moduleSpec) bool {
  1052. if len(a.filter) != len(b.filter) {
  1053. return false
  1054. }
  1055. for i := 0; i < len(a.filter); i++ {
  1056. if a.filter[i] != b.filter[i] {
  1057. return false
  1058. }
  1059. }
  1060. return true
  1061. }
  1062. func TestSetVState(t *testing.T) {
  1063. //Target loggingT value
  1064. want := createTestValueOfLoggingT()
  1065. want.verbosity = Level(3)
  1066. want.vmodule.filter = []modulePat{
  1067. createTestValueOfModulePat("recordio", true, Level(2)),
  1068. createTestValueOfModulePat("file", true, Level(1)),
  1069. createTestValueOfModulePat("gfs*", false, Level(3)),
  1070. createTestValueOfModulePat("gopher*", false, Level(3)),
  1071. }
  1072. want.filterLength = 4
  1073. //loggingT value to which test is run
  1074. target := createTestValueOfLoggingT()
  1075. tf := []modulePat{
  1076. createTestValueOfModulePat("recordio", true, Level(2)),
  1077. createTestValueOfModulePat("file", true, Level(1)),
  1078. createTestValueOfModulePat("gfs*", false, Level(3)),
  1079. createTestValueOfModulePat("gopher*", false, Level(3)),
  1080. }
  1081. target.setVState(Level(3), tf, true)
  1082. if want.verbosity != target.verbosity || !compareModuleSpec(want.vmodule, target.vmodule) || want.filterLength != target.filterLength {
  1083. t.Errorf("setVState method doesn't configure loggingT values' verbosity, vmodule or filterLength:\nwant:\n\tverbosity:\t%v\n\tvmodule:\t%v\n\tfilterLength:\t%v\ngot:\n\tverbosity:\t%v\n\tvmodule:\t%v\n\tfilterLength:\t%v", want.verbosity, want.vmodule, want.filterLength, target.verbosity, target.vmodule, target.filterLength)
  1084. }
  1085. }
  1086. type sampleLogFilter struct{}
  1087. func (f *sampleLogFilter) Filter(args []interface{}) []interface{} {
  1088. for i, arg := range args {
  1089. v, ok := arg.(string)
  1090. if ok && strings.Contains(v, "filter me") {
  1091. args[i] = "[FILTERED]"
  1092. }
  1093. }
  1094. return args
  1095. }
  1096. func (f *sampleLogFilter) FilterF(format string, args []interface{}) (string, []interface{}) {
  1097. return strings.Replace(format, "filter me", "[FILTERED]", 1), f.Filter(args)
  1098. }
  1099. func (f *sampleLogFilter) FilterS(msg string, keysAndValues []interface{}) (string, []interface{}) {
  1100. return strings.Replace(msg, "filter me", "[FILTERED]", 1), f.Filter(keysAndValues)
  1101. }
  1102. func TestLogFilter(t *testing.T) {
  1103. setFlags()
  1104. defer logging.swap(logging.newBuffers())
  1105. SetLogFilter(&sampleLogFilter{})
  1106. defer SetLogFilter(nil)
  1107. funcs := []struct {
  1108. name string
  1109. logFunc func(args ...interface{})
  1110. severity severity
  1111. }{{
  1112. name: "Info",
  1113. logFunc: Info,
  1114. severity: infoLog,
  1115. }, {
  1116. name: "InfoDepth",
  1117. logFunc: func(args ...interface{}) {
  1118. InfoDepth(1, args...)
  1119. },
  1120. severity: infoLog,
  1121. }, {
  1122. name: "Infoln",
  1123. logFunc: Infoln,
  1124. severity: infoLog,
  1125. }, {
  1126. name: "Infof",
  1127. logFunc: func(args ...interface{}) {
  1128. Infof(args[0].(string), args[1:]...)
  1129. },
  1130. severity: infoLog,
  1131. }, {
  1132. name: "InfoS",
  1133. logFunc: func(args ...interface{}) {
  1134. InfoS(args[0].(string), args[1:]...)
  1135. },
  1136. severity: infoLog,
  1137. }, {
  1138. name: "Warning",
  1139. logFunc: Warning,
  1140. severity: warningLog,
  1141. }, {
  1142. name: "WarningDepth",
  1143. logFunc: func(args ...interface{}) {
  1144. WarningDepth(1, args...)
  1145. },
  1146. severity: warningLog,
  1147. }, {
  1148. name: "Warningln",
  1149. logFunc: Warningln,
  1150. severity: warningLog,
  1151. }, {
  1152. name: "Warningf",
  1153. logFunc: func(args ...interface{}) {
  1154. Warningf(args[0].(string), args[1:]...)
  1155. },
  1156. severity: warningLog,
  1157. }, {
  1158. name: "Error",
  1159. logFunc: Error,
  1160. severity: errorLog,
  1161. }, {
  1162. name: "ErrorDepth",
  1163. logFunc: func(args ...interface{}) {
  1164. ErrorDepth(1, args...)
  1165. },
  1166. severity: errorLog,
  1167. }, {
  1168. name: "Errorln",
  1169. logFunc: Errorln,
  1170. severity: errorLog,
  1171. }, {
  1172. name: "Errorf",
  1173. logFunc: func(args ...interface{}) {
  1174. Errorf(args[0].(string), args[1:]...)
  1175. },
  1176. severity: errorLog,
  1177. }, {
  1178. name: "ErrorS",
  1179. logFunc: func(args ...interface{}) {
  1180. ErrorS(errors.New("testerror"), args[0].(string), args[1:]...)
  1181. },
  1182. severity: errorLog,
  1183. }, {
  1184. name: "V().Info",
  1185. logFunc: func(args ...interface{}) {
  1186. V(0).Info(args...)
  1187. },
  1188. severity: infoLog,
  1189. }, {
  1190. name: "V().Infoln",
  1191. logFunc: func(args ...interface{}) {
  1192. V(0).Infoln(args...)
  1193. },
  1194. severity: infoLog,
  1195. }, {
  1196. name: "V().Infof",
  1197. logFunc: func(args ...interface{}) {
  1198. V(0).Infof(args[0].(string), args[1:]...)
  1199. },
  1200. severity: infoLog,
  1201. }, {
  1202. name: "V().InfoS",
  1203. logFunc: func(args ...interface{}) {
  1204. V(0).InfoS(args[0].(string), args[1:]...)
  1205. },
  1206. severity: infoLog,
  1207. }, {
  1208. name: "V().Error",
  1209. logFunc: func(args ...interface{}) {
  1210. V(0).Error(errors.New("test error"), args[0].(string), args[1:]...)
  1211. },
  1212. severity: errorLog,
  1213. }, {
  1214. name: "V().ErrorS",
  1215. logFunc: func(args ...interface{}) {
  1216. V(0).ErrorS(errors.New("test error"), args[0].(string), args[1:]...)
  1217. },
  1218. severity: errorLog,
  1219. }}
  1220. testcases := []struct {
  1221. name string
  1222. args []interface{}
  1223. expectFiltered bool
  1224. }{{
  1225. args: []interface{}{"%s:%s", "foo", "bar"},
  1226. expectFiltered: false,
  1227. }, {
  1228. args: []interface{}{"%s:%s", "foo", "filter me"},
  1229. expectFiltered: true,
  1230. }, {
  1231. args: []interface{}{"filter me %s:%s", "foo", "bar"},
  1232. expectFiltered: true,
  1233. }}
  1234. for _, f := range funcs {
  1235. for _, tc := range testcases {
  1236. logging.newBuffers()
  1237. f.logFunc(tc.args...)
  1238. got := contains(f.severity, "[FILTERED]", t)
  1239. if got != tc.expectFiltered {
  1240. t.Errorf("%s filter application failed, got %v, want %v", f.name, got, tc.expectFiltered)
  1241. }
  1242. }
  1243. }
  1244. }
  1245. func TestInfoSWithLogr(t *testing.T) {
  1246. logger := new(testLogr)
  1247. testDataInfo := []struct {
  1248. msg string
  1249. keysValues []interface{}
  1250. expected testLogrEntry
  1251. }{{
  1252. msg: "foo",
  1253. keysValues: []interface{}{},
  1254. expected: testLogrEntry{
  1255. severity: infoLog,
  1256. msg: "foo",
  1257. keysAndValues: []interface{}{},
  1258. },
  1259. }, {
  1260. msg: "bar",
  1261. keysValues: []interface{}{"a", 1},
  1262. expected: testLogrEntry{
  1263. severity: infoLog,
  1264. msg: "bar",
  1265. keysAndValues: []interface{}{"a", 1},
  1266. },
  1267. }}
  1268. for _, data := range testDataInfo {
  1269. t.Run(data.msg, func(t *testing.T) {
  1270. SetLogger(logger)
  1271. defer SetLogger(nil)
  1272. defer logger.reset()
  1273. InfoS(data.msg, data.keysValues...)
  1274. if !reflect.DeepEqual(logger.entries, []testLogrEntry{data.expected}) {
  1275. t.Errorf("expected: %+v; but got: %+v", []testLogrEntry{data.expected}, logger.entries)
  1276. }
  1277. })
  1278. }
  1279. }
  1280. func TestErrorSWithLogr(t *testing.T) {
  1281. logger := new(testLogr)
  1282. testError := errors.New("testError")
  1283. testDataInfo := []struct {
  1284. err error
  1285. msg string
  1286. keysValues []interface{}
  1287. expected testLogrEntry
  1288. }{{
  1289. err: testError,
  1290. msg: "foo1",
  1291. keysValues: []interface{}{},
  1292. expected: testLogrEntry{
  1293. severity: errorLog,
  1294. msg: "foo1",
  1295. keysAndValues: []interface{}{},
  1296. err: testError,
  1297. },
  1298. }, {
  1299. err: testError,
  1300. msg: "bar1",
  1301. keysValues: []interface{}{"a", 1},
  1302. expected: testLogrEntry{
  1303. severity: errorLog,
  1304. msg: "bar1",
  1305. keysAndValues: []interface{}{"a", 1},
  1306. err: testError,
  1307. },
  1308. }, {
  1309. err: nil,
  1310. msg: "foo2",
  1311. keysValues: []interface{}{},
  1312. expected: testLogrEntry{
  1313. severity: errorLog,
  1314. msg: "foo2",
  1315. keysAndValues: []interface{}{},
  1316. err: nil,
  1317. },
  1318. }, {
  1319. err: nil,
  1320. msg: "bar2",
  1321. keysValues: []interface{}{"a", 1},
  1322. expected: testLogrEntry{
  1323. severity: errorLog,
  1324. msg: "bar2",
  1325. keysAndValues: []interface{}{"a", 1},
  1326. err: nil,
  1327. },
  1328. }}
  1329. for _, data := range testDataInfo {
  1330. t.Run(data.msg, func(t *testing.T) {
  1331. SetLogger(logger)
  1332. defer SetLogger(nil)
  1333. defer logger.reset()
  1334. ErrorS(data.err, data.msg, data.keysValues...)
  1335. if !reflect.DeepEqual(logger.entries, []testLogrEntry{data.expected}) {
  1336. t.Errorf("expected: %+v; but got: %+v", []testLogrEntry{data.expected}, logger.entries)
  1337. }
  1338. })
  1339. }
  1340. }
  1341. func TestCallDepthLogr(t *testing.T) {
  1342. logger := &callDepthTestLogr{}
  1343. logger.resetCallDepth()
  1344. testCases := []struct {
  1345. name string
  1346. logFn func()
  1347. }{
  1348. {
  1349. name: "Info log",
  1350. logFn: func() { Info("info log") },
  1351. },
  1352. {
  1353. name: "InfoDepth log",
  1354. logFn: func() { InfoDepth(0, "infodepth log") },
  1355. },
  1356. {
  1357. name: "InfoSDepth log",
  1358. logFn: func() { InfoSDepth(0, "infoSDepth log") },
  1359. },
  1360. {
  1361. name: "Warning log",
  1362. logFn: func() { Warning("warning log") },
  1363. },
  1364. {
  1365. name: "WarningDepth log",
  1366. logFn: func() { WarningDepth(0, "warningdepth log") },
  1367. },
  1368. {
  1369. name: "Error log",
  1370. logFn: func() { Error("error log") },
  1371. },
  1372. {
  1373. name: "ErrorDepth log",
  1374. logFn: func() { ErrorDepth(0, "errordepth log") },
  1375. },
  1376. {
  1377. name: "ErrorSDepth log",
  1378. logFn: func() { ErrorSDepth(0, errors.New("some error"), "errorSDepth log") },
  1379. },
  1380. }
  1381. for _, tc := range testCases {
  1382. t.Run(tc.name, func(t *testing.T) {
  1383. SetLogger(logger)
  1384. defer SetLogger(nil)
  1385. defer logger.reset()
  1386. defer logger.resetCallDepth()
  1387. // Keep these lines together.
  1388. _, wantFile, wantLine, _ := runtime.Caller(0)
  1389. tc.logFn()
  1390. wantLine++
  1391. if len(logger.entries) != 1 {
  1392. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1393. }
  1394. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1395. })
  1396. }
  1397. }
  1398. func TestCallDepthLogrInfoS(t *testing.T) {
  1399. logger := &callDepthTestLogr{}
  1400. logger.resetCallDepth()
  1401. SetLogger(logger)
  1402. // Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1403. logFunc := func() {
  1404. InfoS("infoS log")
  1405. }
  1406. // Keep these lines together.
  1407. _, wantFile, wantLine, _ := runtime.Caller(0)
  1408. logFunc()
  1409. wantLine++
  1410. if len(logger.entries) != 1 {
  1411. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1412. }
  1413. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1414. }
  1415. func TestCallDepthLogrErrorS(t *testing.T) {
  1416. logger := &callDepthTestLogr{}
  1417. logger.resetCallDepth()
  1418. SetLogger(logger)
  1419. // Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1420. logFunc := func() {
  1421. ErrorS(errors.New("some error"), "errorS log")
  1422. }
  1423. // Keep these lines together.
  1424. _, wantFile, wantLine, _ := runtime.Caller(0)
  1425. logFunc()
  1426. wantLine++
  1427. if len(logger.entries) != 1 {
  1428. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1429. }
  1430. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1431. }
  1432. func TestCallDepthLogrGoLog(t *testing.T) {
  1433. logger := &callDepthTestLogr{}
  1434. logger.resetCallDepth()
  1435. SetLogger(logger)
  1436. CopyStandardLogTo("INFO")
  1437. // Add wrapper to ensure callDepthTestLogr +2 offset is correct.
  1438. logFunc := func() {
  1439. stdLog.Print("some log")
  1440. }
  1441. // Keep these lines together.
  1442. _, wantFile, wantLine, _ := runtime.Caller(0)
  1443. logFunc()
  1444. wantLine++
  1445. if len(logger.entries) != 1 {
  1446. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1447. }
  1448. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1449. fmt.Println(logger.entries[0])
  1450. }
  1451. // Test callDepthTestLogr logs the expected offsets.
  1452. func TestCallDepthTestLogr(t *testing.T) {
  1453. logger := &callDepthTestLogr{}
  1454. logger.resetCallDepth()
  1455. logFunc := func() {
  1456. logger.Info("some info log")
  1457. }
  1458. // Keep these lines together.
  1459. _, wantFile, wantLine, _ := runtime.Caller(0)
  1460. logFunc()
  1461. wantLine++
  1462. if len(logger.entries) != 1 {
  1463. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1464. }
  1465. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1466. logger.reset()
  1467. logFunc = func() {
  1468. logger.Error(errors.New("error"), "some error log")
  1469. }
  1470. // Keep these lines together.
  1471. _, wantFile, wantLine, _ = runtime.Caller(0)
  1472. logFunc()
  1473. wantLine++
  1474. if len(logger.entries) != 1 {
  1475. t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
  1476. }
  1477. checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
  1478. }
  1479. type testLogr struct {
  1480. entries []testLogrEntry
  1481. mutex sync.Mutex
  1482. }
  1483. type testLogrEntry struct {
  1484. severity severity
  1485. msg string
  1486. keysAndValues []interface{}
  1487. err error
  1488. }
  1489. func (l *testLogr) reset() {
  1490. l.mutex.Lock()
  1491. defer l.mutex.Unlock()
  1492. l.entries = []testLogrEntry{}
  1493. }
  1494. func (l *testLogr) Info(msg string, keysAndValues ...interface{}) {
  1495. l.mutex.Lock()
  1496. defer l.mutex.Unlock()
  1497. l.entries = append(l.entries, testLogrEntry{
  1498. severity: infoLog,
  1499. msg: msg,
  1500. keysAndValues: keysAndValues,
  1501. })
  1502. }
  1503. func (l *testLogr) Error(err error, msg string, keysAndValues ...interface{}) {
  1504. l.mutex.Lock()
  1505. defer l.mutex.Unlock()
  1506. l.entries = append(l.entries, testLogrEntry{
  1507. severity: errorLog,
  1508. msg: msg,
  1509. keysAndValues: keysAndValues,
  1510. err: err,
  1511. })
  1512. }
  1513. func (l *testLogr) Enabled() bool { panic("not implemented") }
  1514. func (l *testLogr) V(int) logr.Logger { panic("not implemented") }
  1515. func (l *testLogr) WithName(string) logr.Logger { panic("not implemented") }
  1516. func (l *testLogr) WithValues(...interface{}) logr.Logger {
  1517. panic("not implemented")
  1518. }
  1519. type callDepthTestLogr struct {
  1520. testLogr
  1521. callDepth int
  1522. }
  1523. func (l *callDepthTestLogr) resetCallDepth() {
  1524. l.mutex.Lock()
  1525. defer l.mutex.Unlock()
  1526. l.callDepth = 0
  1527. }
  1528. func (l *callDepthTestLogr) WithCallDepth(depth int) logr.Logger {
  1529. l.mutex.Lock()
  1530. defer l.mutex.Unlock()
  1531. // Note: Usually WithCallDepth would be implemented by cloning l
  1532. // and setting the call depth on the clone. We modify l instead in
  1533. // this test helper for simplicity.
  1534. l.callDepth = depth
  1535. return l
  1536. }
  1537. func (l *callDepthTestLogr) Info(msg string, keysAndValues ...interface{}) {
  1538. l.mutex.Lock()
  1539. defer l.mutex.Unlock()
  1540. // Add 2 to depth for the wrapper function caller and for invocation in
  1541. // test case.
  1542. _, file, line, _ := runtime.Caller(l.callDepth + 2)
  1543. l.entries = append(l.entries, testLogrEntry{
  1544. severity: infoLog,
  1545. msg: msg,
  1546. keysAndValues: append([]interface{}{file, line}, keysAndValues...),
  1547. })
  1548. }
  1549. func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interface{}) {
  1550. l.mutex.Lock()
  1551. defer l.mutex.Unlock()
  1552. // Add 2 to depth for the wrapper function caller and for invocation in
  1553. // test case.
  1554. _, file, line, _ := runtime.Caller(l.callDepth + 2)
  1555. l.entries = append(l.entries, testLogrEntry{
  1556. severity: errorLog,
  1557. msg: msg,
  1558. keysAndValues: append([]interface{}{file, line}, keysAndValues...),
  1559. err: err,
  1560. })
  1561. }
  1562. func checkLogrEntryCorrectCaller(t *testing.T, wantFile string, wantLine int, entry testLogrEntry) {
  1563. t.Helper()
  1564. want := fmt.Sprintf("%s:%d", wantFile, wantLine)
  1565. // Log fields contain file and line number as first elements.
  1566. got := fmt.Sprintf("%s:%d", entry.keysAndValues[0], entry.keysAndValues[1])
  1567. if want != got {
  1568. t.Errorf("expected file and line %q but got %q", want, got)
  1569. }
  1570. }
  1571. // existedFlag contains all existed flag, without KlogPrefix
  1572. var existedFlag = map[string]struct{}{
  1573. "log_dir": {},
  1574. "add_dir_header": {},
  1575. "alsologtostderr": {},
  1576. "log_backtrace_at": {},
  1577. "log_file": {},
  1578. "log_file_max_size": {},
  1579. "logtostderr": {},
  1580. "one_output": {},
  1581. "skip_headers": {},
  1582. "skip_log_headers": {},
  1583. "stderrthreshold": {},
  1584. "v": {},
  1585. "vmodule": {},
  1586. }
  1587. // KlogPrefix define new flag prefix
  1588. const KlogPrefix string = "klog"
  1589. // TestKlogFlagPrefix check every klog flag's prefix, exclude flag in existedFlag
  1590. func TestKlogFlagPrefix(t *testing.T) {
  1591. fs := &flag.FlagSet{}
  1592. InitFlags(fs)
  1593. fs.VisitAll(func(f *flag.Flag) {
  1594. if _, found := existedFlag[f.Name]; !found {
  1595. if !strings.HasPrefix(f.Name, KlogPrefix) {
  1596. t.Errorf("flag %s not have klog prefix: %s", f.Name, KlogPrefix)
  1597. }
  1598. }
  1599. })
  1600. }
  1601. func TestKObjs(t *testing.T) {
  1602. tests := []struct {
  1603. name string
  1604. obj interface{}
  1605. want []ObjectRef
  1606. }{
  1607. {
  1608. name: "test for KObjs function with KMetadata slice",
  1609. obj: []kMetadataMock{
  1610. {
  1611. name: "kube-dns",
  1612. ns: "kube-system",
  1613. },
  1614. {
  1615. name: "mi-conf",
  1616. },
  1617. {},
  1618. },
  1619. want: []ObjectRef{
  1620. {
  1621. Name: "kube-dns",
  1622. Namespace: "kube-system",
  1623. },
  1624. {
  1625. Name: "mi-conf",
  1626. },
  1627. {},
  1628. },
  1629. },
  1630. {
  1631. name: "test for KObjs function with KMetadata pointer slice",
  1632. obj: []*kMetadataMock{
  1633. {
  1634. name: "kube-dns",
  1635. ns: "kube-system",
  1636. },
  1637. {
  1638. name: "mi-conf",
  1639. },
  1640. nil,
  1641. },
  1642. want: []ObjectRef{
  1643. {
  1644. Name: "kube-dns",
  1645. Namespace: "kube-system",
  1646. },
  1647. {
  1648. Name: "mi-conf",
  1649. },
  1650. {},
  1651. },
  1652. },
  1653. {
  1654. name: "test for KObjs function with slice does not implement KMetadata",
  1655. obj: []int{1, 2, 3, 4, 6},
  1656. want: nil,
  1657. },
  1658. {
  1659. name: "test for KObjs function with interface",
  1660. obj: "test case",
  1661. want: nil,
  1662. },
  1663. {
  1664. name: "test for KObjs function with nil",
  1665. obj: nil,
  1666. want: nil,
  1667. },
  1668. }
  1669. for _, tt := range tests {
  1670. t.Run(tt.name, func(t *testing.T) {
  1671. if !reflect.DeepEqual(KObjs(tt.obj), tt.want) {
  1672. t.Errorf("\nwant:\t %v\n got:\t %v", tt.want, KObjs(tt.obj))
  1673. }
  1674. })
  1675. }
  1676. }