main: journald support with external correlation

.gitignore

@@ -7,6 +7,8 @@ __pycache__
 /containers/config/
 /bin
 /rpmbuild
+/osbuild-composer
+/osbuild-worker
 
 /tools/appsre-ansible/inventory
 

HACKING.md

@@ -6,6 +6,8 @@
 onto a system. We recommend doing this by building rpms, with:
 
 ```
+dnf install fedora-packager
+dnf builddep osbuild-composer
 make rpm
 ```
 
@@ -94,4 +96,22 @@ To rebuild the containers after a change, add the `--build` flag to the `docker-
 
 ```
 docker-compose up --build
-```
+```
+
+## Shortening the loop
+
+For some components, it is possible to install distribution packages first and then only to replace binaries which may or may not work for smaller changes.
+
+```
+systemctl stop osbuild-composer.service osbuild-composer.socket osbuild-local-worker.socket
+make build && sudo install -m755 bin/osbuild-composer bin/osbuild-worker /usr/libexec/osbuild-composer/
+systemctl start osbuild-composer.socket osbuild-local-worker.socket
+```
+
+## Accessing Cloud API
+
+You can use curl to access the Cloud API:
+
+```
+curl --unix-socket /run/cloudapi/api.socket -XGET http://localhost/api/image-builder-composer/v2/openapi
+```

cmd/osbuild-composer/config.go

@@ -129,7 +129,7 @@ func GetDefaultConfig() *ComposerConfigFile {
 			"rhel-10": "rhel-10.0",
 		},
 		LogLevel:  "info",
-		LogFormat: "text",
+		LogFormat: "journal",
 		DNFJson:   "/usr/libexec/osbuild-depsolve-dnf",
 	}
 }

cmd/osbuild-composer/config_test.go

@@ -77,7 +77,7 @@ func TestDefaultConfig(t *testing.T) {
 	}
 	require.Equal(t, expectedDistroAliases, defaultConfig.DistroAliases)
 
-	require.Equal(t, "text", defaultConfig.LogFormat)
+	require.Equal(t, "journal", defaultConfig.LogFormat)
 }
 
 func TestConfig(t *testing.T) {

cmd/osbuild-composer/main.go

@@ -3,11 +3,15 @@ package main
 import (
 	"context"
 	"flag"
+	"io"
+	"log"
 	"os"
 
 	"github.com/coreos/go-systemd/activation"
+	"github.com/coreos/go-systemd/journal"
 	"github.com/getsentry/sentry-go"
 	sentrylogrus "github.com/getsentry/sentry-go/logrus"
+	"github.com/osbuild/osbuild-composer/internal/common"
 	slogger "github.com/osbuild/osbuild-composer/pkg/splunk_logger"
 	"github.com/sirupsen/logrus"
 )
@@ -28,6 +32,11 @@ func main() {
 	flag.BoolVar(&verbose, "verbose", false, "Print access log")
 	flag.Parse()
 
+	// Redirect Go standard logger into logrus before it's used by other packages
+	log.SetOutput(common.Logger())
+	// Ensure the Go standard logger does not have any prefix or timestamp
+	log.SetFlags(0)
+
 	if !verbose {
 		logrus.Print("verbose flag is provided for backward compatibility only, current behavior is always printing the access log")
 	}
@@ -41,6 +50,8 @@ func main() {
 	logLevel, err := logrus.ParseLevel(config.LogLevel)
 
 	logrus.SetReportCaller(true)
+	// Add context hook to log operation_id and external_id
+	logrus.AddHook(&common.ContextHook{})
 
 	if err == nil {
 		logrus.SetLevel(logLevel)
@@ -49,6 +60,16 @@ func main() {
 	}
 
 	switch config.LogFormat {
+	case "journal":
+		// If we are running under systemd, use the journal. Otherwise,
+		// fallback to text formatter.
+		if journal.Enabled() {
+			logrus.SetFormatter(&logrus.JSONFormatter{})
+			logrus.AddHook(&common.JournalHook{})
+			logrus.SetOutput(io.Discard)
+		} else {
+			logrus.SetFormatter(&logrus.TextFormatter{})
+		}
 	case "text":
 		logrus.SetFormatter(&logrus.TextFormatter{})
 	case "json":

internal/cloudapi/v2/server.go

@@ -87,10 +87,37 @@ func (s *Server) Handler(path string) http.Handler {
 	e := echo.New()
 	e.Binder = binder{}
 	e.HTTPErrorHandler = s.HTTPErrorHandler
-	e.Pre(common.OperationIDMiddleware)
-	e.Use(middleware.Recover())
 	e.Logger = common.Logger()
 
+	// OperationIDMiddleware - generates OperationID random string and puts it into the contexts
+	// ExternalIDMiddleware - extracts ID from HTTP header and puts it into the contexts
+	// LoggerMiddleware - creates context-aware logger for each request
+	e.Pre(common.OperationIDMiddleware, common.ExternalIDMiddleware, common.LoggerMiddleware)
+	e.Use(middleware.Recover())
+
+	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
+		LogURI:     true,
+		LogStatus:  true,
+		LogLatency: true,
+		LogMethod:  true,
+		LogValuesFunc: func(c echo.Context, values middleware.RequestLoggerValues) error {
+			fields := logrus.Fields{
+				"uri":          values.URI,
+				"method":       values.Method,
+				"status":       values.Status,
+				"latency_ms":   values.Latency.Milliseconds(),
+				"operation_id": c.Get(common.OperationIDKey),
+				"external_id":  c.Get(common.ExternalIDKey),
+			}
+			if values.Error != nil {
+				fields["error"] = values.Error
+			}
+			logrus.WithFields(fields).Infof("Processed request %s %s", values.Method, values.URI)
+
+			return nil
+		},
+	}))
+
 	if sentry.CurrentHub().Client() == nil {
 		logrus.Warn("Sentry/Glitchtip not initialized, echo middleware was not enabled")
 	} else {

internal/common/context_hook.go

@@ -0,0 +1,33 @@
+package common
+
+import (
+	"github.com/sirupsen/logrus"
+)
+
+type ContextHook struct{}
+
+func (h *ContextHook) Levels() []logrus.Level {
+	return []logrus.Level{
+		logrus.DebugLevel,
+		logrus.InfoLevel,
+		logrus.WarnLevel,
+		logrus.ErrorLevel,
+		logrus.FatalLevel,
+		logrus.PanicLevel,
+	}
+}
+
+func (h *ContextHook) Fire(e *logrus.Entry) error {
+	if e.Context == nil {
+		return nil
+	}
+
+	if val := e.Context.Value(operationIDKeyCtx); val != nil {
+		e.Data["operation_id"] = val
+	}
+	if val := e.Context.Value(externalIDKeyCtx); val != nil {
+		e.Data["external_id"] = val
+	}
+
+	return nil
+}

internal/common/echo_logrus.go

@@ -1,39 +1,42 @@
 package common
 
 import (
+	"context"
 	"encoding/json"
 	"io"
 
-	"github.com/labstack/gommon/log"
+	lslog "github.com/labstack/gommon/log"
 	"github.com/sirupsen/logrus"
 )
 
 // EchoLogrusLogger extend logrus.Logger
 type EchoLogrusLogger struct {
 	*logrus.Logger
+	Ctx context.Context
 }
 
 var commonLogger = &EchoLogrusLogger{
 	Logger: logrus.StandardLogger(),
+	Ctx:    context.Background(),
 }
 
 func Logger() *EchoLogrusLogger {
 	return commonLogger
 }
 
-func toEchoLevel(level logrus.Level) log.Lvl {
+func toEchoLevel(level logrus.Level) lslog.Lvl {
 	switch level {
 	case logrus.DebugLevel:
-		return log.DEBUG
+		return lslog.DEBUG
 	case logrus.InfoLevel:
-		return log.INFO
+		return lslog.INFO
 	case logrus.WarnLevel:
-		return log.WARN
+		return lslog.WARN
 	case logrus.ErrorLevel:
-		return log.ERROR
+		return lslog.ERROR
 	}
 
-	return log.OFF
+	return lslog.OFF
 }
 
 func (l *EchoLogrusLogger) Output() io.Writer {
@@ -44,11 +47,11 @@ func (l *EchoLogrusLogger) SetOutput(w io.Writer) {
 	// disable operations that would change behavior of global logrus logger.
 }
 
-func (l *EchoLogrusLogger) Level() log.Lvl {
+func (l *EchoLogrusLogger) Level() lslog.Lvl {
 	return toEchoLevel(l.Logger.Level)
 }
 
-func (l *EchoLogrusLogger) SetLevel(v log.Lvl) {
+func (l *EchoLogrusLogger) SetLevel(v lslog.Lvl) {
 	// disable operations that would change behavior of global logrus logger.
 }
 
@@ -63,113 +66,117 @@ func (l *EchoLogrusLogger) SetPrefix(p string) {
 }
 
 func (l *EchoLogrusLogger) Print(i ...interface{}) {
-	l.Logger.Print(i...)
+	l.Logger.WithContext(l.Ctx).Print(i...)
 }
 
 func (l *EchoLogrusLogger) Printf(format string, args ...interface{}) {
-	l.Logger.Printf(format, args...)
+	l.Logger.WithContext(l.Ctx).Printf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Printj(j log.JSON) {
+func (l *EchoLogrusLogger) Printj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Println(string(b))
+	l.Logger.WithContext(l.Ctx).Println(string(b))
 }
 
 func (l *EchoLogrusLogger) Debug(i ...interface{}) {
-	l.Logger.Debug(i...)
+	l.Logger.WithContext(l.Ctx).Debug(i...)
 }
 
 func (l *EchoLogrusLogger) Debugf(format string, args ...interface{}) {
-	l.Logger.Debugf(format, args...)
+	l.Logger.WithContext(l.Ctx).Debugf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Debugj(j log.JSON) {
+func (l *EchoLogrusLogger) Debugj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Debugln(string(b))
+	l.Logger.WithContext(l.Ctx).Debugln(string(b))
 }
 
 func (l *EchoLogrusLogger) Info(i ...interface{}) {
-	l.Logger.Info(i...)
+	l.Logger.WithContext(l.Ctx).Info(i...)
 }
 
 func (l *EchoLogrusLogger) Infof(format string, args ...interface{}) {
-	l.Logger.Infof(format, args...)
+	l.Logger.WithContext(l.Ctx).Infof(format, args...)
 }
 
-func (l *EchoLogrusLogger) Infoj(j log.JSON) {
+func (l *EchoLogrusLogger) Infoj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Infoln(string(b))
+	l.Logger.WithContext(l.Ctx).Infoln(string(b))
 }
 
 func (l *EchoLogrusLogger) Warn(i ...interface{}) {
-	l.Logger.Warn(i...)
+	l.Logger.WithContext(l.Ctx).Warn(i...)
 }
 
 func (l *EchoLogrusLogger) Warnf(format string, args ...interface{}) {
-	l.Logger.Warnf(format, args...)
+	l.Logger.WithContext(l.Ctx).Warnf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Warnj(j log.JSON) {
+func (l *EchoLogrusLogger) Warnj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Warnln(string(b))
+	l.Logger.WithContext(l.Ctx).Warnln(string(b))
 }
 
 func (l *EchoLogrusLogger) Error(i ...interface{}) {
-	l.Logger.Error(i...)
+	l.Logger.WithContext(l.Ctx).Error(i...)
 }
 
 func (l *EchoLogrusLogger) Errorf(format string, args ...interface{}) {
-	l.Logger.Errorf(format, args...)
+	l.Logger.WithContext(l.Ctx).Errorf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Errorj(j log.JSON) {
+func (l *EchoLogrusLogger) Errorj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Errorln(string(b))
+	l.Logger.WithContext(l.Ctx).Errorln(string(b))
 }
 
 func (l *EchoLogrusLogger) Fatal(i ...interface{}) {
-	l.Logger.Fatal(i...)
+	l.Logger.WithContext(l.Ctx).Fatal(i...)
 }
 
 func (l *EchoLogrusLogger) Fatalf(format string, args ...interface{}) {
-	l.Logger.Fatalf(format, args...)
+	l.Logger.WithContext(l.Ctx).Fatalf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Fatalj(j log.JSON) {
+func (l *EchoLogrusLogger) Fatalj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Fatalln(string(b))
+	l.Logger.WithContext(l.Ctx).Fatalln(string(b))
 }
 
 func (l *EchoLogrusLogger) Panic(i ...interface{}) {
-	l.Logger.Panic(i...)
+	l.Logger.WithContext(l.Ctx).Panic(i...)
 }
 
 func (l *EchoLogrusLogger) Panicf(format string, args ...interface{}) {
-	l.Logger.Panicf(format, args...)
+	l.Logger.WithContext(l.Ctx).Panicf(format, args...)
 }
 
-func (l *EchoLogrusLogger) Panicj(j log.JSON) {
+func (l *EchoLogrusLogger) Panicj(j lslog.JSON) {
 	b, err := json.Marshal(j)
 	if err != nil {
 		panic(err)
 	}
-	l.Logger.Panicln(string(b))
+	l.Logger.WithContext(l.Ctx).Panicln(string(b))
+}
+
+func (l *EchoLogrusLogger) Write(p []byte) (n int, err error) {
+	return l.Logger.WithContext(l.Ctx).Writer().Write(p)
 }