osbase/logtree/klog.go

// Copyright 2020 The Monogon Project Authors.
//
// SPDX-License-Identifier: Apache-2.0
//
// 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 logtree

import (
	"fmt"
	"io"
	"regexp"
	"strconv"
	"strings"
	"time"

	"source.monogon.dev/go/logging"
	"source.monogon.dev/osbase/logbuffer"
)

// KLogParser returns an io.WriteCloser to which raw logging from a klog emitter
// can be piped. It will attempt to parse all lines from this log as
// glog/klog-style entries, and pass them over to a LeveledLogger as if they were
// emitted locally.
//
// This allows for piping in external processes that emit klog logging into a
// logtree, leading to niceties like transparently exposing the log severity or
// source file/line.
//
// One caveat, however, is that V-leveled logs will not be translated
// appropriately - anything that the klog-emitter pumps out as Info will be
// directly ingested as Info logging. There is no way to work around this.
//
// Another important limitation is that any written line is interpreted as having
// happened recently (ie. within one hour of the time of execution of this
// function). This is important as klog/glog-formatted loglines don't have a year
// attached, so we have to infer it based on the current timestamp (note: parsed
// lines do not necessarily have their year aleays equal to the current year, as
// the code handles the edge case of parsing a line from the end of a previous
// year at the beginning of the next).
func KLogParser(logger logging.Leveled) io.WriteCloser {
	p, ok := logger.(*leveledPublisher)
	if !ok {
		// Fail fast, as this is a programming error.
		panic("Expected *leveledPublisher in LeveledLogger from supervisor")
	}

	k := &klogParser{
		publisher: p,
	}
	// klog seems to have no line length limit. Let's assume some sane sort of default.
	k.buffer = logbuffer.NewLineBuffer(1024, k.consumeLine)
	return k
}

type klogParser struct {
	publisher *leveledPublisher
	buffer    *logbuffer.LineBuffer
}

func (k *klogParser) Write(p []byte) (n int, err error) {
	return k.buffer.Write(p)
}

// Close must be called exactly once after the parser is done being used. It will
// pipe any leftover data in its write buffer as one last line to parse.
func (k *klogParser) Close() error {
	return k.buffer.Close()
}

// consumeLine is called by the internal LineBuffer any time a new line is fully
// written.
func (k *klogParser) consumeLine(l *logbuffer.Line) {
	p := parse(time.Now(), l.Data)
	if p == nil {
		// We could instead emit that line as a raw log - however, this would lead to
		// interleaving raw logging and leveled logging.
		k.publisher.Errorf("Invalid klog line: %s", l.Data)
		return
	}
	// TODO(q3k): should this be exposed as an API on LeveledLogger? How much should
	// we permit library users to 'fake' logs? This would also permit us to get rid
	// of the type assertion in KLogParser().
	e := &entry{
		origin:  k.publisher.node.dn,
		leveled: p,
	}
	k.publisher.node.tree.journal.append(e)
	k.publisher.node.tree.journal.notify(e)
}

var (
	// reKLog matches and parses klog/glog-formatted log lines. Format: I0312
	// 14:20:04.240540     204 shared_informer.go:247] Caches are synced for attach
	// detach
	reKLog = regexp.MustCompile(`^([IEWF])(\d{4})\s+(\d{2}:\d{2}:\d{2}(\.\d+)?)\s+(\d+)\s+([^:]+):(\d+)]\s+(.+)$`)
)

// parse attempts to parse a klog-formatted line. Returns nil if the line
// couldn't have been parsed successfully.
func parse(now time.Time, s string) *LeveledPayload {
	parts := reKLog.FindStringSubmatch(s)
	if parts == nil {
		return nil
	}

	severityS := parts[1]
	date := parts[2]
	timestamp := parts[3]
	pid := parts[5]
	file := parts[6]
	lineS := parts[7]
	message := parts[8]

	var severity logging.Severity
	switch severityS {
	case "I":
		severity = logging.INFO
	case "W":
		severity = logging.WARNING
	case "E":
		severity = logging.ERROR
	case "F":
		severity = logging.FATAL
	default:
		return nil
	}

	// Possible race due to klog's/glog's format not containing a year.
	// On 2020/12/31 at 23:59:59.99999 a klog logger emits this line:
	//
	//   I1231 23:59:59.99999 1 example.go:10] It's almost 2021! Hooray.
	//
	// Then, if this library parses that line at 2021/01/01 00:00:00.00001, the
	// time will be interpreted as:
	//
	//   2021/12/31 23:59:59
	//
	// So around one year in the future. We attempt to fix this case further down in
	// this function.
	year := now.Year()
	ts, err := parseKLogTime(year, date, timestamp)
	if err != nil {
		return nil
	}

	// Attempt to fix the aforementioned year-in-the-future issue.
	if ts.After(now) && ts.Sub(now) > time.Hour {
		// Parsed timestamp is in the future. How close is it to One-Year-From-Now?
		oyfn := now.Add(time.Hour * 24 * 365)
		dOyfn := ts.Sub(oyfn)
		// Let's make sure Duration-To-One-Year-From-Now is always positive. This
		// simplifies the rest of the checks and papers over some possible edge cases.
		if dOyfn < 0 {
			dOyfn = -dOyfn
		}

		// Okay, is that very close? Then the issue above happened and we should
		// attempt to reparse it with last year. We can't just manipulate the date we
		// already have, as it's difficult to 'subtract one year'.
		if dOyfn < (time.Hour * 24 * 2) {
			ts, err = parseKLogTime(year-1, date, timestamp)
			if err != nil {
				return nil
			}
		} else {
			// Otherwise, we received some seriously time traveling log entry. Abort.
			return nil
		}
	}

	line, err := strconv.Atoi(lineS)
	if err != nil {
		return nil
	}

	// The PID is discarded.
	_ = pid

	// Finally we have extracted all the data from the line. Inject into the log
	// publisher.
	return &LeveledPayload{
		timestamp: ts,
		severity:  severity,
		messages:  []string{message},
		file:      file,
		line:      line,
	}
}

// parseKLogTime parses a klog date and time (eg. "0314", "12:13:14.12345") into
// a time.Time happening at a given year.
func parseKLogTime(year int, d, t string) (time.Time, error) {
	var layout string
	if strings.Contains(t, ".") {
		layout = "2006 0102 15:04:05.000000"
	} else {
		layout = "2006 0102 15:04:05"
	}
	// Make up a string that contains the current year. This permits us to parse
	// fully into an actual timestamp.
	// TODO(q3k): add a timezone? This currently behaves as UTC, which is probably
	// what we want, but we should formalize this.
	return time.Parse(layout, fmt.Sprintf("%d %s %s", year, d, t))
}