feat: replace log with slog

- Adds structured logging with slog
- Rust service's messages are now logged in the correct level
- Adds CARTESI_LOG_PRETTY
- Removes CARTESI_LOG_TIMESTAMP
- cartesi-rollups-cli now prints to stdout directly instead of using a logger

.golangci.yml

@@ -11,3 +11,6 @@ linters-settings:
   lll:
     line-length: 100
     tab-width: 4
+  gomnd:
+    ignored-functions:
+      - "^make"

CHANGELOG.md

@@ -6,6 +6,16 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
+## [Unreleased]
+
+### Added
+
+- Added structured logging with slog. Colored logs can now be enabled with `CARTESI_LOG_PRETTY` environment variable.
+
+### Removed
+
+- Removed `CARTESI_LOG_TIMESTAMP` environment variable
+
 ## [1.3.0] 2024-02-09
 
 ### Added

build/compose-node.yaml

@@ -12,7 +12,7 @@ services:
       - "10000:10000" # Supervisor
     environment:
       CARTESI_LOG_LEVEL: "info"
-      CARTESI_LOG_TIMESTAMP: "false"
+      CARTESI_LOG_PRETTY: "true"
       CARTESI_FEATURE_HOST_MODE: "false"
       CARTESI_FEATURE_DISABLE_CLAIMER: "false"
       CARTESI_HTTP_ADDRESS: "0.0.0.0"

cmd/cartesi-rollups-cli/root/deps/deps.go

@@ -5,10 +5,10 @@ package deps
 
 import (
 	"context"
+	"fmt"
 	"os/signal"
 	"syscall"
 
-	"github.com/cartesi/rollups-node/internal/config"
 	"github.com/cartesi/rollups-node/internal/deps"
 	"github.com/spf13/cobra"
 )
@@ -55,7 +55,7 @@ func run(cmd *cobra.Command, args []string) {
 	depsContainers, err := deps.Run(ctx, *depsConfig)
 	cobra.CheckErr(err)
 
-	config.InfoLogger.Println("all deps are up")
+	fmt.Println("all deps are up")
 
 	<-ctx.Done()
 

cmd/cartesi-rollups-cli/root/execute/execute.go

@@ -4,10 +4,10 @@
 package execute
 
 import (
+	"fmt"
 	"os"
 
 	"github.com/Khan/genqlient/graphql"
-	"github.com/cartesi/rollups-node/internal/config"
 	"github.com/cartesi/rollups-node/pkg/addresses"
 	"github.com/cartesi/rollups-node/pkg/ethutil"
 	"github.com/cartesi/rollups-node/pkg/readerclient"
@@ -70,13 +70,13 @@ func run(cmd *cobra.Command, args []string) {
 	cobra.CheckErr(err)
 
 	if resp.Proof == nil {
-		config.InfoLogger.Printf("The voucher has no associated proof yet.\n")
+		fmt.Println("The voucher has no associated proof yet")
 		os.Exit(0)
 	}
 
 	client, err := ethclient.DialContext(ctx, ethEndpoint)
 	cobra.CheckErr(err)
-	config.InfoLogger.Printf("connected to %v\n", ethEndpoint)
+	fmt.Printf("connected to %v\n", ethEndpoint)
 
 	signer, err := ethutil.NewMnemonicSigner(ctx, client, mnemonic, account)
 	cobra.CheckErr(err)
@@ -91,7 +91,7 @@ func run(cmd *cobra.Command, args []string) {
 
 	proof := readerclient.ConvertToContractProof(resp.Proof)
 
-	config.InfoLogger.Printf("executing voucher %d from input %d\n",
+	fmt.Printf("executing voucher %d from input %d\n",
 		voucherIndex,
 		inputIndex,
 	)
@@ -106,5 +106,5 @@ func run(cmd *cobra.Command, args []string) {
 	)
 	cobra.CheckErr(err)
 
-	config.InfoLogger.Printf("The voucher was executed! (tx=%v)\n", txHash)
+	fmt.Printf("The voucher was executed! (tx=%v)\n", txHash)
 }

cmd/cartesi-rollups-cli/root/savesnapshot/savesnapshot.go

@@ -37,8 +37,6 @@ func init() {
 }
 
 func run(cmd *cobra.Command, args []string) {
-
 	err := machine.Save(sourceDockerImage, destDir, tempContainerName)
-
 	cobra.CheckErr(err)
 }

cmd/cartesi-rollups-cli/root/send/send.go

@@ -4,7 +4,8 @@
 package send
 
 import (
-	"github.com/cartesi/rollups-node/internal/config"
+	"fmt"
+
 	"github.com/cartesi/rollups-node/pkg/addresses"
 	"github.com/cartesi/rollups-node/pkg/ethutil"
 	"github.com/ethereum/go-ethereum/common/hexutil"
@@ -56,7 +57,7 @@ func run(cmd *cobra.Command, args []string) {
 	ctx := cmd.Context()
 	client, err := ethclient.DialContext(ctx, ethEndpoint)
 	cobra.CheckErr(err)
-	config.InfoLogger.Printf("connected to %v", ethEndpoint)
+	fmt.Printf("connected to %v\n", ethEndpoint)
 
 	signer, err := ethutil.NewMnemonicSigner(ctx, client, mnemonic, account)
 	cobra.CheckErr(err)
@@ -69,9 +70,9 @@ func run(cmd *cobra.Command, args []string) {
 		book = addresses.GetTestBook()
 	}
 
-	config.InfoLogger.Printf("sending input to %x", book.CartesiDApp)
+	fmt.Printf("sending input to %x\n", book.CartesiDApp)
 	inputIndex, err := ethutil.AddInput(ctx, client, book, signer, payload)
 	cobra.CheckErr(err)
 
-	config.InfoLogger.Printf("added input with index %v", inputIndex)
+	fmt.Printf("added input with index %v\n", inputIndex)
 }

cmd/cartesi-rollups-cli/root/validate/validate.go

@@ -4,10 +4,10 @@
 package validate
 
 import (
+	"fmt"
 	"os"
 
 	"github.com/Khan/genqlient/graphql"
-	"github.com/cartesi/rollups-node/internal/config"
 	"github.com/cartesi/rollups-node/pkg/addresses"
 	"github.com/cartesi/rollups-node/pkg/ethutil"
 	"github.com/cartesi/rollups-node/pkg/readerclient"
@@ -62,13 +62,13 @@ func run(cmd *cobra.Command, args []string) {
 	cobra.CheckErr(err)
 
 	if resp.Proof == nil {
-		config.InfoLogger.Printf("The notice has no associated proof yet.\n")
+		fmt.Println("The notice has no associated proof yet.")
 		os.Exit(0)
 	}
 
 	client, err := ethclient.DialContext(ctx, ethEndpoint)
 	cobra.CheckErr(err)
-	config.InfoLogger.Printf("connected to %v\n", ethEndpoint)
+	fmt.Printf("connected to %v\n", ethEndpoint)
 
 	var book *addresses.Book
 	if addressBookFile != "" {
@@ -80,13 +80,13 @@ func run(cmd *cobra.Command, args []string) {
 
 	proof := readerclient.ConvertToContractProof(resp.Proof)
 
-	config.InfoLogger.Printf("validating notice %d from input %d with address %x\n",
+	fmt.Printf("validating notice %d from input %d with address %x\n",
 		noticeIndex,
 		inputIndex,
 		book.CartesiDApp,
 	)
 	err = ethutil.ValidateNotice(ctx, client, book, resp.Payload, proof)
 	cobra.CheckErr(err)
 
-	config.InfoLogger.Printf("The notice is valid!\n")
+	fmt.Println("The notice is valid!")
 }

cmd/cartesi-rollups-node/handlers.go

@@ -5,9 +5,11 @@ package main
 
 import (
 	"fmt"
+	"log/slog"
 	"net/http"
 	"net/http/httputil"
 	"net/url"
+	"os"
 
 	"github.com/cartesi/rollups-node/internal/config"
 )
@@ -21,7 +23,8 @@ func newHttpServiceHandler(nodeConfig config.NodeConfig) http.Handler {
 		getPort(nodeConfig.CartesiHttpPort, portOffsetGraphQLServer),
 	)
 	if err != nil {
-		config.ErrorLogger.Fatal(err)
+		slog.Error(err.Error())
+		os.Exit(1)
 	}
 	handler.Handle("/graphql", graphqlProxy)
 
@@ -30,7 +33,8 @@ func newHttpServiceHandler(nodeConfig config.NodeConfig) http.Handler {
 		getPort(nodeConfig.CartesiHttpPort, portOffsetDispatcher),
 	)
 	if err != nil {
-		config.ErrorLogger.Fatal(err)
+		slog.Error(err.Error())
+		os.Exit(1)
 	}
 	handler.Handle("/metrics", dispatcherProxy)
 
@@ -39,7 +43,8 @@ func newHttpServiceHandler(nodeConfig config.NodeConfig) http.Handler {
 		getPort(nodeConfig.CartesiHttpPort, portOffsetInspectServer),
 	)
 	if err != nil {
-		config.ErrorLogger.Fatal(err)
+		slog.Error(err.Error())
+		os.Exit(1)
 	}
 	handler.Handle("/inspect", inspectProxy)
 	handler.Handle("/inspect/", inspectProxy)
@@ -50,15 +55,16 @@ func newHttpServiceHandler(nodeConfig config.NodeConfig) http.Handler {
 			getPort(nodeConfig.CartesiHttpPort, portOffsetHostRunnerRollups),
 		)
 		if err != nil {
-			config.ErrorLogger.Fatal(err)
+			slog.Error(err.Error())
+			os.Exit(1)
 		}
 		handler.Handle("/rollup/", http.StripPrefix("/rollup", hostProxy))
 	}
 	return handler
 }
 
 func healthcheckHandler(w http.ResponseWriter, r *http.Request) {
-	config.DebugLogger.Println("received healthcheck request")
+	slog.Debug("received healthcheck request")
 	w.WriteHeader(http.StatusOK)
 }
 
@@ -75,6 +81,6 @@ func newReverseProxy(httpAddress string, port int) (*httputil.ReverseProxy, erro
 	}
 
 	proxy := httputil.NewSingleHostReverseProxy(url)
-	proxy.ErrorLog = config.ErrorLogger
+	proxy.ErrorLog = slog.NewLogLogger(slog.Default().Handler(), slog.LevelError)
 	return proxy, nil
 }

cmd/cartesi-rollups-node/main.go

@@ -5,6 +5,7 @@ package main
 
 import (
 	"context"
+	"log/slog"
 	"os/signal"
 	"syscall"
 	"time"
@@ -21,6 +22,8 @@ func main() {
 	defer stop()
 
 	nodeConfig := config.NewNodeConfigFromEnv()
+	config.InitLog(nodeConfig)
+	slog.Info("Starting Cartesi Rollups Node", "config", nodeConfig)
 
 	sunodoValidatorEnabled := nodeConfig.CartesiExperimentalSunodoValidatorEnabled
 	if !sunodoValidatorEnabled {
@@ -58,14 +61,14 @@ func main() {
 		select {
 		case <-ready:
 			duration := time.Since(startTime)
-			config.InfoLogger.Printf("rollups-node: ready after %s", duration)
+			slog.Info("rollups-node is ready", "startupTime", duration)
 		case <-ctx.Done():
 		}
 	}()
 
 	// start supervisor
 	supervisor := newSupervisorService(s)
 	if err := supervisor.Start(ctx, ready); err != nil {
-		config.ErrorLogger.Print(err)
+		slog.Error(err.Error())
 	}
 }

cmd/cartesi-rollups-node/services.go

@@ -389,7 +389,7 @@ func newStateServer(nodeConfig config.NodeConfig) services.CommandService {
 
 func newSupervisorService(s []services.Service) services.SupervisorService {
 	return services.SupervisorService{
-		Name:     "rollups-node",
+		Name:     "supervisor",
 		Services: s,
 	}
 }

docs/config.md

@@ -192,9 +192,9 @@ One of "debug", "info", "warning", "error".
 * **Type:** `LogLevel`
 * **Default:** `"info"`
 
-## `CARTESI_LOG_TIMESTAMP`
+## `CARTESI_LOG_PRETTY`
 
-If set to true, the node will print the timestamp when logging.
+If set to true, the node will add colors to its log output.
 
 * **Type:** `bool`
 * **Default:** `"false"`

go.mod

@@ -16,6 +16,8 @@ require github.com/BurntSushi/toml v1.3.2
 require (
 	github.com/Khan/genqlient v0.6.0
 	github.com/deepmap/oapi-codegen/v2 v2.1.0
+	github.com/lmittmann/tint v1.0.4
+	github.com/mattn/go-isatty v0.0.20
 	github.com/oapi-codegen/runtime v1.1.1
 	golang.org/x/sync v0.6.0
 	golang.org/x/text v0.14.0

go.sum

@@ -190,6 +190,8 @@ github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0
 github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw=
 github.com/leanovate/gopter v0.2.9 h1:fQjYxZaynp97ozCzfOyOuAGOU4aU/z37zf/tOujFk7c=
 github.com/leanovate/gopter v0.2.9/go.mod h1:U2L/78B+KVFIx2VmW6onHJQzXtFb+p5y3y2Sh+Jxxv8=
+github.com/lmittmann/tint v1.0.4 h1:LeYihpJ9hyGvE0w+K2okPTGUdVLfng1+nDNVR4vWISc=
+github.com/lmittmann/tint v1.0.4/go.mod h1:HIS3gSy7qNwGCj+5oRjAutErFBl4BzdQP6cJZ0NfMwE=
 github.com/lufia/plan9stats v0.0.0-20211012122336-39d0f177ccd0/go.mod h1:zJYVVT2jmtg6P3p1VtQj7WsuWi/y4VnjVBn7F8KPB3I=
 github.com/lufia/plan9stats v0.0.0-20231016141302-07b5767bb0ed h1:036IscGBfJsFIgJQzlui7nK1Ncm0tp2ktmPj8xO4N/0=
 github.com/lufia/plan9stats v0.0.0-20231016141302-07b5767bb0ed/go.mod h1:ilwx/Dta8jXAgpFYFvSWEMwxmbWXyiUHkd5FwyKhb5k=
@@ -369,6 +371,7 @@ golang.org/x/sys v0.0.0-20201204225414-ed752295db88/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210616094352-59db8d763f22/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.16.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=

internal/config/auth.go

@@ -3,6 +3,8 @@
 
 package config
 
+import "log/slog"
+
 // Auth objects are used to sign transactions.
 type Auth any
 
@@ -17,3 +19,19 @@ type AuthAWS struct {
 	KeyID  string
 	Region string
 }
+
+//FIXME: Generate these also based on the Config.toml?
+
+func (a AuthMnemonic) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("Mnemonic", "[REDACTED]"),
+		slog.String("AccountIndex", "[REDACTED]"),
+	)
+}
+
+func (a AuthAWS) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("KeyID", "[REDACTED]"),
+		slog.String("Region", "[REDACTED]"),
+	)
+}