podman

1
//go:build !remote && linux && systemd
2

3
package libpod
4

5
import (
6
	"context"
7
	"errors"
8
	"fmt"
9
	"strconv"
10
	"strings"
11
	"time"
12

13
	"github.com/containers/podman/v5/libpod/define"
14
	"github.com/containers/podman/v5/libpod/events"
15
	"github.com/containers/podman/v5/libpod/logs"
16
	"github.com/containers/podman/v5/pkg/rootless"
17
	"github.com/coreos/go-systemd/v22/sdjournal"
18
	"github.com/sirupsen/logrus"
19
)
20

21
const (
22
	// journaldLogOut is the journald priority signifying stdout
23
	journaldLogOut = "6"
24

25
	// journaldLogErr is the journald priority signifying stderr
26
	journaldLogErr = "3"
27
)
28

29
func init() {
30
	logDrivers = append(logDrivers, define.JournaldLogging)
31
}
32

33
func (c *Container) readFromJournal(ctx context.Context, options *logs.LogOptions,
34
	logChannel chan *logs.LogLine, colorID int64, passthroughUnit string) error {
35
	// We need the container's events in the same journal to guarantee
36
	// consistency, see #10323.
37
	if options.Follow && c.runtime.config.Engine.EventsLogger != "journald" {
38
		return fmt.Errorf("using --follow with the journald --log-driver but without the journald --events-backend (%s) is not supported", c.runtime.config.Engine.EventsLogger)
39
	}
40

41
	journal, err := sdjournal.NewJournal()
42
	if err != nil {
43
		return err
44
	}
45
	// While logs are written to the `logChannel`, we inspect each event
46
	// and stop once the container has died.  Having logs and events in one
47
	// stream prevents a race condition that we faced in #10323.
48

49
	// Add the filters for events.
50
	match := sdjournal.Match{Field: "SYSLOG_IDENTIFIER", Value: "podman"}
51
	if err := journal.AddMatch(match.String()); err != nil {
52
		return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
53
	}
54
	match = sdjournal.Match{Field: "PODMAN_ID", Value: c.ID()}
55
	if err := journal.AddMatch(match.String()); err != nil {
56
		return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
57
	}
58
	// Make sure we only read events for the current user, while it is unlikely that there
59
	// is a container ID duplication for two users, it is better to have it just in case.
60
	uidMatch := sdjournal.Match{Field: "_UID", Value: strconv.Itoa(rootless.GetRootlessUID())}
61
	if err := journal.AddMatch(uidMatch.String()); err != nil {
62
		return fmt.Errorf("adding filter to journald logger: %v: %w", uidMatch, err)
63
	}
64

65
	// Add the filter for logs.  Note the disjunction so that we match
66
	// either the events or the logs.
67
	if err := journal.AddDisjunction(); err != nil {
68
		return fmt.Errorf("adding filter disjunction to journald logger: %w", err)
69
	}
70

71
	if passthroughUnit != "" {
72
		// Match based on systemd unit which is the container is cgroup
73
		// so we get the exact logs for a single container even in the
74
		// play kube case where a single unit starts more than one container.
75
		unitTypeName := "_SYSTEMD_UNIT"
76
		if rootless.IsRootless() {
77
			unitTypeName = "_SYSTEMD_USER_UNIT"
78
		}
79
		// By default we will have our own systemd cgroup with the name libpod-<ID>.scope.
80
		value := "libpod-" + c.ID() + ".scope"
81
		if c.config.CgroupsMode == cgroupSplit {
82
			// If cgroup split the container runs in the unit cgroup so we use this for logs,
83
			// the good thing is we filter the podman events already out below.
84
			// Thus we are left with the real container log and possibly podman output (e.g. logrus).
85
			value = passthroughUnit
86
		}
87

88
		match = sdjournal.Match{Field: unitTypeName, Value: value}
89
		if err := journal.AddMatch(match.String()); err != nil {
90
			return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
91
		}
92
	} else {
93
		match = sdjournal.Match{Field: "CONTAINER_ID_FULL", Value: c.ID()}
94
		if err := journal.AddMatch(match.String()); err != nil {
95
			return fmt.Errorf("adding filter to journald logger: %v: %w", match, err)
96
		}
97
	}
98

99
	if err := journal.AddMatch(uidMatch.String()); err != nil {
100
		return fmt.Errorf("adding filter to journald logger: %v: %w", uidMatch, err)
101
	}
102

103
	if options.Since.IsZero() {
104
		if err := journal.SeekHead(); err != nil {
105
			return err
106
		}
107
	} else {
108
		// seek based on time which helps to reduce unnecessary event reads
109
		if err := journal.SeekRealtimeUsec(uint64(options.Since.UnixMicro())); err != nil {
110
			return err
111
		}
112
	}
113

114
	c.lock.Lock()
115
	if err := c.syncContainer(); err != nil {
116
		c.lock.Unlock()
117
		return err
118
	}
119
	// The initial "containerCouldBeLogging" state must be correct, we cannot rely on the start event being still in the journal.
120
	// This can happen if the journal was rotated after the container was started or when --since is used.
121
	// https://github.com/containers/podman/issues/16950
122
	containerCouldBeLogging := c.ensureState(define.ContainerStateRunning, define.ContainerStateStopping)
123
	c.lock.Unlock()
124

125
	options.WaitGroup.Add(1)
126
	go func() {
127
		defer func() {
128
			options.WaitGroup.Done()
129
			if err := journal.Close(); err != nil {
130
				logrus.Errorf("Unable to close journal: %v", err)
131
			}
132
		}()
133

134
		tailQueue := []*logs.LogLine{} // needed for options.Tail
135
		doTail := options.Tail >= 0
136
		doTailFunc := func() {
137
			// Flush *once* we hit the end of the journal.
138
			startIndex := int64(len(tailQueue))
139
			outputLines := int64(0)
140
			for startIndex > 0 && outputLines < options.Tail {
141
				startIndex--
142
				for startIndex > 0 && tailQueue[startIndex].Partial() {
143
					startIndex--
144
				}
145
				outputLines++
146
			}
147
			for i := startIndex; i < int64(len(tailQueue)); i++ {
148
				logChannel <- tailQueue[i]
149
			}
150
			tailQueue = nil
151
			doTail = false
152
		}
153
		for {
154
			entry, err := events.GetNextEntry(ctx, journal, !doTail && options.Follow && containerCouldBeLogging, options.Until)
155
			if err != nil {
156
				logrus.Errorf("Failed to get journal entry: %v", err)
157
				return
158
			}
159
			// entry nil == EOF in journal
160
			if entry == nil {
161
				if doTail {
162
					doTailFunc()
163
					continue
164
				}
165
				return
166
			}
167

168
			entryTime := time.Unix(0, int64(entry.RealtimeTimestamp)*int64(time.Microsecond))
169
			if (entryTime.Before(options.Since) && !options.Since.IsZero()) || (entryTime.After(options.Until) && !options.Until.IsZero()) {
170
				continue
171
			}
172
			// If we're reading an event and the container exited/died,
173
			// then we're done and can return.
174
			event, ok := entry.Fields["PODMAN_EVENT"]
175
			if ok {
176
				status, err := events.StringToStatus(event)
177
				if err != nil {
178
					logrus.Errorf("Failed to translate event: %v", err)
179
					return
180
				}
181
				switch status {
182
				case events.History, events.Init, events.Start, events.Restart:
183
					containerCouldBeLogging = true
184
				case events.Exited:
185
					containerCouldBeLogging = false
186
				}
187
				continue
188
			}
189

190
			logLine, err := journalToLogLine(entry)
191
			if err != nil {
192
				logrus.Errorf("Failed parse journal entry: %v", err)
193
				return
194
			}
195
			id := c.ID()
196
			if len(id) > 12 {
197
				id = id[:12]
198
			}
199
			logLine.CID = id
200
			logLine.ColorID = colorID
201
			if options.UseName {
202
				logLine.CName = c.Name()
203
			}
204
			if doTail {
205
				tailQueue = append(tailQueue, logLine)
206
				continue
207
			}
208
			logChannel <- logLine
209
		}
210
	}()
211

212
	return nil
213
}
214

215
func journalToLogLine(entry *sdjournal.JournalEntry) (*logs.LogLine, error) {
216
	line := &logs.LogLine{}
217

218
	usec := entry.RealtimeTimestamp
219
	line.Time = time.Unix(0, int64(usec)*int64(time.Microsecond))
220

221
	priority, ok := entry.Fields["PRIORITY"]
222
	if !ok {
223
		return nil, errors.New("no PRIORITY field present in journal entry")
224
	}
225
	switch priority {
226
	case journaldLogOut:
227
		line.Device = "stdout"
228
	case journaldLogErr:
229
		line.Device = "stderr"
230
	default:
231
		return nil, errors.New("unexpected PRIORITY field in journal entry")
232
	}
233

234
	// if CONTAINER_PARTIAL_MESSAGE is defined, the log type is "P"
235
	if _, ok := entry.Fields["CONTAINER_PARTIAL_MESSAGE"]; ok {
236
		line.ParseLogType = logs.PartialLogType
237
	} else {
238
		line.ParseLogType = logs.FullLogType
239
	}
240

241
	line.Msg, ok = entry.Fields["MESSAGE"]
242
	if !ok {
243
		return nil, errors.New("no MESSAGE field present in journal entry")
244
	}
245
	line.Msg = strings.TrimSuffix(line.Msg, "\n")
246

247
	return line, nil
248
}
249