Kubelet Startup - Log Initialization
Kubernetes defaults to using the klog logging library, which is managed by the k8s.io/component-base/logs
library and is a forked version of glog. This fork was created because glog had several issues, especially when running in containers, and was not easy to test. As a result, Kubernetes maintains its own version of klog.
In Kubernetes version 1.18, it used version v1.0.0 of klog. In this version, the --add_dir_header
option didn’t work as expected. This issue was fixed in https://github.com/kubernetes/klog/pull/101, but it persisted in Kubernetes 1.18. Subsequent minor releases of Kubernetes did not update the klog version.
This article is based on Kubernetes version 1.18.6. Please visit the source code reading repository for more details.
1 Entry Point
In the kubelet, the main
function directly calls k8s.io/component-base/logs
’s InitLogs()
to initialize the logs and uses defer
to execute FlushLogs()
when the program exits.
cmd\kubelet\kubelet.go
import (
"math/rand"
"os"
"time"
"k8s.io/component-base/logs"
_ "k8s.io/component-base/metrics/prometheus/restclient"
_ "k8s.io/component-base/metrics/prometheus/version" // for version metric registration
"k8s.io/kubernetes/cmd/kubelet/app"
)
func main() {
rand.Seed(time.Now().UnixNano())
command := app.NewKubeletCommand()
logs.InitLogs()
defer logs.FlushLogs()
if err := command.Execute(); err != nil {
os.Exit(1)
}
}
2 Module Initialization
2.1 Loading the k8s.io/component-base/logs
Module
This module also loads the klog module, which has its own init()
function.
Global variable logFlushFreq
registers the command line option --log-flush-frequency
, and init()
initializes klog.
const logFlushFreqFlagName = "log-flush-frequency"
var logFlushFreq = pflag.Duration(logFlushFreqFlagName, 5*time.Second, "Maximum number of seconds between log flushes")
func init() {
klog.InitFlags(flag.CommandLine)
}
2.2 Loading the klog Module
This module sets default values for command line options and uses goroutines for periodic log flushing.
// init sets up the defaults and runs flushDaemon.
func init() {
logging.stderrThreshold = errorLog // Default stderrThreshold is ERROR.
logging.setVState(0, nil, false)
logging.logDir = ""
logging.logFile = ""
logging.logFileMaxSizeMB = 1800
logging.toStderr = true
logging.alsoToStderr = false
logging.skipHeaders = false
logging.addDirHeader = false
logging.skipLogHeaders = false
go logging.flushDaemon()
}
flushDaemon()
runs lockAndFlushAll()
every 5 seconds.
const flushInterval = 5 * time.Second
// flushDaemon periodically flushes the log file buffers.
func (l *loggingT) flushDaemon() {
for range time.NewTicker(flushInterval).C {
l.lockAndFlushAll()
}
}
// lockAndFlushAll is like flushAll but locks l.mu first.
func (l *loggingT) lockAndFlushAll() {
l.mu.Lock()
l.flushAll()
l.mu.Unlock()
}
// flushAll flushes all the logs and attempts to "sync" their data to disk.
// l.mu is held.
func (l *loggingT) flushAll() {
// Flush from fatal down, in case there's trouble flushing.
for s := fatalLog; s >= infoLog; s-- {
file := l.file[s]
if file != nil {
file.Flush() // ignore error
file.Sync() // ignore error
}
}
}
2.3 Executing klog.InitFlag
This registers the klog command line options.
// InitFlags is for explicitly initializing the flags.
func InitFlags(flagset *flag.FlagSet) {
if flagset == nil {
flagset = flag.CommandLine
}
flagset.StringVar(&logging.logDir, "log_dir", logging.logDir, "If non-empty, write log files in this directory")
flagset.StringVar(&logging.logFile, "log_file", logging.logFile, "If non-empty, use this log file")
flagset.Uint64Var(&logging.logFileMaxSizeMB, "log_file_max_size", logging.logFileMaxSizeMB,
"Defines the maximum size a log file can grow to. Unit is megabytes. "+
"If the value is 0, the maximum file size is unlimited.")
flagset.BoolVar(&logging.toStderr, "logtostderr", logging.toStderr, "log to standard error instead of files")
flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", logging.alsoToStderr, "log to standard error as well as files")
flagset.Var(&logging.verbosity, "v", "number for the log level verbosity")
flagset.BoolVar(&logging.skipHeaders, "add_dir_header", logging.addDirHeader, "If true, adds the file directory to the header")
flagset.BoolVar(&logging.skipHeaders, "skip_headers", logging.skipHeaders, "If true, avoid header prefixes in the log messages")
flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files")
flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr")
flagset.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
flagset.Var(&logging.traceLocation, "log_backtrace_at", "when logging hits line file:N, emit a stack trace")
}
3 Executing component-base/logs
’s InitLogs
Compatibility with the system log library - if the system’s log library is used to write logs, it is ultimately recorded using klog. It sets the log library to pass the original logs to klog without any processing.
For example, if log.Print
is used to record logs, it will ultimately call the Write
method of KlogWriter
to log the message.
Why is it necessary to be compatible with the system log library?
It might be due to historical reasons, as some external libraries used for logging might rely on the system’s log library.
// Write implements the io.Writer interface.
func (writer KlogWriter) Write(data []byte) (n int, err error) {
klog.InfoDepth(1, string(data))
return len(data), nil
}
// InitLogs initializes logs the way we want for kubernetes.
func InitLogs() {
// Compatibility with log for logging, but effectively using klog.
log.SetOutput(KlogWriter{})
// Set log output format to empty; log formatting is determined by klog
log.SetFlags(0)
// The default glog flush interval is 5 seconds.
go wait.Forever(klog.Flush, *logFlushFreq)
}
klog.Flush()
- executes log flushing. Here, it executes the same method lockAndFlushAll()
as the goroutine started by the klog initialization above. So, kubelet starts two goroutines to flush logs. This might seem redundant, but it ensures logs are flushed consistently.
// Flush flushes all pending log I/O.
func Flush() {
logging.lockAndFlushAll()
}
4 Registering Klog Command-Line Options Again
When executing addKlogFlags(fs)
, klog.InitFlag
is executed again.
Why is klog.InitFlag
executed again?
If you look closely, you’ll notice that when it’s executed again, it uses a newly created flagset - flag.NewFlagSet(os.Args[0], flag.ExitOnError)
(not flag.CommandLine
). In other words, it re-registers command-line options in this flagset and then adds them to kubelet’s pflagset. The options registered with flag.CommandLine
are not used, which can be seen as wasteful.
Based on commit messages, it seems that addKlogFlags
was added when klog was upgraded to version 0.3.0 - related pull request. It’s possible that klog was upgraded to version 1.0.0, but the kubelet code wasn’t updated accordingly.
cmd\kubelet\app\options\globalflags.go
// AddGlobalFlags explicitly registers flags that libraries (glog, verflag, etc.) register
// against the global flagsets from "flag" and "github.com/spf13/pflag".
// We do this in order to prevent unwanted flags from leaking into the Kubelet's flagset.
func AddGlobalFlags(fs *pflag.FlagSet) {
addKlogFlags(fs)
addCadvisorFlags(fs)
addCredentialProviderFlags(fs)
verflag.AddFlags(fs)
logs.AddFlags(fs)
}
// addKlogFlags adds flags from k8s.io/klog
func addKlogFlags(fs *pflag.FlagSet) {
local := flag.NewFlagSet(os.Args[0], flag.ExitOnError)
klog.InitFlags(local)
fs.AddGoFlagSet(local)
}
5 Flushing Logs on Program Exit
Flushing logs on program exit ensures that logs are not lost.
// FlushLogs flushes logs immediately.
func FlushLogs() {
klog.Flush()
}
6 Conclusion
The logging aspect of Kubernetes has continuously evolved, and there might be some historical baggage, but ultimately, it works. In Kubernetes version 1.20, klog was upgraded to version 2.4.0, offering better support for structured logging.
This analysis doesn’t delve into the klog source code. Perhaps, it can be analyzed in detail in the future. Kubernetes is indeed vast, and it’s a challenge to explore it thoroughly before it undergoes further changes. 😅