Skip to content

Commit cf22f1e

Browse files
sunjayBhatiasunjayBhatia
committed
Call logr with call depth
When a backing logr implementation is in use, take advantage of the CallDepthLogger interface to pass along contextual information that might be useful to the logr implementation. Signed-off-by: Sunjay Bhatia <sunjayb@vmware.com>
1 parent dda2080 commit cf22f1e

2 files changed

Lines changed: 230 additions & 11 deletions

File tree

‎klog.go‎

Lines changed: 9 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -708,7 +708,7 @@ func (l *loggingT) println(s severity, logr logr.Logger, filter LogFilter, args
708708
args = filter.Filter(args)
709709
}
710710
fmt.Fprintln(buf, args...)
711-
l.output(s, logr, buf, file, line, false)
711+
l.output(s, logr, buf, 0 /* depth */, file, line, false)
712712
}
713713

714714
func (l *loggingT) print(s severity, logr logr.Logger, filter LogFilter, args ...interface{}) {
@@ -730,7 +730,7 @@ func (l *loggingT) printDepth(s severity, logr logr.Logger, filter LogFilter, de
730730
if buf.Bytes()[buf.Len()-1] != '\n' {
731731
buf.WriteByte('\n')
732732
}
733-
l.output(s, logr, buf, file, line, false)
733+
l.output(s, logr, buf, depth, file, line, false)
734734
}
735735

736736
func (l *loggingT) printf(s severity, logr logr.Logger, filter LogFilter, format string, args ...interface{}) {
@@ -748,7 +748,7 @@ func (l *loggingT) printf(s severity, logr logr.Logger, filter LogFilter, format
748748
if buf.Bytes()[buf.Len()-1] != '\n' {
749749
buf.WriteByte('\n')
750750
}
751-
l.output(s, logr, buf, file, line, false)
751+
l.output(s, logr, buf, 0 /* depth */, file, line, false)
752752
}
753753

754754
// printWithFileLine behaves like print but uses the provided file and line number. If
@@ -769,7 +769,7 @@ func (l *loggingT) printWithFileLine(s severity, logr logr.Logger, filter LogFil
769769
if buf.Bytes()[buf.Len()-1] != '\n' {
770770
buf.WriteByte('\n')
771771
}
772-
l.output(s, logr, buf, file, line, alsoToStderr)
772+
l.output(s, logr, buf, 2 /* depth */, file, line, alsoToStderr)
773773
}
774774

775775
// if loggr is specified, will call loggr.Error, otherwise output with logging module.
@@ -778,7 +778,7 @@ func (l *loggingT) errorS(err error, loggr logr.Logger, filter LogFilter, depth
778778
msg, keysAndValues = filter.FilterS(msg, keysAndValues)
779779
}
780780
if loggr != nil {
781-
loggr.Error(err, msg, keysAndValues...)
781+
logr.WithCallDepth(loggr, depth+2).Error(err, msg, keysAndValues...)
782782
return
783783
}
784784
l.printS(err, errorLog, depth+1, msg, keysAndValues...)
@@ -790,7 +790,7 @@ func (l *loggingT) infoS(loggr logr.Logger, filter LogFilter, depth int, msg str
790790
msg, keysAndValues = filter.FilterS(msg, keysAndValues)
791791
}
792792
if loggr != nil {
793-
loggr.Info(msg, keysAndValues...)
793+
logr.WithCallDepth(loggr, depth+2).Info(msg, keysAndValues...)
794794
return
795795
}
796796
l.printS(nil, infoLog, depth+1, msg, keysAndValues...)
@@ -855,8 +855,6 @@ func (rb *redirectBuffer) Write(bytes []byte) (n int, err error) {
855855
// SetLogger will set the backing logr implementation for klog.
856856
// If set, all log lines will be suppressed from the regular Output, and
857857
// redirected to the logr implementation.
858-
// All log lines include the 'severity', 'file' and 'line' values attached as
859-
// structured logging values.
860858
// Use as:
861859
// ...
862860
// klog.SetLogger(zapr.NewLogger(zapLog))
@@ -902,7 +900,7 @@ func LogToStderr(stderr bool) {
902900
}
903901

904902
// output writes the data to the log files and releases the buffer.
905-
func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, file string, line int, alsoToStderr bool) {
903+
func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, depth int, file string, line int, alsoToStderr bool) {
906904
l.mu.Lock()
907905
if l.traceLocation.isSet() {
908906
if l.traceLocation.match(file, line) {
@@ -914,9 +912,9 @@ func (l *loggingT) output(s severity, log logr.Logger, buf *buffer, file string,
914912
// TODO: set 'severity' and caller information as structured log info
915913
// keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line}
916914
if s == errorLog {
917-
l.logr.Error(nil, string(data))
915+
logr.WithCallDepth(l.logr, depth+3).Error(nil, string(data))
918916
} else {
919-
log.Info(string(data))
917+
logr.WithCallDepth(log, depth+3).Info(string(data))
920918
}
921919
} else if l.toStderr {
922920
os.Stderr.Write(data)

‎klog_test.go‎

Lines changed: 221 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1447,6 +1447,167 @@ func TestErrorSWithLogr(t *testing.T) {
14471447
}
14481448
}
14491449

1450+
func TestCallDepthLogr(t *testing.T) {
1451+
logger := &callDepthTestLogr{}
1452+
logger.resetCallDepth()
1453+
1454+
testCases := []struct {
1455+
name string
1456+
logFn func()
1457+
}{
1458+
{
1459+
name: "Info log",
1460+
logFn: func() { Info("info log") },
1461+
},
1462+
{
1463+
name: "InfoDepth log",
1464+
logFn: func() { InfoDepth(0, "infodepth log") },
1465+
},
1466+
{
1467+
name: "InfoSDepth log",
1468+
logFn: func() { InfoSDepth(0, "infoSDepth log") },
1469+
},
1470+
{
1471+
name: "Warning log",
1472+
logFn: func() { Warning("warning log") },
1473+
},
1474+
{
1475+
name: "WarningDepth log",
1476+
logFn: func() { WarningDepth(0, "warningdepth log") },
1477+
},
1478+
{
1479+
name: "Error log",
1480+
logFn: func() { Error("error log") },
1481+
},
1482+
{
1483+
name: "ErrorDepth log",
1484+
logFn: func() { ErrorDepth(0, "errordepth log") },
1485+
},
1486+
{
1487+
name: "ErrorSDepth log",
1488+
logFn: func() { ErrorSDepth(0, errors.New("some error"), "errorSDepth log") },
1489+
},
1490+
}
1491+
1492+
for _, tc := range testCases {
1493+
t.Run(tc.name, func(t *testing.T) {
1494+
SetLogger(logger)
1495+
defer SetLogger(nil)
1496+
defer logger.reset()
1497+
defer logger.resetCallDepth()
1498+
1499+
// Keep these lines together.
1500+
_, wantFile, wantLine, _ := runtime.Caller(0)
1501+
tc.logFn()
1502+
wantLine++
1503+
1504+
if len(logger.entries) != 1 {
1505+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1506+
}
1507+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1508+
})
1509+
}
1510+
}
1511+
1512+
func TestCallDepthLogrInfoS(t *testing.T) {
1513+
logger := &callDepthTestLogr{}
1514+
logger.resetCallDepth()
1515+
SetLogger(logger)
1516+
1517+
// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
1518+
logFunc := func() {
1519+
InfoS("infoS log")
1520+
}
1521+
1522+
// Keep these lines together.
1523+
_, wantFile, wantLine, _ := runtime.Caller(0)
1524+
logFunc()
1525+
wantLine++
1526+
1527+
if len(logger.entries) != 1 {
1528+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1529+
}
1530+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1531+
}
1532+
1533+
func TestCallDepthLogrErrorS(t *testing.T) {
1534+
logger := &callDepthTestLogr{}
1535+
logger.resetCallDepth()
1536+
SetLogger(logger)
1537+
1538+
// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
1539+
logFunc := func() {
1540+
ErrorS(errors.New("some error"), "errorS log")
1541+
}
1542+
1543+
// Keep these lines together.
1544+
_, wantFile, wantLine, _ := runtime.Caller(0)
1545+
logFunc()
1546+
wantLine++
1547+
1548+
if len(logger.entries) != 1 {
1549+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1550+
}
1551+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1552+
}
1553+
1554+
func TestCallDepthLogrGoLog(t *testing.T) {
1555+
logger := &callDepthTestLogr{}
1556+
logger.resetCallDepth()
1557+
SetLogger(logger)
1558+
CopyStandardLogTo("INFO")
1559+
1560+
// Add wrapper to ensure callDepthTestLogr +2 offset is correct.
1561+
logFunc := func() {
1562+
stdLog.Print("some log")
1563+
}
1564+
1565+
// Keep these lines together.
1566+
_, wantFile, wantLine, _ := runtime.Caller(0)
1567+
logFunc()
1568+
wantLine++
1569+
1570+
if len(logger.entries) != 1 {
1571+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1572+
}
1573+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1574+
fmt.Println(logger.entries[0])
1575+
}
1576+
1577+
// Test callDepthTestLogr logs the expected offsets.
1578+
func TestCallDepthTestLogr(t *testing.T) {
1579+
logger := &callDepthTestLogr{}
1580+
logger.resetCallDepth()
1581+
1582+
logFunc := func() {
1583+
logger.Info("some info log")
1584+
}
1585+
// Keep these lines together.
1586+
_, wantFile, wantLine, _ := runtime.Caller(0)
1587+
logFunc()
1588+
wantLine++
1589+
1590+
if len(logger.entries) != 1 {
1591+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1592+
}
1593+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1594+
1595+
logger.reset()
1596+
1597+
logFunc = func() {
1598+
logger.Error(errors.New("error"), "some error log")
1599+
}
1600+
// Keep these lines together.
1601+
_, wantFile, wantLine, _ = runtime.Caller(0)
1602+
logFunc()
1603+
wantLine++
1604+
1605+
if len(logger.entries) != 1 {
1606+
t.Errorf("expected a single log entry to be generated, got %d", len(logger.entries))
1607+
}
1608+
checkLogrEntryCorrectCaller(t, wantFile, wantLine, logger.entries[0])
1609+
}
1610+
14501611
type testLogr struct {
14511612
entries []testLogrEntry
14521613
mutex sync.Mutex
@@ -1493,6 +1654,66 @@ func (l *testLogr) WithValues(...interface{}) logr.Logger {
14931654
panic("not implemented")
14941655
}
14951656

1657+
type callDepthTestLogr struct {
1658+
testLogr
1659+
callDepth int
1660+
}
1661+
1662+
func (l *callDepthTestLogr) resetCallDepth() {
1663+
l.mutex.Lock()
1664+
defer l.mutex.Unlock()
1665+
l.callDepth = 0
1666+
}
1667+
1668+
func (l *callDepthTestLogr) WithCallDepth(depth int) logr.Logger {
1669+
l.mutex.Lock()
1670+
defer l.mutex.Unlock()
1671+
// Note: Usually WithCallDepth would be implemented by cloning l
1672+
// and setting the call depth on the clone. We modify l instead in
1673+
// this test helper for simplicity.
1674+
l.callDepth = depth
1675+
return l
1676+
}
1677+
1678+
func (l *callDepthTestLogr) Info(msg string, keysAndValues ...interface{}) {
1679+
l.mutex.Lock()
1680+
defer l.mutex.Unlock()
1681+
// Add 2 to depth for the wrapper function caller and for invocation in
1682+
// test case.
1683+
_, file, line, _ := runtime.Caller(l.callDepth + 2)
1684+
l.entries = append(l.entries, testLogrEntry{
1685+
severity: infoLog,
1686+
msg: msg,
1687+
keysAndValues: append([]interface{}{file, line}, keysAndValues...),
1688+
})
1689+
}
1690+
1691+
func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interface{}) {
1692+
l.mutex.Lock()
1693+
defer l.mutex.Unlock()
1694+
// Add 2 to depth for the wrapper function caller and for invocation in
1695+
// test case.
1696+
_, file, line, _ := runtime.Caller(l.callDepth + 2)
1697+
l.entries = append(l.entries, testLogrEntry{
1698+
severity: errorLog,
1699+
msg: msg,
1700+
keysAndValues: append([]interface{}{file, line}, keysAndValues...),
1701+
err: err,
1702+
})
1703+
}
1704+
1705+
func checkLogrEntryCorrectCaller(t *testing.T, wantFile string, wantLine int, entry testLogrEntry) {
1706+
t.Helper()
1707+
1708+
want := fmt.Sprintf("%s:%d", wantFile, wantLine)
1709+
// Log fields contain file and line number as first elements.
1710+
got := fmt.Sprintf("%s:%d", entry.keysAndValues[0], entry.keysAndValues[1])
1711+
1712+
if want != got {
1713+
t.Errorf("expected file and line %q but got %q", want, got)
1714+
}
1715+
}
1716+
14961717
// existedFlag contains all existed flag, without KlogPrefix
14971718
var existedFlag = map[string]struct{}{
14981719
"log_dir": {},

0 commit comments

Comments
 (0)