Merge pull request 'fix: JSONHandler deadlock from recursive log.Println (closes #3)' (#4) from clawbot/simplelog:fix/json-handler-deadlock into main

Reviewed-on: #4

.gitignore

@@ -1 +1,2 @@
 .aider*
+cmd/example/example

Dockerfile

@@ -0,0 +1,39 @@
+# First stage: Use the golangci-lint image to run the linter
+FROM golangci/golangci-lint:latest as lint
+
+# Set the Current Working Directory inside the container
+WORKDIR /app
+
+# Copy the go.mod file and the rest of the application code
+COPY go.mod ./
+COPY . .
+
+# Run golangci-lint
+RUN golangci-lint run
+
+RUN sh -c 'test -z "$(gofmt -l .)"'
+
+# Second stage: Use the official Golang image to run tests
+FROM golang:1.22 as test
+
+# Set the Current Working Directory inside the container
+WORKDIR /app
+
+# Copy the go.mod file and the rest of the application code
+COPY go.mod ./
+COPY . .
+
+# Run tests
+RUN go test -v ./...
+
+# Final stage: Combine the linting and testing stages
+FROM golang:1.22 as final
+
+# Ensure that the linting stage succeeded
+WORKDIR /app
+COPY --from=lint /app .
+COPY --from=test /app .
+
+# Set the final CMD to something minimal since we only needed to verify lint and tests during build
+CMD ["echo", "Build and tests passed successfully!"]
+

LICENSE

@@ -0,0 +1,14 @@
+            DO WHAT THE FUCK YOU WANT TO PUBLIC LICENSE
+                    Version 2, December 2004
+
+ Copyright (C) 2004 Sam Hocevar <sam@hocevar.net>
+
+ Everyone is permitted to copy and distribute verbatim or modified
+ copies of this license document, and changing it is allowed as long
+ as the name is changed.
+
+            DO WHAT THE FUCK YOU WANT TO PUBLIC LICENSE
+   TERMS AND CONDITIONS FOR COPYING, DISTRIBUTION AND MODIFICATION
+
+  0. You just DO WHAT THE FUCK YOU WANT TO.
+

Makefile

@@ -12,3 +12,6 @@ fmt:
 lint:
 	golangci-lint run
 	sh -c 'test -z "$$(gofmt -l .)"'
+
+docker:
+	docker build --progress plain .

README.md

@@ -1,5 +1,7 @@
 # simplelog
 
+## Summary
+
 simplelog is an opinionated logging package designed to facilitate easy and
 structured logging in Go applications with an absolute minimum of
 boilerplate.
@@ -7,12 +9,19 @@ boilerplate.
 The idea is that you can add a single import line which replaces the
 stdlib `log/slog` default handler, and solve the 90% case for logging.
 
+## Current Status
+
+Released v1.0.0 2024-06-14.  Works as intended.  No known bugs.
+
 ## Features
 
-* if output is a tty, outputs pretty color logs
+-   if output is a tty, outputs pretty color logs
-* if output is not a tty, outputs json
+-   if output is not a tty, outputs json
-* supports delivering logs via tcp RELP (e.g. to remote rsyslog using imrelp)
+-   supports delivering each log message via a webhook
-* supports delivering each log message via a webhook
+
+## Planned Features
+
+-   supports delivering logs via tcp RELP (e.g. to remote rsyslog using imrelp)
 
 ## Installation
 
@@ -25,19 +34,21 @@ go mod init your_project_name
 Then, add SimpleLog to your project:
 
 ```bash
-go get git.eeqj.de/sneak/go-simplelog
+go get sneak.berlin/go/simplelog
 ```
 
 ## Usage
 
-Below is an example of how to use SimpleLog in a Go application. This example is provided in the form of a `main.go` file, which demonstrates logging at various levels using structured logging syntax.
+Below is an example of how to use SimpleLog in a Go application. This
+example is provided in the form of a `main.go` file, which demonstrates
+logging at various levels using structured logging syntax.
 
 ```go
 package main
 
 import (
 	"log/slog"
-	_ "git.eeqj.de/sneak/go-simplelog"
+	_ "sneak.berlin/go/simplelog"
 )
 
 func main() {
@@ -48,3 +59,7 @@ func main() {
 	slog.Error("Failed to save data", slog.String("reason", "permission denied"))
 }
 ```
+
+## License
+
+[WTFPL](./LICENSE)

cmd/example/main.go

@@ -0,0 +1,26 @@
+package main
+
+import (
+	"log/slog"
+
+	_ "sneak.berlin/go/simplelog"
+)
+
+func main() {
+
+	// log structured data with slog as usual:
+	slog.Info(
+		"User login attempt",
+		slog.String("user", "JohnDoe"),
+		slog.Int("attempt", 3),
+	)
+	slog.Warn(
+		"Configuration mismatch",
+		slog.String("expected", "config.json"),
+		slog.String("found", "config.dev.json"),
+	)
+	slog.Error(
+		"Failed to save data",
+		slog.String("reason", "permission denied"),
+	)
+}

console_handler.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"log/slog"
+	"runtime"
 	"time"
 
 	"github.com/fatih/color"
@@ -15,7 +16,10 @@ func NewConsoleHandler() *ConsoleHandler {
 	return &ConsoleHandler{}
 }
 
-func (c *ConsoleHandler) Handle(ctx context.Context, record slog.Record) error {
+func (c *ConsoleHandler) Handle(
+	ctx context.Context,
+	record slog.Record,
+) error {
 	timestamp := time.Now().UTC().Format("2006-01-02T15:04:05.000Z07:00")
 	var colorFunc func(format string, a ...interface{}) string
 
@@ -30,11 +34,29 @@ func (c *ConsoleHandler) Handle(ctx context.Context, record slog.Record) error {
 		colorFunc = color.New(color.FgWhite).SprintfFunc()
 	}
 
-	fmt.Println(colorFunc("%s [%s]: %s", timestamp, record.Level, record.Message))
+	// Get the caller information
+	_, file, line, ok := runtime.Caller(4)
+	if !ok {
+		file = "???"
+		line = 0
+	}
+	fmt.Println(
+		colorFunc(
+			"%s [%s] %s:%d: %s",
+			timestamp,
+			record.Level,
+			file,
+			line,
+			record.Message,
+		),
+	)
 	return nil
 }
 
-func (c *ConsoleHandler) Enabled(ctx context.Context, level slog.Level) bool {
+func (c *ConsoleHandler) Enabled(
+	ctx context.Context,
+	level slog.Level,
+) bool {
 	return true
 }
 

go.mod

@@ -1,4 +1,4 @@
-module git.eeqj.de/sneak/go-simplelog
+module sneak.berlin/go/simplelog
 
 go 1.22.1
 

handler.go

@@ -3,6 +3,6 @@ package simplelog
 import "log/slog"
 
 // Handler defines the interface for different log outputs.
-type Handler interface {
+type ExtendedHandler interface {
 	slog.Handler
 }

json_handler.go

@@ -3,11 +3,9 @@ package simplelog
 import (
 	"context"
 	"encoding/json"
-	"context"
+	"fmt"
-	"encoding/json"
-	"log"
 	"log/slog"
-	"log"
+	"os"
 )
 
 type JSONHandler struct{}
@@ -18,7 +16,7 @@ func NewJSONHandler() *JSONHandler {
 
 func (j *JSONHandler) Handle(ctx context.Context, record slog.Record) error {
 	jsonData, _ := json.Marshal(record)
-	log.Println(string(jsonData))
+	fmt.Fprintln(os.Stdout, string(jsonData))
 	return nil
 }
 

json_handler_test.go

@@ -0,0 +1,33 @@
+package simplelog
+
+import (
+	"log/slog"
+	"testing"
+	"time"
+)
+
+// TestJSONHandlerDeadlock verifies that JSONHandler.Handle does not deadlock
+// when the default slog handler routes log.Println back through slog.
+// On the unfixed code this test will hang (deadlock); with the fix it completes.
+func TestJSONHandlerDeadlock(t *testing.T) {
+	handler := NewJSONHandler()
+
+	// Set our handler as the default so log.Println routes through slog
+	logger := slog.New(handler)
+	slog.SetDefault(logger)
+
+	done := make(chan struct{})
+	go func() {
+		// This call deadlocks on unfixed code because Handle() calls
+		// log.Println() which re-enters slog → Handle() → log.Println() …
+		slog.Info("test message")
+		close(done)
+	}()
+
+	select {
+	case <-done:
+		// success
+	case <-time.After(5 * time.Second):
+		t.Fatal("JSONHandler.Handle deadlocked: timed out after 5 seconds")
+	}
+}

relp_handler.go

@@ -1,264 +0,0 @@
-package simplelog
-
-import (
-	"context"
-	"encoding/json"
-	"fmt"
-	"io/ioutil"
-	"log"
-	"log/slog"
-	"net"
-	"net/url"
-	"os"
-	"os"
-	"path/filepath"
-	"strconv"
-	"time"
-
-	"github.com/google/uuid"
-)
-
-func getEnvAsInt(name string, defaultVal int) int {
-	valStr := os.Getenv(name)
-	if val, err := strconv.Atoi(valStr); err == nil {
-		return val
-	}
-	return defaultVal
-}
-
-func getEnvAsDuration(name string, defaultVal time.Duration) time.Duration {
-	valStr := os.Getenv(name)
-	if val, err := time.ParseDuration(valStr); err == nil {
-		return val
-	}
-	return defaultVal
-}
-
-var (
-	cacheDir, _       = os.UserCacheDir()
-	diskBufferLimit   = getEnvAsInt("LOGGER_DISK_BUFFER_LIMIT", 100)
-	diskWriteInterval = getEnvAsDuration("LOGGER_DISK_WRITE_INTERVAL", time.Second)
-	relpDebug         = os.Getenv("RELP_DEBUG") != ""
-)
-
-type RELPHandler struct {
-	relpServerURL string
-	conn          net.Conn
-	ch            chan Event
-	done          chan struct{}
-	failedCh      chan Event
-	timer         *time.Timer
-}
-
-func NewRELPHandler(relpURL string) (*RELPHandler, error) {
-	parsedURL, err := url.Parse(relpURL)
-	if err != nil {
-		return nil, fmt.Errorf("Error parsing RELP URL: %v", err)
-	}
-	if parsedURL.Scheme != "tcp" {
-		return nil, fmt.Errorf("RELP URL must have the tcp scheme, got %s", parsedURL.Scheme)
-	}
-	if err := os.MkdirAll(filepath.Join(cacheDir, "simplelog"), 0755); err != nil {
-		return nil, fmt.Errorf("Failed to create cache directory: %v", err)
-	}
-	r := &RELPHandler{
-		relpServerURL: parsedURL.Host,
-		ch:            make(chan Event, diskBufferLimit),
-		done:          make(chan struct{}),
-		failedCh:      make(chan Event, diskBufferLimit),
-		timer:         time.NewTimer(diskWriteInterval),
-	}
-	if relpDebug {
-		log.Printf("Created new RELP handler for server at %s", r.relpServerURL)
-	}
-	return r, nil
-}
-
-func (r *RELPHandler) connectToRELPServer() (net.Conn, error) {
-	parsedURL, err := url.Parse(r.relpServerURL)
-	if err != nil {
-		return nil, fmt.Errorf("Error parsing RELP URL: %v", err)
-	}
-	if parsedURL.Scheme != "tcp" {
-		return nil, fmt.Errorf("RELP URL must have the tcp scheme, got %s", parsedURL.Scheme)
-	}
-	host, port, err := net.SplitHostPort(parsedURL.Host)
-	if err != nil {
-		return nil, fmt.Errorf("Error splitting host and port: %v", err)
-	}
-	conn, err := net.Dial("tcp", net.JoinHostPort(host, port))
-	if err != nil {
-		if relpDebug {
-			log.Printf("Failed to connect to RELP server at %s: %v", net.JoinHostPort(host, port), err)
-		}
-		return nil, err
-	}
-	if relpDebug {
-		log.Printf("Successfully connected to RELP server at %s", net.JoinHostPort(host, port))
-	}
-	return conn, nil
-}
-
-func (r *RELPHandler) Startup() error {
-	var err error
-	r.conn, err = r.connectToRELPServer()
-	if err != nil {
-		if relpDebug {
-			log.Printf("Failed to establish TCP connection to RELP server: %v", err)
-		}
-		return fmt.Errorf("Failed to establish TCP connection to RELP server: %v", err)
-	}
-	if relpDebug {
-		log.Printf("Successfully connected to RELP server at %s", r.relpServerURL)
-	}
-	go r.receiveEventsFromChannel()
-	go r.processFailedEvents()
-	go r.watchDirectoryForFailedEventFiles()
-	return nil
-}
-
-func (r *RELPHandler) Enabled(ctx context.Context, level slog.Level) bool {
-	return true
-}
-
-func (r *RELPHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
-	return r
-}
-
-func (r *RELPHandler) WithGroup(name string) slog.Handler {
-	return r
-}
-
-func (r *RELPHandler) Handle(ctx context.Context, record slog.Record) error {
-	attrs := make(map[string]interface{})
-	record.Attrs(func(attr slog.Attr) bool {
-		attrs[attr.Key] = attr.Value
-		return true
-	})
-	jsonData, err := json.Marshal(attrs)
-	if err != nil {
-		return fmt.Errorf("error marshaling attributes: %v", err)
-	}
-	event := NewEvent(record.Level.String(), record.Message, jsonData)
-	select {
-	case r.ch <- event:
-		return nil // Successfully sent event to channel
-	default:
-		return fmt.Errorf("failed to log event: channel is full")
-	}
-}
-
-func (r *RELPHandler) receiveEventsFromChannel() {
-	for {
-		select {
-		case event := <-r.ch:
-			if err := r.sendEventToRELPServer(event); err != nil {
-				r.failedCh <- event
-			}
-		case <-r.done:
-			return
-		}
-	}
-}
-
-func (r *RELPHandler) processFailedEvents() {
-	for {
-		select {
-		case event := <-r.failedCh:
-			if err := r.sendEventToRELPServer(event); err != nil {
-				// If still failing, write to disk
-				r.writeFailedToDisk(event)
-			}
-		case <-r.timer.C:
-			// Flush all events in failedCh to disk
-			for len(r.failedCh) > 0 {
-				event := <-r.failedCh
-				r.writeFailedToDisk(event)
-			}
-		case <-r.done:
-			return
-		}
-	}
-}
-
-func (r *RELPHandler) sendEventToRELPServer(event Event) error {
-	jsonData, err := json.Marshal(event)
-	if err != nil {
-		return fmt.Errorf("error marshaling event: %v", err)
-	}
-	_, err = r.conn.Write(jsonData)
-	if err != nil {
-		return err
-	}
-	// Implement TCP read for the acknowledgment with a timeout
-	r.conn.SetReadDeadline(time.Now().Add(2 * time.Second))
-	ack := make([]byte, 256)
-	n, err := r.conn.Read(ack)
-	if err != nil {
-		return err
-	}
-	if string(ack[:n]) != "ACK" {
-		return fmt.Errorf("expected ACK from server, got %s", string(ack[:n]))
-	}
-	if relpDebug {
-		log.Printf("Received ACK from RELP server for event %s", event.ID)
-	}
-	return nil
-}
-
-func (r *RELPHandler) watchDirectoryForFailedEventFiles() {
-	for {
-		select {
-		case <-r.done:
-			return
-		default:
-			if r.isConnected() {
-				if relpDebug {
-					log.Printf("Reconnected to RELP server at %s", r.relpServerURL)
-				}
-				files, err := ioutil.ReadDir(cacheDir)
-				if err != nil {
-					log.Printf("Error reading cache directory: %v", err)
-					continue
-				}
-				for _, file := range files {
-					filePath := filepath.Join(cacheDir, file.Name())
-					data, err := ioutil.ReadFile(filePath)
-					if err != nil {
-						log.Printf("Error reading event cache file %s: %v", file.Name(), err)
-						continue
-					}
-					var event Event
-					if err := json.Unmarshal(data, &event); err != nil {
-						log.Printf("Error unmarshalling event from file %s: %v", file.Name(), err)
-						continue
-					}
-					r.ch <- event
-					os.Remove(filePath) // Remove file after processing
-				}
-			}
-			time.Sleep(10 * time.Second) // Check disk every 10 seconds
-		}
-	}
-}
-
-func (r *RELPHandler) isConnected() bool {
-	_, err := r.conn.Write([]byte{})
-	return err == nil
-}
-
-func (r *RELPHandler) Shutdown() error {
-	close(r.done)
-	if r.conn != nil {
-		if err := r.conn.Close(); err != nil {
-			return fmt.Errorf("error closing TCP connection: %v", err)
-		}
-	}
-	return nil
-}
-
-func (r *RELPHandler) writeFailedToDisk(event Event) {
-	fileName := filepath.Join(cacheDir, "simplelog", uuid.New().String()+".logevent")
-	data, _ := json.Marshal(event)
-	ioutil.WriteFile(fileName, data, 0600)
-}

simplelog.go

@@ -2,79 +2,41 @@ package simplelog
 
 import (
 	"context"
+	"encoding/json"
 	"log"
 	"log/slog"
 	"os"
+	"time"
 
-	"github.com/mattn/go-isatty"
+	"github.com/google/uuid"
 
 	"github.com/mattn/go-isatty"
 )
 
 var (
-	relpServerURL = os.Getenv("LOGGER_RELP_URL")
+	webhookURL = os.Getenv("LOGGER_WEBHOOK_URL")
-	webhookURL    = os.Getenv("LOGGER_WEBHOOK_URL")
 )
 
-type CustomHandler struct {
-	handlers []slog.Handler
-}
-
-func (cl *CustomHandler) Handle(ctx context.Context, record slog.Record) error {
-	for _, handler := range cl.handlers {
-		if err := handler.Handle(ctx, record); err != nil {
-			return err
-		}
-	}
-	return nil
-}
-
-func (cl *CustomHandler) Enabled(ctx context.Context, level slog.Level) bool {
-	for _, handler := range cl.handlers {
-		if handler.Enabled(ctx, level) {
-			return true
-		}
-	}
-	return false
-}
-
-func (cl *CustomHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
-	newHandlers := make([]slog.Handler, len(cl.handlers))
-	for i, handler := range cl.handlers {
-		newHandlers[i] = handler.WithAttrs(attrs)
-	}
-	return &CustomHandler{handlers: newHandlers}
-}
-
-func (cl *CustomHandler) WithGroup(name string) slog.Handler {
-	newHandlers := make([]slog.Handler, len(cl.handlers))
-	for i, handler := range cl.handlers {
-		newHandlers[i] = handler.WithGroup(name)
-	}
-	return &CustomHandler{handlers: newHandlers}
-}
-
 var ourCustomLogger *slog.Logger
+var ourCustomHandler slog.Handler
 
 func init() {
-	ourCustomLogger = NewCustomHandler()
+	ourCustomHandler = NewMultiplexHandler()
+	ourCustomLogger = slog.New(ourCustomHandler)
 	slog.SetDefault(ourCustomLogger)
 }
 
-func NewCustomHandler() *CustomHandler {
+type MultiplexHandler struct {
-	cl := &CustomHandler{}
+	handlers []ExtendedHandler
+}
+
+func NewMultiplexHandler() slog.Handler {
+	cl := &MultiplexHandler{}
 	if isatty.IsTerminal(os.Stdout.Fd()) {
 		cl.handlers = append(cl.handlers, NewConsoleHandler())
 	} else {
 		cl.handlers = append(cl.handlers, NewJSONHandler())
 	}
-	if relpServerURL != "" {
-		handler, err := NewRELPHandler(relpServerURL)
-		if err != nil {
-			log.Fatalf("Failed to initialize RELP handler: %v", err)
-		}
-		cl.handlers = append(cl.handlers, handler)
-	}
 	if webhookURL != "" {
 		handler, err := NewWebhookHandler(webhookURL)
 		if err != nil {
@@ -84,3 +46,91 @@ func NewCustomHandler() *CustomHandler {
 	}
 	return cl
 }
+
+func (cl *MultiplexHandler) Handle(
+	ctx context.Context,
+	record slog.Record,
+) error {
+	for _, handler := range cl.handlers {
+		if err := handler.Handle(ctx, record); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+func (cl *MultiplexHandler) Enabled(
+	ctx context.Context,
+	level slog.Level,
+) bool {
+	// send us all events
+	return true
+}
+
+func (cl *MultiplexHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	newHandlers := make([]ExtendedHandler, len(cl.handlers))
+	for i, handler := range cl.handlers {
+		newHandlers[i] = handler.WithAttrs(attrs)
+	}
+	return &MultiplexHandler{handlers: newHandlers}
+}
+
+func (cl *MultiplexHandler) WithGroup(name string) slog.Handler {
+	newHandlers := make([]ExtendedHandler, len(cl.handlers))
+	for i, handler := range cl.handlers {
+		newHandlers[i] = handler.WithGroup(name)
+	}
+	return &MultiplexHandler{handlers: newHandlers}
+}
+
+type ExtendedEvent interface {
+	GetID() uuid.UUID
+	GetTimestamp() time.Time
+	GetLevel() string
+	GetMessage() string
+	GetData() json.RawMessage
+	GetFile() string
+	GetLine() int
+}
+
+type extendedEvent struct {
+	Event
+	File string `json:"file"`
+	Line int    `json:"line"`
+}
+
+func (e extendedEvent) GetID() uuid.UUID {
+	return e.ID
+}
+
+func (e extendedEvent) GetTimestamp() time.Time {
+	return e.Timestamp
+}
+
+func (e extendedEvent) GetLevel() string {
+	return e.Level
+}
+
+func (e extendedEvent) GetMessage() string {
+	return e.Message
+}
+
+func (e extendedEvent) GetData() json.RawMessage {
+	return e.Data
+}
+
+func (e extendedEvent) GetFile() string {
+	return e.File
+}
+
+func (e extendedEvent) GetLine() int {
+	return e.Line
+}
+
+func NewExtendedEvent(baseEvent Event, file string, line int) ExtendedEvent {
+	return extendedEvent{
+		Event: baseEvent,
+		File:  file,
+		Line:  line,
+	}
+}

tools/relp_log_trial.go

@@ -3,7 +3,7 @@ package main
 import (
 	"log/slog"
 
-	_ "git.eeqj.de/sneak/go-simplelog" // Using underscore to only invoke init()
+	_ "sneak.berlin/go/simplelog" // Using underscore to only invoke init()
 )
 
 func main() {

tools/run_relp_log_trial.sh

@@ -2,7 +2,7 @@
 
 # Set the environment variables for the RELP server URL and optionally for the webhook URL
 export LOGGER_RELP_URL="tcp://10.201.1.18:20514"
-export LOGGER_WEBHOOK_URL="https://example.com/webhook"
+#export LOGGER_WEBHOOK_URL="https://example.com/webhook"
 export RELP_DEBUG=1
 
 # Run the Go program