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
+go build ./cmd/osbuild-composer && cp osbuild-composer /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/composer.go

@@ -402,7 +402,7 @@ func (c *Composer) Start() error {
 func (c *Composer) ensureStateDirectory(name string, perm os.FileMode) (string, error) {
 	d := path.Join(c.stateDir, name)
 
-	err := os.Mkdir(d, perm)
+	err := os.MkdirAll(d, perm)
 	if err != nil && !os.IsExist(err) {
 		return "", fmt.Errorf("cannot create state directory %s: %v", name, err)
 	}

cmd/osbuild-composer/config.go

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

cmd/osbuild-composer/config_test.go

@@ -75,7 +75,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,10 @@ 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.SetFlags(0)
+	log.SetOutput(common.Logger())
+
 	if !verbose {
 		logrus.Print("verbose flag is provided for backward compatibility only, current behavior is always printing the access log")
 	}
@@ -41,6 +49,7 @@ func main() {
 	logLevel, err := logrus.ParseLevel(config.LogLevel)
 
 	logrus.SetReportCaller(true)
+	logrus.AddHook(&common.ContextHook{})
 
 	if err == nil {
 		logrus.SetLevel(logLevel)
@@ -49,6 +58,14 @@ func main() {
 	}
 
 	switch config.LogFormat {
+	case "journal":
+		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/handler.go

@@ -43,6 +43,8 @@ func (b binder) Bind(i interface{}, ctx echo.Context) error {
 }
 
 func (h *apiHandlers) GetOpenapi(ctx echo.Context) error {
+	ctx.Logger().Info("Returning OpenAPI document")
+
 	spec, err := GetSwagger()
 	if err != nil {
 		return HTTPError(ErrorFailedToLoadOpenAPISpec)

internal/cloudapi/v2/server.go

@@ -87,9 +87,31 @@ func (s *Server) Handler(path string) http.Handler {
 	e := echo.New()
 	e.Binder = binder{}
 	e.HTTPErrorHandler = s.HTTPErrorHandler
-	e.Pre(common.OperationIDMiddleware)
+	e.Pre(common.OperationIDMiddleware, common.ExternalIDMiddleware, common.LoggerMiddleware)
 	e.Use(middleware.Recover())
 	e.Logger = common.Logger()
+	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")

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
+}