diff --git a/cmd/openshift-install/analyze.go b/cmd/openshift-install/analyze.go new file mode 100644 index 00000000000..1d6f02c02d4 --- /dev/null +++ b/cmd/openshift-install/analyze.go @@ -0,0 +1,300 @@ +package main + +import ( + "archive/tar" + "bufio" + "compress/gzip" + "fmt" + "io" + "io/ioutil" + "os" + "path" + "regexp" + "sort" + "strings" + + "github.com/sirupsen/logrus" + "k8s.io/utils/pointer" + + "github.com/openshift/installer/pkg/systemd" +) + +var failedUnitRegexp = regexp.MustCompile(`^[*] (?P[^ ]*) .*`) +var failedSSHRegexp = regexp.MustCompile(`(?Pssh: connect to host (?P[\d.]+) port (?P\d+): (?P.*))$`) + +type unit struct { + // Name is the name of the unit. + Name string + + // State is the unit state + State string + + // Detail is a detailed explaination of the current unit state. + Detail string + + // Log has systemd logs from the unit. + Log *systemd.Log +} + +func (unit *unit) Render(host string) { + logrus.Warnf("%s had %s systemd unit %s", host, unit.State, unit.Name) + if unit.Detail != "" { + logrus.Warnf(unit.Detail) + } + + if unit.Log != nil && unit.Log.Restarts(unit.Name) > 0 { + for _, line := range unit.Log.Format(unit.Name, -2) { + logrus.Warn(line) + } + } +} + +type host struct { + // Name is an identifier for the host. + Name string + + // Role is an identifier for the host's role (e.g. 'control-plane'). + Role string + + // AccessError, if non-empty, is the error from a failed attempt to + // SSH into the host. + AccessError string + + // Units is a set of systemd units from the host. + Units map[string]*unit +} + +func (host *host) Render() { + name := host.Name + if host.Role != "" && host.Role != host.Name { + name = fmt.Sprintf("%s %s", host.Role, name) + } + + if host.AccessError != "" { + logrus.Warnf("%s access error: %s", name, host.AccessError) + return + } + + if len(host.Units) == 0 { + logrus.Infof("%s had no failing or restarting systemd units", name) + return + } + + units := make([]string, 0, len(host.Units)) + for unitKey := range host.Units { + units = append(units, unitKey) + } + sort.Strings(units) + + logrus.Warnf("%s had failing or restarting systemd units: %s", name, strings.Join(units, ", ")) + for _, unitKey := range units { + host.Units[unitKey].Render(name) + } +} + +type bootstrapLogBundle struct { + // AccessError, if non-empty, is the error from a failed attempt to + // SSH into the host. + AccessError string + + // Hosts is a set of hosts referened from the bundle. + Hosts map[string]*host + + // Log is the output of the SSH gather script + Log string +} + +func newBootstrapLogBundle(r io.Reader) (*bootstrapLogBundle, error) { + tarReader := tar.NewReader(r) + bundle := &bootstrapLogBundle{ + Hosts: map[string]*host{}, + } + for { + header, err := tarReader.Next() + if err == io.EOF { + break + } + if err != nil { + return bundle, err + } + + baseName := path.Base(header.Name) + + hostKey := "bootstrap" + role := "bootstrap" + var accessError *string + if strings.Contains(header.Name, "/control-plane/") { + segments := strings.Split(header.Name, "/") + for i, segment := range segments { + if segment == "control-plane" && len(segments) > i && segments[i+1] != "" { + hostKey = segments[i+1] + role = "control-plane" + if len(segments) > i+1 && segments[i+2] != "" { + accessError = pointer.StringPtr("") + } else { + accessError = pointer.StringPtr("failed to SSH into host") + } + break + } + } + } + + if _, ok := bundle.Hosts[hostKey]; !ok { + bundle.Hosts[hostKey] = &host{Name: hostKey, Role: role} + } + host := bundle.Hosts[hostKey] + if accessError != nil { + host.AccessError = *accessError + } + + if strings.HasSuffix(header.Name, "/gather.log") { + data, err := ioutil.ReadAll(tarReader) + if err != nil { + return bundle, fmt.Errorf("reading %q: %w", header.Name, err) + } + bundle.Log = string(data) + } + + if baseName == "failed-units.txt" { + if host.Units == nil { + host.Units = map[string]*unit{} + } + scanner := bufio.NewScanner(tarReader) + for scanner.Scan() { + line := scanner.Text() + matches := failedUnitRegexp.FindStringSubmatch(line) + if matches == nil { + continue + } + + for i, name := range failedUnitRegexp.SubexpNames() { + if name == "unit" { + if u, ok := bundle.Hosts[hostKey].Units[matches[i]]; ok { + u.State = "failed" + } else { + bundle.Hosts[hostKey].Units[matches[i]] = &unit{ + Name: matches[i], + State: "failed", + } + } + break + } + } + } + if err := scanner.Err(); err != nil { + return bundle, fmt.Errorf("reading line from %q: %w", header.Name, err) + } + } + + if path.Base(path.Dir(header.Name)) == "unit-status" { + var extension string + for _, ext := range []string{".txt", ".log.json"} { + if strings.HasSuffix(baseName, ext) { + extension = ext + break + } + } + if extension == "" { + continue + } + + if host.Units == nil { + host.Units = map[string]*unit{} + } + + unitKey := strings.TrimSuffix(baseName, extension) // crio.service.txt -> crio.service + + if _, ok := host.Units[unitKey]; !ok { + host.Units[unitKey] = &unit{Name: unitKey} + } + u := host.Units[unitKey] + if u.State == "" { + u.State = "restarting" // for now, assume we're restarting unless we are failing via failed-units.txt + } + + switch extension { + case ".txt": + data, err := ioutil.ReadAll(tarReader) + if err != nil { + return bundle, fmt.Errorf("reading %q: %w", header.Name, err) + } + u.Detail = string(data) + case ".log.json": + log, err := systemd.NewLog(tarReader) + if err != nil { + return bundle, fmt.Errorf("parsing systemd log JSON %q: %w", header.Name, err) + } + u.Log = log + } + } + } + + scanner := bufio.NewScanner(strings.NewReader(bundle.Log)) + for scanner.Scan() { + line := scanner.Text() + matches := failedSSHRegexp.FindStringSubmatch(line) + if matches == nil { + continue + } + + groups := map[string]string{} + for i, name := range failedSSHRegexp.SubexpNames() { + groups[name] = matches[i] + } + + if host, ok := bundle.Hosts[groups["host"]]; ok { + host.AccessError = strings.TrimSpace(groups["all"]) + } else if bundle.AccessError == "" { + bundle.AccessError = strings.TrimSpace(groups["all"]) + } + } + if err := scanner.Err(); err != nil { + return bundle, fmt.Errorf("reading line from gather log: %w", err) + } + + return bundle, nil +} + +func (bundle *bootstrapLogBundle) Render() { + if bundle.AccessError != "" { + logrus.Warnf("bootstrap access error: %s", bundle.AccessError) + return + } + + hosts := make([]string, 0, len(bundle.Hosts)) + for hostKey := range bundle.Hosts { + hosts = append(hosts, hostKey) + } + sort.Strings(hosts) + + for _, hostKey := range hosts { + bundle.Hosts[hostKey].Render() + } + + if len(hosts) <= 1 { + logrus.Warnf("no control-plane machines in the gathered tarball") + } +} + +func analyzeGatheredBootstrap(tarPath string) error { + file, err := os.Open(tarPath) + if err != nil { + return err + } + defer file.Close() + + gzipReader, err := gzip.NewReader(file) + if err != nil { + return err + } + defer gzipReader.Close() + + bundle, err := newBootstrapLogBundle(gzipReader) + if err != nil { + return fmt.Errorf("parsing bootstrap log bundle %s: %w", tarPath, err) + } + + bundle.Render() + + return nil +} diff --git a/cmd/openshift-install/gather.go b/cmd/openshift-install/gather.go index fde2c203c5a..09df03ca6b7 100644 --- a/cmd/openshift-install/gather.go +++ b/cmd/openshift-install/gather.go @@ -160,11 +160,16 @@ func logGatherBootstrap(bootstrap string, port int, masters []string, directory if err := ssh.PullFileTo(client, fmt.Sprintf("/home/core/log-bundle-%s.tar.gz", gatherID), file); err != nil { return errors.Wrap(err, "failed to pull log file from remote") } + path, err := filepath.Abs(file) if err != nil { return errors.Wrap(err, "failed to stat log file") } logrus.Infof("Bootstrap gather logs captured here %q", path) + + if err := analyzeGatheredBootstrap(path); err != nil { + return errors.Wrapf(err, "failed to analyze %q", file) + } return nil } diff --git a/data/data/bootstrap/files/usr/local/bin/installer-gather.sh b/data/data/bootstrap/files/usr/local/bin/installer-gather.sh index 6d72acb959c..dbee0c1a453 100755 --- a/data/data/bootstrap/files/usr/local/bin/installer-gather.sh +++ b/data/data/bootstrap/files/usr/local/bin/installer-gather.sh @@ -16,10 +16,14 @@ LANG=POSIX systemctl list-units --state=failed >& "${ARTIFACTS}/failed-units.txt echo "Gathering bootstrap failed systemd unit status ..." mkdir -p "${ARTIFACTS}/unit-status" -sed -n 's/^\* \([^ ]*\) .*/\1/p' < "${ARTIFACTS}/failed-units.txt" | while read -r UNIT + +( + journalctl -o json _PID=1 MESSAGE_ID=5eb03494b6584870a536b337290809b3 | jq -r .UNIT + sed -n 's/^\* \([^ ]*\) .*/\1/p' < "${ARTIFACTS}/failed-units.txt" +) | sort -u | while read -r UNIT do systemctl status --full "${UNIT}" >& "${ARTIFACTS}/unit-status/${UNIT}.txt" - journalctl -u "${UNIT}" > "${ARTIFACTS}/unit-status/${UNIT}.log" + journalctl -o json-pretty -u "${UNIT}" > "${ARTIFACTS}/unit-status/${UNIT}.log.json" done echo "Gathering bootstrap journals ..." diff --git a/data/data/bootstrap/files/usr/local/bin/installer-masters-gather.sh b/data/data/bootstrap/files/usr/local/bin/installer-masters-gather.sh index 32625fa4505..91824102eef 100755 --- a/data/data/bootstrap/files/usr/local/bin/installer-masters-gather.sh +++ b/data/data/bootstrap/files/usr/local/bin/installer-masters-gather.sh @@ -14,10 +14,13 @@ LANG=POSIX systemctl list-units --state=failed >& "${ARTIFACTS}/failed-units.txt echo "Gathering master failed systemd unit status ..." mkdir -p "${ARTIFACTS}/unit-status" -sed -n 's/^\* \([^ ]*\) .*/\1/p' < "${ARTIFACTS}/failed-units.txt" | while read -r UNIT +( + journalctl -o json _PID=1 MESSAGE_ID=5eb03494b6584870a536b337290809b3 | jq -r .UNIT + sed -n 's/^\* \([^ ]*\) .*/\1/p' < "${ARTIFACTS}/failed-units.txt" +) | sort -u | while read -r UNIT do systemctl status --full "${UNIT}" >& "${ARTIFACTS}/unit-status/${UNIT}.txt" - journalctl -u "${UNIT}" > "${ARTIFACTS}/unit-status/${UNIT}.log" + journalctl -o json-pretty -u "${UNIT}" > "${ARTIFACTS}/unit-status/${UNIT}.log.json" done echo "Gathering master journals ..." diff --git a/pkg/systemd/entry.go b/pkg/systemd/entry.go new file mode 100644 index 00000000000..ce9959d1f7e --- /dev/null +++ b/pkg/systemd/entry.go @@ -0,0 +1,132 @@ +package systemd + +import ( + "encoding/json" + "fmt" + "strconv" + "time" +) + +// Entry holds a systemd log entry. +// https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html +type Entry struct { + // Hostname is the name of the originating host. + Hostname string + + // InvocationID is a randomized, unique 128-bit ID identifying each + // runtime cycle of the unit. + InvocationID string + + // MessageID is a 128bit message ID for recognizing certain message + // types. + MessageID string + + // Message it the human-readable message string for this entry. This + // is supposed to be the primary text shown to the user. It is + // usually not translated (but might be in some cases), and is + // not supposed to be parsed for metadata. + Message string + + // PID is the process ID of the process the journal entry originates + // from. + PID int + + // RealtimeTimestamp is the wallclock time (CLOCK_REALTIME) at the + // point in time the entry was received by the journal. This has + // different properties from SourceRealtimeTimestamp, as it is usually + // a bit later but more likely to be monotonic. + RealtimeTimestamp time.Time + + // Restarts is a counter of unit restarts, as long as the unit isn't + // fully stopped, i.e. as long as it remains up or remains in + // auto-start states. This is only set on entries that schedule + // restarts. + Restarts int + + // SourceRealtimeTimestamp is the earliest trusted timestamp of the + // message, if any is known that is different from the reception time + // of the journal. + SourceRealtimeTimestamp time.Time + + // SyslogIdentifier is the identifier string (i.e. "tag") as + // specified in the original datagram. + SyslogIdentifier string + + // SystemdInvocationID is the invocation ID for the runtime cycle of + // the unit the message was generated in, as available to processes of + // the unit in InvocationID. + SystemdInvocationID string + + // SystemdUnit is the systemd unit name of the process the journal + // entry originates from. + SystemdUnit string + + // Unit is the systemd unit name of the unit being operated on. + // This is only set on entries where systemd logging its management + // of other units. + Unit string +} + +// UnmarshalJSON unmarshals entry JSON. +func (e *Entry) UnmarshalJSON(b []byte) error { + var data map[string]string + if err := json.Unmarshal(b, &data); err != nil { + return err + } + + e.Hostname = data["_HOSTNAME"] + e.InvocationID = data["INVOCATION_ID"] + e.MessageID = data["MESSAGE_ID"] + e.Message = data["MESSAGE"] + e.SyslogIdentifier = data["SYSLOG_IDENTIFIER"] + e.SystemdInvocationID = data["_SYSTEMD_INVOCATION_ID"] + e.SystemdUnit = data["_SYSTEMD_UNIT"] + e.Unit = data["UNIT"] + + var err error + e.PID, err = strconv.Atoi(data["_PID"]) + if err != nil { + return fmt.Errorf("parse _PID: %w", err) + } + + if data["N_RESTARTS"] != "" { + e.Restarts, err = strconv.Atoi(data["N_RESTARTS"]) + if err != nil { + return fmt.Errorf("parse N_RESTARTS: %w", err) + } + } + + e.RealtimeTimestamp, err = parseTime(data["__REALTIME_TIMESTAMP"]) + if err != nil { + return fmt.Errorf("parse __REALTIME_TIMESTAMP: %w", err) + } + + if data["_SOURCE_REALTIME_TIMESTAMP"] != "" { + e.SourceRealtimeTimestamp, err = parseTime(data["_SOURCE_REALTIME_TIMESTAMP"]) + if err != nil { + return fmt.Errorf("parse _SOURCE_REALTIME_TIMESTAMP: %w", err) + } + } + + return nil +} + +// parseTime parses a time in microseconds since the epoch UTC, +// formatted as a decimal string. +func parseTime(data string) (time.Time, error) { + milliseconds, err := strconv.ParseInt(data, 10, 64) + if err != nil { + return time.Time{}, err + } + + return time.Unix(milliseconds/1000000, (milliseconds%1000000)*1000).UTC(), nil +} + +// String formats the entry similarly to a syslog log line. +func (e *Entry) String() string { + timestamp := e.SourceRealtimeTimestamp + if timestamp.IsZero() { + timestamp = e.RealtimeTimestamp + } + return fmt.Sprintf("%s %s %s[%d]: %s", timestamp.Format(time.RFC3339), e.Hostname, e.SyslogIdentifier, e.PID, e.Message) +} diff --git a/pkg/systemd/entry_test.go b/pkg/systemd/entry_test.go new file mode 100644 index 00000000000..84bc959340f --- /dev/null +++ b/pkg/systemd/entry_test.go @@ -0,0 +1,78 @@ +package systemd + +import ( + "encoding/json" + "testing" +) + +var exampleEntry string = ` +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11c7;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593e13e9;t=5b3750cd2db69;x=83b2de9fcedfdd27", + "__REALTIME_TIMESTAMP" : "1604690191244137", + "__MONOTONIC_TIMESTAMP" : "1497240553", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "2147", + "CODE_FUNC" : "service_enter_restart", + "MESSAGE_ID" : "5eb03494b6584870a536b337290809b3", + "INVOCATION_ID" : "d026e6248ad24604b8450541ff5f1eca", + "MESSAGE" : "bootkube.service: Scheduled restart job, restart counter is at 277.", + "N_RESTARTS" : "277", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191244128" +} +` + +func TestEntry(t *testing.T) { + var entry Entry + if err := json.Unmarshal([]byte(exampleEntry), &entry); err != nil { + t.Fatal(err) + } + + t.Run("InvocationID", func(t *testing.T) { + expected := "d026e6248ad24604b8450541ff5f1eca" + if entry.InvocationID != expected { + t.Fatalf("got %q , expected %q", entry.InvocationID, expected) + } + }) + + t.Run("Restarts", func(t *testing.T) { + expected := 277 + if entry.Restarts != expected { + t.Fatalf("got %d , expected %d", entry.Restarts, expected) + } + }) + + t.Run("String", func(t *testing.T) { + expected := "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Scheduled restart job, restart counter is at 277." + actual := entry.String() + if actual != expected { + t.Fatalf("got %q , expected %q", actual, expected) + } + }) + + t.Run("Unit", func(t *testing.T) { + expected := "bootkube.service" + if entry.Unit != expected { + t.Fatalf("got %q , expected %q", entry.Unit, expected) + } + }) + +} diff --git a/pkg/systemd/systemd.go b/pkg/systemd/systemd.go new file mode 100644 index 00000000000..bfb777ae216 --- /dev/null +++ b/pkg/systemd/systemd.go @@ -0,0 +1,95 @@ +// Package systemd contains handlers for systemd logs. +package systemd + +import ( + "encoding/json" + "io" +) + +// Log holds systemd unit logs. +type Log struct { + // Entries holds entries from the log. + Entries []Entry +} + +// NewLog parsers systemd's JSON log format. +// https://www.freedesktop.org/wiki/Software/systemd/json/ +func NewLog(r io.Reader) (*Log, error) { + decoder := json.NewDecoder(r) + log := &Log{ + Entries: []Entry{}, + } + for { + var entry Entry + if err := decoder.Decode(&entry); err == io.EOF { + return log, nil + } else if err != nil { + return log, err + } + log.Entries = append(log.Entries, entry) + } +} + +// Format formats unit logs similarly to syslog log lines for the +// given number of runtime cycle invocations. Zero will return all +// invocations, positive numbers will return the initial count +// invocations, and negative numbers will return the final count +// invocations. For example, log.Render("my.unit", -2) will format +// the final two invocations of my.unit. +func (log *Log) Format(unit string, invocations int) []string { + allInvocations := []string{} + invocation := "" + for _, entry := range log.Entries { + if entry.Unit == unit || entry.SystemdUnit == unit { + if entry.InvocationID != "" && entry.InvocationID != invocation { + allInvocations = append(allInvocations, entry.InvocationID) + } else if entry.SystemdInvocationID != "" && entry.SystemdInvocationID != invocation { + allInvocations = append(allInvocations, entry.SystemdInvocationID) + } + } + } + + var selectedInvocations []string + switch { + case invocations == 0: + selectedInvocations = allInvocations + case invocations > 0: + selectedInvocations = allInvocations[:invocations] + default: // invocations < 0 + selectedInvocations = allInvocations[len(allInvocations)+invocations:] + } + + selected := make(map[string]struct{}, len(selectedInvocations)) + exists := struct{}{} + for _, invocation := range selectedInvocations { + selected[invocation] = exists + } + + lines := []string{} + for _, entry := range log.Entries { + if entry.Unit == unit || entry.SystemdUnit == unit { + match := false + if _, ok := selected[entry.InvocationID]; ok { + match = true + } else if _, ok := selected[entry.SystemdInvocationID]; ok { + match = true + } + if match { + lines = append(lines, entry.String()) + } + } + } + return lines +} + +// Restarts returns the number of unit restarts, as long as the unit +// isn't fully stopped, i.e. as long as it remains up or remains in +// auto-start states. +func (log *Log) Restarts(unit string) int { + for i := len(log.Entries) - 1; i >= 0; i-- { + if log.Entries[i].Unit == unit && log.Entries[i].Restarts > 0 { + return log.Entries[i].Restarts + } + } + return 0 +} diff --git a/pkg/systemd/systemd_test.go b/pkg/systemd/systemd_test.go new file mode 100644 index 00000000000..29a128f9bb4 --- /dev/null +++ b/pkg/systemd/systemd_test.go @@ -0,0 +1,513 @@ +package systemd + +import ( + "strings" + "testing" +) + +var data string = ` +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11c6;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593e126d;t=5b3750cd2d9ed;x=15a8b3547325a0", + "__REALTIME_TIMESTAMP" : "1604690191243757", + "__MONOTONIC_TIMESTAMP" : "1497240173", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "3532", + "CODE_FUNC" : "service_dispatch_timer", + "MESSAGE" : "bootkube.service: Service RestartSec=5s expired, scheduling restart.", + "INVOCATION_ID" : "d026e6248ad24604b8450541ff5f1eca", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191243740" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11c7;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593e13e9;t=5b3750cd2db69;x=83b2de9fcedfdd27", + "__REALTIME_TIMESTAMP" : "1604690191244137", + "__MONOTONIC_TIMESTAMP" : "1497240553", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "2147", + "CODE_FUNC" : "service_enter_restart", + "MESSAGE_ID" : "5eb03494b6584870a536b337290809b3", + "INVOCATION_ID" : "d026e6248ad24604b8450541ff5f1eca", + "MESSAGE" : "bootkube.service: Scheduled restart job, restart counter is at 277.", + "N_RESTARTS" : "277", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191244128" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11c8;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593e1555;t=5b3750cd2dcd4;x=11d7ab1a97962d88", + "__REALTIME_TIMESTAMP" : "1604690191244500", + "__MONOTONIC_TIMESTAMP" : "1497240917", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "CODE_FILE" : "../src/core/job.c", + "CODE_LINE" : "827", + "CODE_FUNC" : "job_log_status_message", + "SYSLOG_IDENTIFIER" : "systemd", + "JOB_RESULT" : "done", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "MESSAGE_ID" : "9d1aaa27d60140bd96365438aad20286", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "MESSAGE" : "Stopped Bootstrap a Kubernetes cluster.", + "JOB_TYPE" : "restart", + "INVOCATION_ID" : "d026e6248ad24604b8450541ff5f1eca", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191244271" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11c9;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593e1e39;t=5b3750cd2e5b9;x=85e60042f2e8731c", + "__REALTIME_TIMESTAMP" : "1604690191246777", + "__MONOTONIC_TIMESTAMP" : "1497243193", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "CODE_FILE" : "../src/core/job.c", + "CODE_LINE" : "827", + "CODE_FUNC" : "job_log_status_message", + "SYSLOG_IDENTIFIER" : "systemd", + "JOB_TYPE" : "start", + "JOB_RESULT" : "done", + "MESSAGE_ID" : "39f53479d3a045ac8e11786248231fbf", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "MESSAGE" : "Started Bootstrap a Kubernetes cluster.", + "UNIT" : "bootkube.service", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191246053" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11ca;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593f710c;t=5b3750cd4388b;x=d0ab83b4af8fb625", + "__REALTIME_TIMESTAMP" : "1604690191333515", + "__MONOTONIC_TIMESTAMP" : "1497329932", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_SYSTEMD_SLICE" : "system.slice", + "_TRANSPORT" : "stdout", + "_EXE" : "/usr/bin/bash", + "_CAP_EFFECTIVE" : "3fffffffff", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_COMM" : "bash", + "SYSLOG_IDENTIFIER" : "bootkube.sh", + "MESSAGE" : "/usr/local/bin/bootkube.sh: line 6: i-am-a-command-that-does-not-exist: command not found", + "_CMDLINE" : "bash /usr/local/bin/bootkube.sh", + "_SYSTEMD_UNIT" : "bootkube.service", + "_SYSTEMD_CGROUP" : "/system.slice/bootkube.service", + "_STREAM_ID" : "d266c2bb271448bb92d956fa4e036391", + "_PID" : "15907", + "_SYSTEMD_INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11cb;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593f7377;t=5b3750cd43af7;x=72a6951ba697a82d", + "__REALTIME_TIMESTAMP" : "1604690191334135", + "__MONOTONIC_TIMESTAMP" : "1497330551", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "PRIORITY" : "5", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "3216", + "CODE_FUNC" : "service_sigchld_event", + "MESSAGE" : "bootkube.service: Main process exited, code=exited, status=127/n/a", + "EXIT_CODE" : "exited", + "EXIT_STATUS" : "127", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191334126" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11cc;b=d87bb9b0bf4e418badc5b2a5762d823a;m=593f7432;t=5b3750cd43bb2;x=e418aea7132d34e0", + "__REALTIME_TIMESTAMP" : "1604690191334322", + "__MONOTONIC_TIMESTAMP" : "1497330738", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "4", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "CODE_LINE" : "1683", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_FUNC" : "service_enter_dead", + "MESSAGE" : "bootkube.service: Failed with result 'exit-code'.", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690191334314" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11cd;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598e2e3e;t=5b3750d22f5be;x=9492525567447af8", + "__REALTIME_TIMESTAMP" : "1604690196493758", + "__MONOTONIC_TIMESTAMP" : "1502490174", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "3532", + "CODE_FUNC" : "service_dispatch_timer", + "MESSAGE" : "bootkube.service: Service RestartSec=5s expired, scheduling restart.", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196493742" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11ce;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598e2ff5;t=5b3750d22f775;x=513a85f2f6b632aa", + "__REALTIME_TIMESTAMP" : "1604690196494197", + "__MONOTONIC_TIMESTAMP" : "1502490613", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "2147", + "CODE_FUNC" : "service_enter_restart", + "MESSAGE_ID" : "5eb03494b6584870a536b337290809b3", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "MESSAGE" : "bootkube.service: Scheduled restart job, restart counter is at 278.", + "N_RESTARTS" : "278", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196494129" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11cf;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598e3156;t=5b3750d22f8d5;x=ddc8f54f297e172b", + "__REALTIME_TIMESTAMP" : "1604690196494549", + "__MONOTONIC_TIMESTAMP" : "1502490966", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "CODE_FILE" : "../src/core/job.c", + "CODE_LINE" : "827", + "CODE_FUNC" : "job_log_status_message", + "SYSLOG_IDENTIFIER" : "systemd", + "JOB_RESULT" : "done", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "MESSAGE_ID" : "9d1aaa27d60140bd96365438aad20286", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "MESSAGE" : "Stopped Bootstrap a Kubernetes cluster.", + "JOB_TYPE" : "restart", + "INVOCATION_ID" : "76e11720db5940948eb008a8eab2d5c0", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196494269" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11d0;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598e39dd;t=5b3750d23015d;x=c985b3968c937b83", + "__REALTIME_TIMESTAMP" : "1604690196496733", + "__MONOTONIC_TIMESTAMP" : "1502493149", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "CODE_FILE" : "../src/core/job.c", + "CODE_LINE" : "827", + "CODE_FUNC" : "job_log_status_message", + "SYSLOG_IDENTIFIER" : "systemd", + "JOB_TYPE" : "start", + "JOB_RESULT" : "done", + "MESSAGE_ID" : "39f53479d3a045ac8e11786248231fbf", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "MESSAGE" : "Started Bootstrap a Kubernetes cluster.", + "UNIT" : "bootkube.service", + "INVOCATION_ID" : "65231f59bdf84a7497c30ac4a09e6f2c", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196496016" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11d1;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598f84de;t=5b3750d244c5d;x=2709ebb1da03d4f2", + "__REALTIME_TIMESTAMP" : "1604690196581469", + "__MONOTONIC_TIMESTAMP" : "1502577886", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "6", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_SYSTEMD_SLICE" : "system.slice", + "_TRANSPORT" : "stdout", + "_EXE" : "/usr/bin/bash", + "_CAP_EFFECTIVE" : "3fffffffff", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_COMM" : "bash", + "SYSLOG_IDENTIFIER" : "bootkube.sh", + "MESSAGE" : "/usr/local/bin/bootkube.sh: line 6: i-am-a-command-that-does-not-exist: command not found", + "_CMDLINE" : "bash /usr/local/bin/bootkube.sh", + "_SYSTEMD_UNIT" : "bootkube.service", + "_SYSTEMD_CGROUP" : "/system.slice/bootkube.service", + "_STREAM_ID" : "01685a93fb9a41ee99699f6f450ef3bd", + "_PID" : "15950", + "_SYSTEMD_INVOCATION_ID" : "65231f59bdf84a7497c30ac4a09e6f2c" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11d2;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598f8757;t=5b3750d244ed7;x=25b5b1f488146de1", + "__REALTIME_TIMESTAMP" : "1604690196582103", + "__MONOTONIC_TIMESTAMP" : "1502578519", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "PRIORITY" : "5", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_LINE" : "3216", + "CODE_FUNC" : "service_sigchld_event", + "MESSAGE" : "bootkube.service: Main process exited, code=exited, status=127/n/a", + "EXIT_CODE" : "exited", + "EXIT_STATUS" : "127", + "INVOCATION_ID" : "65231f59bdf84a7497c30ac4a09e6f2c", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196582095" +} +{ + "__CURSOR" : "s=74ca9654289b49dc904ebc649cc80943;i=11d3;b=d87bb9b0bf4e418badc5b2a5762d823a;m=598f8835;t=5b3750d244fb5;x=2a021d7682aad7f", + "__REALTIME_TIMESTAMP" : "1604690196582325", + "__MONOTONIC_TIMESTAMP" : "1502578741", + "_BOOT_ID" : "d87bb9b0bf4e418badc5b2a5762d823a", + "_MACHINE_ID" : "ec207e03c25f54405b7e8b2f0280b4e1", + "PRIORITY" : "4", + "SYSLOG_FACILITY" : "3", + "_UID" : "0", + "_GID" : "0", + "_CAP_EFFECTIVE" : "3fffffffff", + "SYSLOG_IDENTIFIER" : "systemd", + "_TRANSPORT" : "journal", + "_PID" : "1", + "_COMM" : "systemd", + "_EXE" : "/usr/lib/systemd/systemd", + "_SYSTEMD_CGROUP" : "/init.scope", + "_SYSTEMD_UNIT" : "init.scope", + "_SYSTEMD_SLICE" : "-.slice", + "CODE_LINE" : "1683", + "_HOSTNAME" : "ip-10-0-4-236", + "_SELINUX_CONTEXT" : "system_u:system_r:init_t:s0", + "_CMDLINE" : "/usr/lib/systemd/systemd --switched-root --system --deserialize 16", + "UNIT" : "bootkube.service", + "CODE_FILE" : "../src/core/service.c", + "CODE_FUNC" : "service_enter_dead", + "MESSAGE" : "bootkube.service: Failed with result 'exit-code'.", + "INVOCATION_ID" : "65231f59bdf84a7497c30ac4a09e6f2c", + "_SOURCE_REALTIME_TIMESTAMP" : "1604690196582317" +} +` + +func TestLog(t *testing.T) { + log, err := NewLog(strings.NewReader(data)) + if err != nil { + t.Fatal(err) + } + + t.Run("Restarts", func(t *testing.T) { + expected := 278 + actual := log.Restarts("bootkube.service") + if actual != expected { + t.Fatalf("got %d , expected %d", actual, expected) + } + }) + + t.Run("Format", func(t *testing.T) { + t.Run("all invocations", func(t *testing.T) { + expected := []string{ + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Service RestartSec=5s expired, scheduling restart.", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Scheduled restart job, restart counter is at 277.", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: Stopped Bootstrap a Kubernetes cluster.", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: Started Bootstrap a Kubernetes cluster.", + "2020-11-06T19:16:31Z ip-10-0-4-236 bootkube.sh[15907]: /usr/local/bin/bootkube.sh: line 6: i-am-a-command-that-does-not-exist: command not found", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Main process exited, code=exited, status=127/n/a", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Failed with result 'exit-code'.", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Service RestartSec=5s expired, scheduling restart.", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Scheduled restart job, restart counter is at 278.", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: Stopped Bootstrap a Kubernetes cluster.", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: Started Bootstrap a Kubernetes cluster.", + "2020-11-06T19:16:36Z ip-10-0-4-236 bootkube.sh[15950]: /usr/local/bin/bootkube.sh: line 6: i-am-a-command-that-does-not-exist: command not found", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Main process exited, code=exited, status=127/n/a", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Failed with result 'exit-code'.", + } + actual := log.Format("bootkube.service", 0) + assertStringArraysEqual(t, actual, expected) + }) + + t.Run("positive invocations", func(t *testing.T) { + expected := []string{ + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Service RestartSec=5s expired, scheduling restart.", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: bootkube.service: Scheduled restart job, restart counter is at 277.", + "2020-11-06T19:16:31Z ip-10-0-4-236 systemd[1]: Stopped Bootstrap a Kubernetes cluster.", + } + actual := log.Format("bootkube.service", 1) + assertStringArraysEqual(t, actual, expected) + }) + + t.Run("negative invocations", func(t *testing.T) { + expected := []string{ + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: Started Bootstrap a Kubernetes cluster.", + "2020-11-06T19:16:36Z ip-10-0-4-236 bootkube.sh[15950]: /usr/local/bin/bootkube.sh: line 6: i-am-a-command-that-does-not-exist: command not found", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Main process exited, code=exited, status=127/n/a", + "2020-11-06T19:16:36Z ip-10-0-4-236 systemd[1]: bootkube.service: Failed with result 'exit-code'.", + } + actual := log.Format("bootkube.service", -1) + assertStringArraysEqual(t, actual, expected) + }) + }) +} + +func assertStringArraysEqual(t *testing.T, actual, expected []string) { + for i, e := range expected { + if i >= len(actual) { + t.Fatalf("no actual line %d, expected %q", i, e) + } else if actual[i] != e { + t.Fatalf("line %d: got %q , expected %q", i, actual[i], e) + } + } + if len(actual) > len(expected) { + t.Fatalf("unexpected line %d: %q", len(expected), actual[len(expected)]) + } +}