Structured logging prototype

client/client.go

@@ -17,6 +17,7 @@ import (
 	"github.com/relab/hotstuff/core/eventloop"
 	"github.com/relab/hotstuff/core/logging"
 	"github.com/relab/hotstuff/internal/proto/clientpb"
+	"go.uber.org/zap"
 	"golang.org/x/time/rate"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials"
@@ -62,7 +63,7 @@ type Config struct {
 // Client is a hotstuff client.
 type Client struct {
 	eventLoop *eventloop.EventLoop
-	logger    logging.Logger
+	logger    logging.Logger2
 	id        ID
 
 	mut              sync.Mutex
@@ -83,7 +84,7 @@ type Client struct {
 // New returns a new Client.
 func New(
 	eventLoop *eventloop.EventLoop,
-	logger logging.Logger,
+	logger logging.Logger2,
 	id ID,
 	conf Config,
 ) (client *Client) {
@@ -155,14 +156,16 @@ func (c *Client) Run(ctx context.Context) {
 
 	err := c.sendCommands(ctx)
 	if err != nil && !errors.Is(err, io.EOF) {
-		c.logger.Panicf("Failed to send commands: %v", err)
+		c.logger.Error("Failed to send commands", zap.Error(err))
+		panic(err)
 	}
 	c.close()
 
 	commandStats := <-commandStatsChan
-	c.logger.Infof(
-		"Done sending commands (executed: %d, failed: %d, timeouts: %d)",
-		commandStats.executed, commandStats.failed, commandStats.timeout,
+	c.logger.Info("Done sending commands",
+		zap.Int("executed", commandStats.executed),
+		zap.Int("failed", commandStats.failed),
+		zap.Int("timeouts", commandStats.timeout),
 	)
 	<-eventLoopDone
 	close(c.done)
@@ -185,7 +188,7 @@ func (c *Client) close() {
 	c.mgr.Close()
 	err := c.reader.Close()
 	if err != nil {
-		c.logger.Warn("Failed to close reader: ", err)
+		c.logger.Warn("Failed to close reader", zap.Error(err))
 	}
 }
 
@@ -249,7 +252,7 @@ loop:
 		}
 
 		if time.Now().After(nextLogTime) {
-			c.logger.Infof("%d commands sent so far", num)
+			c.logger.Info("commands sent so far", zap.Uint64("count", num))
 			nextLogTime = time.Now().Add(time.Second)
 		}
 
@@ -280,7 +283,7 @@ func (c *Client) handleCommands(ctx context.Context) (executed, failed, timeout
 				c.logger.Debug("Command timed out.")
 				timeout++
 			} else if !errors.Is(err, context.Canceled) {
-				c.logger.Debugf("Did not get enough replies for command: %v\n", err)
+				c.logger.Debug("Did not get enough replies for command", zap.Error(err))
 				failed++
 			}
 		} else {

cmd/logger/main.go

@@ -0,0 +1,77 @@
+package main
+
+import (
+	"errors"
+	"time"
+
+	"github.com/relab/hotstuff/core/logging"
+	"go.uber.org/zap"
+)
+
+func main() {
+	// Original unstructured logging
+	something := logging.New("test")
+	something.Info("Testing...")
+
+	// Native zap logger (for comparison)
+	logger, _ := zap.NewProduction()
+	defer logger.Sync()
+	url := "http://example.com"
+	logger.Info("failed to fetch URL",
+		// Structured context as strongly typed Field values.
+		zap.String("url", url),
+		zap.Int("attempt", 3),
+		zap.Duration("backoff", time.Second),
+	)
+
+	// Logger2 interface
+	structuredLogger := logging.New2("structured-test")
+
+	structuredLogger.Info("Application started",
+		zap.String("version", "1.0.0"),
+		zap.Int("port", 8080),
+		zap.Bool("debug", true),
+	)
+
+	structuredLogger.Debug("Processing request",
+		zap.String("method", "GET"),
+		zap.String("path", "/api/health"),
+		zap.Duration("latency", time.Millisecond*150),
+	)
+
+	structuredLogger.Warn("High memory usage detected",
+		zap.Float64("memory_usage_gb", 7.8),
+		zap.Int64("available_gb", 2),
+	)
+
+	// Error logging with structured context
+	err := errors.New("database connection failed")
+	structuredLogger.Error("Failed to connect to database",
+		zap.Error(err),
+		zap.String("host", "localhost"),
+		zap.Int("port", 5432),
+		zap.String("database", "hotstuff_db"),
+	)
+
+	// Using With() to create a logger with pre-set fields
+	userLogger := structuredLogger.With(
+		zap.String("user_id", "12345"),
+		zap.String("session_id", "abcdef"),
+	)
+
+	userLogger.Info("User action performed",
+		zap.String("action", "login"),
+		zap.Duration("response_time", time.Millisecond*45),
+	)
+
+	// Using Named() to create a sub-logger
+	dbLogger := structuredLogger.Named("database")
+	dbLogger.Info("Query executed",
+		zap.String("query", "SELECT * FROM users"),
+		zap.Duration("execution_time", time.Millisecond*23),
+		zap.Int("rows_affected", 42),
+	)
+}
+
+
+/*./hotstuff run --config scripts/local_config.cue --ssh-config scripts/ssh_config.local --log-level debug &> x.log*/

core/eventloop/context_test.go

@@ -11,7 +11,7 @@ import (
 
 // TestTimeoutContext tests that a timeout context is canceled after receiving a timeout event.
 func TestTimeoutContext(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	eventloop := eventloop.New(logger, 10)
 	ctx, cancel := eventloop.TimeoutContext()
 	defer cancel()
@@ -25,7 +25,7 @@ func TestTimeoutContext(t *testing.T) {
 
 // TestTimeoutContextView tests that a timeout context is canceled after receiving a view change event.
 func TestTimeoutContextView(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	eventloop := eventloop.New(logger, 10)
 	ctx, cancel := eventloop.TimeoutContext()
 	defer cancel()
@@ -39,7 +39,7 @@ func TestTimeoutContextView(t *testing.T) {
 
 // TestViewContext tests that a view context is canceled after receiving a view change event.
 func TestViewContext(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	eventloop := eventloop.New(logger, 10)
 	ctx, cancel := eventloop.ViewContext(nil)
 	defer cancel()
@@ -53,7 +53,7 @@ func TestViewContext(t *testing.T) {
 
 // TestViewContextEarlierView tests that a view context is not canceled when receiving a view change event for an earlier view.
 func TestViewContextEarlierView(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	eventloop := eventloop.New(logger, 10)
 	v := hotstuff.View(1)
 	ctx, cancel := eventloop.ViewContext(&v)

core/eventloop/eventloop.go

@@ -14,6 +14,7 @@ import (
 	"time"
 
 	"github.com/relab/hotstuff/core/logging"
+	"go.uber.org/zap"
 )
 
 type handlerOpts struct {
@@ -52,7 +53,7 @@ type handler struct {
 
 // EventLoop accepts events of any type and executes registered event handlers.
 type EventLoop struct {
-	logger logging.Logger
+	logger logging.Logger2
 
 	eventQ queue
 
@@ -70,7 +71,7 @@ type EventLoop struct {
 
 // New returns a new event loop with the requested buffer size.
 func New(
-	logger logging.Logger,
+	logger logging.Logger2,
 	bufferSize uint,
 ) *EventLoop {
 	el := &EventLoop{
@@ -82,6 +83,9 @@ func New(
 		handlers:      make(map[reflect.Type][]handler),
 		tickers:       make(map[int]*ticker),
 	}
+	logger.Debug("EventLoop created",
+		zap.Uint("buffer_size", bufferSize),
+	)
 	return el
 }
 
@@ -135,7 +139,10 @@ func (el *EventLoop) AddEvent(event any) {
 		el.processEvent(event, true)
 		droppedEvent := el.eventQ.push(event)
 		if droppedEvent != nil {
-			el.logger.Warnf("event queue is full, dropped event: %v", droppedEvent)
+			el.logger.Warn("Event queue is full, dropped event",
+				zap.String("dropped_event_type", reflect.TypeOf(droppedEvent).String()),
+				zap.Any("dropped_event", droppedEvent),
+			)
 		}
 	}
 }
@@ -301,7 +308,11 @@ func (el *EventLoop) AddTicker(interval time.Duration, callback func(tick time.T
 	// so we need to start the ticker from the run loop.
 	droppedEvent := el.eventQ.push(startTickerEvent{id})
 	if droppedEvent != nil {
-		el.logger.Warnf("event queue is full, dropped event: %v", droppedEvent)
+		el.logger.Warn("Event queue is full, dropped ticker start event",
+			zap.Int("ticker_id", id),
+			zap.Duration("interval", interval),
+			zap.String("dropped_event_type", reflect.TypeOf(droppedEvent).String()),
+		)
 	}
 
 	return id

core/eventloop/eventloop_test.go

@@ -13,7 +13,7 @@ import (
 type testEvent int
 
 func TestHandler(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 10)
 	c := make(chan any)
 	eventloop.Register(el, func(event testEvent) {
@@ -53,7 +53,7 @@ func TestPrioritize(t *testing.T) {
 		handler bool
 	}
 
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 10)
 	c := make(chan eventData)
 	eventloop.Register(el, func(event testEvent) {
@@ -103,7 +103,7 @@ func TestTicker(t *testing.T) {
 		return
 	}
 
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 10)
 	count := 0
 	eventloop.Register(el, func(event testEvent) {
@@ -135,7 +135,7 @@ func TestTicker(t *testing.T) {
 }
 
 func TestDelayedEvent(t *testing.T) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 10)
 	c := make(chan testEvent)
 
@@ -166,7 +166,7 @@ func TestDelayedEvent(t *testing.T) {
 }
 
 func BenchmarkEventLoopWithPrioritize(b *testing.B) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 100)
 
 	for range 100 {
@@ -184,7 +184,7 @@ func BenchmarkEventLoopWithPrioritize(b *testing.B) {
 }
 
 func BenchmarkEventLoopWithUnsafeRunInAddEventHandlers(b *testing.B) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 100)
 
 	for range 100 {
@@ -210,7 +210,7 @@ func BenchmarkEventLoopWithUnsafeRunInAddEventHandlers(b *testing.B) {
 }
 
 func BenchmarkDelay(b *testing.B) {
-	logger := logging.New("test")
+	logger := logging.New2("test")
 	el := eventloop.New(logger, 100)
 
 	for b.Loop() {