Switch appservice module to zerolog

appservice/appservice.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2020 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -7,29 +7,25 @@
 package appservice
 
 import (
-	"errors"
 	"fmt"
-	"html/template"
 	"net/http"
 	"net/http/cookiejar"
 	"os"
-	"path/filepath"
-	"strings"
 	"sync"
 	"syscall"
 	"time"
 
 	"github.com/gorilla/mux"
 	"github.com/gorilla/websocket"
+	"github.com/rs/zerolog"
 	"golang.org/x/net/publicsuffix"
 	"gopkg.in/yaml.v3"
 
-	"maunium.net/go/maulogger/v2"
+	"go.mau.fi/zeroconfig"
 
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/event"
 	"maunium.net/go/mautrix/id"
-	"maunium.net/go/mautrix/util"
 )
 
 // EventChannelSize is the size for the Events channel in Appservice instances.
@@ -39,8 +35,15 @@ var OTKChannelSize = 4
 // Create a blank appservice instance.
 func Create() *AppService {
 	jar, _ := cookiejar.New(&cookiejar.Options{PublicSuffixList: publicsuffix.List})
+	defaultLogLevel := zerolog.TraceLevel
 	return &AppService{
-		LogConfig:  CreateLogConfig(),
+		LogConfig: &zeroconfig.Config{
+			MinLevel: &defaultLogLevel,
+			Writers: []zeroconfig.WriterConfig{{
+				Type:   zeroconfig.WriterTypeStdout,
+				Format: zeroconfig.LogFormatPrettyColored,
+			}},
+		},
 		clients:    make(map[id.UserID]*mautrix.Client),
 		intents:    make(map[id.UserID]*IntentAPI),
 		HTTPClient: &http.Client{Timeout: 180 * time.Second, Jar: jar},
@@ -96,14 +99,14 @@ type StateStore interface {
 // AppService is the main config for all appservices.
 // It also serves as the appservice instance struct.
 type AppService struct {
-	HomeserverDomain string     `yaml:"homeserver_domain"`
-	HomeserverURL    string     `yaml:"homeserver_url"`
-	RegistrationPath string     `yaml:"registration"`
-	Host             HostConfig `yaml:"host"`
-	LogConfig        LogConfig  `yaml:"logging"`
+	HomeserverDomain string             `yaml:"homeserver_domain"`
+	HomeserverURL    string             `yaml:"homeserver_url"`
+	RegistrationPath string             `yaml:"registration"`
+	Host             HostConfig         `yaml:"host"`
+	LogConfig        *zeroconfig.Config `yaml:"logging"`
 
-	Registration *Registration    `yaml:"-"`
-	Log          maulogger.Logger `yaml:"-"`
+	Registration *Registration  `yaml:"-"`
+	Log          zerolog.Logger `yaml:"-"`
 
 	txnIDC *TransactionIDCache
 
@@ -211,11 +214,18 @@ func (as *AppService) makeIntent(userID id.UserID) *IntentAPI {
 	localpart, homeserver, err := userID.Parse()
 	if err != nil || len(localpart) == 0 || homeserver != as.HomeserverDomain {
 		if err != nil {
-			as.Log.Fatalfln("Failed to parse user ID %s: %v", userID, err)
+			as.Log.Error().Err(err).
+				Str("user_id", userID.String()).
+				Msg("Failed to parse user ID")
 		} else if len(localpart) == 0 {
-			as.Log.Fatalfln("Failed to make intent for %s: localpart is empty", userID)
+			as.Log.Error().Err(err).
+				Str("user_id", userID.String()).
+				Msg("Failed to make intent: localpart is empty")
 		} else if homeserver != as.HomeserverDomain {
-			as.Log.Fatalfln("Failed to make intent for %s: homeserver isn't %s", userID, as.HomeserverDomain)
+			as.Log.Error().Err(err).
+				Str("user_id", userID.String()).
+				Str("expected_homeserver", as.HomeserverDomain).
+				Msg("Failed to make intent: homeserver doesn't match")
 		}
 		return nil
 	}
@@ -252,7 +262,7 @@ func (as *AppService) makeClient(userID id.UserID) *mautrix.Client {
 
 	client, err := mautrix.NewClient(as.HomeserverURL, userID, as.Registration.AppToken)
 	if err != nil {
-		as.Log.Fatalln("Failed to create mautrix client instance:", err)
+		as.Log.Error().Err(err).Msg("Failed to create mautrix client instance")
 		return nil
 	}
 	client.UserAgent = as.UserAgent
@@ -260,7 +270,7 @@ func (as *AppService) makeClient(userID id.UserID) *mautrix.Client {
 	client.Store = nil
 	client.StateStore = as.StateStore
 	client.SetAppServiceUserID = true
-	client.Logger = *util.MauToZeroLog(as.Log.Sub(string(userID)))
+	client.Logger = as.Log.With().Str("as_user_id", client.UserID.String()).Logger()
 	client.Client = as.HTTPClient
 	client.DefaultHTTPRetries = as.DefaultHTTPRetries
 	as.clients[userID] = client
@@ -280,7 +290,6 @@ func (as *AppService) Client(userID id.UserID) *mautrix.Client {
 func (as *AppService) BotClient() *mautrix.Client {
 	if as.botClient == nil {
 		as.botClient = as.makeClient(as.BotMXID())
-		as.botClient.Logger = *util.MauToZeroLog(as.Log.Sub("Bot"))
 	}
 	return as.botClient
 }
@@ -300,9 +309,14 @@ func (as *AppService) Init() (bool, error) {
 		as.ProcessID = getDefaultProcessID()
 	}
 
-	as.Log = maulogger.Create()
-	as.LogConfig.Configure(as.Log)
-	as.Log.Debugln("Logger initialized successfully.")
+	if as.LogConfig != nil {
+		log, err := as.LogConfig.Compile()
+		if err != nil {
+			return false, fmt.Errorf("error initializing logger: %w", err)
+		}
+		as.Log = *log
+		as.Log.Debug().Msg("Logger initialized successfully")
+	}
 
 	if len(as.RegistrationPath) > 0 {
 		var err error
@@ -312,111 +326,8 @@ func (as *AppService) Init() (bool, error) {
 		}
 	}
 
-	as.Log.Debugln("Appservice initialized successfully.")
+	if as.LogConfig != nil {
+		as.Log.Debug().Msg("Appservice initialized successfully")
+	}
 	return true, nil
 }
-
-// LogConfig contains configs for the logger.
-type LogConfig struct {
-	Directory       string `yaml:"directory"`
-	FileNameFormat  string `yaml:"file_name_format"`
-	FileDateFormat  string `yaml:"file_date_format"`
-	FileMode        uint32 `yaml:"file_mode"`
-	TimestampFormat string `yaml:"timestamp_format"`
-	RawPrintLevel   string `yaml:"print_level"`
-	JSONStdout      bool   `yaml:"print_json"`
-	JSONFile        bool   `yaml:"file_json"`
-	PrintLevel      int    `yaml:"-"`
-}
-
-type umLogConfig LogConfig
-
-func (lc *LogConfig) UnmarshalYAML(unmarshal func(interface{}) error) error {
-	err := unmarshal((*umLogConfig)(lc))
-	if err != nil {
-		return err
-	}
-
-	switch strings.ToUpper(lc.RawPrintLevel) {
-	case "TRACE":
-		lc.PrintLevel = -10
-	case "DEBUG":
-		lc.PrintLevel = maulogger.LevelDebug.Severity
-	case "INFO":
-		lc.PrintLevel = maulogger.LevelInfo.Severity
-	case "WARN", "WARNING":
-		lc.PrintLevel = maulogger.LevelWarn.Severity
-	case "ERR", "ERROR":
-		lc.PrintLevel = maulogger.LevelError.Severity
-	case "FATAL":
-		lc.PrintLevel = maulogger.LevelFatal.Severity
-	default:
-		return errors.New("invalid print level " + lc.RawPrintLevel)
-	}
-	return err
-}
-
-func (lc *LogConfig) MarshalYAML() (interface{}, error) {
-	switch {
-	case lc.PrintLevel >= maulogger.LevelFatal.Severity:
-		lc.RawPrintLevel = maulogger.LevelFatal.Name
-	case lc.PrintLevel >= maulogger.LevelError.Severity:
-		lc.RawPrintLevel = maulogger.LevelError.Name
-	case lc.PrintLevel >= maulogger.LevelWarn.Severity:
-		lc.RawPrintLevel = maulogger.LevelWarn.Name
-	case lc.PrintLevel >= maulogger.LevelInfo.Severity:
-		lc.RawPrintLevel = maulogger.LevelInfo.Name
-	default:
-		lc.RawPrintLevel = maulogger.LevelDebug.Name
-	}
-	return lc, nil
-}
-
-// CreateLogConfig creates a basic LogConfig.
-func CreateLogConfig() LogConfig {
-	return LogConfig{
-		Directory:       "./logs",
-		FileNameFormat:  "%[1]s-%02[2]d.log",
-		TimestampFormat: "Jan _2, 2006 15:04:05",
-		FileMode:        0600,
-		FileDateFormat:  "2006-01-02",
-		PrintLevel:      10,
-	}
-}
-
-type FileFormatData struct {
-	Date  string
-	Index int
-}
-
-// GetFileFormat returns a mauLogger-compatible logger file format based on the data in the struct.
-func (lc LogConfig) GetFileFormat() maulogger.LoggerFileFormat {
-	if len(lc.Directory) > 0 {
-		_ = os.MkdirAll(lc.Directory, 0700)
-	}
-	path := filepath.Join(lc.Directory, lc.FileNameFormat)
-	tpl, _ := template.New("fileformat").Parse(path)
-
-	return func(now string, i int) string {
-		var buf strings.Builder
-		_ = tpl.Execute(&buf, FileFormatData{
-			Date:  now,
-			Index: i,
-		})
-		return buf.String()
-	}
-}
-
-// Configure configures a mauLogger instance with the data in this struct.
-func (lc LogConfig) Configure(log maulogger.Logger) {
-	basicLogger := log.(*maulogger.BasicLogger)
-	basicLogger.FileFormat = lc.GetFileFormat()
-	basicLogger.FileMode = os.FileMode(lc.FileMode)
-	basicLogger.FileTimeFormat = lc.FileDateFormat
-	basicLogger.TimeFormat = lc.TimestampFormat
-	basicLogger.PrintLevel = lc.PrintLevel
-	basicLogger.JSONFile = lc.JSONFile
-	if lc.JSONStdout {
-		basicLogger.EnableJSONStdout()
-	}
-}

appservice/eventprocessor.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2020 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -10,7 +10,7 @@ import (
 	"encoding/json"
 	"runtime/debug"
 
-	log "maunium.net/go/maulogger/v2"
+	"github.com/rs/zerolog"
 
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/event"
@@ -32,7 +32,6 @@ type EventProcessor struct {
 	ExecMode ExecMode
 
 	as       *AppService
-	log      log.Logger
 	stop     chan struct{}
 	handlers map[event.Type][]EventHandler
 
@@ -44,7 +43,6 @@ func NewEventProcessor(as *AppService) *EventProcessor {
 	return &EventProcessor{
 		ExecMode: AsyncHandlers,
 		as:       as,
-		log:      as.Log.Sub("Events"),
 		stop:     make(chan struct{}, 1),
 		handlers: make(map[event.Type][]EventHandler),
 
@@ -84,7 +82,11 @@ func (ep *EventProcessor) OnDeviceList(handler DeviceListHandler) {
 func (ep *EventProcessor) recoverFunc(data interface{}) {
 	if err := recover(); err != nil {
 		d, _ := json.Marshal(data)
-		ep.log.Errorfln("Panic in Matrix event handler: %v (event content: %s):\n%s", err, string(d), string(debug.Stack()))
+		ep.as.Log.Error().
+			Str(zerolog.ErrorStackFieldName, string(debug.Stack())).
+			Interface(zerolog.ErrorFieldName, err).
+			Str("event_content", string(d)).
+			Msg("Panic in Matrix event handler")
 	}
 }
 

appservice/http.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2022 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -16,6 +16,7 @@ import (
 	"time"
 
 	"github.com/gorilla/mux"
+	"github.com/rs/zerolog"
 
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/event"
@@ -38,16 +39,17 @@ func (as *AppService) Start() {
 		Addr:    as.Host.Address(),
 		Handler: as.Router,
 	}
-	as.Log.Infoln("Listening on", as.Host.Address())
 	if len(as.Host.TLSCert) == 0 || len(as.Host.TLSKey) == 0 {
+		as.Log.Info().Str("address", as.Host.Address()).Msg("Starting HTTP listener")
 		err = as.server.ListenAndServe()
 	} else {
+		as.Log.Info().Str("address", as.Host.Address()).Msg("Starting HTTP listener with TLS")
 		err = as.server.ListenAndServeTLS(as.Host.TLSCert, as.Host.TLSKey)
 	}
 	if err != nil && !errors.Is(err, http.ErrServerClosed) {
-		as.Log.Fatalln("Error while listening:", err)
+		as.Log.Error().Err(err).Msg("Error in HTTP listener")
 	} else {
-		as.Log.Debugln("Listener stopped.")
+		as.Log.Debug().Msg("HTTP listener stopped")
 	}
 }
 
@@ -116,57 +118,61 @@ func (as *AppService) PutTransaction(w http.ResponseWriter, r *http.Request) {
 		}.Write(w)
 		return
 	}
+	log := as.Log.With().Str("txn_id", txnID).Logger()
+	ctx := context.Background()
+	ctx = log.WithContext(ctx)
 	if as.txnIDC.IsProcessed(txnID) {
 		// Duplicate transaction ID: no-op
 		WriteBlankOK(w)
-		as.Log.Debugfln("Ignoring duplicate transaction %s", txnID)
+		log.Debug().Msg("Ignoring duplicate transaction")
 		return
 	}
 
 	var txn Transaction
 	err = json.Unmarshal(body, &txn)
 	if err != nil {
-		as.Log.Warnfln("Failed to parse JSON of transaction %s: %v", txnID, err)
+		log.Error().Err(err).Msg("Failed to parse transaction content")
 		Error{
 			ErrorCode:  ErrBadJSON,
 			HTTPStatus: http.StatusBadRequest,
 			Message:    "Failed to parse body JSON",
 		}.Write(w)
 	} else {
-		as.handleTransaction(txnID, &txn)
+		as.handleTransaction(ctx, txnID, &txn)
 		WriteBlankOK(w)
 	}
 }
 
-func (as *AppService) handleTransaction(id string, txn *Transaction) {
-	as.Log.Debugfln("Starting handling of transaction %s (%s)", id, txn.ContentString())
+func (as *AppService) handleTransaction(ctx context.Context, id string, txn *Transaction) {
+	log := zerolog.Ctx(ctx)
+	log.Debug().Object("content", txn).Msg("Starting handling of transaction")
 	if as.Registration.EphemeralEvents {
 		if txn.EphemeralEvents != nil {
-			as.handleEvents(txn.EphemeralEvents, event.EphemeralEventType)
+			as.handleEvents(ctx, txn.EphemeralEvents, event.EphemeralEventType)
 		} else if txn.MSC2409EphemeralEvents != nil {
-			as.handleEvents(txn.MSC2409EphemeralEvents, event.EphemeralEventType)
+			as.handleEvents(ctx, txn.MSC2409EphemeralEvents, event.EphemeralEventType)
 		}
 		if txn.ToDeviceEvents != nil {
-			as.handleEvents(txn.ToDeviceEvents, event.ToDeviceEventType)
+			as.handleEvents(ctx, txn.ToDeviceEvents, event.ToDeviceEventType)
 		} else if txn.MSC2409ToDeviceEvents != nil {
-			as.handleEvents(txn.MSC2409ToDeviceEvents, event.ToDeviceEventType)
+			as.handleEvents(ctx, txn.MSC2409ToDeviceEvents, event.ToDeviceEventType)
 		}
 	}
-	as.handleEvents(txn.Events, event.UnknownEventType)
+	as.handleEvents(ctx, txn.Events, event.UnknownEventType)
 	if txn.DeviceLists != nil {
-		as.handleDeviceLists(txn.DeviceLists)
+		as.handleDeviceLists(ctx, txn.DeviceLists)
 	} else if txn.MSC3202DeviceLists != nil {
-		as.handleDeviceLists(txn.MSC3202DeviceLists)
+		as.handleDeviceLists(ctx, txn.MSC3202DeviceLists)
 	}
 	if txn.DeviceOTKCount != nil {
-		as.handleOTKCounts(txn.DeviceOTKCount)
+		as.handleOTKCounts(ctx, txn.DeviceOTKCount)
 	} else if txn.MSC3202DeviceOTKCount != nil {
-		as.handleOTKCounts(txn.MSC3202DeviceOTKCount)
+		as.handleOTKCounts(ctx, txn.MSC3202DeviceOTKCount)
 	}
 	as.txnIDC.MarkProcessed(id)
 }
 
-func (as *AppService) handleOTKCounts(otks OTKCountMap) {
+func (as *AppService) handleOTKCounts(ctx context.Context, otks OTKCountMap) {
 	for userID, devices := range otks {
 		for deviceID, otkCounts := range devices {
 			otkCounts.UserID = userID
@@ -174,21 +180,23 @@ func (as *AppService) handleOTKCounts(otks OTKCountMap) {
 			select {
 			case as.OTKCounts <- &otkCounts:
 			default:
-				as.Log.Warnfln("Dropped OTK count update for %s because channel is full", userID)
+				zerolog.Ctx(ctx).Warn().
+					Str("user_id", userID.String()).
+					Msg("Dropped OTK count update for user because channel is full")
 			}
 		}
 	}
 }
 
-func (as *AppService) handleDeviceLists(dl *mautrix.DeviceLists) {
+func (as *AppService) handleDeviceLists(ctx context.Context, dl *mautrix.DeviceLists) {
 	select {
 	case as.DeviceLists <- dl:
 	default:
-		as.Log.Warnln("Dropped device list update because channel is full")
+		zerolog.Ctx(ctx).Warn().Msg("Dropped device list update because channel is full")
 	}
 }
 
-func (as *AppService) handleEvents(evts []*event.Event, defaultTypeClass event.TypeClass) {
+func (as *AppService) handleEvents(ctx context.Context, evts []*event.Event, defaultTypeClass event.TypeClass) {
 	for _, evt := range evts {
 		evt.Mautrix.ReceivedAt = time.Now()
 		if defaultTypeClass != event.UnknownEventType {
@@ -200,16 +208,23 @@ func (as *AppService) handleEvents(evts []*event.Event, defaultTypeClass event.T
 		}
 		err := evt.Content.ParseRaw(evt.Type)
 		if errors.Is(err, event.ErrUnsupportedContentType) {
-			as.Log.Debugfln("Not parsing content of %s: %v", evt.ID, err)
+			zerolog.Ctx(ctx).Debug().Str("event_id", evt.ID.String()).Msg("Not parsing content of unsupported event")
 		} else if err != nil {
-			as.Log.Debugfln("Failed to parse content of %s (type %s): %v", evt.ID, evt.Type.Type, err)
+			zerolog.Ctx(ctx).Warn().Err(err).
+				Str("event_id", evt.ID.String()).
+				Str("event_type", evt.Type.Type).
+				Msg("Failed to parse content of event")
 		}
 
 		if evt.Type.IsState() {
 			// TODO remove this check after making sure the log doesn't happen
 			historical, ok := evt.Content.Raw["org.matrix.msc2716.historical"].(bool)
 			if ok && historical {
-				as.Log.Warnfln("Received historical state event %s (%s/%s)", evt.ID, evt.Type.Type, evt.GetStateKey())
+				zerolog.Ctx(ctx).Warn().
+					Str("event_id", evt.ID.String()).
+					Str("event_type", evt.Type.Type).
+					Str("state_key", evt.GetStateKey()).
+					Msg("Received historical state event")
 			} else {
 				mautrix.UpdateStateStore(as.StateStore, evt)
 			}

appservice/protocol.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2022 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -41,16 +41,30 @@ type Transaction struct {
 
 func (txn *Transaction) MarshalZerologObject(ctx *zerolog.Event) {
 	ctx.Int("pdu", len(txn.Events))
-	ctx.Int("edu", len(txn.EphemeralEvents))
-	ctx.Int("to_device", len(txn.ToDeviceEvents))
+	if txn.EphemeralEvents != nil {
+		ctx.Int("edu", len(txn.EphemeralEvents))
+	} else if txn.MSC2409EphemeralEvents != nil {
+		ctx.Int("unstable_edu", len(txn.MSC2409EphemeralEvents))
+	}
+	if txn.ToDeviceEvents != nil {
+		ctx.Int("to_device", len(txn.ToDeviceEvents))
+	} else if txn.MSC2409ToDeviceEvents != nil {
+		ctx.Int("unstable_to_device", len(txn.MSC2409ToDeviceEvents))
+	}
 	if len(txn.DeviceOTKCount) > 0 {
 		ctx.Int("otk_count_users", len(txn.DeviceOTKCount))
+	} else if len(txn.MSC3202DeviceOTKCount) > 0 {
+		ctx.Int("unstable_otk_count_users", len(txn.MSC3202DeviceOTKCount))
 	}
 	if txn.DeviceLists != nil {
 		ctx.Int("device_changes", len(txn.DeviceLists.Changed))
+	} else if txn.MSC3202DeviceLists != nil {
+		ctx.Int("unstable_device_changes", len(txn.MSC3202DeviceLists.Changed))
 	}
 	if txn.FallbackKeys != nil {
 		ctx.Int("fallback_key_users", len(txn.FallbackKeys))
+	} else if txn.MSC3202FallbackKeys != nil {
+		ctx.Int("unstable_fallback_key_users", len(txn.MSC3202FallbackKeys))
 	}
 }
 

appservice/websocket.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2022 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -20,6 +20,7 @@ import (
 	"time"
 
 	"github.com/gorilla/websocket"
+	"github.com/rs/zerolog"
 	"github.com/tidwall/gjson"
 	"github.com/tidwall/sjson"
 )
@@ -36,6 +37,8 @@ type WebsocketCommand struct {
 	ReqID   int             `json:"id,omitempty"`
 	Command string          `json:"command"`
 	Data    json.RawMessage `json:"data"`
+
+	Ctx context.Context `json:"-"`
 }
 
 func (wsc *WebsocketCommand) MakeResponse(ok bool, data interface{}) *WebsocketRequest {
@@ -252,7 +255,7 @@ func (as *AppService) RequestWebsocket(ctx context.Context, cmd *WebsocketReques
 }
 
 func (as *AppService) unknownCommandHandler(cmd WebsocketCommand) (bool, interface{}) {
-	as.Log.Warnfln("No handler for websocket command %s (%d)", cmd.Command, cmd.ReqID)
+	zerolog.Ctx(cmd.Ctx).Warn().Msg("No handler for websocket command")
 	return false, fmt.Errorf("unknown request type")
 }
 
@@ -264,28 +267,36 @@ func (as *AppService) SetWebsocketCommandHandler(cmd string, handler WebsocketHa
 
 func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn) {
 	defer stopFunc(ErrWebsocketUnknownError)
+	ctx := context.Background()
 	for {
 		var msg WebsocketMessage
 		err := ws.ReadJSON(&msg)
 		if err != nil {
-			as.Log.Debugln("Error reading from websocket:", err)
+			as.Log.Debug().Err(err).Msg("Error reading from websocket")
 			stopFunc(parseCloseError(err))
 			return
 		}
+		log := as.Log.With().
+			Int("req_id", msg.ReqID).
+			Str("command", msg.Command).
+			Logger()
+		ctx = log.WithContext(ctx)
 		if msg.Command == "" || msg.Command == "transaction" {
 			if msg.TxnID == "" || !as.txnIDC.IsProcessed(msg.TxnID) {
-				as.handleTransaction(msg.TxnID, &msg.Transaction)
+				as.handleTransaction(ctx, msg.TxnID, &msg.Transaction)
 			} else {
-				as.Log.Debugfln("Ignoring duplicate transaction %s (%s)", msg.TxnID, msg.Transaction.ContentString())
+				log.Debug().
+					Object("content", &msg.Transaction).
+					Msg("Ignoring duplicate transaction")
 			}
 			go func() {
 				err = as.SendWebsocket(msg.MakeResponse(true, &WebsocketTransactionResponse{TxnID: msg.TxnID}))
 				if err != nil {
-					as.Log.Warnfln("Failed to send response to %s %d: %v", msg.Command, msg.ReqID, err)
+					log.Warn().Err(err).Msg("Failed to send response to websocket transaction")
 				}
 			}()
 		} else if msg.Command == "connect" {
-			as.Log.Debugln("Websocket connect confirmation received")
+			log.Debug().Msg("Websocket connect confirmation received")
 		} else if msg.Command == "response" || msg.Command == "error" {
 			as.websocketRequestsLock.RLock()
 			respChan, ok := as.websocketRequests[msg.ReqID]
@@ -293,14 +304,14 @@ func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn)
 				select {
 				case respChan <- &msg.WebsocketCommand:
 				default:
-					as.Log.Warnfln("Failed to handle response to %d: channel didn't accept response", msg.ReqID)
+					log.Warn().Msg("Failed to handle response: channel didn't accept response")
 				}
 			} else {
-				as.Log.Warnfln("Dropping response to %d: unknown request ID", msg.ReqID)
+				log.Warn().Msg("Dropping response to unknown request ID")
 			}
 			as.websocketRequestsLock.RUnlock()
 		} else {
-			as.Log.Debugfln("Received command request %s %d", msg.Command, msg.ReqID)
+			log.Debug().Msg("Received websocket command")
 			as.websocketHandlersLock.RLock()
 			handler, ok := as.websocketHandlers[msg.Command]
 			as.websocketHandlersLock.RUnlock()
@@ -311,11 +322,11 @@ func (as *AppService) consumeWebsocket(stopFunc func(error), ws *websocket.Conn)
 				okResp, data := handler(msg.WebsocketCommand)
 				err = as.SendWebsocket(msg.MakeResponse(okResp, data))
 				if err != nil {
-					as.Log.Warnfln("Failed to send response to %s %d: %v", msg.Command, msg.ReqID, err)
+					log.Error().Err(err).Msg("Failed to send response to websocket command")
 				} else if okResp {
-					as.Log.Debugfln("Sent success response to %s %d", msg.Command, msg.ReqID)
+					log.Debug().Msg("Sent success response to websocket command")
 				} else {
-					as.Log.Debugfln("Sent error response to %s %d", msg.Command, msg.ReqID)
+					log.Debug().Msg("Sent error response to websocket command")
 				}
 			}()
 		}
@@ -364,7 +375,7 @@ func (as *AppService) StartWebsocket(baseURL string, onConnect func()) error {
 	as.ws = ws
 	as.StopWebsocket = stopFunc
 	as.PrepareWebsocket()
-	as.Log.Debugln("Appservice transaction websocket connected")
+	as.Log.Debug().Msg("Appservice transaction websocket opened")
 
 	go as.consumeWebsocket(stopFunc, ws)
 
@@ -382,11 +393,11 @@ func (as *AppService) StartWebsocket(baseURL string, onConnect func()) error {
 	_ = ws.SetWriteDeadline(time.Now().Add(3 * time.Second))
 	err = ws.WriteMessage(websocket.CloseMessage, websocket.FormatCloseMessage(websocket.CloseGoingAway, ""))
 	if err != nil && !errors.Is(err, websocket.ErrCloseSent) {
-		as.Log.Warnln("Error writing close message to websocket:", err)
+		as.Log.Warn().Err(err).Msg("Error writing close message to websocket")
 	}
 	err = ws.Close()
 	if err != nil {
-		as.Log.Warnln("Error closing websocket:", err)
+		as.Log.Warn().Err(err).Msg("Error closing websocket")
 	}
 	return closeErr
 }

bridge/bridge.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2022 Tulir Asokan
+// Copyright (c) 2023 Tulir Asokan
 //
 // This Source Code Form is subject to the terms of the Mozilla Public
 // License, v. 2.0. If a copy of the MPL was not distributed with this
@@ -17,9 +17,10 @@ import (
 	"time"
 
 	"github.com/mattn/go-sqlite3"
+	"github.com/rs/zerolog"
 	"gopkg.in/yaml.v3"
 	flag "maunium.net/go/mauflag"
-	log "maunium.net/go/maulogger/v2"
+	"maunium.net/go/maulogger/v2"
 
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/appservice"
@@ -28,6 +29,7 @@ import (
 	"maunium.net/go/mautrix/event"
 	"maunium.net/go/mautrix/id"
 	"maunium.net/go/mautrix/sqlstatestore"
+	"maunium.net/go/mautrix/util"
 	"maunium.net/go/mautrix/util/configupgrade"
 	"maunium.net/go/mautrix/util/dbutil"
 	_ "maunium.net/go/mautrix/util/dbutil/litestream"
@@ -163,12 +165,15 @@ type Bridge struct {
 	RegistrationPath string
 	SaveConfig       bool
 	ConfigUpgrader   configupgrade.BaseUpgrader
-	Log              log.Logger
 	DB               *dbutil.Database
 	StateStore       *sqlstatestore.SQLStateStore
 	Crypto           Crypto
 	CryptoPickleKey  string
 
+	// Deprecated: Switch to ZLog
+	Log  maulogger.Logger
+	ZLog *zerolog.Logger
+
 	MediaConfig  mautrix.RespMediaConfig
 	SpecVersions mautrix.RespVersions
 
@@ -394,31 +399,26 @@ func (br *Bridge) init() {
 
 	br.MediaConfig.UploadSize = 50 * 1024 * 1024
 
+	br.ZLog, err = br.Config.Logging.Compile()
+	if err != nil {
+		_, _ = fmt.Fprintln(os.Stderr, "Failed to initialize logger:", err)
+		os.Exit(12)
+	}
+	br.Log = util.ZeroToMauLog(br.ZLog)
+
 	br.AS = br.Config.MakeAppService()
 	br.AS.DoublePuppetValue = br.Name
 	br.AS.GetProfile = br.getProfile
+	br.AS.Log = *br.ZLog
+	br.AS.LogConfig = nil
 	_, _ = br.AS.Init()
 
-	if br.Log == nil {
-		br.Log = log.Create()
-	}
-	br.Config.Logging.Configure(br.Log)
-	log.DefaultLogger = br.Log.(*log.BasicLogger)
-	if len(br.Config.Logging.FileNameFormat) > 0 {
-		err = log.OpenFile()
-		if err != nil {
-			_, _ = fmt.Fprintln(os.Stderr, "Failed to open log file:", err)
-			os.Exit(12)
-		}
-	}
-
 	err = br.validateConfig()
 	if err != nil {
 		br.Log.Fatalln("Configuration error:", err)
 		os.Exit(11)
 	}
 
-	br.AS.Log = log.Sub("Matrix")
 	br.Bot = br.AS.BotIntent()
 	br.Log.Infoln("Initializing", br.VersionDesc)
 

bridge/bridgeconfig/config.go

@@ -11,6 +11,8 @@ import (
 	"regexp"
 	"strings"
 
+	"go.mau.fi/zeroconfig"
+
 	"maunium.net/go/mautrix/appservice"
 	"maunium.net/go/mautrix/id"
 	"maunium.net/go/mautrix/util"
@@ -197,10 +199,10 @@ type ManagementRoomTexts struct {
 }
 
 type BaseConfig struct {
-	Homeserver HomeserverConfig     `yaml:"homeserver"`
-	AppService AppserviceConfig     `yaml:"appservice"`
-	Bridge     BridgeConfig         `yaml:"-"`
-	Logging    appservice.LogConfig `yaml:"logging"`
+	Homeserver HomeserverConfig  `yaml:"homeserver"`
+	AppService AppserviceConfig  `yaml:"appservice"`
+	Bridge     BridgeConfig      `yaml:"-"`
+	Logging    zeroconfig.Config `yaml:"logging"`
 }
 
 func doUpgrade(helper *up.Helper) {
@@ -239,14 +241,16 @@ func doUpgrade(helper *up.Helper) {
 	helper.Copy(up.Str, "appservice", "as_token")
 	helper.Copy(up.Str, "appservice", "hs_token")
 
-	helper.Copy(up.Str, "logging", "directory")
-	helper.Copy(up.Str|up.Null, "logging", "file_name_format")
-	helper.Copy(up.Str|up.Timestamp, "logging", "file_date_format")
-	helper.Copy(up.Int, "logging", "file_mode")
-	helper.Copy(up.Str|up.Timestamp, "logging", "timestamp_format")
-	helper.Copy(up.Str, "logging", "print_level")
-	helper.Copy(up.Bool, "logging", "print_json")
-	helper.Copy(up.Bool, "logging", "file_json")
+	helper.Copy(up.Map, "logging")
+	// TODO migrate approximate settings from old config
+	//helper.Copy(up.Str, "logging", "directory")
+	//helper.Copy(up.Str|up.Null, "logging", "file_name_format")
+	//helper.Copy(up.Str|up.Timestamp, "logging", "file_date_format")
+	//helper.Copy(up.Int, "logging", "file_mode")
+	//helper.Copy(up.Str|up.Timestamp, "logging", "timestamp_format")
+	//helper.Copy(up.Str, "logging", "print_level")
+	//helper.Copy(up.Bool, "logging", "print_json")
+	//helper.Copy(up.Bool, "logging", "file_json")
 }
 
 // Upgrader is a config upgrader that copies the default fields in the homeserver, appservice and logging blocks.

go.mod

@@ -13,6 +13,7 @@ require (
 	github.com/tidwall/gjson v1.14.4
 	github.com/tidwall/sjson v1.2.5
 	github.com/yuin/goldmark v1.5.4
+	go.mau.fi/zeroconfig v0.0.0-20230220212126-e089a3ad8557
 	golang.org/x/crypto v0.6.0
 	golang.org/x/net v0.6.0
 	gopkg.in/yaml.v3 v3.0.1
@@ -21,6 +22,7 @@ require (
 )
 
 require (
+	github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/mattn/go-colorable v0.1.12 // indirect
 	github.com/mattn/go-isatty v0.0.14 // indirect
@@ -28,4 +30,5 @@ require (
 	github.com/tidwall/match v1.1.1 // indirect
 	github.com/tidwall/pretty v1.2.0 // indirect
 	golang.org/x/sys v0.5.0 // indirect
+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
 )

go.sum

@@ -1,5 +1,6 @@
 github.com/DATA-DOG/go-sqlmock v1.5.0 h1:Shsta01QNfFxHCfpW6YH2STWB0MudeXXEWMr20OEh60=
 github.com/DATA-DOG/go-sqlmock v1.5.0/go.mod h1:f/Ixk793poVmq4qj/V1dPUg2JEAKC73Q5eFN3EC/SaM=
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534 h1:rtAn27wIbmOGUs7RIbVgPEjb31ehTVniDwPGXyMxm5U=
 github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
@@ -41,6 +42,8 @@ github.com/tidwall/sjson v1.2.5 h1:kLy8mja+1c9jlljvWTlSazM7cKDRfJuR/bOJhcY5NcY=
 github.com/tidwall/sjson v1.2.5/go.mod h1:Fvgq9kS/6ociJEDnK0Fk1cpYF4FIW6ZF7LAe+6jwd28=
 github.com/yuin/goldmark v1.5.4 h1:2uY/xC0roWy8IBEGLgB1ywIoEJFGmRrX21YQcvGZzjU=
 github.com/yuin/goldmark v1.5.4/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
+go.mau.fi/zeroconfig v0.0.0-20230220212126-e089a3ad8557 h1:KaQ6/4NzWIndaxdz49ijHkuZEtE4KAs1ExrHlpiiXG8=
+go.mau.fi/zeroconfig v0.0.0-20230220212126-e089a3ad8557/go.mod h1:NcSJkf180JT+1IId76PcMuLTNa1CzsFFZ0nBygIQM70=
 golang.org/x/crypto v0.6.0 h1:qfktjS5LUO+fFKeJXZ+ikTRijMmljikvG68fpMMruSc=
 golang.org/x/crypto v0.6.0/go.mod h1:OFC/31mSvZgRz0V1QTNCzfAI1aIRzbiufJtkMIlEp58=
 golang.org/x/net v0.6.0 h1:L4ZwwTvKW9gr0ZMS1yrHD9GZhIuVjOBBnaKH+SPQK0Q=
@@ -51,6 +54,8 @@ golang.org/x/sys v0.5.0 h1:MUK/U/4lj1t1oPg0HfuXDN/Z1wv31ZJ/YcPiGccS4DU=
 golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
 gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

util/mauzerolog.go

@@ -0,0 +1,178 @@
+// Copyright (c) 2023 Tulir Asokan
+//
+// This Source Code Form is subject to the terms of the Mozilla Public
+// License, v. 2.0. If a copy of the MPL was not distributed with this
+// file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+package util
+
+import (
+	"fmt"
+	"io"
+	"strings"
+
+	"github.com/rs/zerolog"
+	"maunium.net/go/maulogger/v2"
+)
+
+type MauZeroLog struct {
+	*zerolog.Logger
+	mod string
+}
+
+func ZeroToMauLog(log *zerolog.Logger) maulogger.Logger {
+	return MauZeroLog{log, ""}
+}
+
+var _ maulogger.Logger = (*MauZeroLog)(nil)
+
+func (m MauZeroLog) Sub(module string) maulogger.Logger {
+	if m.mod != "" {
+		module = fmt.Sprintf("%s/%s", m.mod, module)
+	}
+	log := m.With().Str("module", module).Logger()
+	return MauZeroLog{&log, module}
+}
+
+func (m MauZeroLog) Subm(module string, metadata map[string]interface{}) maulogger.Logger {
+	if m.mod != "" {
+		module = fmt.Sprintf("%s/%s", m.mod, module)
+	}
+	with := m.With().Str("module", module)
+	for key, value := range metadata {
+		with = with.Interface(key, value)
+	}
+	log := with.Logger()
+	return MauZeroLog{&log, module}
+}
+
+func (m MauZeroLog) WithDefaultLevel(_ maulogger.Level) maulogger.Logger {
+	return m
+}
+
+func (m MauZeroLog) GetParent() maulogger.Logger {
+	return nil
+}
+
+type nopWriteCloser struct {
+	io.Writer
+}
+
+func (nopWriteCloser) Close() error { return nil }
+
+func (m MauZeroLog) Writer(level maulogger.Level) io.WriteCloser {
+	return nopWriteCloser{m.Logger.With().Str(zerolog.LevelFieldName, zerolog.LevelFieldMarshalFunc(mauToZeroLevel(level))).Logger()}
+}
+
+func mauToZeroLevel(level maulogger.Level) zerolog.Level {
+	switch level {
+	case maulogger.LevelDebug:
+		return zerolog.DebugLevel
+	case maulogger.LevelInfo:
+		return zerolog.InfoLevel
+	case maulogger.LevelWarn:
+		return zerolog.WarnLevel
+	case maulogger.LevelError:
+		return zerolog.ErrorLevel
+	case maulogger.LevelFatal:
+		return zerolog.FatalLevel
+	default:
+		return zerolog.TraceLevel
+	}
+}
+
+func (m MauZeroLog) Log(level maulogger.Level, parts ...interface{}) {
+	m.Logger.WithLevel(mauToZeroLevel(level)).Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Logln(level maulogger.Level, parts ...interface{}) {
+	m.Logger.WithLevel(mauToZeroLevel(level)).Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Logf(level maulogger.Level, message string, args ...interface{}) {
+	m.Logger.WithLevel(mauToZeroLevel(level)).Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Logfln(level maulogger.Level, message string, args ...interface{}) {
+	m.Logger.WithLevel(mauToZeroLevel(level)).Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Debug(parts ...interface{}) {
+	m.Logger.Debug().Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Debugln(parts ...interface{}) {
+	m.Logger.Debug().Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Debugf(message string, args ...interface{}) {
+	m.Logger.Debug().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Debugfln(message string, args ...interface{}) {
+	m.Logger.Debug().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Info(parts ...interface{}) {
+	m.Logger.Info().Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Infoln(parts ...interface{}) {
+	m.Logger.Info().Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Infof(message string, args ...interface{}) {
+	m.Logger.Info().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Infofln(message string, args ...interface{}) {
+	m.Logger.Info().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Warn(parts ...interface{}) {
+	m.Logger.Warn().Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Warnln(parts ...interface{}) {
+	m.Logger.Warn().Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Warnf(message string, args ...interface{}) {
+	m.Logger.Warn().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Warnfln(message string, args ...interface{}) {
+	m.Logger.Warn().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Error(parts ...interface{}) {
+	m.Logger.Error().Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Errorln(parts ...interface{}) {
+	m.Logger.Error().Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Errorf(message string, args ...interface{}) {
+	m.Logger.Error().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Errorfln(message string, args ...interface{}) {
+	m.Logger.Error().Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Fatal(parts ...interface{}) {
+	m.Logger.WithLevel(zerolog.FatalLevel).Msg(fmt.Sprint(parts...))
+}
+
+func (m MauZeroLog) Fatalln(parts ...interface{}) {
+	m.Logger.WithLevel(zerolog.FatalLevel).Msg(strings.TrimSuffix(fmt.Sprintln(parts...), "\n"))
+}
+
+func (m MauZeroLog) Fatalf(message string, args ...interface{}) {
+	m.Logger.WithLevel(zerolog.FatalLevel).Msg(fmt.Sprintf(message, args...))
+}
+
+func (m MauZeroLog) Fatalfln(message string, args ...interface{}) {
+	m.Logger.WithLevel(zerolog.FatalLevel).Msg(fmt.Sprintf(message, args...))
+}