treewide: introduce osbase package and move things around
All except localregistry moved from metropolis/pkg to osbase,
localregistry moved to metropolis/test as its only used there anyway.
Change-Id: If1a4bf377364bef0ac23169e1b90379c71b06d72
Reviewed-on: https://review.monogon.dev/c/monogon/+/3079
Tested-by: Jenkins CI
Reviewed-by: Serge Bazanski <serge@monogon.tech>
diff --git a/osbase/logtree/klog.go b/osbase/logtree/klog.go
new file mode 100644
index 0000000..ad7e162
--- /dev/null
+++ b/osbase/logtree/klog.go
@@ -0,0 +1,214 @@
+// 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/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 LeveledLogger) 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 Severity
+ switch severityS {
+ case "I":
+ severity = INFO
+ case "W":
+ severity = WARNING
+ case "E":
+ severity = ERROR
+ case "F":
+ severity = 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))
+}