Revision cb53bb57e3c6327b2667f78321d45f48ace3fbc0 authored by Joe Stringer on 10 March 2021, 19:06:53 UTC, committed by Joe Stringer on 10 March 2021, 19:21:03 UTC
Signed-off-by: Joe Stringer <joe@cilium.io>
1 parent b564795
Raw File
log.go
// Copyright 2017-2019 Authors of Cilium
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package endpoint

import (
	"os"
	"path/filepath"
	"strconv"
	"sync"
	"sync/atomic"
	"unsafe"

	"github.com/cilium/cilium/pkg/logging"
	"github.com/cilium/cilium/pkg/logging/logfields"
	"github.com/cilium/cilium/pkg/option"

	"github.com/sirupsen/logrus"
	"gopkg.in/natefinch/lumberjack.v2"
)

var (
	log       = logging.DefaultLogger.WithField(logfields.LogSubsys, subsystem)
	policyLog = logrus.New()

	policyLogOnce sync.Once
)

const (
	subsystem = "endpoint"

	fieldRegenLevel = "regeneration-level"
)

// getLogger returns a logrus object with EndpointID, containerID and the Endpoint
// revision fields.
func (e *Endpoint) getLogger() *logrus.Entry {
	v := atomic.LoadPointer(&e.logger)
	return (*logrus.Entry)(v)
}

// getPolicyLogger returns a logger to be used for policy update debugging, or nil,
// if not configured.
func (e *Endpoint) getPolicyLogger() *logrus.Entry {
	v := atomic.LoadPointer(&e.policyLogger)
	return (*logrus.Entry)(v)
}

// policyDebug logs the 'msg' with 'fields' if policy debug logging is enabled.
func (e *Endpoint) policyDebug(fields logrus.Fields, msg string) {
	if dbgLog := e.getPolicyLogger(); dbgLog != nil {
		dbgLog.WithFields(fields).Debug(msg)
	}
}

// Logger returns a logrus object with EndpointID, containerID and the Endpoint
// revision fields. The caller must specify their subsystem.
func (e *Endpoint) Logger(subsystem string) *logrus.Entry {
	if e == nil {
		return log.WithField(logfields.LogSubsys, subsystem)
	}

	return e.getLogger().WithField(logfields.LogSubsys, subsystem)
}

// UpdateLogger creates a logger instance specific to this endpoint. It will
// create a custom Debug logger for this endpoint when the option on it is set.
// If fields is not nil only the those specific fields will be updated in the
// endpoint's logger, otherwise a full update of those fields is executed.
//
// Note: You must hold Endpoint.mutex.Lock() to synchronize logger pointer
// updates if the endpoint is already exposed. Callers that create new
// endopoints do not need locks to call this.
func (e *Endpoint) UpdateLogger(fields map[string]interface{}) {
	e.updatePolicyLogger(fields)
	v := atomic.LoadPointer(&e.logger)
	epLogger := (*logrus.Entry)(v)
	if fields != nil && epLogger != nil {
		newLogger := epLogger.WithFields(fields)
		atomic.StorePointer(&e.logger, unsafe.Pointer(newLogger))
		return
	}

	// We need to update if
	// - e.logger is nil (this happens on the first ever call to UpdateLogger via
	//   Logger above). This clause has to come first to guard the others.
	// - If any of EndpointID, containerID or policyRevision are different on the
	//   endpoint from the logger.
	// - The debug option on the endpoint is true, and the logger is not debug,
	//   or vice versa.
	shouldUpdate := epLogger == nil || (e.Options != nil &&
		e.Options.IsEnabled(option.Debug) != (epLogger.Level == logrus.DebugLevel))

	// do nothing if we do not need an update
	if !shouldUpdate {
		return
	}

	// default to using the log var set above
	baseLogger := log.Logger

	// If this endpoint is set to debug ensure it will print debug by giving it
	// an independent logger
	if e.Options != nil && e.Options.IsEnabled(option.Debug) {
		baseLogger = logging.InitializeDefaultLogger()
		baseLogger.SetLevel(logrus.DebugLevel)
	} else {
		// Debug mode takes priority; if not in debug, check what log level user
		// has set and set the endpoint's log to log at that level.
		if lvl, ok := logging.GetLogLevelFromConfig(); ok {
			baseLogger.SetLevel(lvl)
		}
	}

	// When adding new fields, make sure they are abstracted by a setter
	// and update the logger when the value is set.
	l := baseLogger.WithFields(logrus.Fields{
		logfields.LogSubsys:              subsystem,
		logfields.EndpointID:             e.ID,
		logfields.ContainerID:            e.getShortContainerID(),
		logfields.DatapathPolicyRevision: e.policyRevision,
		logfields.DesiredPolicyRevision:  e.nextPolicyRevision,
		logfields.IPv4:                   e.IPv4.String(),
		logfields.IPv6:                   e.IPv6.String(),
		logfields.K8sPodName:             e.getK8sNamespaceAndPodName(),
	})

	if e.SecurityIdentity != nil {
		l = l.WithField(logfields.Identity, e.SecurityIdentity.ID.StringID())
	}

	atomic.StorePointer(&e.logger, unsafe.Pointer(l))
}

// Only to be called from UpdateLogger() above
func (e *Endpoint) updatePolicyLogger(fields map[string]interface{}) {
	pv := atomic.LoadPointer(&e.policyLogger)
	policyLogger := (*logrus.Entry)(pv)
	// e.Options check needed for unit testing.
	if policyLogger == nil && e.Options != nil && e.Options.IsEnabled(option.DebugPolicy) {
		policyLogOnce.Do(func() {
			maxSize := 10 // 10 MB
			if ms := os.Getenv("CILIUM_DBG_POLICY_LOG_MAX_SIZE"); ms != "" {
				if ms, err := strconv.Atoi(ms); err == nil {
					maxSize = ms
				}
			}
			maxBackups := 3
			if mb := os.Getenv("CILIUM_DBG_POLICY_LOG_MAX_BACKUPS"); mb != "" {
				if mb, err := strconv.Atoi(mb); err == nil {
					maxBackups = mb
				}
			}
			lumberjackLogger := &lumberjack.Logger{
				Filename:   filepath.Join(option.Config.StateDir, "endpoint-policy.log"),
				MaxSize:    maxSize,
				MaxBackups: maxBackups,
				MaxAge:     28, // days
				LocalTime:  true,
				Compress:   true,
			}
			policyLog.SetOutput(lumberjackLogger)
			policyLog.SetLevel(logrus.DebugLevel)
		})
		policyLogger = logrus.NewEntry(policyLog)
	}
	if policyLogger == nil || e.Options == nil {
		return
	}

	if !e.Options.IsEnabled(option.DebugPolicy) {
		policyLogger = nil
	} else if fields != nil {
		policyLogger = policyLogger.WithFields(fields)
	} else {
		policyLogger = policyLogger.WithFields(logrus.Fields{
			logfields.LogSubsys:              subsystem,
			logfields.EndpointID:             e.ID,
			logfields.ContainerID:            e.getShortContainerID(),
			logfields.DatapathPolicyRevision: e.policyRevision,
			logfields.DesiredPolicyRevision:  e.nextPolicyRevision,
			logfields.IPv4:                   e.IPv4.String(),
			logfields.IPv6:                   e.IPv6.String(),
			logfields.K8sPodName:             e.getK8sNamespaceAndPodName(),
		})

		if e.SecurityIdentity != nil {
			policyLogger = policyLogger.WithField(logfields.Identity, e.SecurityIdentity.ID.StringID())
		}
	}
	atomic.StorePointer(&e.policyLogger, unsafe.Pointer(policyLogger))
}
back to top