implement logging

README.md

@@ -10,11 +10,12 @@ goaim requires [go 1.21](https://go.dev/).
 
 Server configuration is set through environment variables. The following are the most useful configs:
 
-| Env Variable | Description |
-| ------------ | ----------- |
-| `OSCAR_HOST`   | The hostname that the server should bind to. If exposing to the internet, use the public IP. |
+| Env Variable   | Description                                                                                              |
+|----------------|----------------------------------------------------------------------------------------------------------|
+| `OSCAR_HOST`   | The hostname that the server should bind to. If exposing to the internet, use the public IP.             |
 | `DISABLE_AUTH` | If true, auto-create screen names at login and skip the password check. Useful for development purposes. |
-| `DB_PATH`      | The path to the SQLite database. |
+| `DB_PATH`      | The path to the SQLite database.                                                                         |
+| `LOG_LEVEL`    | Set logging granularity. Possible values: `trace`, `debug`, `info`, `warn`, `error`                      |
 
 ### Starting Up
 

cmd/main.go

@@ -1,14 +1,16 @@
 package main
 
 import (
-	"errors"
+	"context"
 	"fmt"
+	"log"
+	"log/slog"
+	"net"
+	"os"
+
 	"github.com/google/uuid"
 	"github.com/kelseyhightower/envconfig"
 	"github.com/mkaminski/goaim/server"
-	"io"
-	"log"
-	"net"
 )
 
 func main() {
@@ -16,29 +18,35 @@ func main() {
 	var cfg server.Config
 	err := envconfig.Process("", &cfg)
 	if err != nil {
-		log.Fatal(err.Error())
+		_, _ = fmt.Fprintf(os.Stderr, "unable to process app config: %s", err.Error())
+		os.Exit(1)
 	}
 
+	logger := server.NewLogger(cfg)
+
 	fm, err := server.NewFeedbagStore(cfg.DBPath)
 	if err != nil {
-		log.Fatal(err)
+		logger.Error("unable to create feedbag store", "err", err.Error())
+		os.Exit(1)
 	}
 
-	go server.StartManagementAPI(fm)
+	go server.StartManagementAPI(fm, logger)
 
-	sm := server.NewSessionManager()
+	sm := server.NewSessionManager(logger)
 	cr := server.NewChatRegistry()
 
-	go listenBOS(cfg, sm, fm, cr)
-	go listenChat(cfg, fm, cr)
+	go listenBOS(cfg, sm, fm, cr, logger.With("svc", "BOS"))
+	go listenChat(cfg, fm, cr, logger.With("svc", "CHAT"))
 
-	listener, err := net.Listen("tcp", server.Address("", cfg.OSCARPort))
+	addr := server.Address("", cfg.OSCARPort)
+	listener, err := net.Listen("tcp", addr)
 	if err != nil {
-		log.Fatal(err)
+		logger.Error("unable to bind OSCAR server address", "err", err.Error())
+		os.Exit(1)
 	}
 	defer listener.Close()
 
-	fmt.Printf("OSCAR server listening on %s\n", server.Address(cfg.OSCARHost, cfg.OSCARPort))
+	logger.Info("starting OSCAR server", "addr", addr)
 
 	for {
 		conn, err := listener.Accept()
@@ -51,43 +59,53 @@ func main() {
 	}
 }
 
-func listenBOS(cfg server.Config, sm *server.InMemorySessionManager, fm *server.FeedbagStore, cr *server.ChatRegistry) {
-	listener, err := net.Listen("tcp", server.Address("", cfg.BOSPort))
+func listenBOS(cfg server.Config, sm *server.InMemorySessionManager, fm *server.FeedbagStore, cr *server.ChatRegistry, logger *slog.Logger) {
+	addr := server.Address("", cfg.BOSPort)
+	listener, err := net.Listen("tcp", addr)
 	if err != nil {
-		log.Fatal(err)
+		logger.Error("unable to bind BOS server address", "err", err.Error())
+		os.Exit(1)
 	}
 	defer listener.Close()
 
-	fmt.Printf("BOS server listening on %s\n", server.Address(cfg.OSCARHost, cfg.BOSPort))
+	logger.Info("starting service", "addr", addr)
 
-	router := server.NewRouter()
+	router := server.NewRouter(logger)
 	for {
 		conn, err := listener.Accept()
 		if err != nil {
 			log.Println(err)
 			continue
 		}
-		go handleBOSConnection(cfg, sm, fm, cr, conn, router)
+		ctx := context.Background()
+		ctx = context.WithValue(ctx, "ip", conn.RemoteAddr().String())
+		logger.DebugContext(ctx, "accepted connection")
+		go handleBOSConnection(ctx, cfg, sm, fm, cr, conn, router, logger)
 	}
 }
 
-func listenChat(cfg server.Config, fm *server.FeedbagStore, cr *server.ChatRegistry) {
-	listener, err := net.Listen("tcp", server.Address("", cfg.ChatPort))
+func listenChat(cfg server.Config, fm *server.FeedbagStore, cr *server.ChatRegistry, logger *slog.Logger) {
+	addr := server.Address("", cfg.ChatPort)
+	listener, err := net.Listen("tcp", addr)
 	if err != nil {
-		log.Fatal(err)
+		logger.Error("unable to bind chat server address", "err", err.Error())
+		os.Exit(1)
 	}
 	defer listener.Close()
 
-	fmt.Printf("Chat server listening on %s\n", server.Address(cfg.OSCARHost, cfg.ChatPort))
+	logger.Info("starting service", "addr", addr)
 
-	router := server.NewRouterForChat()
+	router := server.NewRouterForChat(logger)
 	for {
 		conn, err := listener.Accept()
 		if err != nil {
 			log.Println(err)
 			continue
 		}
-		go handleChatConnection(cfg, fm, cr, conn, router)
+		ctx := context.Background()
+		ctx = context.WithValue(ctx, "ip", conn.RemoteAddr().String())
+		logger.DebugContext(ctx, "accepted connection")
+		go handleChatConnection(ctx, cfg, fm, cr, conn, router, logger)
 	}
 }
 
@@ -113,10 +131,10 @@ func handleAuthConnection(cfg server.Config, sm *server.InMemorySessionManager,
 	}
 }
 
-func handleBOSConnection(cfg server.Config, sm *server.InMemorySessionManager, fm *server.FeedbagStore, cr *server.ChatRegistry, conn net.Conn, router server.Router) {
+func handleBOSConnection(ctx context.Context, cfg server.Config, sm *server.InMemorySessionManager, fm *server.FeedbagStore, cr *server.ChatRegistry, conn net.Conn, router server.Router, logger *slog.Logger) {
 	sess, seq, err := server.VerifyLogin(sm, conn)
 	if err != nil {
-		fmt.Printf("user disconnected with error: %s\n", err.Error())
+		logger.ErrorContext(ctx, "user disconnected with error", "err", err.Error())
 		return
 	}
 
@@ -125,54 +143,43 @@ func handleBOSConnection(cfg server.Config, sm *server.InMemorySessionManager, f
 
 	go func() {
 		<-sess.Closed()
-		server.Signout(sess, sm, fm)
+		server.Signout(ctx, logger, sess, sm, fm)
 	}()
 
-	if err := server.ReadBos(cfg, sess, seq, sm, fm, cr, conn, server.ChatRoom{}, router); err != nil {
-		switch {
-		case errors.Is(io.EOF, err):
-			fallthrough
-		case errors.Is(server.ErrSignedOff, err):
-			fmt.Println("user signed off")
-		default:
-			fmt.Printf("user disconnected with error: %s\n", err.Error())
-		}
-	}
+	ctx = context.WithValue(ctx, "screenName", sess.ScreenName)
+
+	server.ReadBos(ctx, cfg, sess, seq, sm, fm, cr, conn, server.ChatRoom{}, router, logger)
 }
 
-func handleChatConnection(cfg server.Config, fm *server.FeedbagStore, cr *server.ChatRegistry, conn net.Conn, router server.Router) {
+func handleChatConnection(ctx context.Context, cfg server.Config, fm *server.FeedbagStore, cr *server.ChatRegistry, conn net.Conn, router server.Router, logger *slog.Logger) {
 	cookie, seq, err := server.VerifyChatLogin(conn)
 	if err != nil {
-		fmt.Printf("user disconnected with error: %s\n", err.Error())
+		logger.ErrorContext(ctx, "user disconnected with error", "err", err.Error())
 		return
 	}
 
 	room, err := cr.Retrieve(string(cookie.Cookie))
 	if err != nil {
-		fmt.Printf("unable to find chat room: %s\n", err.Error())
+		logger.ErrorContext(ctx, "unable to find chat room", "err", err.Error())
 		return
 	}
 
 	chatSess, found := room.Retrieve(cookie.SessID)
 	if !found {
-		fmt.Printf("unable to find user for session: %s\n", cookie.SessID)
+		logger.ErrorContext(ctx, "unable to find user for session", "sessID", cookie.SessID)
 		return
 	}
 
 	defer chatSess.Close()
 	go func() {
 		<-chatSess.Closed()
-		server.AlertUserLeft(chatSess, room)
+		server.AlertUserLeft(ctx, chatSess, room)
 		room.Remove(chatSess)
 		cr.MaybeRemoveRoom(room.Cookie)
 		conn.Close()
 	}()
 
-	if err := server.ReadBos(cfg, chatSess, seq, room.SessionManager, fm, cr, conn, room, router); err != nil {
-		if err != io.EOF {
-			fmt.Printf("user disconnected with error: %s\n", err.Error())
-		} else {
-			fmt.Println("user disconnected")
-		}
-	}
+	ctx = context.WithValue(ctx, "screenName", chatSess.ScreenName)
+
+	server.ReadBos(ctx, cfg, chatSess, seq, room.SessionManager, fm, cr, conn, room, router, logger)
 }

oscar/snacs_string.go

@@ -0,0 +1,255 @@
+package oscar
+
+var foodGroupStr = map[uint16]string{
+	OSERVICE:      "OSERVICE",
+	LOCATE:        "LOCATE",
+	BUDDY:         "BUDDY",
+	ICBM:          "ICBM",
+	ADVERT:        "ADVERT",
+	INVITE:        "INVITE",
+	ADMIN:         "ADMIN",
+	POPUP:         "POPUP",
+	PD:            "PD",
+	USER_LOOKUP:   "USER_LOOKUP",
+	STATS:         "STATS",
+	TRANSLATE:     "TRANSLATE",
+	CHAT_NAV:      "CHAT_NAV",
+	CHAT:          "CHAT",
+	ODIR:          "ODIR",
+	BART:          "BART",
+	FEEDBAG:       "FEEDBAG",
+	ICQ:           "ICQ",
+	BUCP:          "BUCP",
+	ALERT:         "ALERT",
+	PLUGIN:        "PLUGIN",
+	UNNAMED_FG_24: "UNNAMED_FG_24",
+	MDIR:          "MDIR",
+	ARS:           "ARS",
+}
+
+func FoodGroupStr(v uint16) string {
+	return foodGroupStr[v]
+}
+
+var subGroupStr = map[uint16]map[uint16]string{
+	OSERVICE: {
+		OServiceErr:               "OServiceErr",
+		OServiceClientOnline:      "OServiceClientOnline",
+		OServiceHostOnline:        "OServiceHostOnline",
+		OServiceServiceRequest:    "OServiceServiceRequest",
+		OServiceServiceResponse:   "OServiceServiceResponse",
+		OServiceRateParamsQuery:   "OServiceRateParamsQuery",
+		OServiceRateParamsReply:   "OServiceRateParamsReply",
+		OServiceRateParamsSubAdd:  "OServiceRateParamsSubAdd",
+		OServiceRateDelParamSub:   "OServiceRateDelParamSub",
+		OServiceRateParamChange:   "OServiceRateParamChange",
+		OServicePauseReq:          "OServicePauseReq",
+		OServicePauseAck:          "OServicePauseAck",
+		OServiceResume:            "OServiceResume",
+		OServiceUserInfoQuery:     "OServiceUserInfoQuery",
+		OServiceUserInfoUpdate:    "OServiceUserInfoUpdate",
+		OServiceEvilNotification:  "OServiceEvilNotification",
+		OServiceIdleNotification:  "OServiceIdleNotification",
+		OServiceMigrateGroups:     "OServiceMigrateGroups",
+		OServiceMotd:              "OServiceMotd",
+		OServiceSetPrivacyFlags:   "OServiceSetPrivacyFlags",
+		OServiceWellKnownUrls:     "OServiceWellKnownUrls",
+		OServiceNoop:              "OServiceNoop",
+		OServiceClientVersions:    "OServiceClientVersions",
+		OServiceHostVersions:      "OServiceHostVersions",
+		OServiceMaxConfigQuery:    "OServiceMaxConfigQuery",
+		OServiceMaxConfigReply:    "OServiceMaxConfigReply",
+		OServiceStoreConfig:       "OServiceStoreConfig",
+		OServiceConfigQuery:       "OServiceConfigQuery",
+		OServiceConfigReply:       "OServiceConfigReply",
+		OServiceSetUserInfoFields: "OServiceSetUserInfoFields",
+		OServiceProbeReq:          "OServiceProbeReq",
+		OServiceProbeAck:          "OServiceProbeAck",
+		OServiceBartReply:         "OServiceBartReply",
+		OServiceBartQuery2:        "OServiceBartQuery2",
+		OServiceBartReply2:        "OServiceBartReply2",
+	},
+	LOCATE: {
+		LocateErr:                  "LocateErr",
+		LocateRightsQuery:          "LocateRightsQuery",
+		LocateRightsReply:          "LocateRightsReply",
+		LocateSetInfo:              "LocateSetInfo",
+		LocateUserInfoQuery:        "LocateUserInfoQuery",
+		LocateUserInfoReply:        "LocateUserInfoReply",
+		LocateWatcherSubRequest:    "LocateWatcherSubRequest",
+		LocateWatcherNotification:  "LocateWatcherNotification",
+		LocateSetDirInfo:           "LocateSetDirInfo",
+		LocateSetDirReply:          "LocateSetDirReply",
+		LocateGetDirInfo:           "LocateGetDirInfo",
+		LocateGetDirReply:          "LocateGetDirReply",
+		LocateGroupCapabilityQuery: "LocateGroupCapabilityQuery",
+		LocateGroupCapabilityReply: "LocateGroupCapabilityReply",
+		LocateSetKeywordInfo:       "LocateSetKeywordInfo",
+		LocateSetKeywordReply:      "LocateSetKeywordReply",
+		LocateGetKeywordInfo:       "LocateGetKeywordInfo",
+		LocateGetKeywordReply:      "LocateGetKeywordReply",
+		LocateFindListByEmail:      "LocateFindListByEmail",
+		LocateFindListReply:        "LocateFindListReply",
+		LocateUserInfoQuery2:       "LocateUserInfoQuery2",
+	},
+	BUDDY: {
+		BuddyErr:                 "BuddyErr",
+		BuddyRightsQuery:         "BuddyRightsQuery",
+		BuddyRightsReply:         "BuddyRightsReply",
+		BuddyAddBuddies:          "BuddyAddBuddies",
+		BuddyDelBuddies:          "BuddyDelBuddies",
+		BuddyWatcherListQuery:    "BuddyWatcherListQuery",
+		BuddyWatcherListResponse: "BuddyWatcherListResponse",
+		BuddyWatcherSubRequest:   "BuddyWatcherSubRequest",
+		BuddyWatcherNotification: "BuddyWatcherNotification",
+		BuddyRejectNotification:  "BuddyRejectNotification",
+		BuddyArrived:             "BuddyArrived",
+		BuddyDeparted:            "BuddyDeparted",
+		BuddyAddTempBuddies:      "BuddyAddTempBuddies",
+		BuddyDelTempBuddies:      "BuddyDelTempBuddies",
+	},
+	ICBM: {
+		ICBMErr:                "ICBMErr",
+		ICBMAddParameters:      "ICBMAddParameters",
+		ICBMDelParameters:      "ICBMDelParameters",
+		ICBMParameterQuery:     "ICBMParameterQuery",
+		ICBMParameterReply:     "ICBMParameterReply",
+		ICBMChannelMsgToHost:   "ICBMChannelMsgToHost",
+		ICBMChannelMsgToclient: "ICBMChannelMsgToclient",
+		ICBMEvilRequest:        "ICBMEvilRequest",
+		ICBMEvilReply:          "ICBMEvilReply",
+		ICBMMissedCalls:        "ICBMMissedCalls",
+		ICBMClientErr:          "ICBMClientErr",
+		ICBMHostAck:            "ICBMHostAck",
+		ICBMSinStored:          "ICBMSinStored",
+		ICBMSinListQuery:       "ICBMSinListQuery",
+		ICBMSinListReply:       "ICBMSinListReply",
+		ICBMSinRetrieve:        "ICBMSinRetrieve",
+		ICBMSinDelete:          "ICBMSinDelete",
+		ICBMNotifyRequest:      "ICBMNotifyRequest",
+		ICBMNotifyReply:        "ICBMNotifyReply",
+		ICBMClientEvent:        "ICBMClientEvent",
+		ICBMSinReply:           "ICBMSinReply",
+	},
+	CHAT_NAV: {
+		ChatNavErr:                 "ChatNavErr",
+		ChatNavRequestChatRights:   "ChatNavRequestChatRights",
+		ChatNavRequestExchangeInfo: "ChatNavRequestExchangeInfo",
+		ChatNavRequestRoomInfo:     "ChatNavRequestRoomInfo",
+		ChatNavRequestMoreRoomInfo: "ChatNavRequestMoreRoomInfo",
+		ChatNavRequestOccupantList: "ChatNavRequestOccupantList",
+		ChatNavSearchForRoom:       "ChatNavSearchForRoom",
+		ChatNavCreateRoom:          "ChatNavCreateRoom",
+		ChatNavNavInfo:             "ChatNavNavInfo",
+	},
+	CHAT: {
+		ChatErr:                "ChatErr",
+		ChatRoomInfoUpdate:     "ChatRoomInfoUpdate",
+		ChatUsersJoined:        "ChatUsersJoined",
+		ChatUsersLeft:          "ChatUsersLeft",
+		ChatChannelMsgToHost:   "ChatChannelMsgToHost",
+		ChatChannelMsgToClient: "ChatChannelMsgToClient",
+		ChatEvilRequest:        "ChatEvilRequest",
+		ChatEvilReply:          "ChatEvilReply",
+		ChatClientErr:          "ChatClientErr",
+		ChatPauseRoomReq:       "ChatPauseRoomReq",
+		ChatPauseRoomAck:       "ChatPauseRoomAck",
+		ChatResumeRoom:         "ChatResumeRoom",
+		ChatShowMyRow:          "ChatShowMyRow",
+		ChatShowRowByUsername:  "ChatShowRowByUsername",
+		ChatShowRowByNumber:    "ChatShowRowByNumber",
+		ChatShowRowByName:      "ChatShowRowByName",
+		ChatRowInfo:            "ChatRowInfo",
+		ChatListRows:           "ChatListRows",
+		ChatRowListInfo:        "ChatRowListInfo",
+		ChatMoreRows:           "ChatMoreRows",
+		ChatMoveToRow:          "ChatMoveToRow",
+		ChatToggleChat:         "ChatToggleChat",
+		ChatSendQuestion:       "ChatSendQuestion",
+		ChatSendComment:        "ChatSendComment",
+		ChatTallyVote:          "ChatTallyVote",
+		ChatAcceptBid:          "ChatAcceptBid",
+		ChatSendInvite:         "ChatSendInvite",
+		ChatDeclineInvite:      "ChatDeclineInvite",
+		ChatAcceptInvite:       "ChatAcceptInvite",
+		ChatNotifyMessage:      "ChatNotifyMessage",
+		ChatGotoRow:            "ChatGotoRow",
+		ChatStageUserJoin:      "ChatStageUserJoin",
+		ChatStageUserLeft:      "ChatStageUserLeft",
+		ChatUnnamedSnac22:      "ChatUnnamedSnac22",
+		ChatClose:              "ChatClose",
+		ChatUserBan:            "ChatUserBan",
+		ChatUserUnban:          "ChatUserUnban",
+		ChatJoined:             "ChatJoined",
+		ChatUnnamedSnac27:      "ChatUnnamedSnac27",
+		ChatUnnamedSnac28:      "ChatUnnamedSnac28",
+		ChatUnnamedSnac29:      "ChatUnnamedSnac29",
+		ChatRoomInfoOwner:      "ChatRoomInfoOwner",
+	},
+	FEEDBAG: {
+		FeedbagErr:                      "FeedbagErr",
+		FeedbagRightsQuery:              "FeedbagRightsQuery",
+		FeedbagRightsReply:              "FeedbagRightsReply",
+		FeedbagQuery:                    "FeedbagQuery",
+		FeedbagQueryIfModified:          "FeedbagQueryIfModified",
+		FeedbagReply:                    "FeedbagReply",
+		FeedbagUse:                      "FeedbagUse",
+		FeedbagInsertItem:               "FeedbagInsertItem",
+		FeedbagUpdateItem:               "FeedbagUpdateItem",
+		FeedbagDeleteItem:               "FeedbagDeleteItem",
+		FeedbagInsertClass:              "FeedbagInsertClass",
+		FeedbagUpdateClass:              "FeedbagUpdateClass",
+		FeedbagDeleteClass:              "FeedbagDeleteClass",
+		FeedbagStatus:                   "FeedbagStatus",
+		FeedbagReplyNotModified:         "FeedbagReplyNotModified",
+		FeedbagDeleteUser:               "FeedbagDeleteUser",
+		FeedbagStartCluster:             "FeedbagStartCluster",
+		FeedbagEndCluster:               "FeedbagEndCluster",
+		FeedbagAuthorizeBuddy:           "FeedbagAuthorizeBuddy",
+		FeedbagPreAuthorizeBuddy:        "FeedbagPreAuthorizeBuddy",
+		FeedbagPreAuthorizedBuddy:       "FeedbagPreAuthorizedBuddy",
+		FeedbagRemoveMe:                 "FeedbagRemoveMe",
+		FeedbagRemoveMe2:                "FeedbagRemoveMe2",
+		FeedbagRequestAuthorizeToHost:   "FeedbagRequestAuthorizeToHost",
+		FeedbagRequestAuthorizeToClient: "FeedbagRequestAuthorizeToClient",
+		FeedbagRespondAuthorizeToHost:   "FeedbagRespondAuthorizeToHost",
+		FeedbagRespondAuthorizeToClient: "FeedbagRespondAuthorizeToClient",
+		FeedbagBuddyAdded:               "FeedbagBuddyAdded",
+		FeedbagRequestAuthorizeToBadog:  "FeedbagRequestAuthorizeToBadog",
+		FeedbagRespondAuthorizeToBadog:  "FeedbagRespondAuthorizeToBadog",
+		FeedbagBuddyAddedToBadog:        "FeedbagBuddyAddedToBadog",
+		FeedbagTestSnac:                 "FeedbagTestSnac",
+		FeedbagForwardMsg:               "FeedbagForwardMsg",
+		FeedbagIsAuthRequiredQuery:      "FeedbagIsAuthRequiredQuery",
+		FeedbagIsAuthRequiredReply:      "FeedbagIsAuthRequiredReply",
+		FeedbagRecentBuddyUpdate:        "FeedbagRecentBuddyUpdate",
+	},
+	ALERT: {
+		AlertErr:                       "AlertErr",
+		AlertSetAlertRequest:           "AlertSetAlertRequest",
+		AlertSetAlertReply:             "AlertSetAlertReply",
+		AlertGetSubsRequest:            "AlertGetSubsRequest",
+		AlertGetSubsResponse:           "AlertGetSubsResponse",
+		AlertNotifyCapabilities:        "AlertNotifyCapabilities",
+		AlertNotify:                    "AlertNotify",
+		AlertGetRuleRequest:            "AlertGetRuleRequest",
+		AlertGetRuleReply:              "AlertGetRuleReply",
+		AlertGetFeedRequest:            "AlertGetFeedRequest",
+		AlertGetFeedReply:              "AlertGetFeedReply",
+		AlertRefreshFeed:               "AlertRefreshFeed",
+		AlertEvent:                     "AlertEvent",
+		AlertQogSnac:                   "AlertQogSnac",
+		AlertRefreshFeedStock:          "AlertRefreshFeedStock",
+		AlertNotifyTransport:           "AlertNotifyTransport",
+		AlertSetAlertRequestV2:         "AlertSetAlertRequestV2",
+		AlertSetAlertReplyV2:           "AlertSetAlertReplyV2",
+		AlertTransitReply:              "AlertTransitReply",
+		AlertNotifyAck:                 "AlertNotifyAck",
+		AlertNotifyDisplayCapabilities: "AlertNotifyDisplayCapabilities",
+		AlertUserOnline:                "AlertUserOnline",
+	},
+}
+
+func SubGroupStr(foodGroup uint16, subGroup uint16) string {
+	return subGroupStr[foodGroup][subGroup]
+}

oscar/snacs_test.go

@@ -2,7 +2,6 @@ package oscar
 
 import (
 	"bytes"
-	"fmt"
 	"reflect"
 	"testing"
 )
@@ -23,7 +22,7 @@ func TestMarshal(t *testing.T) {
 	if err := Marshal(snac, buf1); err != nil {
 		t.Fatalf("error: %s", err.Error())
 	}
-	fmt.Println(buf1)
+	t.Log(buf1)
 }
 
 func TestUnmarshal(t *testing.T) {
@@ -55,9 +54,7 @@ func TestUnmarshal(t *testing.T) {
 	}
 
 	if !reflect.DeepEqual(snac1, snac2) {
-		fmt.Printf("%+v\n", snac1)
-		fmt.Printf("%+v\n", snac2)
-		t.Fatal("structs are not the same")
+		t.Fatalf("structs are not the same: %v %v", snac1, snac2)
 	}
 }
 

server/alert.go

@@ -1,23 +1,31 @@
 package server
 
 import (
+	"context"
 	"github.com/mkaminski/goaim/oscar"
+	"log/slog"
 )
 
-func NewAlertRouter() AlertRouter {
-	return AlertRouter{}
+func NewAlertRouter(logger *slog.Logger) AlertRouter {
+	return AlertRouter{
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
+	}
 }
 
 type AlertRouter struct {
+	RouteLogger
 }
 
-func (rt *AlertRouter) RouteAlert(SNACFrame oscar.SnacFrame) error {
+func (rt *AlertRouter) RouteAlert(ctx context.Context, SNACFrame oscar.SnacFrame) error {
 	switch SNACFrame.SubGroup {
 	case oscar.AlertNotifyCapabilities:
 		fallthrough
 	case oscar.AlertNotifyDisplayCapabilities:
 		// just read the request to placate the client. no need to send a
 		// response.
+		rt.logRequest(ctx, SNACFrame, nil)
 		return nil
 	default:
 		return ErrUnsupportedSubGroup

server/alert_test.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"github.com/mkaminski/goaim/oscar"
 	"github.com/stretchr/testify/assert"
 	"testing"
@@ -58,7 +59,11 @@ func TestAlertRouter_RouteAlert(t *testing.T) {
 
 	for _, tc := range cases {
 		t.Run(tc.name, func(t *testing.T) {
-			router := AlertRouter{}
+			router := AlertRouter{
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
+			}
 
 			bufIn := &bytes.Buffer{}
 			assert.NoError(t, oscar.Marshal(tc.input.snacOut, bufIn))
@@ -66,7 +71,7 @@ func TestAlertRouter_RouteAlert(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(1)
 
-			err := router.RouteAlert(tc.input.snacFrame)
+			err := router.RouteAlert(context.Background(), tc.input.snacFrame)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/bucp.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"io"
 
@@ -21,7 +22,7 @@ const (
 	BUCPRegistrationImageRequest        = 0x000C
 )
 
-func routeBUCP() error {
+func routeBUCP(context.Context) error {
 	return ErrUnsupportedSubGroup
 }
 

server/bucp_test.go

@@ -134,7 +134,7 @@ func TestReceiveAndSendBUCPLoginRequest(t *testing.T) {
 				assert.NoError(t, err)
 			}
 			assert.NoError(t, fs.InsertUser(tc.userInDB))
-			sm := NewSessionManager()
+			sm := NewSessionManager(NewLogger(Config{}))
 			//
 			// send input SNAC
 			//

server/buddy.go

@@ -1,33 +1,40 @@
 package server
 
 import (
+	"context"
 	"io"
+	"log/slog"
 
 	"github.com/mkaminski/goaim/oscar"
 )
 
 type BuddyHandler interface {
-	RightsQueryHandler() XMessage
+	RightsQueryHandler(ctx context.Context) XMessage
 }
 
-func NewBuddyRouter() BuddyRouter {
+func NewBuddyRouter(logger *slog.Logger) BuddyRouter {
 	return BuddyRouter{
 		BuddyHandler: BuddyService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type BuddyRouter struct {
 	BuddyHandler
+	RouteLogger
 }
 
-func (rt *BuddyRouter) RouteBuddy(SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+func (rt *BuddyRouter) RouteBuddy(ctx context.Context, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
 	switch SNACFrame.SubGroup {
 	case oscar.BuddyRightsQuery:
 		inSNAC := oscar.SNAC_0x03_0x02_BuddyRightsQuery{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC := rt.RightsQueryHandler()
+		outSNAC := rt.RightsQueryHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	default:
 		return ErrUnsupportedSubGroup
@@ -37,7 +44,7 @@ func (rt *BuddyRouter) RouteBuddy(SNACFrame oscar.SnacFrame, r io.Reader, w io.W
 type BuddyService struct {
 }
 
-func (s BuddyService) RightsQueryHandler() XMessage {
+func (s BuddyService) RightsQueryHandler(context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.BUDDY,
@@ -56,13 +63,13 @@ func (s BuddyService) RightsQueryHandler() XMessage {
 	}
 }
 
-func BroadcastArrival(sess *Session, sm SessionManager, fm FeedbagManager) error {
+func BroadcastArrival(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager) error {
 	screenNames, err := fm.InterestedUsers(sess.ScreenName)
 	if err != nil {
 		return err
 	}
 
-	sm.BroadcastToScreenNames(screenNames, XMessage{
+	sm.BroadcastToScreenNames(ctx, screenNames, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.BUDDY,
 			SubGroup:  oscar.BuddyArrived,
@@ -81,13 +88,13 @@ func BroadcastArrival(sess *Session, sm SessionManager, fm FeedbagManager) error
 	return nil
 }
 
-func BroadcastDeparture(sess *Session, sm SessionManager, fm *FeedbagStore) error {
+func BroadcastDeparture(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore) error {
 	screenNames, err := fm.InterestedUsers(sess.ScreenName)
 	if err != nil {
 		return err
 	}
 
-	sm.BroadcastToScreenNames(screenNames, XMessage{
+	sm.BroadcastToScreenNames(ctx, screenNames, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.BUDDY,
 			SubGroup:  oscar.BuddyDeparted,
@@ -103,7 +110,7 @@ func BroadcastDeparture(sess *Session, sm SessionManager, fm *FeedbagStore) erro
 	return nil
 }
 
-func UnicastArrival(srcScreenName, destScreenName string, sm SessionManager) error {
+func UnicastArrival(ctx context.Context, srcScreenName, destScreenName string, sm SessionManager) error {
 	sess, err := sm.RetrieveByScreenName(srcScreenName)
 	switch {
 	case err != nil:
@@ -111,7 +118,7 @@ func UnicastArrival(srcScreenName, destScreenName string, sm SessionManager) err
 	case sess.Invisible(): // don't tell user this buddy is online
 		return nil
 	}
-	sm.SendToScreenName(destScreenName, XMessage{
+	sm.SendToScreenName(ctx, destScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.BUDDY,
 			SubGroup:  oscar.BuddyArrived,
@@ -124,7 +131,7 @@ func UnicastArrival(srcScreenName, destScreenName string, sm SessionManager) err
 	return nil
 }
 
-func UnicastDeparture(srcScreenName, destScreenName string, sm SessionManager) error {
+func UnicastDeparture(ctx context.Context, srcScreenName, destScreenName string, sm SessionManager) error {
 	sess, err := sm.RetrieveByScreenName(srcScreenName)
 	switch {
 	case err != nil:
@@ -133,7 +140,7 @@ func UnicastDeparture(srcScreenName, destScreenName string, sm SessionManager) e
 		return nil
 	}
 
-	sm.SendToScreenName(destScreenName, XMessage{
+	sm.SendToScreenName(ctx, destScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.BUDDY,
 			SubGroup:  oscar.BuddyDeparted,

server/buddy_mock.go

@@ -2,7 +2,11 @@
 
 package server
 
-import mock "github.com/stretchr/testify/mock"
+import (
+	context "context"
+
+	mock "github.com/stretchr/testify/mock"
+)
 
 // MockBuddyHandler is an autogenerated mock type for the BuddyHandler type
 type MockBuddyHandler struct {
@@ -17,13 +21,13 @@ func (_m *MockBuddyHandler) EXPECT() *MockBuddyHandler_Expecter {
 	return &MockBuddyHandler_Expecter{mock: &_m.Mock}
 }
 
-// RightsQueryHandler provides a mock function with given fields:
-func (_m *MockBuddyHandler) RightsQueryHandler() XMessage {
-	ret := _m.Called()
+// RightsQueryHandler provides a mock function with given fields: ctx
+func (_m *MockBuddyHandler) RightsQueryHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -37,13 +41,14 @@ type MockBuddyHandler_RightsQueryHandler_Call struct {
 }
 
 // RightsQueryHandler is a helper method to define mock.On call
-func (_e *MockBuddyHandler_Expecter) RightsQueryHandler() *MockBuddyHandler_RightsQueryHandler_Call {
-	return &MockBuddyHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler")}
+//   - ctx context.Context
+func (_e *MockBuddyHandler_Expecter) RightsQueryHandler(ctx interface{}) *MockBuddyHandler_RightsQueryHandler_Call {
+	return &MockBuddyHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler", ctx)}
 }
 
-func (_c *MockBuddyHandler_RightsQueryHandler_Call) Run(run func()) *MockBuddyHandler_RightsQueryHandler_Call {
+func (_c *MockBuddyHandler_RightsQueryHandler_Call) Run(run func(ctx context.Context)) *MockBuddyHandler_RightsQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -53,7 +58,7 @@ func (_c *MockBuddyHandler_RightsQueryHandler_Call) Return(_a0 XMessage) *MockBu
 	return _c
 }
 
-func (_c *MockBuddyHandler_RightsQueryHandler_Call) RunAndReturn(run func() XMessage) *MockBuddyHandler_RightsQueryHandler_Call {
+func (_c *MockBuddyHandler_RightsQueryHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockBuddyHandler_RightsQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/buddy_test.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"github.com/mkaminski/goaim/oscar"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/mock"
 	"testing"
 )
 
@@ -73,12 +74,15 @@ func TestBuddyRouter_RouteBuddy(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockBuddyHandler(t)
 			svc.EXPECT().
-				RightsQueryHandler().
+				RightsQueryHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 
 			router := BuddyRouter{
 				BuddyHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -87,7 +91,7 @@ func TestBuddyRouter_RouteBuddy(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(1)
 
-			err := router.RouteBuddy(tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteBuddy(nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/chat.go

@@ -1,36 +1,47 @@
 package server
 
 import (
+	"context"
 	"io"
+	"log/slog"
 
 	"github.com/mkaminski/goaim/oscar"
 )
 
 type ChatHandler interface {
-	ChannelMsgToHostHandler(sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)
+	ChannelMsgToHostHandler(ctx context.Context, sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)
 }
 
-func NewChatRouter() ChatRouter {
+func NewChatRouter(logger *slog.Logger) ChatRouter {
 	return ChatRouter{
 		ChatHandler: ChatService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type ChatRouter struct {
 	ChatHandler
+	RouteLogger
 }
 
-func (rt *ChatRouter) RouteChat(sess *Session, sm SessionManager, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+func (rt *ChatRouter) RouteChat(ctx context.Context, sess *Session, sm SessionManager, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
 	switch SNACFrame.SubGroup {
 	case oscar.ChatChannelMsgToHost:
 		inSNAC := oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.ChannelMsgToHostHandler(sess, sm, inSNAC)
-		if err != nil || outSNAC == nil {
+		outSNAC, err := rt.ChannelMsgToHostHandler(ctx, sess, sm, inSNAC)
+		if err != nil {
 			return err
 		}
+		if outSNAC == nil {
+			return nil
+		}
+		rt.Logger.InfoContext(ctx, "user sent a chat message")
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	default:
 		return ErrUnsupportedSubGroup
@@ -40,7 +51,7 @@ func (rt *ChatRouter) RouteChat(sess *Session, sm SessionManager, SNACFrame osca
 type ChatService struct {
 }
 
-func (s ChatService) ChannelMsgToHostHandler(sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error) {
+func (s ChatService) ChannelMsgToHostHandler(ctx context.Context, sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error) {
 	snacFrameOut := oscar.SnacFrame{
 		FoodGroup: oscar.CHAT,
 		SubGroup:  oscar.ChatChannelMsgToClient,
@@ -63,7 +74,7 @@ func (s ChatService) ChannelMsgToHostHandler(sess *Session, sm SessionManager, s
 	)
 
 	// send message to all the participants except sender
-	sm.BroadcastExcept(sess, XMessage{
+	sm.BroadcastExcept(ctx, sess, XMessage{
 		snacFrame: snacFrameOut,
 		snacOut:   snacPayloadOut,
 	})
@@ -80,7 +91,7 @@ func (s ChatService) ChannelMsgToHostHandler(sess *Session, sm SessionManager, s
 	return ret, nil
 }
 
-func SetOnlineChatUsers(sess *Session, sm SessionManager) {
+func SetOnlineChatUsers(ctx context.Context, sess *Session, sm SessionManager) {
 	snacPayloadOut := oscar.SNAC_0x0E_0x03_ChatUsersJoined{}
 	sessions := sm.Participants()
 
@@ -94,7 +105,7 @@ func SetOnlineChatUsers(sess *Session, sm SessionManager) {
 		})
 	}
 
-	sm.SendToScreenName(sess.ScreenName, XMessage{
+	sm.SendToScreenName(ctx, sess.ScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.CHAT,
 			SubGroup:  oscar.ChatUsersJoined,
@@ -103,8 +114,8 @@ func SetOnlineChatUsers(sess *Session, sm SessionManager) {
 	})
 }
 
-func AlertUserJoined(sess *Session, sm SessionManager) {
-	sm.BroadcastExcept(sess, XMessage{
+func AlertUserJoined(ctx context.Context, sess *Session, sm SessionManager) {
+	sm.BroadcastExcept(ctx, sess, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.CHAT,
 			SubGroup:  oscar.ChatUsersJoined,
@@ -123,8 +134,8 @@ func AlertUserJoined(sess *Session, sm SessionManager) {
 	})
 }
 
-func AlertUserLeft(sess *Session, sm SessionManager) {
-	sm.BroadcastExcept(sess, XMessage{
+func AlertUserLeft(ctx context.Context, sess *Session, sm SessionManager) {
+	sm.BroadcastExcept(ctx, sess, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.CHAT,
 			SubGroup:  oscar.ChatUsersLeft,
@@ -143,8 +154,8 @@ func AlertUserLeft(sess *Session, sm SessionManager) {
 	})
 }
 
-func SendChatRoomInfoUpdate(sess *Session, sm SessionManager, room ChatRoom) {
-	sm.SendToScreenName(sess.ScreenName, XMessage{
+func SendChatRoomInfoUpdate(ctx context.Context, sess *Session, sm SessionManager, room ChatRoom) {
+	sm.SendToScreenName(ctx, sess.ScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.CHAT,
 			SubGroup:  oscar.ChatRoomInfoUpdate,

server/chat_mock.go

@@ -3,6 +3,8 @@
 package server
 
 import (
+	context "context"
+
 	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
 )
@@ -20,25 +22,25 @@ func (_m *MockChatHandler) EXPECT() *MockChatHandler_Expecter {
 	return &MockChatHandler_Expecter{mock: &_m.Mock}
 }
 
-// ChannelMsgToHostHandler provides a mock function with given fields: sess, sm, snacPayloadIn
-func (_m *MockChatHandler) ChannelMsgToHostHandler(sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error) {
-	ret := _m.Called(sess, sm, snacPayloadIn)
+// ChannelMsgToHostHandler provides a mock function with given fields: ctx, sess, sm, snacPayloadIn
+func (_m *MockChatHandler) ChannelMsgToHostHandler(ctx context.Context, sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error) {
+	ret := _m.Called(ctx, sess, sm, snacPayloadIn)
 
 	var r0 *XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)); ok {
-		return rf(sess, sm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)); ok {
+		return rf(ctx, sess, sm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) *XMessage); ok {
-		r0 = rf(sess, sm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) *XMessage); ok {
+		r0 = rf(ctx, sess, sm, snacPayloadIn)
 	} else {
 		if ret.Get(0) != nil {
 			r0 = ret.Get(0).(*XMessage)
 		}
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) error); ok {
-		r1 = rf(sess, sm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) error); ok {
+		r1 = rf(ctx, sess, sm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -52,16 +54,17 @@ type MockChatHandler_ChannelMsgToHostHandler_Call struct {
 }
 
 // ChannelMsgToHostHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - sm SessionManager
 //   - snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost
-func (_e *MockChatHandler_Expecter) ChannelMsgToHostHandler(sess interface{}, sm interface{}, snacPayloadIn interface{}) *MockChatHandler_ChannelMsgToHostHandler_Call {
-	return &MockChatHandler_ChannelMsgToHostHandler_Call{Call: _e.mock.On("ChannelMsgToHostHandler", sess, sm, snacPayloadIn)}
+func (_e *MockChatHandler_Expecter) ChannelMsgToHostHandler(ctx interface{}, sess interface{}, sm interface{}, snacPayloadIn interface{}) *MockChatHandler_ChannelMsgToHostHandler_Call {
+	return &MockChatHandler_ChannelMsgToHostHandler_Call{Call: _e.mock.On("ChannelMsgToHostHandler", ctx, sess, sm, snacPayloadIn)}
 }
 
-func (_c *MockChatHandler_ChannelMsgToHostHandler_Call) Run(run func(sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost)) *MockChatHandler_ChannelMsgToHostHandler_Call {
+func (_c *MockChatHandler_ChannelMsgToHostHandler_Call) Run(run func(ctx context.Context, sess *Session, sm SessionManager, snacPayloadIn oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost)) *MockChatHandler_ChannelMsgToHostHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(SessionManager), args[2].(oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(SessionManager), args[3].(oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost))
 	})
 	return _c
 }
@@ -71,7 +74,7 @@ func (_c *MockChatHandler_ChannelMsgToHostHandler_Call) Return(_a0 *XMessage, _a
 	return _c
 }
 
-func (_c *MockChatHandler_ChannelMsgToHostHandler_Call) RunAndReturn(run func(*Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)) *MockChatHandler_ChannelMsgToHostHandler_Call {
+func (_c *MockChatHandler_ChannelMsgToHostHandler_Call) RunAndReturn(run func(context.Context, *Session, SessionManager, oscar.SNAC_0x0E_0x05_ChatChannelMsgToHost) (*XMessage, error)) *MockChatHandler_ChannelMsgToHostHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/chat_nav.go

@@ -1,53 +1,66 @@
 package server
 
 import (
+	"context"
 	"errors"
 	"github.com/google/uuid"
 	"github.com/mkaminski/goaim/oscar"
 	"io"
+	"log/slog"
 	"time"
 )
 
 type ChatNavHandler interface {
-	CreateRoomHandler(sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)
-	RequestChatRightsHandler() XMessage
-	RequestRoomInfoHandler(cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)
+	CreateRoomHandler(ctx context.Context, sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)
+	RequestChatRightsHandler(ctx context.Context) XMessage
+	RequestRoomInfoHandler(ctx context.Context, cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)
 }
 
-func NewChatNavRouter() ChatNavRouter {
+func NewChatNavRouter(logger *slog.Logger) ChatNavRouter {
 	return ChatNavRouter{
-		ChatNavHandler: ChatNavService{},
+		ChatNavHandler: ChatNavService{
+			Logger: logger,
+		},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type ChatNavRouter struct {
 	ChatNavHandler
+	RouteLogger
 }
 
-func (rt *ChatNavRouter) RouteChatNav(sess *Session, cr *ChatRegistry, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+func (rt *ChatNavRouter) RouteChatNav(ctx context.Context, sess *Session, cr *ChatRegistry, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
 	switch SNACFrame.SubGroup {
 	case oscar.ChatNavRequestChatRights:
-		outSNAC := rt.RequestChatRightsHandler()
+		outSNAC := rt.RequestChatRightsHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, nil, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.ChatNavRequestRoomInfo:
 		inSNAC := oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.RequestRoomInfoHandler(cr, inSNAC)
+		outSNAC, err := rt.RequestRoomInfoHandler(ctx, cr, inSNAC)
 		if err != nil {
 			return err
 		}
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.ChatNavCreateRoom:
-		snacPayloadIn := oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate{}
-		if err := oscar.Unmarshal(&snacPayloadIn, r); err != nil {
+		inSNAC := oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate{}
+		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.CreateRoomHandler(sess, cr, NewChatRoom, snacPayloadIn)
+		outSNAC, err := rt.CreateRoomHandler(ctx, sess, cr, NewChatRoom, inSNAC)
 		if err != nil {
 			return err
 		}
+		roomName, _ := inSNAC.GetString(oscar.ChatTLVRoomName)
+		rt.Logger.InfoContext(ctx, "user started a chat room", slog.String("roomName", roomName))
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	default:
 		return ErrUnsupportedSubGroup
@@ -55,6 +68,7 @@ func (rt *ChatNavRouter) RouteChatNav(sess *Session, cr *ChatRegistry, SNACFrame
 }
 
 type ChatNavService struct {
+	Logger *slog.Logger
 }
 
 type ChatCookie struct {
@@ -62,7 +76,7 @@ type ChatCookie struct {
 	SessID string `len_prefix:"uint16"`
 }
 
-func (s ChatNavService) RequestChatRightsHandler() XMessage {
+func (s ChatNavService) RequestChatRightsHandler(context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.CHAT_NAV,
@@ -93,23 +107,23 @@ func (s ChatNavService) RequestChatRightsHandler() XMessage {
 	}
 }
 
-func NewChatRoom() ChatRoom {
+func NewChatRoom(logger *slog.Logger) ChatRoom {
 	return ChatRoom{
 		Cookie:         uuid.New().String(),
 		CreateTime:     time.Now(),
-		SessionManager: NewSessionManager(),
+		SessionManager: NewSessionManager(logger),
 	}
 }
 
-type ChatRoomFactory func() ChatRoom
+type ChatRoomFactory func(logger *slog.Logger) ChatRoom
 
-func (s ChatNavService) CreateRoomHandler(sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error) {
+func (s ChatNavService) CreateRoomHandler(_ context.Context, sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error) {
 	name, hasName := snacPayloadIn.GetString(oscar.ChatTLVRoomName)
 	if !hasName {
 		return XMessage{}, errors.New("unable to find chat name")
 	}
 
-	room := newChatRoom()
+	room := newChatRoom(s.Logger)
 	room.DetailLevel = snacPayloadIn.DetailLevel
 	room.Exchange = snacPayloadIn.Exchange
 	room.InstanceNumber = snacPayloadIn.InstanceNumber
@@ -142,7 +156,7 @@ func (s ChatNavService) CreateRoomHandler(sess *Session, cr *ChatRegistry, newCh
 	}, nil
 }
 
-func (s ChatNavService) RequestRoomInfoHandler(cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error) {
+func (s ChatNavService) RequestRoomInfoHandler(_ context.Context, cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error) {
 	room, err := cr.Retrieve(string(snacPayloadIn.Cookie))
 	if err != nil {
 		return XMessage{}, err

server/chat_nav_mock.go

@@ -3,6 +3,8 @@
 package server
 
 import (
+	context "context"
+
 	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
 )
@@ -20,23 +22,23 @@ func (_m *MockChatNavHandler) EXPECT() *MockChatNavHandler_Expecter {
 	return &MockChatNavHandler_Expecter{mock: &_m.Mock}
 }
 
-// CreateRoomHandler provides a mock function with given fields: sess, cr, newChatRoom, snacPayloadIn
-func (_m *MockChatNavHandler) CreateRoomHandler(sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error) {
-	ret := _m.Called(sess, cr, newChatRoom, snacPayloadIn)
+// CreateRoomHandler provides a mock function with given fields: ctx, sess, cr, newChatRoom, snacPayloadIn
+func (_m *MockChatNavHandler) CreateRoomHandler(ctx context.Context, sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error) {
+	ret := _m.Called(ctx, sess, cr, newChatRoom, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)); ok {
-		return rf(sess, cr, newChatRoom, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)); ok {
+		return rf(ctx, sess, cr, newChatRoom, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) XMessage); ok {
-		r0 = rf(sess, cr, newChatRoom, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) XMessage); ok {
+		r0 = rf(ctx, sess, cr, newChatRoom, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) error); ok {
-		r1 = rf(sess, cr, newChatRoom, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) error); ok {
+		r1 = rf(ctx, sess, cr, newChatRoom, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -50,17 +52,18 @@ type MockChatNavHandler_CreateRoomHandler_Call struct {
 }
 
 // CreateRoomHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - cr *ChatRegistry
 //   - newChatRoom ChatRoomFactory
 //   - snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate
-func (_e *MockChatNavHandler_Expecter) CreateRoomHandler(sess interface{}, cr interface{}, newChatRoom interface{}, snacPayloadIn interface{}) *MockChatNavHandler_CreateRoomHandler_Call {
-	return &MockChatNavHandler_CreateRoomHandler_Call{Call: _e.mock.On("CreateRoomHandler", sess, cr, newChatRoom, snacPayloadIn)}
+func (_e *MockChatNavHandler_Expecter) CreateRoomHandler(ctx interface{}, sess interface{}, cr interface{}, newChatRoom interface{}, snacPayloadIn interface{}) *MockChatNavHandler_CreateRoomHandler_Call {
+	return &MockChatNavHandler_CreateRoomHandler_Call{Call: _e.mock.On("CreateRoomHandler", ctx, sess, cr, newChatRoom, snacPayloadIn)}
 }
 
-func (_c *MockChatNavHandler_CreateRoomHandler_Call) Run(run func(sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate)) *MockChatNavHandler_CreateRoomHandler_Call {
+func (_c *MockChatNavHandler_CreateRoomHandler_Call) Run(run func(ctx context.Context, sess *Session, cr *ChatRegistry, newChatRoom ChatRoomFactory, snacPayloadIn oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate)) *MockChatNavHandler_CreateRoomHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(*ChatRegistry), args[2].(ChatRoomFactory), args[3].(oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(*ChatRegistry), args[3].(ChatRoomFactory), args[4].(oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate))
 	})
 	return _c
 }
@@ -70,18 +73,18 @@ func (_c *MockChatNavHandler_CreateRoomHandler_Call) Return(_a0 XMessage, _a1 er
 	return _c
 }
 
-func (_c *MockChatNavHandler_CreateRoomHandler_Call) RunAndReturn(run func(*Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)) *MockChatNavHandler_CreateRoomHandler_Call {
+func (_c *MockChatNavHandler_CreateRoomHandler_Call) RunAndReturn(run func(context.Context, *Session, *ChatRegistry, ChatRoomFactory, oscar.SNAC_0x0E_0x02_ChatRoomInfoUpdate) (XMessage, error)) *MockChatNavHandler_CreateRoomHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// RequestChatRightsHandler provides a mock function with given fields:
-func (_m *MockChatNavHandler) RequestChatRightsHandler() XMessage {
-	ret := _m.Called()
+// RequestChatRightsHandler provides a mock function with given fields: ctx
+func (_m *MockChatNavHandler) RequestChatRightsHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -95,13 +98,14 @@ type MockChatNavHandler_RequestChatRightsHandler_Call struct {
 }
 
 // RequestChatRightsHandler is a helper method to define mock.On call
-func (_e *MockChatNavHandler_Expecter) RequestChatRightsHandler() *MockChatNavHandler_RequestChatRightsHandler_Call {
-	return &MockChatNavHandler_RequestChatRightsHandler_Call{Call: _e.mock.On("RequestChatRightsHandler")}
+//   - ctx context.Context
+func (_e *MockChatNavHandler_Expecter) RequestChatRightsHandler(ctx interface{}) *MockChatNavHandler_RequestChatRightsHandler_Call {
+	return &MockChatNavHandler_RequestChatRightsHandler_Call{Call: _e.mock.On("RequestChatRightsHandler", ctx)}
 }
 
-func (_c *MockChatNavHandler_RequestChatRightsHandler_Call) Run(run func()) *MockChatNavHandler_RequestChatRightsHandler_Call {
+func (_c *MockChatNavHandler_RequestChatRightsHandler_Call) Run(run func(ctx context.Context)) *MockChatNavHandler_RequestChatRightsHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -111,28 +115,28 @@ func (_c *MockChatNavHandler_RequestChatRightsHandler_Call) Return(_a0 XMessage)
 	return _c
 }
 
-func (_c *MockChatNavHandler_RequestChatRightsHandler_Call) RunAndReturn(run func() XMessage) *MockChatNavHandler_RequestChatRightsHandler_Call {
+func (_c *MockChatNavHandler_RequestChatRightsHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockChatNavHandler_RequestChatRightsHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// RequestRoomInfoHandler provides a mock function with given fields: cr, snacPayloadIn
-func (_m *MockChatNavHandler) RequestRoomInfoHandler(cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error) {
-	ret := _m.Called(cr, snacPayloadIn)
+// RequestRoomInfoHandler provides a mock function with given fields: ctx, cr, snacPayloadIn
+func (_m *MockChatNavHandler) RequestRoomInfoHandler(ctx context.Context, cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error) {
+	ret := _m.Called(ctx, cr, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)); ok {
-		return rf(cr, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)); ok {
+		return rf(ctx, cr, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) XMessage); ok {
-		r0 = rf(cr, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) XMessage); ok {
+		r0 = rf(ctx, cr, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) error); ok {
-		r1 = rf(cr, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) error); ok {
+		r1 = rf(ctx, cr, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -146,15 +150,16 @@ type MockChatNavHandler_RequestRoomInfoHandler_Call struct {
 }
 
 // RequestRoomInfoHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - cr *ChatRegistry
 //   - snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo
-func (_e *MockChatNavHandler_Expecter) RequestRoomInfoHandler(cr interface{}, snacPayloadIn interface{}) *MockChatNavHandler_RequestRoomInfoHandler_Call {
-	return &MockChatNavHandler_RequestRoomInfoHandler_Call{Call: _e.mock.On("RequestRoomInfoHandler", cr, snacPayloadIn)}
+func (_e *MockChatNavHandler_Expecter) RequestRoomInfoHandler(ctx interface{}, cr interface{}, snacPayloadIn interface{}) *MockChatNavHandler_RequestRoomInfoHandler_Call {
+	return &MockChatNavHandler_RequestRoomInfoHandler_Call{Call: _e.mock.On("RequestRoomInfoHandler", ctx, cr, snacPayloadIn)}
 }
 
-func (_c *MockChatNavHandler_RequestRoomInfoHandler_Call) Run(run func(cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo)) *MockChatNavHandler_RequestRoomInfoHandler_Call {
+func (_c *MockChatNavHandler_RequestRoomInfoHandler_Call) Run(run func(ctx context.Context, cr *ChatRegistry, snacPayloadIn oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo)) *MockChatNavHandler_RequestRoomInfoHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*ChatRegistry), args[1].(oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo))
+		run(args[0].(context.Context), args[1].(*ChatRegistry), args[2].(oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo))
 	})
 	return _c
 }
@@ -164,7 +169,7 @@ func (_c *MockChatNavHandler_RequestRoomInfoHandler_Call) Return(_a0 XMessage, _
 	return _c
 }
 
-func (_c *MockChatNavHandler_RequestRoomInfoHandler_Call) RunAndReturn(run func(*ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)) *MockChatNavHandler_RequestRoomInfoHandler_Call {
+func (_c *MockChatNavHandler_RequestRoomInfoHandler_Call) RunAndReturn(run func(context.Context, *ChatRegistry, oscar.SNAC_0x0D_0x04_ChatNavRequestRoomInfo) (XMessage, error)) *MockChatNavHandler_RequestRoomInfoHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/chat_nav_test.go

@@ -2,6 +2,8 @@ package server
 
 import (
 	"bytes"
+	"context"
+	"log/slog"
 	"testing"
 	"time"
 
@@ -25,7 +27,7 @@ func TestSendAndReceiveCreateRoom(t *testing.T) {
 	sm.EXPECT().NewSessionWithSN(userSess.ID, userSess.ScreenName).
 		Return(&Session{})
 
-	crf := func() ChatRoom {
+	crf := func(logger *slog.Logger) ChatRoom {
 		return ChatRoom{
 			Cookie:         "dummy-cookie",
 			CreateTime:     time.UnixMilli(0),
@@ -48,7 +50,7 @@ func TestSendAndReceiveCreateRoom(t *testing.T) {
 		},
 	}
 	svc := ChatNavService{}
-	outputSNAC, err := svc.CreateRoomHandler(userSess, cr, crf, inputSNAC)
+	outputSNAC, err := svc.CreateRoomHandler(context.Background(), userSess, cr, crf, inputSNAC)
 	assert.NoError(t, err)
 
 	//
@@ -202,20 +204,23 @@ func TestChatNavRouter_RouteChatNavRouter(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockChatNavHandler(t)
 			svc.EXPECT().
-				RequestChatRightsHandler().
+				RequestChatRightsHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				RequestRoomInfoHandler(mock.Anything, tc.input.snacOut).
+				RequestRoomInfoHandler(mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				CreateRoomHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				CreateRoomHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 
 			router := ChatNavRouter{
 				ChatNavHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -224,7 +229,7 @@ func TestChatNavRouter_RouteChatNavRouter(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(0)
 
-			err := router.RouteChatNav(nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteChatNav(nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/chat_test.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"github.com/stretchr/testify/mock"
 	"testing"
 
@@ -128,12 +129,12 @@ func TestSendAndReceiveChatChannelMsgToHost(t *testing.T) {
 			//
 			crm := NewMockSessionManager(t)
 			crm.EXPECT().
-				BroadcastExcept(tc.userSession, tc.expectSNACToParticipants)
+				BroadcastExcept(mock.Anything, tc.userSession, tc.expectSNACToParticipants)
 			//
 			// send input SNAC
 			//
 			svc := ChatService{}
-			outputSNAC, err := svc.ChannelMsgToHostHandler(tc.userSession, crm, tc.inputSNAC)
+			outputSNAC, err := svc.ChannelMsgToHostHandler(context.Background(), tc.userSession, crm, tc.inputSNAC)
 			assert.NoError(t, err)
 
 			if tc.expectOutput.snacFrame == (oscar.SnacFrame{}) {
@@ -210,12 +211,15 @@ func TestChatRouter_RouteChat(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockChatHandler(t)
 			svc.EXPECT().
-				ChannelMsgToHostHandler(mock.Anything, mock.Anything, tc.input.snacOut).
+				ChannelMsgToHostHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 
 			router := ChatRouter{
 				ChatHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -224,7 +228,7 @@ func TestChatRouter_RouteChat(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(0)
 
-			err := router.RouteChat(nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteChat(nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/feedbag.go

@@ -1,98 +1,113 @@
 package server
 
 import (
+	"context"
 	"errors"
 	"io"
+	"log/slog"
 	"time"
 
 	"github.com/mkaminski/goaim/oscar"
 )
 
 type FeedbagHandler interface {
-	DeleteItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)
-	InsertItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)
-	QueryHandler(sess *Session, fm FeedbagManager) (XMessage, error)
-	QueryIfModifiedHandler(sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)
-	RightsQueryHandler() XMessage
-	StartClusterHandler(oscar.SNAC_0x13_0x11_FeedbagStartCluster)
-	UpdateItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)
+	DeleteItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)
+	InsertItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)
+	QueryHandler(ctx context.Context, sess *Session, fm FeedbagManager) (XMessage, error)
+	QueryIfModifiedHandler(ctx context.Context, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)
+	RightsQueryHandler(context.Context) XMessage
+	StartClusterHandler(context.Context, oscar.SNAC_0x13_0x11_FeedbagStartCluster)
+	UpdateItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)
 }
 
-func NewFeedbagRouter() FeedbagRouter {
+func NewFeedbagRouter(logger *slog.Logger) FeedbagRouter {
 	return FeedbagRouter{
 		FeedbagHandler: FeedbagService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type FeedbagRouter struct {
 	FeedbagHandler
+	RouteLogger
 }
 
-func (rt FeedbagRouter) RouteFeedbag(sm SessionManager, sess *Session, fm FeedbagManager, snac oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
-	switch snac.SubGroup {
+func (rt FeedbagRouter) RouteFeedbag(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+	switch SNACFrame.SubGroup {
 	case oscar.FeedbagRightsQuery:
 		inSNAC := oscar.SNAC_0x13_0x02_FeedbagRightsQuery{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC := rt.RightsQueryHandler()
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		outSNAC := rt.RightsQueryHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.FeedbagQuery:
-		inSNAC, err := rt.QueryHandler(sess, fm)
+		inSNAC, err := rt.QueryHandler(ctx, sess, fm)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, inSNAC.snacFrame, inSNAC.snacOut, sequence, w)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return writeOutSNAC(SNACFrame, inSNAC.snacFrame, inSNAC.snacOut, sequence, w)
 	case oscar.FeedbagQueryIfModified:
 		inSNAC := oscar.SNAC_0x13_0x05_FeedbagQueryIfModified{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.QueryIfModifiedHandler(sess, fm, inSNAC)
+		outSNAC, err := rt.QueryIfModifiedHandler(ctx, sess, fm, inSNAC)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.FeedbagUse:
+		rt.logRequest(ctx, SNACFrame, nil)
 		return nil
 	case oscar.FeedbagInsertItem:
 		inSNAC := oscar.SNAC_0x13_0x08_FeedbagInsertItem{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.InsertItemHandler(sm, sess, fm, inSNAC)
+		outSNAC, err := rt.InsertItemHandler(ctx, sm, sess, fm, inSNAC)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.FeedbagUpdateItem:
 		inSNAC := oscar.SNAC_0x13_0x09_FeedbagUpdateItem{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.UpdateItemHandler(sm, sess, fm, inSNAC)
+		outSNAC, err := rt.UpdateItemHandler(ctx, sm, sess, fm, inSNAC)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.FeedbagDeleteItem:
 		inSNAC := oscar.SNAC_0x13_0x0A_FeedbagDeleteItem{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.DeleteItemHandler(sm, sess, fm, inSNAC)
+		outSNAC, err := rt.DeleteItemHandler(ctx, sm, sess, fm, inSNAC)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.FeedbagStartCluster:
 		inSNAC := oscar.SNAC_0x13_0x11_FeedbagStartCluster{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		rt.StartClusterHandler(inSNAC)
+		rt.StartClusterHandler(ctx, inSNAC)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
 		return nil
 	case oscar.FeedbagEndCluster:
+		rt.logRequest(ctx, SNACFrame, nil)
 		return nil
 	default:
 		return ErrUnsupportedSubGroup
@@ -102,7 +117,7 @@ func (rt FeedbagRouter) RouteFeedbag(sm SessionManager, sess *Session, fm Feedba
 type FeedbagService struct {
 }
 
-func (s FeedbagService) RightsQueryHandler() XMessage {
+func (s FeedbagService) RightsQueryHandler(context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.FEEDBAG,
@@ -150,7 +165,7 @@ func (s FeedbagService) RightsQueryHandler() XMessage {
 	}
 }
 
-func (s FeedbagService) QueryHandler(sess *Session, fm FeedbagManager) (XMessage, error) {
+func (s FeedbagService) QueryHandler(ctx context.Context, sess *Session, fm FeedbagManager) (XMessage, error) {
 	fb, err := fm.Retrieve(sess.ScreenName)
 	if err != nil {
 		return XMessage{}, err
@@ -178,7 +193,7 @@ func (s FeedbagService) QueryHandler(sess *Session, fm FeedbagManager) (XMessage
 	}, nil
 }
 
-func (s FeedbagService) QueryIfModifiedHandler(sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error) {
+func (s FeedbagService) QueryIfModifiedHandler(ctx context.Context, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error) {
 	fb, err := fm.Retrieve(sess.ScreenName)
 	if err != nil {
 		return XMessage{}, err
@@ -218,7 +233,7 @@ func (s FeedbagService) QueryIfModifiedHandler(sess *Session, fm FeedbagManager,
 	}, nil
 }
 
-func (s FeedbagService) InsertItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error) {
+func (s FeedbagService) InsertItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error) {
 	for _, item := range snacPayloadIn.Items {
 		// don't let users block themselves, it causes the AIM client to go
 		// into a weird state.
@@ -242,7 +257,7 @@ func (s FeedbagService) InsertItemHandler(sm SessionManager, sess *Session, fm F
 	for _, item := range snacPayloadIn.Items {
 		switch item.ClassID {
 		case oscar.FeedbagClassIdBuddy, oscar.FeedbagClassIDPermit: // add new buddy
-			err := UnicastArrival(item.Name, sess.ScreenName, sm)
+			err := UnicastArrival(ctx, item.Name, sess.ScreenName, sm)
 			switch {
 			case errors.Is(err, ErrSessNotFound):
 				continue
@@ -251,7 +266,7 @@ func (s FeedbagService) InsertItemHandler(sm SessionManager, sess *Session, fm F
 			}
 		case oscar.FeedbagClassIDDeny: // block buddy
 			// notify this user that buddy is offline
-			err := UnicastDeparture(item.Name, sess.ScreenName, sm)
+			err := UnicastDeparture(ctx, item.Name, sess.ScreenName, sm)
 			switch {
 			case errors.Is(err, ErrSessNotFound):
 				continue
@@ -259,7 +274,7 @@ func (s FeedbagService) InsertItemHandler(sm SessionManager, sess *Session, fm F
 				return XMessage{}, err
 			}
 			// notify former buddy that this user is offline
-			if err := UnicastDeparture(sess.ScreenName, item.Name, sm); err != nil {
+			if err := UnicastDeparture(ctx, sess.ScreenName, item.Name, sm); err != nil {
 				return XMessage{}, err
 			}
 		}
@@ -279,7 +294,7 @@ func (s FeedbagService) InsertItemHandler(sm SessionManager, sess *Session, fm F
 	}, nil
 }
 
-func (s FeedbagService) UpdateItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error) {
+func (s FeedbagService) UpdateItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error) {
 	if err := fm.Upsert(sess.ScreenName, snacPayloadIn.Items); err != nil {
 		return XMessage{}, nil
 	}
@@ -287,7 +302,7 @@ func (s FeedbagService) UpdateItemHandler(sm SessionManager, sess *Session, fm F
 	for _, item := range snacPayloadIn.Items {
 		switch item.ClassID {
 		case oscar.FeedbagClassIdBuddy, oscar.FeedbagClassIDPermit:
-			err := UnicastArrival(item.Name, sess.ScreenName, sm)
+			err := UnicastArrival(ctx, item.Name, sess.ScreenName, sm)
 			switch {
 			case errors.Is(err, ErrSessNotFound):
 				continue
@@ -311,21 +326,21 @@ func (s FeedbagService) UpdateItemHandler(sm SessionManager, sess *Session, fm F
 	}, nil
 }
 
-func (s FeedbagService) DeleteItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error) {
+func (s FeedbagService) DeleteItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error) {
 	if err := fm.Delete(sess.ScreenName, snacPayloadIn.Items); err != nil {
 		return XMessage{}, err
 	}
 
 	for _, item := range snacPayloadIn.Items {
 		if item.ClassID == oscar.FeedbagClassIDDeny {
-			err := UnicastArrival(item.Name, sess.ScreenName, sm)
+			err := UnicastArrival(ctx, item.Name, sess.ScreenName, sm)
 			switch {
 			case errors.Is(err, ErrSessNotFound):
 				continue
 			case err != nil:
 				return XMessage{}, err
 			}
-			err = UnicastArrival(sess.ScreenName, item.Name, sm)
+			err = UnicastArrival(ctx, sess.ScreenName, item.Name, sm)
 			switch {
 			case errors.Is(err, ErrSessNotFound):
 				continue
@@ -351,5 +366,5 @@ func (s FeedbagService) DeleteItemHandler(sm SessionManager, sess *Session, fm F
 
 // StartClusterHandler exists to capture the SNAC input in unit tests to verify
 // it's correctly unmarshalled.
-func (s FeedbagService) StartClusterHandler(oscar.SNAC_0x13_0x11_FeedbagStartCluster) {
+func (s FeedbagService) StartClusterHandler(context.Context, oscar.SNAC_0x13_0x11_FeedbagStartCluster) {
 }

server/feedbag_mock.go

@@ -3,6 +3,8 @@
 package server
 
 import (
+	context "context"
+
 	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
 )
@@ -20,23 +22,23 @@ func (_m *MockFeedbagHandler) EXPECT() *MockFeedbagHandler_Expecter {
 	return &MockFeedbagHandler_Expecter{mock: &_m.Mock}
 }
 
-// DeleteItemHandler provides a mock function with given fields: sm, sess, fm, snacPayloadIn
-func (_m *MockFeedbagHandler) DeleteItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error) {
-	ret := _m.Called(sm, sess, fm, snacPayloadIn)
+// DeleteItemHandler provides a mock function with given fields: ctx, sm, sess, fm, snacPayloadIn
+func (_m *MockFeedbagHandler) DeleteItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error) {
+	ret := _m.Called(ctx, sm, sess, fm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)); ok {
-		return rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)); ok {
+		return rf(ctx, sm, sess, fm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) XMessage); ok {
-		r0 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) XMessage); ok {
+		r0 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) error); ok {
-		r1 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) error); ok {
+		r1 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -50,17 +52,18 @@ type MockFeedbagHandler_DeleteItemHandler_Call struct {
 }
 
 // DeleteItemHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - sess *Session
 //   - fm FeedbagManager
 //   - snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem
-func (_e *MockFeedbagHandler_Expecter) DeleteItemHandler(sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_DeleteItemHandler_Call {
-	return &MockFeedbagHandler_DeleteItemHandler_Call{Call: _e.mock.On("DeleteItemHandler", sm, sess, fm, snacPayloadIn)}
+func (_e *MockFeedbagHandler_Expecter) DeleteItemHandler(ctx interface{}, sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_DeleteItemHandler_Call {
+	return &MockFeedbagHandler_DeleteItemHandler_Call{Call: _e.mock.On("DeleteItemHandler", ctx, sm, sess, fm, snacPayloadIn)}
 }
 
-func (_c *MockFeedbagHandler_DeleteItemHandler_Call) Run(run func(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem)) *MockFeedbagHandler_DeleteItemHandler_Call {
+func (_c *MockFeedbagHandler_DeleteItemHandler_Call) Run(run func(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x0A_FeedbagDeleteItem)) *MockFeedbagHandler_DeleteItemHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(*Session), args[2].(FeedbagManager), args[3].(oscar.SNAC_0x13_0x0A_FeedbagDeleteItem))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(*Session), args[3].(FeedbagManager), args[4].(oscar.SNAC_0x13_0x0A_FeedbagDeleteItem))
 	})
 	return _c
 }
@@ -70,28 +73,28 @@ func (_c *MockFeedbagHandler_DeleteItemHandler_Call) Return(_a0 XMessage, _a1 er
 	return _c
 }
 
-func (_c *MockFeedbagHandler_DeleteItemHandler_Call) RunAndReturn(run func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)) *MockFeedbagHandler_DeleteItemHandler_Call {
+func (_c *MockFeedbagHandler_DeleteItemHandler_Call) RunAndReturn(run func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x0A_FeedbagDeleteItem) (XMessage, error)) *MockFeedbagHandler_DeleteItemHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// InsertItemHandler provides a mock function with given fields: sm, sess, fm, snacPayloadIn
-func (_m *MockFeedbagHandler) InsertItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error) {
-	ret := _m.Called(sm, sess, fm, snacPayloadIn)
+// InsertItemHandler provides a mock function with given fields: ctx, sm, sess, fm, snacPayloadIn
+func (_m *MockFeedbagHandler) InsertItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error) {
+	ret := _m.Called(ctx, sm, sess, fm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)); ok {
-		return rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)); ok {
+		return rf(ctx, sm, sess, fm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) XMessage); ok {
-		r0 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) XMessage); ok {
+		r0 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) error); ok {
-		r1 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) error); ok {
+		r1 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -105,17 +108,18 @@ type MockFeedbagHandler_InsertItemHandler_Call struct {
 }
 
 // InsertItemHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - sess *Session
 //   - fm FeedbagManager
 //   - snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem
-func (_e *MockFeedbagHandler_Expecter) InsertItemHandler(sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_InsertItemHandler_Call {
-	return &MockFeedbagHandler_InsertItemHandler_Call{Call: _e.mock.On("InsertItemHandler", sm, sess, fm, snacPayloadIn)}
+func (_e *MockFeedbagHandler_Expecter) InsertItemHandler(ctx interface{}, sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_InsertItemHandler_Call {
+	return &MockFeedbagHandler_InsertItemHandler_Call{Call: _e.mock.On("InsertItemHandler", ctx, sm, sess, fm, snacPayloadIn)}
 }
 
-func (_c *MockFeedbagHandler_InsertItemHandler_Call) Run(run func(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem)) *MockFeedbagHandler_InsertItemHandler_Call {
+func (_c *MockFeedbagHandler_InsertItemHandler_Call) Run(run func(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x08_FeedbagInsertItem)) *MockFeedbagHandler_InsertItemHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(*Session), args[2].(FeedbagManager), args[3].(oscar.SNAC_0x13_0x08_FeedbagInsertItem))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(*Session), args[3].(FeedbagManager), args[4].(oscar.SNAC_0x13_0x08_FeedbagInsertItem))
 	})
 	return _c
 }
@@ -125,28 +129,28 @@ func (_c *MockFeedbagHandler_InsertItemHandler_Call) Return(_a0 XMessage, _a1 er
 	return _c
 }
 
-func (_c *MockFeedbagHandler_InsertItemHandler_Call) RunAndReturn(run func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)) *MockFeedbagHandler_InsertItemHandler_Call {
+func (_c *MockFeedbagHandler_InsertItemHandler_Call) RunAndReturn(run func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x08_FeedbagInsertItem) (XMessage, error)) *MockFeedbagHandler_InsertItemHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// QueryHandler provides a mock function with given fields: sess, fm
-func (_m *MockFeedbagHandler) QueryHandler(sess *Session, fm FeedbagManager) (XMessage, error) {
-	ret := _m.Called(sess, fm)
+// QueryHandler provides a mock function with given fields: ctx, sess, fm
+func (_m *MockFeedbagHandler) QueryHandler(ctx context.Context, sess *Session, fm FeedbagManager) (XMessage, error) {
+	ret := _m.Called(ctx, sess, fm)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, FeedbagManager) (XMessage, error)); ok {
-		return rf(sess, fm)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, FeedbagManager) (XMessage, error)); ok {
+		return rf(ctx, sess, fm)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, FeedbagManager) XMessage); ok {
-		r0 = rf(sess, fm)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, FeedbagManager) XMessage); ok {
+		r0 = rf(ctx, sess, fm)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, FeedbagManager) error); ok {
-		r1 = rf(sess, fm)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, FeedbagManager) error); ok {
+		r1 = rf(ctx, sess, fm)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -160,15 +164,16 @@ type MockFeedbagHandler_QueryHandler_Call struct {
 }
 
 // QueryHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - fm FeedbagManager
-func (_e *MockFeedbagHandler_Expecter) QueryHandler(sess interface{}, fm interface{}) *MockFeedbagHandler_QueryHandler_Call {
-	return &MockFeedbagHandler_QueryHandler_Call{Call: _e.mock.On("QueryHandler", sess, fm)}
+func (_e *MockFeedbagHandler_Expecter) QueryHandler(ctx interface{}, sess interface{}, fm interface{}) *MockFeedbagHandler_QueryHandler_Call {
+	return &MockFeedbagHandler_QueryHandler_Call{Call: _e.mock.On("QueryHandler", ctx, sess, fm)}
 }
 
-func (_c *MockFeedbagHandler_QueryHandler_Call) Run(run func(sess *Session, fm FeedbagManager)) *MockFeedbagHandler_QueryHandler_Call {
+func (_c *MockFeedbagHandler_QueryHandler_Call) Run(run func(ctx context.Context, sess *Session, fm FeedbagManager)) *MockFeedbagHandler_QueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(FeedbagManager))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(FeedbagManager))
 	})
 	return _c
 }
@@ -178,28 +183,28 @@ func (_c *MockFeedbagHandler_QueryHandler_Call) Return(_a0 XMessage, _a1 error)
 	return _c
 }
 
-func (_c *MockFeedbagHandler_QueryHandler_Call) RunAndReturn(run func(*Session, FeedbagManager) (XMessage, error)) *MockFeedbagHandler_QueryHandler_Call {
+func (_c *MockFeedbagHandler_QueryHandler_Call) RunAndReturn(run func(context.Context, *Session, FeedbagManager) (XMessage, error)) *MockFeedbagHandler_QueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// QueryIfModifiedHandler provides a mock function with given fields: sess, fm, snacPayloadIn
-func (_m *MockFeedbagHandler) QueryIfModifiedHandler(sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error) {
-	ret := _m.Called(sess, fm, snacPayloadIn)
+// QueryIfModifiedHandler provides a mock function with given fields: ctx, sess, fm, snacPayloadIn
+func (_m *MockFeedbagHandler) QueryIfModifiedHandler(ctx context.Context, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error) {
+	ret := _m.Called(ctx, sess, fm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)); ok {
-		return rf(sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)); ok {
+		return rf(ctx, sess, fm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) XMessage); ok {
-		r0 = rf(sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) XMessage); ok {
+		r0 = rf(ctx, sess, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) error); ok {
-		r1 = rf(sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) error); ok {
+		r1 = rf(ctx, sess, fm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -213,16 +218,17 @@ type MockFeedbagHandler_QueryIfModifiedHandler_Call struct {
 }
 
 // QueryIfModifiedHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - fm FeedbagManager
 //   - snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified
-func (_e *MockFeedbagHandler_Expecter) QueryIfModifiedHandler(sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
-	return &MockFeedbagHandler_QueryIfModifiedHandler_Call{Call: _e.mock.On("QueryIfModifiedHandler", sess, fm, snacPayloadIn)}
+func (_e *MockFeedbagHandler_Expecter) QueryIfModifiedHandler(ctx interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
+	return &MockFeedbagHandler_QueryIfModifiedHandler_Call{Call: _e.mock.On("QueryIfModifiedHandler", ctx, sess, fm, snacPayloadIn)}
 }
 
-func (_c *MockFeedbagHandler_QueryIfModifiedHandler_Call) Run(run func(sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified)) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
+func (_c *MockFeedbagHandler_QueryIfModifiedHandler_Call) Run(run func(ctx context.Context, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x05_FeedbagQueryIfModified)) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(FeedbagManager), args[2].(oscar.SNAC_0x13_0x05_FeedbagQueryIfModified))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(FeedbagManager), args[3].(oscar.SNAC_0x13_0x05_FeedbagQueryIfModified))
 	})
 	return _c
 }
@@ -232,18 +238,18 @@ func (_c *MockFeedbagHandler_QueryIfModifiedHandler_Call) Return(_a0 XMessage, _
 	return _c
 }
 
-func (_c *MockFeedbagHandler_QueryIfModifiedHandler_Call) RunAndReturn(run func(*Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
+func (_c *MockFeedbagHandler_QueryIfModifiedHandler_Call) RunAndReturn(run func(context.Context, *Session, FeedbagManager, oscar.SNAC_0x13_0x05_FeedbagQueryIfModified) (XMessage, error)) *MockFeedbagHandler_QueryIfModifiedHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// RightsQueryHandler provides a mock function with given fields:
-func (_m *MockFeedbagHandler) RightsQueryHandler() XMessage {
-	ret := _m.Called()
+// RightsQueryHandler provides a mock function with given fields: _a0
+func (_m *MockFeedbagHandler) RightsQueryHandler(_a0 context.Context) XMessage {
+	ret := _m.Called(_a0)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(_a0)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -257,13 +263,14 @@ type MockFeedbagHandler_RightsQueryHandler_Call struct {
 }
 
 // RightsQueryHandler is a helper method to define mock.On call
-func (_e *MockFeedbagHandler_Expecter) RightsQueryHandler() *MockFeedbagHandler_RightsQueryHandler_Call {
-	return &MockFeedbagHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler")}
+//   - _a0 context.Context
+func (_e *MockFeedbagHandler_Expecter) RightsQueryHandler(_a0 interface{}) *MockFeedbagHandler_RightsQueryHandler_Call {
+	return &MockFeedbagHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler", _a0)}
 }
 
-func (_c *MockFeedbagHandler_RightsQueryHandler_Call) Run(run func()) *MockFeedbagHandler_RightsQueryHandler_Call {
+func (_c *MockFeedbagHandler_RightsQueryHandler_Call) Run(run func(_a0 context.Context)) *MockFeedbagHandler_RightsQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -273,14 +280,14 @@ func (_c *MockFeedbagHandler_RightsQueryHandler_Call) Return(_a0 XMessage) *Mock
 	return _c
 }
 
-func (_c *MockFeedbagHandler_RightsQueryHandler_Call) RunAndReturn(run func() XMessage) *MockFeedbagHandler_RightsQueryHandler_Call {
+func (_c *MockFeedbagHandler_RightsQueryHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockFeedbagHandler_RightsQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// StartClusterHandler provides a mock function with given fields: _a0
-func (_m *MockFeedbagHandler) StartClusterHandler(_a0 oscar.SNAC_0x13_0x11_FeedbagStartCluster) {
-	_m.Called(_a0)
+// StartClusterHandler provides a mock function with given fields: _a0, _a1
+func (_m *MockFeedbagHandler) StartClusterHandler(_a0 context.Context, _a1 oscar.SNAC_0x13_0x11_FeedbagStartCluster) {
+	_m.Called(_a0, _a1)
 }
 
 // MockFeedbagHandler_StartClusterHandler_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'StartClusterHandler'
@@ -289,14 +296,15 @@ type MockFeedbagHandler_StartClusterHandler_Call struct {
 }
 
 // StartClusterHandler is a helper method to define mock.On call
-//   - _a0 oscar.SNAC_0x13_0x11_FeedbagStartCluster
-func (_e *MockFeedbagHandler_Expecter) StartClusterHandler(_a0 interface{}) *MockFeedbagHandler_StartClusterHandler_Call {
-	return &MockFeedbagHandler_StartClusterHandler_Call{Call: _e.mock.On("StartClusterHandler", _a0)}
+//   - _a0 context.Context
+//   - _a1 oscar.SNAC_0x13_0x11_FeedbagStartCluster
+func (_e *MockFeedbagHandler_Expecter) StartClusterHandler(_a0 interface{}, _a1 interface{}) *MockFeedbagHandler_StartClusterHandler_Call {
+	return &MockFeedbagHandler_StartClusterHandler_Call{Call: _e.mock.On("StartClusterHandler", _a0, _a1)}
 }
 
-func (_c *MockFeedbagHandler_StartClusterHandler_Call) Run(run func(_a0 oscar.SNAC_0x13_0x11_FeedbagStartCluster)) *MockFeedbagHandler_StartClusterHandler_Call {
+func (_c *MockFeedbagHandler_StartClusterHandler_Call) Run(run func(_a0 context.Context, _a1 oscar.SNAC_0x13_0x11_FeedbagStartCluster)) *MockFeedbagHandler_StartClusterHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(oscar.SNAC_0x13_0x11_FeedbagStartCluster))
+		run(args[0].(context.Context), args[1].(oscar.SNAC_0x13_0x11_FeedbagStartCluster))
 	})
 	return _c
 }
@@ -306,28 +314,28 @@ func (_c *MockFeedbagHandler_StartClusterHandler_Call) Return() *MockFeedbagHand
 	return _c
 }
 
-func (_c *MockFeedbagHandler_StartClusterHandler_Call) RunAndReturn(run func(oscar.SNAC_0x13_0x11_FeedbagStartCluster)) *MockFeedbagHandler_StartClusterHandler_Call {
+func (_c *MockFeedbagHandler_StartClusterHandler_Call) RunAndReturn(run func(context.Context, oscar.SNAC_0x13_0x11_FeedbagStartCluster)) *MockFeedbagHandler_StartClusterHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// UpdateItemHandler provides a mock function with given fields: sm, sess, fm, snacPayloadIn
-func (_m *MockFeedbagHandler) UpdateItemHandler(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error) {
-	ret := _m.Called(sm, sess, fm, snacPayloadIn)
+// UpdateItemHandler provides a mock function with given fields: ctx, sm, sess, fm, snacPayloadIn
+func (_m *MockFeedbagHandler) UpdateItemHandler(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error) {
+	ret := _m.Called(ctx, sm, sess, fm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)); ok {
-		return rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)); ok {
+		return rf(ctx, sm, sess, fm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) XMessage); ok {
-		r0 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) XMessage); ok {
+		r0 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) error); ok {
-		r1 = rf(sm, sess, fm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) error); ok {
+		r1 = rf(ctx, sm, sess, fm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -341,17 +349,18 @@ type MockFeedbagHandler_UpdateItemHandler_Call struct {
 }
 
 // UpdateItemHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - sess *Session
 //   - fm FeedbagManager
 //   - snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem
-func (_e *MockFeedbagHandler_Expecter) UpdateItemHandler(sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_UpdateItemHandler_Call {
-	return &MockFeedbagHandler_UpdateItemHandler_Call{Call: _e.mock.On("UpdateItemHandler", sm, sess, fm, snacPayloadIn)}
+func (_e *MockFeedbagHandler_Expecter) UpdateItemHandler(ctx interface{}, sm interface{}, sess interface{}, fm interface{}, snacPayloadIn interface{}) *MockFeedbagHandler_UpdateItemHandler_Call {
+	return &MockFeedbagHandler_UpdateItemHandler_Call{Call: _e.mock.On("UpdateItemHandler", ctx, sm, sess, fm, snacPayloadIn)}
 }
 
-func (_c *MockFeedbagHandler_UpdateItemHandler_Call) Run(run func(sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem)) *MockFeedbagHandler_UpdateItemHandler_Call {
+func (_c *MockFeedbagHandler_UpdateItemHandler_Call) Run(run func(ctx context.Context, sm SessionManager, sess *Session, fm FeedbagManager, snacPayloadIn oscar.SNAC_0x13_0x09_FeedbagUpdateItem)) *MockFeedbagHandler_UpdateItemHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(*Session), args[2].(FeedbagManager), args[3].(oscar.SNAC_0x13_0x09_FeedbagUpdateItem))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(*Session), args[3].(FeedbagManager), args[4].(oscar.SNAC_0x13_0x09_FeedbagUpdateItem))
 	})
 	return _c
 }
@@ -361,7 +370,7 @@ func (_c *MockFeedbagHandler_UpdateItemHandler_Call) Return(_a0 XMessage, _a1 er
 	return _c
 }
 
-func (_c *MockFeedbagHandler_UpdateItemHandler_Call) RunAndReturn(run func(SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)) *MockFeedbagHandler_UpdateItemHandler_Call {
+func (_c *MockFeedbagHandler_UpdateItemHandler_Call) RunAndReturn(run func(context.Context, SessionManager, *Session, FeedbagManager, oscar.SNAC_0x13_0x09_FeedbagUpdateItem) (XMessage, error)) *MockFeedbagHandler_UpdateItemHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/feedbag_store.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"crypto/md5"
 	"database/sql"
 	"errors"
@@ -399,15 +400,15 @@ type FeedbagManager interface {
 }
 
 type SessionManager interface {
-	BroadcastToScreenNames(screenNames []string, msg XMessage)
+	BroadcastToScreenNames(ctx context.Context, screenNames []string, msg XMessage)
 	Empty() bool
 	NewSessionWithSN(sessID string, screenName string) *Session
 	Remove(sess *Session)
 	Retrieve(ID string) (*Session, bool)
 	RetrieveByScreenName(screenName string) (*Session, error)
-	SendToScreenName(screenName string, msg XMessage)
-	Broadcast(msg XMessage)
-	BroadcastExcept(except *Session, msg XMessage)
+	SendToScreenName(ctx context.Context, screenName string, msg XMessage)
+	Broadcast(ctx context.Context, msg XMessage)
+	BroadcastExcept(ctx context.Context, except *Session, msg XMessage)
 	Participants() []*Session
 }
 

server/feedbag_test.go

@@ -92,7 +92,7 @@ func TestQueryHandler(t *testing.T) {
 				ScreenName: tc.screenName,
 			}
 			svc := FeedbagService{}
-			outputSNAC, err := svc.QueryHandler(senderSession, fm)
+			outputSNAC, err := svc.QueryHandler(nil, senderSession, fm)
 			assert.NoError(t, err)
 			assert.Equal(t, tc.expectOutput, outputSNAC)
 		})
@@ -216,7 +216,7 @@ func TestQueryIfModifiedHandler(t *testing.T) {
 				ScreenName: tc.screenName,
 			}
 			svc := FeedbagService{}
-			outputSNAC, err := svc.QueryIfModifiedHandler(senderSession, fm, tc.inputSNAC)
+			outputSNAC, err := svc.QueryIfModifiedHandler(nil, senderSession, fm, tc.inputSNAC)
 			assert.NoError(t, err)
 			//
 			// verify output
@@ -547,14 +547,14 @@ func TestInsertItemHandler(t *testing.T) {
 			}
 			for _, n := range tc.buddyMessages {
 				sm.EXPECT().
-					SendToScreenName(n.user, n.msg).
+					SendToScreenName(mock.Anything, n.user, n.msg).
 					Maybe()
 			}
 			//
 			// send input SNAC
 			//
 			svc := FeedbagService{}
-			output, err := svc.InsertItemHandler(sm, tc.userSession, fm, tc.inputSNAC)
+			output, err := svc.InsertItemHandler(nil, sm, tc.userSession, fm, tc.inputSNAC)
 			assert.NoError(t, err)
 			//
 			// verify response
@@ -796,35 +796,38 @@ func TestFeedbagRouter_RouteFeedbag(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockFeedbagHandler(t)
 			svc.EXPECT().
-				DeleteItemHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				DeleteItemHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				QueryHandler(mock.Anything, mock.Anything).
+				QueryHandler(mock.Anything, mock.Anything, mock.Anything).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				QueryIfModifiedHandler(mock.Anything, mock.Anything, tc.input.snacOut).
+				QueryIfModifiedHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				RightsQueryHandler().
+				RightsQueryHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				InsertItemHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				InsertItemHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				UpdateItemHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				UpdateItemHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				StartClusterHandler(tc.input.snacOut).
+				StartClusterHandler(mock.Anything, tc.input.snacOut).
 				Maybe()
 
 			router := FeedbagRouter{
 				FeedbagHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -833,7 +836,7 @@ func TestFeedbagRouter_RouteFeedbag(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(0)
 
-			err := router.RouteFeedbag(nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteFeedbag(nil, nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/icbm.go

@@ -1,8 +1,10 @@
 package server
 
 import (
+	"context"
 	"errors"
 	"io"
+	"log/slog"
 
 	"github.com/mkaminski/goaim/oscar"
 )
@@ -13,59 +15,70 @@ const (
 )
 
 type ICBMHandler interface {
-	ChannelMsgToHostHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)
-	ClientEventHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error
-	EvilRequestHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)
-	ParameterQueryHandler() XMessage
+	ChannelMsgToHostHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)
+	ClientEventHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error
+	EvilRequestHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)
+	ParameterQueryHandler(context.Context) XMessage
 }
 
-func NewICBMRouter() ICBMRouter {
+func NewICBMRouter(logger *slog.Logger) ICBMRouter {
 	return ICBMRouter{
 		ICBMHandler: ICBMService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type ICBMRouter struct {
 	ICBMHandler
+	RouteLogger
 }
 
-func (rt *ICBMRouter) RouteICBM(sm SessionManager, fm FeedbagManager, sess *Session, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+func (rt *ICBMRouter) RouteICBM(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
 	switch SNACFrame.SubGroup {
 	case oscar.ICBMAddParameters:
 		inSNAC := oscar.SNAC_0x04_0x02_ICBMAddParameters{}
+		rt.logRequest(ctx, SNACFrame, inSNAC)
 		return oscar.Unmarshal(&inSNAC, r)
 	case oscar.ICBMParameterQuery:
-		outSNAC := rt.ParameterQueryHandler()
+		outSNAC := rt.ParameterQueryHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, outSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.ICBMChannelMsgToHost:
 		inSNAC := oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.ChannelMsgToHostHandler(sm, fm, sess, inSNAC)
+		outSNAC, err := rt.ChannelMsgToHostHandler(ctx, sm, fm, sess, inSNAC)
 		if err != nil || outSNAC == nil {
 			return err
 		}
+		rt.Logger.InfoContext(ctx, "user sent an IM", slog.String("recipient", inSNAC.ScreenName))
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.ICBMEvilRequest:
 		inSNAC := oscar.SNAC_0x04_0x08_ICBMEvilRequest{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.EvilRequestHandler(sm, fm, sess, inSNAC)
+		outSNAC, err := rt.EvilRequestHandler(ctx, sm, fm, sess, inSNAC)
 		if err != nil {
 			return err
 		}
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.ICBMClientErr:
 		inSNAC := oscar.SNAC_0x04_0x0B_ICBMClientErr{}
+		rt.logRequest(ctx, SNACFrame, inSNAC)
 		return oscar.Unmarshal(&inSNAC, r)
 	case oscar.ICBMClientEvent:
 		inSNAC := oscar.SNAC_0x04_0x14_ICBMClientEvent{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		return rt.ClientEventHandler(sm, fm, sess, inSNAC)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return rt.ClientEventHandler(ctx, sm, fm, sess, inSNAC)
 	default:
 		return ErrUnsupportedSubGroup
 	}
@@ -74,7 +87,7 @@ func (rt *ICBMRouter) RouteICBM(sm SessionManager, fm FeedbagManager, sess *Sess
 type ICBMService struct {
 }
 
-func (s ICBMService) ParameterQueryHandler() XMessage {
+func (s ICBMService) ParameterQueryHandler(context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.ICBM,
@@ -91,7 +104,7 @@ func (s ICBMService) ParameterQueryHandler() XMessage {
 	}
 }
 
-func (s ICBMService) ChannelMsgToHostHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error) {
+func (s ICBMService) ChannelMsgToHostHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error) {
 	blocked, err := fm.Blocked(sess.ScreenName, snacPayloadIn.ScreenName)
 	if err != nil {
 		return nil, err
@@ -150,7 +163,7 @@ func (s ICBMService) ChannelMsgToHostHandler(sm SessionManager, fm FeedbagManage
 	// far as I can tell.
 	clientIM.AddTLVList(snacPayloadIn.TLVRestBlock.TLVList)
 
-	sm.SendToScreenName(recipSess.ScreenName, XMessage{
+	sm.SendToScreenName(ctx, recipSess.ScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.ICBM,
 			SubGroup:  oscar.ICBMChannelMsgToclient,
@@ -177,7 +190,7 @@ func (s ICBMService) ChannelMsgToHostHandler(sm SessionManager, fm FeedbagManage
 	}, nil
 }
 
-func (s ICBMService) ClientEventHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error {
+func (s ICBMService) ClientEventHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error {
 	blocked, err := fm.Blocked(sess.ScreenName, snacPayloadIn.ScreenName)
 
 	switch {
@@ -186,7 +199,7 @@ func (s ICBMService) ClientEventHandler(sm SessionManager, fm FeedbagManager, se
 	case blocked != BlockedNo:
 		return nil
 	default:
-		sm.SendToScreenName(snacPayloadIn.ScreenName, XMessage{
+		sm.SendToScreenName(ctx, snacPayloadIn.ScreenName, XMessage{
 			snacFrame: oscar.SnacFrame{
 				FoodGroup: oscar.ICBM,
 				SubGroup:  oscar.ICBMClientEvent,
@@ -202,7 +215,7 @@ func (s ICBMService) ClientEventHandler(sm SessionManager, fm FeedbagManager, se
 	}
 }
 
-func (s ICBMService) EvilRequestHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error) {
+func (s ICBMService) EvilRequestHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error) {
 	// don't let users warn themselves, it causes the AIM client to go into a
 	// weird state.
 	if snacPayloadIn.ScreenName == sess.ScreenName {
@@ -259,7 +272,7 @@ func (s ICBMService) EvilRequestHandler(sm SessionManager, fm FeedbagManager, se
 		}
 	}
 
-	sm.SendToScreenName(recipSess.ScreenName, XMessage{
+	sm.SendToScreenName(ctx, recipSess.ScreenName, XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.OSERVICE,
 			SubGroup:  oscar.OServiceEvilNotification,
@@ -267,7 +280,7 @@ func (s ICBMService) EvilRequestHandler(sm SessionManager, fm FeedbagManager, se
 		snacOut: notif,
 	})
 
-	if err := BroadcastArrival(recipSess, sm, fm); err != nil {
+	if err := BroadcastArrival(ctx, recipSess, sm, fm); err != nil {
 		return XMessage{}, nil
 	}
 

server/icbm_mock.go

@@ -3,6 +3,8 @@
 package server
 
 import (
+	context "context"
+
 	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
 )
@@ -20,25 +22,25 @@ func (_m *MockICBMHandler) EXPECT() *MockICBMHandler_Expecter {
 	return &MockICBMHandler_Expecter{mock: &_m.Mock}
 }
 
-// ChannelMsgToHostHandler provides a mock function with given fields: sm, fm, sess, snacPayloadIn
-func (_m *MockICBMHandler) ChannelMsgToHostHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error) {
-	ret := _m.Called(sm, fm, sess, snacPayloadIn)
+// ChannelMsgToHostHandler provides a mock function with given fields: ctx, sm, fm, sess, snacPayloadIn
+func (_m *MockICBMHandler) ChannelMsgToHostHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error) {
+	ret := _m.Called(ctx, sm, fm, sess, snacPayloadIn)
 
 	var r0 *XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)); ok {
-		return rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)); ok {
+		return rf(ctx, sm, fm, sess, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) *XMessage); ok {
-		r0 = rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) *XMessage); ok {
+		r0 = rf(ctx, sm, fm, sess, snacPayloadIn)
 	} else {
 		if ret.Get(0) != nil {
 			r0 = ret.Get(0).(*XMessage)
 		}
 	}
 
-	if rf, ok := ret.Get(1).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) error); ok {
-		r1 = rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) error); ok {
+		r1 = rf(ctx, sm, fm, sess, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -52,17 +54,18 @@ type MockICBMHandler_ChannelMsgToHostHandler_Call struct {
 }
 
 // ChannelMsgToHostHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - sess *Session
 //   - snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost
-func (_e *MockICBMHandler_Expecter) ChannelMsgToHostHandler(sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_ChannelMsgToHostHandler_Call {
-	return &MockICBMHandler_ChannelMsgToHostHandler_Call{Call: _e.mock.On("ChannelMsgToHostHandler", sm, fm, sess, snacPayloadIn)}
+func (_e *MockICBMHandler_Expecter) ChannelMsgToHostHandler(ctx interface{}, sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_ChannelMsgToHostHandler_Call {
+	return &MockICBMHandler_ChannelMsgToHostHandler_Call{Call: _e.mock.On("ChannelMsgToHostHandler", ctx, sm, fm, sess, snacPayloadIn)}
 }
 
-func (_c *MockICBMHandler_ChannelMsgToHostHandler_Call) Run(run func(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost)) *MockICBMHandler_ChannelMsgToHostHandler_Call {
+func (_c *MockICBMHandler_ChannelMsgToHostHandler_Call) Run(run func(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost)) *MockICBMHandler_ChannelMsgToHostHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(FeedbagManager), args[2].(*Session), args[3].(oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(FeedbagManager), args[3].(*Session), args[4].(oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost))
 	})
 	return _c
 }
@@ -72,18 +75,18 @@ func (_c *MockICBMHandler_ChannelMsgToHostHandler_Call) Return(_a0 *XMessage, _a
 	return _c
 }
 
-func (_c *MockICBMHandler_ChannelMsgToHostHandler_Call) RunAndReturn(run func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)) *MockICBMHandler_ChannelMsgToHostHandler_Call {
+func (_c *MockICBMHandler_ChannelMsgToHostHandler_Call) RunAndReturn(run func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x06_ICBMChannelMsgToHost) (*XMessage, error)) *MockICBMHandler_ChannelMsgToHostHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// ClientEventHandler provides a mock function with given fields: sm, fm, sess, snacPayloadIn
-func (_m *MockICBMHandler) ClientEventHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error {
-	ret := _m.Called(sm, fm, sess, snacPayloadIn)
+// ClientEventHandler provides a mock function with given fields: ctx, sm, fm, sess, snacPayloadIn
+func (_m *MockICBMHandler) ClientEventHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent) error {
+	ret := _m.Called(ctx, sm, fm, sess, snacPayloadIn)
 
 	var r0 error
-	if rf, ok := ret.Get(0).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x14_ICBMClientEvent) error); ok {
-		r0 = rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x14_ICBMClientEvent) error); ok {
+		r0 = rf(ctx, sm, fm, sess, snacPayloadIn)
 	} else {
 		r0 = ret.Error(0)
 	}
@@ -97,17 +100,18 @@ type MockICBMHandler_ClientEventHandler_Call struct {
 }
 
 // ClientEventHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - sess *Session
 //   - snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent
-func (_e *MockICBMHandler_Expecter) ClientEventHandler(sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_ClientEventHandler_Call {
-	return &MockICBMHandler_ClientEventHandler_Call{Call: _e.mock.On("ClientEventHandler", sm, fm, sess, snacPayloadIn)}
+func (_e *MockICBMHandler_Expecter) ClientEventHandler(ctx interface{}, sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_ClientEventHandler_Call {
+	return &MockICBMHandler_ClientEventHandler_Call{Call: _e.mock.On("ClientEventHandler", ctx, sm, fm, sess, snacPayloadIn)}
 }
 
-func (_c *MockICBMHandler_ClientEventHandler_Call) Run(run func(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent)) *MockICBMHandler_ClientEventHandler_Call {
+func (_c *MockICBMHandler_ClientEventHandler_Call) Run(run func(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x14_ICBMClientEvent)) *MockICBMHandler_ClientEventHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(FeedbagManager), args[2].(*Session), args[3].(oscar.SNAC_0x04_0x14_ICBMClientEvent))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(FeedbagManager), args[3].(*Session), args[4].(oscar.SNAC_0x04_0x14_ICBMClientEvent))
 	})
 	return _c
 }
@@ -117,28 +121,28 @@ func (_c *MockICBMHandler_ClientEventHandler_Call) Return(_a0 error) *MockICBMHa
 	return _c
 }
 
-func (_c *MockICBMHandler_ClientEventHandler_Call) RunAndReturn(run func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x14_ICBMClientEvent) error) *MockICBMHandler_ClientEventHandler_Call {
+func (_c *MockICBMHandler_ClientEventHandler_Call) RunAndReturn(run func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x14_ICBMClientEvent) error) *MockICBMHandler_ClientEventHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// EvilRequestHandler provides a mock function with given fields: sm, fm, sess, snacPayloadIn
-func (_m *MockICBMHandler) EvilRequestHandler(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error) {
-	ret := _m.Called(sm, fm, sess, snacPayloadIn)
+// EvilRequestHandler provides a mock function with given fields: ctx, sm, fm, sess, snacPayloadIn
+func (_m *MockICBMHandler) EvilRequestHandler(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error) {
+	ret := _m.Called(ctx, sm, fm, sess, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)); ok {
-		return rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)); ok {
+		return rf(ctx, sm, fm, sess, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) XMessage); ok {
-		r0 = rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) XMessage); ok {
+		r0 = rf(ctx, sm, fm, sess, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) error); ok {
-		r1 = rf(sm, fm, sess, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) error); ok {
+		r1 = rf(ctx, sm, fm, sess, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -152,17 +156,18 @@ type MockICBMHandler_EvilRequestHandler_Call struct {
 }
 
 // EvilRequestHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - sess *Session
 //   - snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest
-func (_e *MockICBMHandler_Expecter) EvilRequestHandler(sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_EvilRequestHandler_Call {
-	return &MockICBMHandler_EvilRequestHandler_Call{Call: _e.mock.On("EvilRequestHandler", sm, fm, sess, snacPayloadIn)}
+func (_e *MockICBMHandler_Expecter) EvilRequestHandler(ctx interface{}, sm interface{}, fm interface{}, sess interface{}, snacPayloadIn interface{}) *MockICBMHandler_EvilRequestHandler_Call {
+	return &MockICBMHandler_EvilRequestHandler_Call{Call: _e.mock.On("EvilRequestHandler", ctx, sm, fm, sess, snacPayloadIn)}
 }
 
-func (_c *MockICBMHandler_EvilRequestHandler_Call) Run(run func(sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest)) *MockICBMHandler_EvilRequestHandler_Call {
+func (_c *MockICBMHandler_EvilRequestHandler_Call) Run(run func(ctx context.Context, sm SessionManager, fm FeedbagManager, sess *Session, snacPayloadIn oscar.SNAC_0x04_0x08_ICBMEvilRequest)) *MockICBMHandler_EvilRequestHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(SessionManager), args[1].(FeedbagManager), args[2].(*Session), args[3].(oscar.SNAC_0x04_0x08_ICBMEvilRequest))
+		run(args[0].(context.Context), args[1].(SessionManager), args[2].(FeedbagManager), args[3].(*Session), args[4].(oscar.SNAC_0x04_0x08_ICBMEvilRequest))
 	})
 	return _c
 }
@@ -172,18 +177,18 @@ func (_c *MockICBMHandler_EvilRequestHandler_Call) Return(_a0 XMessage, _a1 erro
 	return _c
 }
 
-func (_c *MockICBMHandler_EvilRequestHandler_Call) RunAndReturn(run func(SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)) *MockICBMHandler_EvilRequestHandler_Call {
+func (_c *MockICBMHandler_EvilRequestHandler_Call) RunAndReturn(run func(context.Context, SessionManager, FeedbagManager, *Session, oscar.SNAC_0x04_0x08_ICBMEvilRequest) (XMessage, error)) *MockICBMHandler_EvilRequestHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// ParameterQueryHandler provides a mock function with given fields:
-func (_m *MockICBMHandler) ParameterQueryHandler() XMessage {
-	ret := _m.Called()
+// ParameterQueryHandler provides a mock function with given fields: _a0
+func (_m *MockICBMHandler) ParameterQueryHandler(_a0 context.Context) XMessage {
+	ret := _m.Called(_a0)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(_a0)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -197,13 +202,14 @@ type MockICBMHandler_ParameterQueryHandler_Call struct {
 }
 
 // ParameterQueryHandler is a helper method to define mock.On call
-func (_e *MockICBMHandler_Expecter) ParameterQueryHandler() *MockICBMHandler_ParameterQueryHandler_Call {
-	return &MockICBMHandler_ParameterQueryHandler_Call{Call: _e.mock.On("ParameterQueryHandler")}
+//   - _a0 context.Context
+func (_e *MockICBMHandler_Expecter) ParameterQueryHandler(_a0 interface{}) *MockICBMHandler_ParameterQueryHandler_Call {
+	return &MockICBMHandler_ParameterQueryHandler_Call{Call: _e.mock.On("ParameterQueryHandler", _a0)}
 }
 
-func (_c *MockICBMHandler_ParameterQueryHandler_Call) Run(run func()) *MockICBMHandler_ParameterQueryHandler_Call {
+func (_c *MockICBMHandler_ParameterQueryHandler_Call) Run(run func(_a0 context.Context)) *MockICBMHandler_ParameterQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -213,7 +219,7 @@ func (_c *MockICBMHandler_ParameterQueryHandler_Call) Return(_a0 XMessage) *Mock
 	return _c
 }
 
-func (_c *MockICBMHandler_ParameterQueryHandler_Call) RunAndReturn(run func() XMessage) *MockICBMHandler_ParameterQueryHandler_Call {
+func (_c *MockICBMHandler_ParameterQueryHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockICBMHandler_ParameterQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/icbm_test.go

@@ -238,13 +238,13 @@ func TestSendAndReceiveChannelMsgTohost(t *testing.T) {
 				Return(tc.recipientSession, tc.recipRetrieveErr).
 				Maybe()
 			sm.EXPECT().
-				SendToScreenName(tc.recipientSession.ScreenName, tc.expectSNACToClient).
+				SendToScreenName(mock.Anything, tc.recipientSession.ScreenName, tc.expectSNACToClient).
 				Maybe()
 			//
 			// send input SNAC
 			//
 			svc := ICBMService{}
-			outputSNAC, err := svc.ChannelMsgToHostHandler(sm, fm, tc.senderSession, tc.inputSNAC)
+			outputSNAC, err := svc.ChannelMsgToHostHandler(nil, sm, fm, tc.senderSession, tc.inputSNAC)
 			assert.NoError(t, err)
 			//
 			// verify output
@@ -314,7 +314,7 @@ func TestSendAndReceiveClientEvent(t *testing.T) {
 			sm := NewMockSessionManager(t)
 			if tc.blockedState == BlockedNo {
 				sm.EXPECT().
-					SendToScreenName(tc.inputSNAC.ScreenName, tc.expectSNACToClient)
+					SendToScreenName(mock.Anything, tc.inputSNAC.ScreenName, tc.expectSNACToClient)
 			}
 			//
 			// send input SNAC
@@ -323,7 +323,7 @@ func TestSendAndReceiveClientEvent(t *testing.T) {
 				ScreenName: tc.senderScreenName,
 			}
 			svc := ICBMService{}
-			assert.NoError(t, svc.ClientEventHandler(sm, fm, senderSession, tc.inputSNAC))
+			assert.NoError(t, svc.ClientEventHandler(nil, sm, fm, senderSession, tc.inputSNAC))
 		})
 	}
 }
@@ -543,10 +543,10 @@ func TestSendAndReceiveEvilRequest(t *testing.T) {
 				Return(recipSess, tc.recipRetrieveErr).
 				Maybe()
 			sm.EXPECT().
-				SendToScreenName(tc.recipientScreenName, tc.expectSNACToClient).
+				SendToScreenName(mock.Anything, tc.recipientScreenName, tc.expectSNACToClient).
 				Maybe()
 			sm.EXPECT().
-				BroadcastToScreenNames(tc.recipientBuddies, tc.broadcastMessage).
+				BroadcastToScreenNames(mock.Anything, tc.recipientBuddies, tc.broadcastMessage).
 				Maybe()
 			//
 			// send input SNAC
@@ -555,7 +555,7 @@ func TestSendAndReceiveEvilRequest(t *testing.T) {
 				ScreenName: tc.senderSession.ScreenName,
 			}
 			svc := ICBMService{}
-			outputSNAC, err := svc.EvilRequestHandler(sm, fm, senderSession, tc.inputSNAC)
+			outputSNAC, err := svc.EvilRequestHandler(nil, sm, fm, senderSession, tc.inputSNAC)
 			assert.NoError(t, err)
 			assert.Equal(t, tc.expectOutput, outputSNAC)
 		})
@@ -706,26 +706,29 @@ func TestICBMRouter_RouteICBM(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockICBMHandler(t)
 			svc.EXPECT().
-				ChannelMsgToHostHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				ChannelMsgToHostHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				ClientEventHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				ClientEventHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.handlerErr).
 				Maybe()
 			if tc.output != nil {
 				svc.EXPECT().
-					EvilRequestHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+					EvilRequestHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 					Return(*tc.output, tc.handlerErr).
 					Maybe()
 				svc.EXPECT().
-					ParameterQueryHandler().
+					ParameterQueryHandler(mock.Anything).
 					Return(*tc.output).
 					Maybe()
 			}
 
 			router := ICBMRouter{
 				ICBMHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -734,7 +737,7 @@ func TestICBMRouter_RouteICBM(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(1)
 
-			err := router.RouteICBM(nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteICBM(nil, nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/locate.go

@@ -1,68 +1,80 @@
 package server
 
 import (
+	"context"
 	"errors"
 	"io"
+	"log/slog"
 
 	"github.com/mkaminski/goaim/oscar"
 )
 
 type LocateHandler interface {
-	RightsQueryHandler() XMessage
-	SetDirInfoHandler() XMessage
-	SetInfoHandler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error
-	SetKeywordInfoHandler() XMessage
-	UserInfoQuery2Handler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)
+	RightsQueryHandler(ctx context.Context) XMessage
+	SetDirInfoHandler(ctx context.Context) XMessage
+	SetInfoHandler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error
+	SetKeywordInfoHandler(ctx context.Context) XMessage
+	UserInfoQuery2Handler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)
 }
 
-func NewLocateRouter() LocateRouter {
+func NewLocateRouter(logger *slog.Logger) LocateRouter {
 	return LocateRouter{
 		LocateHandler: LocateService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type LocateRouter struct {
 	LocateHandler
+	RouteLogger
 }
 
-func (rt LocateRouter) RouteLocate(sess *Session, sm SessionManager, fm *FeedbagStore, snac oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
-	switch snac.SubGroup {
+func (rt LocateRouter) RouteLocate(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+	switch SNACFrame.SubGroup {
 	case oscar.LocateRightsQuery:
-		outSNAC := rt.RightsQueryHandler()
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		outSNAC := rt.RightsQueryHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, nil, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.LocateSetInfo:
-		snacPayloadIn := oscar.SNAC_0x02_0x04_LocateSetInfo{}
-		if err := oscar.Unmarshal(&snacPayloadIn, r); err != nil {
+		inSNAC := oscar.SNAC_0x02_0x04_LocateSetInfo{}
+		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		return rt.SetInfoHandler(sess, sm, fm, fm, snacPayloadIn)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return rt.SetInfoHandler(ctx, sess, sm, fm, fm, inSNAC)
 	case oscar.LocateSetDirInfo:
-		snacPayloadIn := oscar.SNAC_0x02_0x09_LocateSetDirInfo{}
-		if err := oscar.Unmarshal(&snacPayloadIn, r); err != nil {
+		inSNAC := oscar.SNAC_0x02_0x09_LocateSetDirInfo{}
+		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC := rt.SetDirInfoHandler()
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		outSNAC := rt.SetDirInfoHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.LocateGetDirInfo:
-		snacPayloadIn := oscar.SNAC_0x02_0x0B_LocateGetDirInfo{}
-		return oscar.Unmarshal(&snacPayloadIn, r)
+		inSNAC := oscar.SNAC_0x02_0x0B_LocateGetDirInfo{}
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return oscar.Unmarshal(&inSNAC, r)
 	case oscar.LocateSetKeywordInfo:
-		snacPayloadIn := oscar.SNAC_0x02_0x0F_LocateSetKeywordInfo{}
-		if err := oscar.Unmarshal(&snacPayloadIn, r); err != nil {
+		inSNAC := oscar.SNAC_0x02_0x0F_LocateSetKeywordInfo{}
+		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC := rt.SetKeywordInfoHandler()
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		outSNAC := rt.SetKeywordInfoHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.LocateUserInfoQuery2:
-		snacPayloadIn := oscar.SNAC_0x02_0x15_LocateUserInfoQuery2{}
-		if err := oscar.Unmarshal(&snacPayloadIn, r); err != nil {
+		inSNAC := oscar.SNAC_0x02_0x15_LocateUserInfoQuery2{}
+		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.UserInfoQuery2Handler(sess, sm, fm, fm, snacPayloadIn)
+		outSNAC, err := rt.UserInfoQuery2Handler(ctx, sess, sm, fm, fm, inSNAC)
 		if err != nil {
 			return err
 		}
-		return writeOutSNAC(snac, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
+		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	default:
 		return ErrUnsupportedSubGroup
 	}
@@ -71,7 +83,7 @@ func (rt LocateRouter) RouteLocate(sess *Session, sm SessionManager, fm *Feedbag
 type LocateService struct {
 }
 
-func (s LocateService) RightsQueryHandler() XMessage {
+func (s LocateService) RightsQueryHandler(context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.LOCATE,
@@ -91,7 +103,7 @@ func (s LocateService) RightsQueryHandler() XMessage {
 	}
 }
 
-func (s LocateService) SetInfoHandler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error {
+func (s LocateService) SetInfoHandler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error {
 	// update profile
 	if profile, hasProfile := snacPayloadIn.GetString(oscar.LocateTLVTagsInfoSigData); hasProfile {
 		if err := pm.UpsertProfile(sess.ScreenName, profile); err != nil {
@@ -102,14 +114,14 @@ func (s LocateService) SetInfoHandler(sess *Session, sm SessionManager, fm Feedb
 	// broadcast away message change to buddies
 	if awayMsg, hasAwayMsg := snacPayloadIn.GetString(oscar.LocateTLVTagsInfoUnavailableData); hasAwayMsg {
 		sess.SetAwayMessage(awayMsg)
-		if err := BroadcastArrival(sess, sm, fm); err != nil {
+		if err := BroadcastArrival(ctx, sess, sm, fm); err != nil {
 			return err
 		}
 	}
 	return nil
 }
 
-func (s LocateService) UserInfoQuery2Handler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error) {
+func (s LocateService) UserInfoQuery2Handler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error) {
 	blocked, err := fm.Blocked(sess.ScreenName, snacPayloadIn.ScreenName)
 	switch {
 	case err != nil:
@@ -176,7 +188,7 @@ func (s LocateService) UserInfoQuery2Handler(sess *Session, sm SessionManager, f
 	}, nil
 }
 
-func (s LocateService) SetDirInfoHandler() XMessage {
+func (s LocateService) SetDirInfoHandler(ctx context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.LOCATE,
@@ -188,7 +200,7 @@ func (s LocateService) SetDirInfoHandler() XMessage {
 	}
 }
 
-func (s LocateService) SetKeywordInfoHandler() XMessage {
+func (s LocateService) SetKeywordInfoHandler(ctx context.Context) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.LOCATE,

server/locate_mock.go

@@ -3,6 +3,8 @@
 package server
 
 import (
+	context "context"
+
 	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
 )
@@ -20,13 +22,13 @@ func (_m *MockLocateHandler) EXPECT() *MockLocateHandler_Expecter {
 	return &MockLocateHandler_Expecter{mock: &_m.Mock}
 }
 
-// RightsQueryHandler provides a mock function with given fields:
-func (_m *MockLocateHandler) RightsQueryHandler() XMessage {
-	ret := _m.Called()
+// RightsQueryHandler provides a mock function with given fields: ctx
+func (_m *MockLocateHandler) RightsQueryHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -40,13 +42,14 @@ type MockLocateHandler_RightsQueryHandler_Call struct {
 }
 
 // RightsQueryHandler is a helper method to define mock.On call
-func (_e *MockLocateHandler_Expecter) RightsQueryHandler() *MockLocateHandler_RightsQueryHandler_Call {
-	return &MockLocateHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler")}
+//   - ctx context.Context
+func (_e *MockLocateHandler_Expecter) RightsQueryHandler(ctx interface{}) *MockLocateHandler_RightsQueryHandler_Call {
+	return &MockLocateHandler_RightsQueryHandler_Call{Call: _e.mock.On("RightsQueryHandler", ctx)}
 }
 
-func (_c *MockLocateHandler_RightsQueryHandler_Call) Run(run func()) *MockLocateHandler_RightsQueryHandler_Call {
+func (_c *MockLocateHandler_RightsQueryHandler_Call) Run(run func(ctx context.Context)) *MockLocateHandler_RightsQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -56,18 +59,18 @@ func (_c *MockLocateHandler_RightsQueryHandler_Call) Return(_a0 XMessage) *MockL
 	return _c
 }
 
-func (_c *MockLocateHandler_RightsQueryHandler_Call) RunAndReturn(run func() XMessage) *MockLocateHandler_RightsQueryHandler_Call {
+func (_c *MockLocateHandler_RightsQueryHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockLocateHandler_RightsQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// SetDirInfoHandler provides a mock function with given fields:
-func (_m *MockLocateHandler) SetDirInfoHandler() XMessage {
-	ret := _m.Called()
+// SetDirInfoHandler provides a mock function with given fields: ctx
+func (_m *MockLocateHandler) SetDirInfoHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -81,13 +84,14 @@ type MockLocateHandler_SetDirInfoHandler_Call struct {
 }
 
 // SetDirInfoHandler is a helper method to define mock.On call
-func (_e *MockLocateHandler_Expecter) SetDirInfoHandler() *MockLocateHandler_SetDirInfoHandler_Call {
-	return &MockLocateHandler_SetDirInfoHandler_Call{Call: _e.mock.On("SetDirInfoHandler")}
+//   - ctx context.Context
+func (_e *MockLocateHandler_Expecter) SetDirInfoHandler(ctx interface{}) *MockLocateHandler_SetDirInfoHandler_Call {
+	return &MockLocateHandler_SetDirInfoHandler_Call{Call: _e.mock.On("SetDirInfoHandler", ctx)}
 }
 
-func (_c *MockLocateHandler_SetDirInfoHandler_Call) Run(run func()) *MockLocateHandler_SetDirInfoHandler_Call {
+func (_c *MockLocateHandler_SetDirInfoHandler_Call) Run(run func(ctx context.Context)) *MockLocateHandler_SetDirInfoHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -97,18 +101,18 @@ func (_c *MockLocateHandler_SetDirInfoHandler_Call) Return(_a0 XMessage) *MockLo
 	return _c
 }
 
-func (_c *MockLocateHandler_SetDirInfoHandler_Call) RunAndReturn(run func() XMessage) *MockLocateHandler_SetDirInfoHandler_Call {
+func (_c *MockLocateHandler_SetDirInfoHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockLocateHandler_SetDirInfoHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// SetInfoHandler provides a mock function with given fields: sess, sm, fm, pm, snacPayloadIn
-func (_m *MockLocateHandler) SetInfoHandler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error {
-	ret := _m.Called(sess, sm, fm, pm, snacPayloadIn)
+// SetInfoHandler provides a mock function with given fields: ctx, sess, sm, fm, pm, snacPayloadIn
+func (_m *MockLocateHandler) SetInfoHandler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo) error {
+	ret := _m.Called(ctx, sess, sm, fm, pm, snacPayloadIn)
 
 	var r0 error
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x04_LocateSetInfo) error); ok {
-		r0 = rf(sess, sm, fm, pm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x04_LocateSetInfo) error); ok {
+		r0 = rf(ctx, sess, sm, fm, pm, snacPayloadIn)
 	} else {
 		r0 = ret.Error(0)
 	}
@@ -122,18 +126,19 @@ type MockLocateHandler_SetInfoHandler_Call struct {
 }
 
 // SetInfoHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - pm ProfileManager
 //   - snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo
-func (_e *MockLocateHandler_Expecter) SetInfoHandler(sess interface{}, sm interface{}, fm interface{}, pm interface{}, snacPayloadIn interface{}) *MockLocateHandler_SetInfoHandler_Call {
-	return &MockLocateHandler_SetInfoHandler_Call{Call: _e.mock.On("SetInfoHandler", sess, sm, fm, pm, snacPayloadIn)}
+func (_e *MockLocateHandler_Expecter) SetInfoHandler(ctx interface{}, sess interface{}, sm interface{}, fm interface{}, pm interface{}, snacPayloadIn interface{}) *MockLocateHandler_SetInfoHandler_Call {
+	return &MockLocateHandler_SetInfoHandler_Call{Call: _e.mock.On("SetInfoHandler", ctx, sess, sm, fm, pm, snacPayloadIn)}
 }
 
-func (_c *MockLocateHandler_SetInfoHandler_Call) Run(run func(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo)) *MockLocateHandler_SetInfoHandler_Call {
+func (_c *MockLocateHandler_SetInfoHandler_Call) Run(run func(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x04_LocateSetInfo)) *MockLocateHandler_SetInfoHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(SessionManager), args[2].(FeedbagManager), args[3].(ProfileManager), args[4].(oscar.SNAC_0x02_0x04_LocateSetInfo))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(SessionManager), args[3].(FeedbagManager), args[4].(ProfileManager), args[5].(oscar.SNAC_0x02_0x04_LocateSetInfo))
 	})
 	return _c
 }
@@ -143,18 +148,18 @@ func (_c *MockLocateHandler_SetInfoHandler_Call) Return(_a0 error) *MockLocateHa
 	return _c
 }
 
-func (_c *MockLocateHandler_SetInfoHandler_Call) RunAndReturn(run func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x04_LocateSetInfo) error) *MockLocateHandler_SetInfoHandler_Call {
+func (_c *MockLocateHandler_SetInfoHandler_Call) RunAndReturn(run func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x04_LocateSetInfo) error) *MockLocateHandler_SetInfoHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// SetKeywordInfoHandler provides a mock function with given fields:
-func (_m *MockLocateHandler) SetKeywordInfoHandler() XMessage {
-	ret := _m.Called()
+// SetKeywordInfoHandler provides a mock function with given fields: ctx
+func (_m *MockLocateHandler) SetKeywordInfoHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -168,13 +173,14 @@ type MockLocateHandler_SetKeywordInfoHandler_Call struct {
 }
 
 // SetKeywordInfoHandler is a helper method to define mock.On call
-func (_e *MockLocateHandler_Expecter) SetKeywordInfoHandler() *MockLocateHandler_SetKeywordInfoHandler_Call {
-	return &MockLocateHandler_SetKeywordInfoHandler_Call{Call: _e.mock.On("SetKeywordInfoHandler")}
+//   - ctx context.Context
+func (_e *MockLocateHandler_Expecter) SetKeywordInfoHandler(ctx interface{}) *MockLocateHandler_SetKeywordInfoHandler_Call {
+	return &MockLocateHandler_SetKeywordInfoHandler_Call{Call: _e.mock.On("SetKeywordInfoHandler", ctx)}
 }
 
-func (_c *MockLocateHandler_SetKeywordInfoHandler_Call) Run(run func()) *MockLocateHandler_SetKeywordInfoHandler_Call {
+func (_c *MockLocateHandler_SetKeywordInfoHandler_Call) Run(run func(ctx context.Context)) *MockLocateHandler_SetKeywordInfoHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -184,28 +190,28 @@ func (_c *MockLocateHandler_SetKeywordInfoHandler_Call) Return(_a0 XMessage) *Mo
 	return _c
 }
 
-func (_c *MockLocateHandler_SetKeywordInfoHandler_Call) RunAndReturn(run func() XMessage) *MockLocateHandler_SetKeywordInfoHandler_Call {
+func (_c *MockLocateHandler_SetKeywordInfoHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockLocateHandler_SetKeywordInfoHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// UserInfoQuery2Handler provides a mock function with given fields: sess, sm, fm, pm, snacPayloadIn
-func (_m *MockLocateHandler) UserInfoQuery2Handler(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error) {
-	ret := _m.Called(sess, sm, fm, pm, snacPayloadIn)
+// UserInfoQuery2Handler provides a mock function with given fields: ctx, sess, sm, fm, pm, snacPayloadIn
+func (_m *MockLocateHandler) UserInfoQuery2Handler(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error) {
+	ret := _m.Called(ctx, sess, sm, fm, pm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)); ok {
-		return rf(sess, sm, fm, pm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)); ok {
+		return rf(ctx, sess, sm, fm, pm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) XMessage); ok {
-		r0 = rf(sess, sm, fm, pm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) XMessage); ok {
+		r0 = rf(ctx, sess, sm, fm, pm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) error); ok {
-		r1 = rf(sess, sm, fm, pm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) error); ok {
+		r1 = rf(ctx, sess, sm, fm, pm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -219,18 +225,19 @@ type MockLocateHandler_UserInfoQuery2Handler_Call struct {
 }
 
 // UserInfoQuery2Handler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - pm ProfileManager
 //   - snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2
-func (_e *MockLocateHandler_Expecter) UserInfoQuery2Handler(sess interface{}, sm interface{}, fm interface{}, pm interface{}, snacPayloadIn interface{}) *MockLocateHandler_UserInfoQuery2Handler_Call {
-	return &MockLocateHandler_UserInfoQuery2Handler_Call{Call: _e.mock.On("UserInfoQuery2Handler", sess, sm, fm, pm, snacPayloadIn)}
+func (_e *MockLocateHandler_Expecter) UserInfoQuery2Handler(ctx interface{}, sess interface{}, sm interface{}, fm interface{}, pm interface{}, snacPayloadIn interface{}) *MockLocateHandler_UserInfoQuery2Handler_Call {
+	return &MockLocateHandler_UserInfoQuery2Handler_Call{Call: _e.mock.On("UserInfoQuery2Handler", ctx, sess, sm, fm, pm, snacPayloadIn)}
 }
 
-func (_c *MockLocateHandler_UserInfoQuery2Handler_Call) Run(run func(sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2)) *MockLocateHandler_UserInfoQuery2Handler_Call {
+func (_c *MockLocateHandler_UserInfoQuery2Handler_Call) Run(run func(ctx context.Context, sess *Session, sm SessionManager, fm FeedbagManager, pm ProfileManager, snacPayloadIn oscar.SNAC_0x02_0x15_LocateUserInfoQuery2)) *MockLocateHandler_UserInfoQuery2Handler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(SessionManager), args[2].(FeedbagManager), args[3].(ProfileManager), args[4].(oscar.SNAC_0x02_0x15_LocateUserInfoQuery2))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(SessionManager), args[3].(FeedbagManager), args[4].(ProfileManager), args[5].(oscar.SNAC_0x02_0x15_LocateUserInfoQuery2))
 	})
 	return _c
 }
@@ -240,7 +247,7 @@ func (_c *MockLocateHandler_UserInfoQuery2Handler_Call) Return(_a0 XMessage, _a1
 	return _c
 }
 
-func (_c *MockLocateHandler_UserInfoQuery2Handler_Call) RunAndReturn(run func(*Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)) *MockLocateHandler_UserInfoQuery2Handler_Call {
+func (_c *MockLocateHandler_UserInfoQuery2Handler_Call) RunAndReturn(run func(context.Context, *Session, SessionManager, FeedbagManager, ProfileManager, oscar.SNAC_0x02_0x15_LocateUserInfoQuery2) (XMessage, error)) *MockLocateHandler_UserInfoQuery2Handler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/locate_test.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"github.com/mkaminski/goaim/oscar"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -284,7 +285,7 @@ func TestSendAndReceiveUserInfoQuery2(t *testing.T) {
 			}
 
 			svc := LocateService{}
-			outputSNAC, err := svc.UserInfoQuery2Handler(tc.userSession, sm, fm, pm, tc.inputSNAC)
+			outputSNAC, err := svc.UserInfoQuery2Handler(context.Background(), tc.userSession, sm, fm, pm, tc.inputSNAC)
 			assert.NoError(t, err)
 			assert.Equal(t, tc.expectOutput, outputSNAC)
 		})
@@ -469,28 +470,31 @@ func TestLocateRouter_RouteLocate(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockLocateHandler(t)
 			svc.EXPECT().
-				RightsQueryHandler().
+				RightsQueryHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				SetDirInfoHandler().
+				SetDirInfoHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				SetInfoHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				SetInfoHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				SetKeywordInfoHandler().
+				SetKeywordInfoHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				UserInfoQuery2Handler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				UserInfoQuery2Handler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 
 			router := LocateRouter{
 				LocateHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -499,7 +503,7 @@ func TestLocateRouter_RouteLocate(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(1)
 
-			err := router.RouteLocate(nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteLocate(nil, nil, nil, nil, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/logging.go

@@ -0,0 +1,117 @@
+package server
+
+import (
+	"context"
+	"log/slog"
+	"os"
+	"strings"
+
+	"github.com/mkaminski/goaim/oscar"
+)
+
+const (
+	LevelTrace = slog.Level(-8)
+)
+
+var levelNames = map[slog.Leveler]string{
+	LevelTrace: "TRACE",
+}
+
+func NewLogger(cfg Config) *slog.Logger {
+	var level slog.Level
+	switch strings.ToLower(cfg.LogLevel) {
+	case "trace":
+		level = LevelTrace
+	case "debug":
+		level = slog.LevelDebug
+	case "warn":
+		level = slog.LevelWarn
+	case "error":
+		level = slog.LevelError
+	case "info":
+		fallthrough
+	default:
+		level = slog.LevelInfo
+	}
+
+	opts := &slog.HandlerOptions{
+		Level: level,
+		ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+			if a.Key == slog.LevelKey {
+				level := a.Value.Any().(slog.Level)
+				levelLabel, exists := levelNames[level]
+				if !exists {
+					levelLabel = level.String()
+				}
+				a.Value = slog.StringValue(levelLabel)
+			}
+
+			return a
+		},
+	}
+	return slog.New(Handler{slog.NewTextHandler(os.Stdout, opts)})
+}
+
+type Handler struct {
+	slog.Handler
+}
+
+func (h Handler) Handle(ctx context.Context, r slog.Record) error {
+	if sn := ctx.Value("screenName"); sn != nil {
+		r.AddAttrs(slog.Attr{Key: "screenName", Value: slog.StringValue(sn.(string))})
+	}
+	if ip := ctx.Value("ip"); ip != nil {
+		r.AddAttrs(slog.Attr{Key: "ip", Value: slog.StringValue(ip.(string))})
+	}
+	return h.Handler.Handle(ctx, r)
+}
+
+func (h Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return Handler{h.Handler.WithAttrs(attrs)}
+}
+
+func (h Handler) WithGroup(name string) slog.Handler {
+	return h.Handler.WithGroup(name)
+}
+
+type RouteLogger struct {
+	Logger *slog.Logger
+}
+
+func (rt RouteLogger) logRequestAndResponse(ctx context.Context, inFrame oscar.SnacFrame, inSNAC any, outFrame oscar.SnacFrame, outSNAC any) {
+	msg := "client request -> server response"
+	switch {
+	case rt.Logger.Enabled(ctx, LevelTrace):
+		rt.Logger.LogAttrs(ctx, LevelTrace, msg, SNACLogGroupWithPayload("request", inFrame, inSNAC),
+			SNACLogGroupWithPayload("response", outFrame, outSNAC))
+	case rt.Logger.Enabled(ctx, slog.LevelDebug):
+		rt.Logger.LogAttrs(ctx, slog.LevelDebug, msg, SNACLogGroup("request", inFrame),
+			SNACLogGroup("response", outFrame))
+	}
+}
+
+func (rt RouteLogger) logRequest(ctx context.Context, inFrame oscar.SnacFrame, inSNAC any) {
+	const msg = "client request"
+	switch {
+	case rt.Logger.Enabled(ctx, LevelTrace):
+		rt.Logger.LogAttrs(ctx, LevelTrace, msg, SNACLogGroupWithPayload("request", inFrame, inSNAC))
+	case rt.Logger.Enabled(ctx, slog.LevelDebug):
+		rt.Logger.LogAttrs(ctx, slog.LevelDebug, msg, slog.Group("request", SNACLogGroup("request", inFrame)))
+	}
+}
+
+func SNACLogGroup(key string, outFrame oscar.SnacFrame) slog.Attr {
+	return slog.Group(key,
+		slog.String("food_group", oscar.FoodGroupStr(outFrame.FoodGroup)),
+		slog.String("sub_group", oscar.SubGroupStr(outFrame.FoodGroup, outFrame.SubGroup)),
+	)
+}
+
+func SNACLogGroupWithPayload(key string, outFrame oscar.SnacFrame, outSNAC any) slog.Attr {
+	return slog.Group(key,
+		slog.String("food_group", oscar.FoodGroupStr(outFrame.FoodGroup)),
+		slog.String("sub_group", oscar.SubGroupStr(outFrame.FoodGroup, outFrame.SubGroup)),
+		slog.Any("snac_frame", outFrame),
+		slog.Any("snac_payload", outSNAC),
+	)
+}

server/mgmt_api.go

@@ -3,12 +3,15 @@ package server
 import (
 	"encoding/json"
 	"fmt"
+	"log/slog"
+	"net"
 	"net/http"
+	"os"
 
 	"github.com/google/uuid"
 )
 
-func StartManagementAPI(fs *FeedbagStore) {
+func StartManagementAPI(fs *FeedbagStore, logger *slog.Logger) {
 	http.HandleFunc("/user", func(w http.ResponseWriter, r *http.Request) {
 		switch r.Method {
 		case http.MethodGet:
@@ -20,10 +23,16 @@ func StartManagementAPI(fs *FeedbagStore) {
 		}
 	})
 	//todo make port configurable
-	port := 8080
-	fmt.Printf("Server is running on :%d...\n", port)
-	if err := http.ListenAndServe(fmt.Sprintf(":%d", port), nil); err != nil {
-		panic(err)
+	addr := Address("", 8080)
+	listener, err := net.Listen("tcp", addr)
+	if err != nil {
+		logger.Error("unable to bind management API address address", "err", err.Error())
+		os.Exit(1)
+	}
+	logger.Info("starting management API server", "addr", addr)
+	if err := http.Serve(listener, nil); err != nil {
+		logger.Info("unable to start management API server", "err", err.Error())
+		os.Exit(1)
 	}
 }
 

server/oservice.go

@@ -2,91 +2,106 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"github.com/mkaminski/goaim/oscar"
 	"io"
+	"log/slog"
 	"time"
 )
 
 type OServiceHandler interface {
 	WriteOServiceHostOnline(w io.Writer, sequence *uint32) error
-	ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error
-	ClientVersionsHandler(snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage
-	IdleNotificationHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error
-	RateParamsQueryHandler() XMessage
-	RateParamsSubAddHandler(oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)
-	ServiceRequestHandler(cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)
-	SetUserInfoFieldsHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)
-	UserInfoQueryHandler(sess *Session) XMessage
+	ClientOnlineHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error
+	ClientVersionsHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage
+	IdleNotificationHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error
+	RateParamsQueryHandler(ctx context.Context) XMessage
+	RateParamsSubAddHandler(context.Context, oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)
+	ServiceRequestHandler(ctx context.Context, cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)
+	SetUserInfoFieldsHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)
+	UserInfoQueryHandler(ctx context.Context, sess *Session) XMessage
 }
 
-func NewOServiceRouter() OServiceRouter {
+func NewOServiceRouter(logger *slog.Logger) OServiceRouter {
 	return OServiceRouter{
 		OServiceHandler: OServiceService{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type OServiceRouter struct {
 	OServiceHandler
+	RouteLogger
 }
 
-func (rt OServiceRouter) RouteOService(cfg Config, cr *ChatRegistry, sm SessionManager, fm *FeedbagStore, sess *Session, room ChatRoom, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
+func (rt OServiceRouter) RouteOService(ctx context.Context, cfg Config, cr *ChatRegistry, sm SessionManager, fm *FeedbagStore, sess *Session, room ChatRoom, SNACFrame oscar.SnacFrame, r io.Reader, w io.Writer, sequence *uint32) error {
 	switch SNACFrame.SubGroup {
 	case oscar.OServiceClientOnline:
 		inSNAC := oscar.SNAC_0x01_0x02_OServiceClientOnline{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		return rt.ClientOnlineHandler(inSNAC, sess, sm, fm, room)
+		rt.Logger.InfoContext(ctx, "user signed on")
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return rt.ClientOnlineHandler(ctx, inSNAC, sess, sm, fm, room)
 	case oscar.OServiceServiceRequest:
 		inSNAC := oscar.SNAC_0x01_0x04_OServiceServiceRequest{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.ServiceRequestHandler(cfg, cr, sess, inSNAC)
+		outSNAC, err := rt.ServiceRequestHandler(ctx, cfg, cr, sess, inSNAC)
 		switch {
 		case errors.Is(err, ErrUnsupportedSubGroup):
 			return sendInvalidSNACErr(SNACFrame, w, sequence)
 		case err != nil:
 			return err
 		}
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.OServiceRateParamsQuery:
-		outSNAC := rt.RateParamsQueryHandler()
+		outSNAC := rt.RateParamsQueryHandler(ctx)
+		rt.logRequestAndResponse(ctx, SNACFrame, nil, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.OServiceRateParamsSubAdd:
 		inSNAC := oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		rt.RateParamsSubAddHandler(inSNAC)
+		rt.RateParamsSubAddHandler(ctx, inSNAC)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
 		return oscar.Unmarshal(&inSNAC, r)
 	case oscar.OServiceUserInfoQuery:
-		outSNAC := rt.UserInfoQueryHandler(sess)
+		outSNAC := rt.UserInfoQueryHandler(ctx, sess)
+		rt.logRequestAndResponse(ctx, SNACFrame, nil, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.OServiceIdleNotification:
 		inSNAC := oscar.SNAC_0x01_0x11_OServiceIdleNotification{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		return rt.IdleNotificationHandler(sess, sm, fm, inSNAC)
+		rt.logRequest(ctx, SNACFrame, inSNAC)
+		return rt.IdleNotificationHandler(ctx, sess, sm, fm, inSNAC)
 	case oscar.OServiceClientVersions:
 		inSNAC := oscar.SNAC_0x01_0x17_OServiceClientVersions{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC := rt.ClientVersionsHandler(inSNAC)
+		outSNAC := rt.ClientVersionsHandler(ctx, inSNAC)
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	case oscar.OServiceSetUserInfoFields:
 		inSNAC := oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields{}
 		if err := oscar.Unmarshal(&inSNAC, r); err != nil {
 			return err
 		}
-		outSNAC, err := rt.SetUserInfoFieldsHandler(sess, sm, fm, inSNAC)
+		outSNAC, err := rt.SetUserInfoFieldsHandler(ctx, sess, sm, fm, inSNAC)
 		if err != nil {
 			return err
 		}
+		rt.logRequestAndResponse(ctx, SNACFrame, inSNAC, outSNAC.snacFrame, outSNAC.snacOut)
 		return writeOutSNAC(SNACFrame, outSNAC.snacFrame, outSNAC.snacOut, sequence, w)
 	default:
 		return ErrUnsupportedSubGroup
@@ -97,7 +112,6 @@ type OServiceService struct {
 }
 
 func (s OServiceService) WriteOServiceHostOnline(w io.Writer, sequence *uint32) error {
-	fmt.Println("writeOServiceHostOnline...")
 	snacFrameOut := oscar.SnacFrame{
 		FoodGroup: oscar.OSERVICE,
 		SubGroup:  oscar.OServiceHostOnline,
@@ -116,7 +130,7 @@ func (s OServiceService) WriteOServiceHostOnline(w io.Writer, sequence *uint32)
 	return writeOutSNAC(oscar.SnacFrame{}, snacFrameOut, snacPayloadOut, sequence, w)
 }
 
-func (s OServiceService) ClientVersionsHandler(snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage {
+func (s OServiceService) ClientVersionsHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.OSERVICE,
@@ -128,7 +142,7 @@ func (s OServiceService) ClientVersionsHandler(snacPayloadIn oscar.SNAC_0x01_0x1
 	}
 }
 
-func (s OServiceService) RateParamsQueryHandler() XMessage {
+func (s OServiceService) RateParamsQueryHandler(ctx context.Context) XMessage {
 	snacFrameOut := oscar.SnacFrame{
 		FoodGroup: oscar.OSERVICE,
 		SubGroup:  oscar.OServiceRateParamsReply,
@@ -195,7 +209,7 @@ func (s OServiceService) RateParamsQueryHandler() XMessage {
 	}
 }
 
-func (s OServiceService) UserInfoQueryHandler(sess *Session) XMessage {
+func (s OServiceService) UserInfoQueryHandler(ctx context.Context, sess *Session) XMessage {
 	return XMessage{
 		snacFrame: oscar.SnacFrame{
 			FoodGroup: oscar.OSERVICE,
@@ -207,11 +221,8 @@ func (s OServiceService) UserInfoQueryHandler(sess *Session) XMessage {
 	}
 }
 
-func (s OServiceService) ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
-	for _, version := range snacPayloadIn.GroupVersions {
-		fmt.Printf("ClientOnlineHandler read SNAC client messageType: %+v\n", version)
-	}
-	if err := BroadcastArrival(sess, sm, fm); err != nil {
+func (s OServiceService) ClientOnlineHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
+	if err := BroadcastArrival(ctx, sess, sm, fm); err != nil {
 		return err
 	}
 	buddies, err := fm.Buddies(sess.ScreenName)
@@ -219,7 +230,7 @@ func (s OServiceService) ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_
 		return err
 	}
 	for _, buddy := range buddies {
-		err := UnicastArrival(buddy, sess.ScreenName, sm)
+		err := UnicastArrival(ctx, buddy, sess.ScreenName, sm)
 		switch {
 		case errors.Is(err, ErrSessNotFound):
 			continue
@@ -230,17 +241,17 @@ func (s OServiceService) ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_
 	return nil
 }
 
-func (s OServiceService) SetUserInfoFieldsHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error) {
+func (s OServiceService) SetUserInfoFieldsHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error) {
 	if status, hasStatus := snacPayloadIn.GetUint32(0x06); hasStatus {
 		switch status {
 		case 0x000:
 			sess.SetInvisible(false)
-			if err := BroadcastArrival(sess, sm, fm); err != nil {
+			if err := BroadcastArrival(ctx, sess, sm, fm); err != nil {
 				return XMessage{}, err
 			}
 		case 0x100:
 			sess.SetInvisible(true)
-			if err := BroadcastDeparture(sess, sm, fm); err != nil {
+			if err := BroadcastDeparture(ctx, sess, sm, fm); err != nil {
 				return XMessage{}, err
 			}
 		default:
@@ -258,16 +269,16 @@ func (s OServiceService) SetUserInfoFieldsHandler(sess *Session, sm SessionManag
 	}, nil
 }
 
-func (s OServiceService) IdleNotificationHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error {
+func (s OServiceService) IdleNotificationHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error {
 	if snacPayloadIn.IdleTime == 0 {
 		sess.SetActive()
 	} else {
 		sess.SetIdle(time.Duration(snacPayloadIn.IdleTime) * time.Second)
 	}
-	return BroadcastArrival(sess, sm, fm)
+	return BroadcastArrival(ctx, sess, sm, fm)
 }
 
-func (s OServiceService) ServiceRequestHandler(cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error) {
+func (s OServiceService) ServiceRequestHandler(ctx context.Context, cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error) {
 	if snacPayloadIn.FoodGroup != oscar.CHAT {
 		return XMessage{}, ErrUnsupportedSubGroup
 	}
@@ -312,21 +323,24 @@ func (s OServiceService) ServiceRequestHandler(cfg Config, cr *ChatRegistry, ses
 
 // RateParamsSubAddHandler exists to capture the SNAC input in unit tests to
 // verify it's correctly unmarshalled.
-func (s OServiceService) RateParamsSubAddHandler(oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd) {
+func (s OServiceService) RateParamsSubAddHandler(context.Context, oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd) {
 }
 
-func NewOServiceRouterForChat() OServiceRouter {
+func NewOServiceRouterForChat(logger *slog.Logger) OServiceRouter {
 	return OServiceRouter{
 		OServiceHandler: OServiceServiceForChat{},
+		RouteLogger: RouteLogger{
+			Logger: logger,
+		},
 	}
 }
 
 type OServiceServiceForChat struct {
 	OServiceService
+	RouteLogger
 }
 
 func (s OServiceServiceForChat) WriteOServiceHostOnline(w io.Writer, sequence *uint32) error {
-	fmt.Println("writeOServiceHostOnline...")
 	snacFrameOut := oscar.SnacFrame{
 		FoodGroup: oscar.OSERVICE,
 		SubGroup:  oscar.OServiceHostOnline,
@@ -337,12 +351,9 @@ func (s OServiceServiceForChat) WriteOServiceHostOnline(w io.Writer, sequence *u
 	return writeOutSNAC(oscar.SnacFrame{}, snacFrameOut, snacPayloadOut, sequence, w)
 }
 
-func (s OServiceServiceForChat) ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
-	for _, version := range snacPayloadIn.GroupVersions {
-		fmt.Printf("ClientOnlineHandler read SNAC client messageType: %+v\n", version)
-	}
-	SendChatRoomInfoUpdate(sess, sm, room)
-	AlertUserJoined(sess, sm)
-	SetOnlineChatUsers(sess, sm)
+func (s OServiceServiceForChat) ClientOnlineHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
+	SendChatRoomInfoUpdate(ctx, sess, sm, room)
+	AlertUserJoined(ctx, sess, sm)
+	SetOnlineChatUsers(ctx, sess, sm)
 	return nil
 }

server/oservice_mock.go

@@ -3,10 +3,12 @@
 package server
 
 import (
+	context "context"
 	io "io"
 
-	oscar "github.com/mkaminski/goaim/oscar"
 	mock "github.com/stretchr/testify/mock"
+
+	oscar "github.com/mkaminski/goaim/oscar"
 )
 
 // MockOServiceHandler is an autogenerated mock type for the OServiceHandler type
@@ -22,13 +24,13 @@ func (_m *MockOServiceHandler) EXPECT() *MockOServiceHandler_Expecter {
 	return &MockOServiceHandler_Expecter{mock: &_m.Mock}
 }
 
-// ClientOnlineHandler provides a mock function with given fields: snacPayloadIn, sess, sm, fm, room
-func (_m *MockOServiceHandler) ClientOnlineHandler(snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
-	ret := _m.Called(snacPayloadIn, sess, sm, fm, room)
+// ClientOnlineHandler provides a mock function with given fields: ctx, snacPayloadIn, sess, sm, fm, room
+func (_m *MockOServiceHandler) ClientOnlineHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom) error {
+	ret := _m.Called(ctx, snacPayloadIn, sess, sm, fm, room)
 
 	var r0 error
-	if rf, ok := ret.Get(0).(func(oscar.SNAC_0x01_0x02_OServiceClientOnline, *Session, SessionManager, FeedbagManager, ChatRoom) error); ok {
-		r0 = rf(snacPayloadIn, sess, sm, fm, room)
+	if rf, ok := ret.Get(0).(func(context.Context, oscar.SNAC_0x01_0x02_OServiceClientOnline, *Session, SessionManager, FeedbagManager, ChatRoom) error); ok {
+		r0 = rf(ctx, snacPayloadIn, sess, sm, fm, room)
 	} else {
 		r0 = ret.Error(0)
 	}
@@ -42,18 +44,19 @@ type MockOServiceHandler_ClientOnlineHandler_Call struct {
 }
 
 // ClientOnlineHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline
 //   - sess *Session
 //   - sm SessionManager
 //   - fm FeedbagManager
 //   - room ChatRoom
-func (_e *MockOServiceHandler_Expecter) ClientOnlineHandler(snacPayloadIn interface{}, sess interface{}, sm interface{}, fm interface{}, room interface{}) *MockOServiceHandler_ClientOnlineHandler_Call {
-	return &MockOServiceHandler_ClientOnlineHandler_Call{Call: _e.mock.On("ClientOnlineHandler", snacPayloadIn, sess, sm, fm, room)}
+func (_e *MockOServiceHandler_Expecter) ClientOnlineHandler(ctx interface{}, snacPayloadIn interface{}, sess interface{}, sm interface{}, fm interface{}, room interface{}) *MockOServiceHandler_ClientOnlineHandler_Call {
+	return &MockOServiceHandler_ClientOnlineHandler_Call{Call: _e.mock.On("ClientOnlineHandler", ctx, snacPayloadIn, sess, sm, fm, room)}
 }
 
-func (_c *MockOServiceHandler_ClientOnlineHandler_Call) Run(run func(snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom)) *MockOServiceHandler_ClientOnlineHandler_Call {
+func (_c *MockOServiceHandler_ClientOnlineHandler_Call) Run(run func(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x02_OServiceClientOnline, sess *Session, sm SessionManager, fm FeedbagManager, room ChatRoom)) *MockOServiceHandler_ClientOnlineHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(oscar.SNAC_0x01_0x02_OServiceClientOnline), args[1].(*Session), args[2].(SessionManager), args[3].(FeedbagManager), args[4].(ChatRoom))
+		run(args[0].(context.Context), args[1].(oscar.SNAC_0x01_0x02_OServiceClientOnline), args[2].(*Session), args[3].(SessionManager), args[4].(FeedbagManager), args[5].(ChatRoom))
 	})
 	return _c
 }
@@ -63,18 +66,18 @@ func (_c *MockOServiceHandler_ClientOnlineHandler_Call) Return(_a0 error) *MockO
 	return _c
 }
 
-func (_c *MockOServiceHandler_ClientOnlineHandler_Call) RunAndReturn(run func(oscar.SNAC_0x01_0x02_OServiceClientOnline, *Session, SessionManager, FeedbagManager, ChatRoom) error) *MockOServiceHandler_ClientOnlineHandler_Call {
+func (_c *MockOServiceHandler_ClientOnlineHandler_Call) RunAndReturn(run func(context.Context, oscar.SNAC_0x01_0x02_OServiceClientOnline, *Session, SessionManager, FeedbagManager, ChatRoom) error) *MockOServiceHandler_ClientOnlineHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// ClientVersionsHandler provides a mock function with given fields: snacPayloadIn
-func (_m *MockOServiceHandler) ClientVersionsHandler(snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage {
-	ret := _m.Called(snacPayloadIn)
+// ClientVersionsHandler provides a mock function with given fields: ctx, snacPayloadIn
+func (_m *MockOServiceHandler) ClientVersionsHandler(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage {
+	ret := _m.Called(ctx, snacPayloadIn)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func(oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage); ok {
-		r0 = rf(snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage); ok {
+		r0 = rf(ctx, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -88,14 +91,15 @@ type MockOServiceHandler_ClientVersionsHandler_Call struct {
 }
 
 // ClientVersionsHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions
-func (_e *MockOServiceHandler_Expecter) ClientVersionsHandler(snacPayloadIn interface{}) *MockOServiceHandler_ClientVersionsHandler_Call {
-	return &MockOServiceHandler_ClientVersionsHandler_Call{Call: _e.mock.On("ClientVersionsHandler", snacPayloadIn)}
+func (_e *MockOServiceHandler_Expecter) ClientVersionsHandler(ctx interface{}, snacPayloadIn interface{}) *MockOServiceHandler_ClientVersionsHandler_Call {
+	return &MockOServiceHandler_ClientVersionsHandler_Call{Call: _e.mock.On("ClientVersionsHandler", ctx, snacPayloadIn)}
 }
 
-func (_c *MockOServiceHandler_ClientVersionsHandler_Call) Run(run func(snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions)) *MockOServiceHandler_ClientVersionsHandler_Call {
+func (_c *MockOServiceHandler_ClientVersionsHandler_Call) Run(run func(ctx context.Context, snacPayloadIn oscar.SNAC_0x01_0x17_OServiceClientVersions)) *MockOServiceHandler_ClientVersionsHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(oscar.SNAC_0x01_0x17_OServiceClientVersions))
+		run(args[0].(context.Context), args[1].(oscar.SNAC_0x01_0x17_OServiceClientVersions))
 	})
 	return _c
 }
@@ -105,18 +109,18 @@ func (_c *MockOServiceHandler_ClientVersionsHandler_Call) Return(_a0 XMessage) *
 	return _c
 }
 
-func (_c *MockOServiceHandler_ClientVersionsHandler_Call) RunAndReturn(run func(oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage) *MockOServiceHandler_ClientVersionsHandler_Call {
+func (_c *MockOServiceHandler_ClientVersionsHandler_Call) RunAndReturn(run func(context.Context, oscar.SNAC_0x01_0x17_OServiceClientVersions) XMessage) *MockOServiceHandler_ClientVersionsHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// IdleNotificationHandler provides a mock function with given fields: sess, sm, fm, snacPayloadIn
-func (_m *MockOServiceHandler) IdleNotificationHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error {
-	ret := _m.Called(sess, sm, fm, snacPayloadIn)
+// IdleNotificationHandler provides a mock function with given fields: ctx, sess, sm, fm, snacPayloadIn
+func (_m *MockOServiceHandler) IdleNotificationHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification) error {
+	ret := _m.Called(ctx, sess, sm, fm, snacPayloadIn)
 
 	var r0 error
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x11_OServiceIdleNotification) error); ok {
-		r0 = rf(sess, sm, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x11_OServiceIdleNotification) error); ok {
+		r0 = rf(ctx, sess, sm, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Error(0)
 	}
@@ -130,17 +134,18 @@ type MockOServiceHandler_IdleNotificationHandler_Call struct {
 }
 
 // IdleNotificationHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - sm SessionManager
 //   - fm *FeedbagStore
 //   - snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification
-func (_e *MockOServiceHandler_Expecter) IdleNotificationHandler(sess interface{}, sm interface{}, fm interface{}, snacPayloadIn interface{}) *MockOServiceHandler_IdleNotificationHandler_Call {
-	return &MockOServiceHandler_IdleNotificationHandler_Call{Call: _e.mock.On("IdleNotificationHandler", sess, sm, fm, snacPayloadIn)}
+func (_e *MockOServiceHandler_Expecter) IdleNotificationHandler(ctx interface{}, sess interface{}, sm interface{}, fm interface{}, snacPayloadIn interface{}) *MockOServiceHandler_IdleNotificationHandler_Call {
+	return &MockOServiceHandler_IdleNotificationHandler_Call{Call: _e.mock.On("IdleNotificationHandler", ctx, sess, sm, fm, snacPayloadIn)}
 }
 
-func (_c *MockOServiceHandler_IdleNotificationHandler_Call) Run(run func(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification)) *MockOServiceHandler_IdleNotificationHandler_Call {
+func (_c *MockOServiceHandler_IdleNotificationHandler_Call) Run(run func(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x11_OServiceIdleNotification)) *MockOServiceHandler_IdleNotificationHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(SessionManager), args[2].(*FeedbagStore), args[3].(oscar.SNAC_0x01_0x11_OServiceIdleNotification))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(SessionManager), args[3].(*FeedbagStore), args[4].(oscar.SNAC_0x01_0x11_OServiceIdleNotification))
 	})
 	return _c
 }
@@ -150,18 +155,18 @@ func (_c *MockOServiceHandler_IdleNotificationHandler_Call) Return(_a0 error) *M
 	return _c
 }
 
-func (_c *MockOServiceHandler_IdleNotificationHandler_Call) RunAndReturn(run func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x11_OServiceIdleNotification) error) *MockOServiceHandler_IdleNotificationHandler_Call {
+func (_c *MockOServiceHandler_IdleNotificationHandler_Call) RunAndReturn(run func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x11_OServiceIdleNotification) error) *MockOServiceHandler_IdleNotificationHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// RateParamsQueryHandler provides a mock function with given fields:
-func (_m *MockOServiceHandler) RateParamsQueryHandler() XMessage {
-	ret := _m.Called()
+// RateParamsQueryHandler provides a mock function with given fields: ctx
+func (_m *MockOServiceHandler) RateParamsQueryHandler(ctx context.Context) XMessage {
+	ret := _m.Called(ctx)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func() XMessage); ok {
-		r0 = rf()
+	if rf, ok := ret.Get(0).(func(context.Context) XMessage); ok {
+		r0 = rf(ctx)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -175,13 +180,14 @@ type MockOServiceHandler_RateParamsQueryHandler_Call struct {
 }
 
 // RateParamsQueryHandler is a helper method to define mock.On call
-func (_e *MockOServiceHandler_Expecter) RateParamsQueryHandler() *MockOServiceHandler_RateParamsQueryHandler_Call {
-	return &MockOServiceHandler_RateParamsQueryHandler_Call{Call: _e.mock.On("RateParamsQueryHandler")}
+//   - ctx context.Context
+func (_e *MockOServiceHandler_Expecter) RateParamsQueryHandler(ctx interface{}) *MockOServiceHandler_RateParamsQueryHandler_Call {
+	return &MockOServiceHandler_RateParamsQueryHandler_Call{Call: _e.mock.On("RateParamsQueryHandler", ctx)}
 }
 
-func (_c *MockOServiceHandler_RateParamsQueryHandler_Call) Run(run func()) *MockOServiceHandler_RateParamsQueryHandler_Call {
+func (_c *MockOServiceHandler_RateParamsQueryHandler_Call) Run(run func(ctx context.Context)) *MockOServiceHandler_RateParamsQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run()
+		run(args[0].(context.Context))
 	})
 	return _c
 }
@@ -191,14 +197,14 @@ func (_c *MockOServiceHandler_RateParamsQueryHandler_Call) Return(_a0 XMessage)
 	return _c
 }
 
-func (_c *MockOServiceHandler_RateParamsQueryHandler_Call) RunAndReturn(run func() XMessage) *MockOServiceHandler_RateParamsQueryHandler_Call {
+func (_c *MockOServiceHandler_RateParamsQueryHandler_Call) RunAndReturn(run func(context.Context) XMessage) *MockOServiceHandler_RateParamsQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// RateParamsSubAddHandler provides a mock function with given fields: _a0
-func (_m *MockOServiceHandler) RateParamsSubAddHandler(_a0 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd) {
-	_m.Called(_a0)
+// RateParamsSubAddHandler provides a mock function with given fields: _a0, _a1
+func (_m *MockOServiceHandler) RateParamsSubAddHandler(_a0 context.Context, _a1 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd) {
+	_m.Called(_a0, _a1)
 }
 
 // MockOServiceHandler_RateParamsSubAddHandler_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'RateParamsSubAddHandler'
@@ -207,14 +213,15 @@ type MockOServiceHandler_RateParamsSubAddHandler_Call struct {
 }
 
 // RateParamsSubAddHandler is a helper method to define mock.On call
-//   - _a0 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd
-func (_e *MockOServiceHandler_Expecter) RateParamsSubAddHandler(_a0 interface{}) *MockOServiceHandler_RateParamsSubAddHandler_Call {
-	return &MockOServiceHandler_RateParamsSubAddHandler_Call{Call: _e.mock.On("RateParamsSubAddHandler", _a0)}
+//   - _a0 context.Context
+//   - _a1 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd
+func (_e *MockOServiceHandler_Expecter) RateParamsSubAddHandler(_a0 interface{}, _a1 interface{}) *MockOServiceHandler_RateParamsSubAddHandler_Call {
+	return &MockOServiceHandler_RateParamsSubAddHandler_Call{Call: _e.mock.On("RateParamsSubAddHandler", _a0, _a1)}
 }
 
-func (_c *MockOServiceHandler_RateParamsSubAddHandler_Call) Run(run func(_a0 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)) *MockOServiceHandler_RateParamsSubAddHandler_Call {
+func (_c *MockOServiceHandler_RateParamsSubAddHandler_Call) Run(run func(_a0 context.Context, _a1 oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)) *MockOServiceHandler_RateParamsSubAddHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd))
+		run(args[0].(context.Context), args[1].(oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd))
 	})
 	return _c
 }
@@ -224,28 +231,28 @@ func (_c *MockOServiceHandler_RateParamsSubAddHandler_Call) Return() *MockOServi
 	return _c
 }
 
-func (_c *MockOServiceHandler_RateParamsSubAddHandler_Call) RunAndReturn(run func(oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)) *MockOServiceHandler_RateParamsSubAddHandler_Call {
+func (_c *MockOServiceHandler_RateParamsSubAddHandler_Call) RunAndReturn(run func(context.Context, oscar.SNAC_0x01_0x08_OServiceRateParamsSubAdd)) *MockOServiceHandler_RateParamsSubAddHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// ServiceRequestHandler provides a mock function with given fields: cfg, cr, sess, snacPayloadIn
-func (_m *MockOServiceHandler) ServiceRequestHandler(cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error) {
-	ret := _m.Called(cfg, cr, sess, snacPayloadIn)
+// ServiceRequestHandler provides a mock function with given fields: ctx, cfg, cr, sess, snacPayloadIn
+func (_m *MockOServiceHandler) ServiceRequestHandler(ctx context.Context, cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error) {
+	ret := _m.Called(ctx, cfg, cr, sess, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)); ok {
-		return rf(cfg, cr, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)); ok {
+		return rf(ctx, cfg, cr, sess, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) XMessage); ok {
-		r0 = rf(cfg, cr, sess, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) XMessage); ok {
+		r0 = rf(ctx, cfg, cr, sess, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) error); ok {
-		r1 = rf(cfg, cr, sess, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) error); ok {
+		r1 = rf(ctx, cfg, cr, sess, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -259,17 +266,18 @@ type MockOServiceHandler_ServiceRequestHandler_Call struct {
 }
 
 // ServiceRequestHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - cfg Config
 //   - cr *ChatRegistry
 //   - sess *Session
 //   - snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest
-func (_e *MockOServiceHandler_Expecter) ServiceRequestHandler(cfg interface{}, cr interface{}, sess interface{}, snacPayloadIn interface{}) *MockOServiceHandler_ServiceRequestHandler_Call {
-	return &MockOServiceHandler_ServiceRequestHandler_Call{Call: _e.mock.On("ServiceRequestHandler", cfg, cr, sess, snacPayloadIn)}
+func (_e *MockOServiceHandler_Expecter) ServiceRequestHandler(ctx interface{}, cfg interface{}, cr interface{}, sess interface{}, snacPayloadIn interface{}) *MockOServiceHandler_ServiceRequestHandler_Call {
+	return &MockOServiceHandler_ServiceRequestHandler_Call{Call: _e.mock.On("ServiceRequestHandler", ctx, cfg, cr, sess, snacPayloadIn)}
 }
 
-func (_c *MockOServiceHandler_ServiceRequestHandler_Call) Run(run func(cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest)) *MockOServiceHandler_ServiceRequestHandler_Call {
+func (_c *MockOServiceHandler_ServiceRequestHandler_Call) Run(run func(ctx context.Context, cfg Config, cr *ChatRegistry, sess *Session, snacPayloadIn oscar.SNAC_0x01_0x04_OServiceServiceRequest)) *MockOServiceHandler_ServiceRequestHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(Config), args[1].(*ChatRegistry), args[2].(*Session), args[3].(oscar.SNAC_0x01_0x04_OServiceServiceRequest))
+		run(args[0].(context.Context), args[1].(Config), args[2].(*ChatRegistry), args[3].(*Session), args[4].(oscar.SNAC_0x01_0x04_OServiceServiceRequest))
 	})
 	return _c
 }
@@ -279,28 +287,28 @@ func (_c *MockOServiceHandler_ServiceRequestHandler_Call) Return(_a0 XMessage, _
 	return _c
 }
 
-func (_c *MockOServiceHandler_ServiceRequestHandler_Call) RunAndReturn(run func(Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)) *MockOServiceHandler_ServiceRequestHandler_Call {
+func (_c *MockOServiceHandler_ServiceRequestHandler_Call) RunAndReturn(run func(context.Context, Config, *ChatRegistry, *Session, oscar.SNAC_0x01_0x04_OServiceServiceRequest) (XMessage, error)) *MockOServiceHandler_ServiceRequestHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// SetUserInfoFieldsHandler provides a mock function with given fields: sess, sm, fm, snacPayloadIn
-func (_m *MockOServiceHandler) SetUserInfoFieldsHandler(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error) {
-	ret := _m.Called(sess, sm, fm, snacPayloadIn)
+// SetUserInfoFieldsHandler provides a mock function with given fields: ctx, sess, sm, fm, snacPayloadIn
+func (_m *MockOServiceHandler) SetUserInfoFieldsHandler(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error) {
+	ret := _m.Called(ctx, sess, sm, fm, snacPayloadIn)
 
 	var r0 XMessage
 	var r1 error
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)); ok {
-		return rf(sess, sm, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)); ok {
+		return rf(ctx, sess, sm, fm, snacPayloadIn)
 	}
-	if rf, ok := ret.Get(0).(func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) XMessage); ok {
-		r0 = rf(sess, sm, fm, snacPayloadIn)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) XMessage); ok {
+		r0 = rf(ctx, sess, sm, fm, snacPayloadIn)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
 
-	if rf, ok := ret.Get(1).(func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) error); ok {
-		r1 = rf(sess, sm, fm, snacPayloadIn)
+	if rf, ok := ret.Get(1).(func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) error); ok {
+		r1 = rf(ctx, sess, sm, fm, snacPayloadIn)
 	} else {
 		r1 = ret.Error(1)
 	}
@@ -314,17 +322,18 @@ type MockOServiceHandler_SetUserInfoFieldsHandler_Call struct {
 }
 
 // SetUserInfoFieldsHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
 //   - sm SessionManager
 //   - fm *FeedbagStore
 //   - snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields
-func (_e *MockOServiceHandler_Expecter) SetUserInfoFieldsHandler(sess interface{}, sm interface{}, fm interface{}, snacPayloadIn interface{}) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
-	return &MockOServiceHandler_SetUserInfoFieldsHandler_Call{Call: _e.mock.On("SetUserInfoFieldsHandler", sess, sm, fm, snacPayloadIn)}
+func (_e *MockOServiceHandler_Expecter) SetUserInfoFieldsHandler(ctx interface{}, sess interface{}, sm interface{}, fm interface{}, snacPayloadIn interface{}) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
+	return &MockOServiceHandler_SetUserInfoFieldsHandler_Call{Call: _e.mock.On("SetUserInfoFieldsHandler", ctx, sess, sm, fm, snacPayloadIn)}
 }
 
-func (_c *MockOServiceHandler_SetUserInfoFieldsHandler_Call) Run(run func(sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields)) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
+func (_c *MockOServiceHandler_SetUserInfoFieldsHandler_Call) Run(run func(ctx context.Context, sess *Session, sm SessionManager, fm *FeedbagStore, snacPayloadIn oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields)) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(SessionManager), args[2].(*FeedbagStore), args[3].(oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(SessionManager), args[3].(*FeedbagStore), args[4].(oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields))
 	})
 	return _c
 }
@@ -334,18 +343,18 @@ func (_c *MockOServiceHandler_SetUserInfoFieldsHandler_Call) Return(_a0 XMessage
 	return _c
 }
 
-func (_c *MockOServiceHandler_SetUserInfoFieldsHandler_Call) RunAndReturn(run func(*Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
+func (_c *MockOServiceHandler_SetUserInfoFieldsHandler_Call) RunAndReturn(run func(context.Context, *Session, SessionManager, *FeedbagStore, oscar.SNAC_0x01_0x1E_OServiceSetUserInfoFields) (XMessage, error)) *MockOServiceHandler_SetUserInfoFieldsHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// UserInfoQueryHandler provides a mock function with given fields: sess
-func (_m *MockOServiceHandler) UserInfoQueryHandler(sess *Session) XMessage {
-	ret := _m.Called(sess)
+// UserInfoQueryHandler provides a mock function with given fields: ctx, sess
+func (_m *MockOServiceHandler) UserInfoQueryHandler(ctx context.Context, sess *Session) XMessage {
+	ret := _m.Called(ctx, sess)
 
 	var r0 XMessage
-	if rf, ok := ret.Get(0).(func(*Session) XMessage); ok {
-		r0 = rf(sess)
+	if rf, ok := ret.Get(0).(func(context.Context, *Session) XMessage); ok {
+		r0 = rf(ctx, sess)
 	} else {
 		r0 = ret.Get(0).(XMessage)
 	}
@@ -359,14 +368,15 @@ type MockOServiceHandler_UserInfoQueryHandler_Call struct {
 }
 
 // UserInfoQueryHandler is a helper method to define mock.On call
+//   - ctx context.Context
 //   - sess *Session
-func (_e *MockOServiceHandler_Expecter) UserInfoQueryHandler(sess interface{}) *MockOServiceHandler_UserInfoQueryHandler_Call {
-	return &MockOServiceHandler_UserInfoQueryHandler_Call{Call: _e.mock.On("UserInfoQueryHandler", sess)}
+func (_e *MockOServiceHandler_Expecter) UserInfoQueryHandler(ctx interface{}, sess interface{}) *MockOServiceHandler_UserInfoQueryHandler_Call {
+	return &MockOServiceHandler_UserInfoQueryHandler_Call{Call: _e.mock.On("UserInfoQueryHandler", ctx, sess)}
 }
 
-func (_c *MockOServiceHandler_UserInfoQueryHandler_Call) Run(run func(sess *Session)) *MockOServiceHandler_UserInfoQueryHandler_Call {
+func (_c *MockOServiceHandler_UserInfoQueryHandler_Call) Run(run func(ctx context.Context, sess *Session)) *MockOServiceHandler_UserInfoQueryHandler_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session))
+		run(args[0].(context.Context), args[1].(*Session))
 	})
 	return _c
 }
@@ -376,7 +386,7 @@ func (_c *MockOServiceHandler_UserInfoQueryHandler_Call) Return(_a0 XMessage) *M
 	return _c
 }
 
-func (_c *MockOServiceHandler_UserInfoQueryHandler_Call) RunAndReturn(run func(*Session) XMessage) *MockOServiceHandler_UserInfoQueryHandler_Call {
+func (_c *MockOServiceHandler_UserInfoQueryHandler_Call) RunAndReturn(run func(context.Context, *Session) XMessage) *MockOServiceHandler_UserInfoQueryHandler_Call {
 	_c.Call.Return(run)
 	return _c
 }

server/oservice_test.go

@@ -136,7 +136,7 @@ func TestReceiveAndSendServiceRequest(t *testing.T) {
 			// send input SNAC
 			//
 			svc := OServiceService{}
-			outputSNAC, err := svc.ServiceRequestHandler(tc.cfg, cr, tc.userSession, tc.inputSNAC)
+			outputSNAC, err := svc.ServiceRequestHandler(nil, tc.cfg, cr, tc.userSession, tc.inputSNAC)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return
@@ -359,39 +359,42 @@ func TestOServiceRouter_RouteOService(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			svc := NewMockOServiceHandler(t)
 			svc.EXPECT().
-				ServiceRequestHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				ServiceRequestHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				RateParamsQueryHandler().
+				RateParamsQueryHandler(mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				UserInfoQueryHandler(mock.Anything).
+				UserInfoQueryHandler(mock.Anything, mock.Anything).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				ClientVersionsHandler(tc.input.snacOut).
+				ClientVersionsHandler(mock.Anything, tc.input.snacOut).
 				Return(tc.output).
 				Maybe()
 			svc.EXPECT().
-				SetUserInfoFieldsHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				SetUserInfoFieldsHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.output, tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				ClientOnlineHandler(tc.input.snacOut, mock.Anything, mock.Anything, mock.Anything, mock.Anything).
+				ClientOnlineHandler(mock.Anything, tc.input.snacOut, mock.Anything, mock.Anything, mock.Anything, mock.Anything).
 				Return(tc.handlerErr).
 				Maybe()
 			svc.EXPECT().
-				RateParamsSubAddHandler(tc.input.snacOut).
+				RateParamsSubAddHandler(mock.Anything, tc.input.snacOut).
 				Maybe()
 			svc.EXPECT().
-				IdleNotificationHandler(mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
+				IdleNotificationHandler(mock.Anything, mock.Anything, mock.Anything, mock.Anything, tc.input.snacOut).
 				Return(tc.handlerErr).
 				Maybe()
 
 			router := OServiceRouter{
 				OServiceHandler: svc,
+				RouteLogger: RouteLogger{
+					Logger: NewLogger(Config{}),
+				},
 			}
 
 			bufIn := &bytes.Buffer{}
@@ -400,7 +403,7 @@ func TestOServiceRouter_RouteOService(t *testing.T) {
 			bufOut := &bytes.Buffer{}
 			seq := uint32(1)
 
-			err := router.RouteOService(Config{}, nil, nil, nil, nil, ChatRoom{}, tc.input.snacFrame, bufIn, bufOut, &seq)
+			err := router.RouteOService(nil, Config{}, nil, nil, nil, nil, ChatRoom{}, tc.input.snacFrame, bufIn, bufOut, &seq)
 			assert.ErrorIs(t, err, tc.expectErr)
 			if tc.expectErr != nil {
 				return

server/protocol.go

@@ -2,11 +2,13 @@ package server
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"github.com/google/uuid"
 	"github.com/mkaminski/goaim/oscar"
 	"io"
+	"log/slog"
 )
 
 const (
@@ -69,6 +71,7 @@ type Config struct {
 	FailFast    bool   `envconfig:"FAIL_FAST" default:"false"`
 	OSCARHost   string `envconfig:"OSCAR_HOST" required:"true"`
 	OSCARPort   int    `envconfig:"OSCAR_PORT" default:"5190"`
+	LogLevel    string `envconfig:"LOG_LEVEL" default:"info"`
 }
 
 func Address(host string, port int) string {
@@ -92,8 +95,6 @@ func SendAndReceiveSignonFrame(rw io.ReadWriter, sequence *uint32) (oscar.FlapSi
 		return oscar.FlapSignonFrame{}, err
 	}
 
-	fmt.Printf("SendAndReceiveSignonFrame read FLAP: %+v\n", flapFrameOut)
-
 	// receive
 	flapFrameIn := oscar.FlapFrame{}
 	if err := oscar.Unmarshal(&flapFrameIn, rw); err != nil {
@@ -108,8 +109,6 @@ func SendAndReceiveSignonFrame(rw io.ReadWriter, sequence *uint32) (oscar.FlapSi
 		return oscar.FlapSignonFrame{}, err
 	}
 
-	fmt.Printf("SendAndReceiveSignonFrame write FLAP: %+v\n", flapSignonFrameIn)
-
 	*sequence++
 
 	return flapSignonFrameIn, nil
@@ -117,7 +116,6 @@ func SendAndReceiveSignonFrame(rw io.ReadWriter, sequence *uint32) (oscar.FlapSi
 
 func VerifyLogin(sm SessionManager, rw io.ReadWriter) (*Session, uint32, error) {
 	seq := uint32(100)
-	fmt.Println("VerifyLogin...")
 
 	flap, err := SendAndReceiveSignonFrame(rw, &seq)
 	if err != nil {
@@ -140,7 +138,6 @@ func VerifyLogin(sm SessionManager, rw io.ReadWriter) (*Session, uint32, error)
 
 func VerifyChatLogin(rw io.ReadWriter) (*ChatCookie, uint32, error) {
 	seq := uint32(100)
-	fmt.Println("VerifyChatLogin...")
 
 	flap, err := SendAndReceiveSignonFrame(rw, &seq)
 	if err != nil {
@@ -181,7 +178,7 @@ func sendInvalidSNACErr(snac oscar.SnacFrame, w io.Writer, sequence *uint32) err
 	return writeOutSNAC(snac, snacFrameOut, snacPayloadOut, sequence, w)
 }
 
-func readIncomingRequests(rw io.Reader, msgCh chan IncomingMessage, errCh chan error) {
+func readIncomingRequests(ctx context.Context, logger *slog.Logger, rw io.Reader, msgCh chan IncomingMessage, errCh chan error) {
 	defer close(msgCh)
 	defer close(errCh)
 
@@ -222,7 +219,7 @@ func readIncomingRequests(rw io.Reader, msgCh chan IncomingMessage, errCh chan e
 			errCh <- ErrSignedOff
 			return
 		case oscar.FlapFrameKeepAlive:
-			fmt.Println("keepalive heartbeat")
+			logger.DebugContext(ctx, "keepalive heartbeat")
 		default:
 			errCh <- fmt.Errorf("unknown frame type: %v", flap)
 			return
@@ -230,53 +227,77 @@ func readIncomingRequests(rw io.Reader, msgCh chan IncomingMessage, errCh chan e
 	}
 }
 
-func Signout(sess *Session, sm SessionManager, fm *FeedbagStore) {
-	if err := BroadcastDeparture(sess, sm, fm); err != nil {
-		fmt.Printf("error notifying departure: %s", err.Error())
+func Signout(ctx context.Context, logger *slog.Logger, sess *Session, sm SessionManager, fm *FeedbagStore) {
+	if err := BroadcastDeparture(ctx, sess, sm, fm); err != nil {
+		logger.ErrorContext(ctx, "error notifying departure", "err", err.Error())
 	}
 	sm.Remove(sess)
 }
 
-func ReadBos(cfg Config, sess *Session, seq uint32, sm SessionManager, fm *FeedbagStore, cr *ChatRegistry, rwc io.ReadWriter, room ChatRoom, router Router) error {
+func ReadBos(ctx context.Context, cfg Config, sess *Session, seq uint32, sm SessionManager, fm *FeedbagStore, cr *ChatRegistry, rwc io.ReadWriter, room ChatRoom, router Router, logger *slog.Logger) {
 	if err := router.WriteOServiceHostOnline(rwc, &seq); err != nil {
-		return err
+		logger.ErrorContext(ctx, "error WriteOServiceHostOnline")
 	}
 
 	// buffered so that the go routine has room to exit
 	msgCh := make(chan IncomingMessage, 1)
 	errCh := make(chan error, 1)
-	go readIncomingRequests(rwc, msgCh, errCh)
+	go readIncomingRequests(ctx, logger, rwc, msgCh, errCh)
+
+	rl := RouteLogger{
+		Logger: logger,
+	}
 
 	for {
 		select {
 		case m := <-msgCh:
-			if err := router.routeIncomingRequests(cfg, sm, sess, fm, cr, rwc, &seq, m.snac, m.buf, room); err != nil {
-				switch {
-				case errors.Is(err, ErrUnsupportedSubGroup) || errors.Is(err, ErrUnsupportedFoodGroup):
-					if err := sendInvalidSNACErr(m.snac, rwc, &seq); err != nil {
-						return err
+			if err := router.routeIncomingRequests(ctx, cfg, sm, sess, fm, cr, rwc, &seq, m.snac, m.buf, room); err != nil {
+				if errors.Is(err, ErrUnsupportedSubGroup) || errors.Is(err, ErrUnsupportedFoodGroup) {
+					if err1 := sendInvalidSNACErr(m.snac, rwc, &seq); err1 != nil {
+						err = errors.Join(err1, err)
 					}
-					msg := fmt.Sprintf("unimplemented SNAC: %+v", m.snac)
 					if cfg.FailFast {
-						panic(msg)
+						panic(err.Error())
 					}
-					fmt.Println(msg)
-				default:
-					return err
 				}
+				logRequestError(ctx, logger, m.snac, err)
+				return
 			}
 		case m := <-sess.RecvMessage():
 			if err := writeOutSNAC(oscar.SnacFrame{}, m.snacFrame, m.snacOut, &seq, rwc); err != nil {
-				return err
+				logRequestError(ctx, logger, m.snacFrame, err)
+				return
 			}
+			rl.logRequest(ctx, m.snacFrame, m.snacOut)
 		case <-sess.Closed():
-			return gracefulDisconnect(seq, rwc)
+			if err := gracefulDisconnect(seq, rwc); err != nil {
+				logger.ErrorContext(ctx, "unable to gracefully disconnect user", "err", err)
+			}
+			return
 		case err := <-errCh:
-			return err
+			switch {
+			case errors.Is(io.EOF, err):
+				fallthrough
+			case errors.Is(ErrSignedOff, err):
+				logger.InfoContext(ctx, "client signed off")
+			default:
+				logger.ErrorContext(ctx, "client disconnected with error", "err", err)
+			}
+			return
 		}
 	}
 }
 
+func logRequestError(ctx context.Context, logger *slog.Logger, inFrame oscar.SnacFrame, err error) {
+	logger.LogAttrs(ctx, slog.LevelError, "client disconnected with error",
+		slog.Group("request",
+			slog.String("food_group", oscar.FoodGroupStr(inFrame.FoodGroup)),
+			slog.String("sub_group", oscar.SubGroupStr(inFrame.FoodGroup, inFrame.SubGroup)),
+		),
+		slog.String("err", err.Error()),
+	)
+}
+
 func gracefulDisconnect(seq uint32, rwc io.ReadWriter) error {
 	return oscar.Marshal(oscar.FlapFrame{
 		StartMarker: 42,
@@ -285,22 +306,22 @@ func gracefulDisconnect(seq uint32, rwc io.ReadWriter) error {
 	}, rwc)
 }
 
-func NewRouter() Router {
+func NewRouter(logger *slog.Logger) Router {
 	return Router{
-		AlertRouter:    NewAlertRouter(),
-		BuddyRouter:    NewBuddyRouter(),
-		ChatNavRouter:  NewChatNavRouter(),
-		ChatRouter:     NewChatRouter(),
-		FeedbagRouter:  NewFeedbagRouter(),
-		ICBMRouter:     NewICBMRouter(),
-		LocateRouter:   NewLocateRouter(),
-		OServiceRouter: NewOServiceRouter(),
+		AlertRouter:    NewAlertRouter(logger),
+		BuddyRouter:    NewBuddyRouter(logger),
+		ChatNavRouter:  NewChatNavRouter(logger),
+		ChatRouter:     NewChatRouter(logger),
+		FeedbagRouter:  NewFeedbagRouter(logger),
+		ICBMRouter:     NewICBMRouter(logger),
+		LocateRouter:   NewLocateRouter(logger),
+		OServiceRouter: NewOServiceRouter(logger),
 	}
 }
 
-func NewRouterForChat() Router {
-	r := NewRouter()
-	r.OServiceRouter = NewOServiceRouterForChat()
+func NewRouterForChat(logger *slog.Logger) Router {
+	r := NewRouter(logger)
+	r.OServiceRouter = NewOServiceRouterForChat(logger)
 	return r
 }
 
@@ -315,26 +336,26 @@ type Router struct {
 	OServiceRouter
 }
 
-func (rt *Router) routeIncomingRequests(cfg Config, sm SessionManager, sess *Session, fm *FeedbagStore, cr *ChatRegistry, rw io.ReadWriter, sequence *uint32, snac oscar.SnacFrame, buf io.Reader, room ChatRoom) error {
+func (rt *Router) routeIncomingRequests(ctx context.Context, cfg Config, sm SessionManager, sess *Session, fm *FeedbagStore, cr *ChatRegistry, rw io.ReadWriter, sequence *uint32, snac oscar.SnacFrame, buf io.Reader, room ChatRoom) error {
 	switch snac.FoodGroup {
 	case oscar.OSERVICE:
-		return rt.RouteOService(cfg, cr, sm, fm, sess, room, snac, buf, rw, sequence)
+		return rt.RouteOService(ctx, cfg, cr, sm, fm, sess, room, snac, buf, rw, sequence)
 	case oscar.LOCATE:
-		return rt.RouteLocate(sess, sm, fm, snac, buf, rw, sequence)
+		return rt.RouteLocate(ctx, sess, sm, fm, snac, buf, rw, sequence)
 	case oscar.BUDDY:
-		return rt.RouteBuddy(snac, buf, rw, sequence)
+		return rt.RouteBuddy(ctx, snac, buf, rw, sequence)
 	case oscar.ICBM:
-		return rt.RouteICBM(sm, fm, sess, snac, buf, rw, sequence)
+		return rt.RouteICBM(ctx, sm, fm, sess, snac, buf, rw, sequence)
 	case oscar.CHAT_NAV:
-		return rt.RouteChatNav(sess, cr, snac, buf, rw, sequence)
+		return rt.RouteChatNav(ctx, sess, cr, snac, buf, rw, sequence)
 	case oscar.FEEDBAG:
-		return rt.RouteFeedbag(sm, sess, fm, snac, buf, rw, sequence)
+		return rt.RouteFeedbag(ctx, sm, sess, fm, snac, buf, rw, sequence)
 	case oscar.BUCP:
-		return routeBUCP()
+		return routeBUCP(ctx)
 	case oscar.CHAT:
-		return rt.RouteChat(sess, sm, snac, buf, rw, sequence)
+		return rt.RouteChat(ctx, sess, sm, snac, buf, rw, sequence)
 	case oscar.ALERT:
-		return rt.RouteAlert(snac)
+		return rt.RouteAlert(ctx, snac)
 	default:
 		return ErrUnsupportedFoodGroup
 	}
@@ -360,14 +381,10 @@ func writeOutSNAC(originsnac oscar.SnacFrame, snacFrame oscar.SnacFrame, snacOut
 		PayloadLength: uint16(snacBuf.Len()),
 	}
 
-	fmt.Printf(" write FLAP: %+v\n", flap)
-
 	if err := oscar.Marshal(flap, w); err != nil {
 		return err
 	}
 
-	fmt.Printf(" write SNAC: %+v\n", snacOut)
-
 	expectLen := snacBuf.Len()
 	c, err := w.Write(snacBuf.Bytes())
 	if err != nil {

server/session.go

@@ -1,9 +1,11 @@
 package server
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"github.com/mkaminski/goaim/oscar"
+	"log/slog"
 	"sync"
 	"time"
 )
@@ -181,28 +183,30 @@ func (s *Session) Closed() <-chan struct{} {
 type InMemorySessionManager struct {
 	store    map[string]*Session
 	mapMutex sync.RWMutex
+	logger   *slog.Logger
 }
 
-func NewSessionManager() *InMemorySessionManager {
+func NewSessionManager(logger *slog.Logger) *InMemorySessionManager {
 	return &InMemorySessionManager{
-		store: make(map[string]*Session),
+		logger: logger,
+		store:  make(map[string]*Session),
 	}
 }
 
-func (s *InMemorySessionManager) Broadcast(msg XMessage) {
+func (s *InMemorySessionManager) Broadcast(ctx context.Context, msg XMessage) {
 	s.mapMutex.RLock()
 	defer s.mapMutex.RUnlock()
 	for _, sess := range s.store {
-		go s.maybeSendMessage(msg, sess)
+		go s.maybeSendMessage(ctx, msg, sess)
 	}
 }
 
-func (s *InMemorySessionManager) maybeSendMessage(msg XMessage, sess *Session) {
+func (s *InMemorySessionManager) maybeSendMessage(ctx context.Context, msg XMessage, sess *Session) {
 	switch sess.SendMessage(msg) {
 	case SessSendClosed:
-		fmt.Printf("can't send message to %s because the session was closed: %+v\n", sess.ScreenName, msg)
+		s.logger.WarnContext(ctx, "can't send notification because the user's session is closed", "recipient", sess.ScreenName, "message", msg)
 	case SessSendTimeout:
-		fmt.Printf("message to %s timed out\n", sess.ScreenName)
+		s.logger.WarnContext(ctx, "can't send notification because of send timeout", "recipient", sess.ScreenName, "message", msg)
 		sess.Close()
 	}
 }
@@ -223,14 +227,14 @@ func (s *InMemorySessionManager) Participants() []*Session {
 	return sessions
 }
 
-func (s *InMemorySessionManager) BroadcastExcept(except *Session, msg XMessage) {
+func (s *InMemorySessionManager) BroadcastExcept(ctx context.Context, except *Session, msg XMessage) {
 	s.mapMutex.RLock()
 	defer s.mapMutex.RUnlock()
 	for _, sess := range s.store {
 		if sess == except {
 			continue
 		}
-		go s.maybeSendMessage(msg, sess)
+		go s.maybeSendMessage(ctx, msg, sess)
 	}
 }
 
@@ -266,18 +270,18 @@ func (s *InMemorySessionManager) retrieveByScreenNames(screenNames []string) []*
 	return ret
 }
 
-func (s *InMemorySessionManager) SendToScreenName(screenName string, msg XMessage) {
+func (s *InMemorySessionManager) SendToScreenName(ctx context.Context, screenName string, msg XMessage) {
 	sess, err := s.RetrieveByScreenName(screenName)
 	if err != nil {
-		fmt.Printf("error sending to screen name: %s\n", screenName)
+		s.logger.WarnContext(ctx, "can't send notification because user is not online", "recipient", screenName, "message", msg)
 		return
 	}
-	go s.maybeSendMessage(msg, sess)
+	go s.maybeSendMessage(ctx, msg, sess)
 }
 
-func (s *InMemorySessionManager) BroadcastToScreenNames(screenNames []string, msg XMessage) {
+func (s *InMemorySessionManager) BroadcastToScreenNames(ctx context.Context, screenNames []string, msg XMessage) {
 	for _, sess := range s.retrieveByScreenNames(screenNames) {
-		go s.maybeSendMessage(msg, sess)
+		go s.maybeSendMessage(ctx, msg, sess)
 	}
 }
 

server/session_manager_mock.go

@@ -2,7 +2,11 @@
 
 package server
 
-import mock "github.com/stretchr/testify/mock"
+import (
+	context "context"
+
+	mock "github.com/stretchr/testify/mock"
+)
 
 // MockSessionManager is an autogenerated mock type for the SessionManager type
 type MockSessionManager struct {
@@ -17,9 +21,9 @@ func (_m *MockSessionManager) EXPECT() *MockSessionManager_Expecter {
 	return &MockSessionManager_Expecter{mock: &_m.Mock}
 }
 
-// Broadcast provides a mock function with given fields: msg
-func (_m *MockSessionManager) Broadcast(msg XMessage) {
-	_m.Called(msg)
+// Broadcast provides a mock function with given fields: ctx, msg
+func (_m *MockSessionManager) Broadcast(ctx context.Context, msg XMessage) {
+	_m.Called(ctx, msg)
 }
 
 // MockSessionManager_Broadcast_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'Broadcast'
@@ -28,14 +32,15 @@ type MockSessionManager_Broadcast_Call struct {
 }
 
 // Broadcast is a helper method to define mock.On call
+//   - ctx context.Context
 //   - msg XMessage
-func (_e *MockSessionManager_Expecter) Broadcast(msg interface{}) *MockSessionManager_Broadcast_Call {
-	return &MockSessionManager_Broadcast_Call{Call: _e.mock.On("Broadcast", msg)}
+func (_e *MockSessionManager_Expecter) Broadcast(ctx interface{}, msg interface{}) *MockSessionManager_Broadcast_Call {
+	return &MockSessionManager_Broadcast_Call{Call: _e.mock.On("Broadcast", ctx, msg)}
 }
 
-func (_c *MockSessionManager_Broadcast_Call) Run(run func(msg XMessage)) *MockSessionManager_Broadcast_Call {
+func (_c *MockSessionManager_Broadcast_Call) Run(run func(ctx context.Context, msg XMessage)) *MockSessionManager_Broadcast_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(XMessage))
+		run(args[0].(context.Context), args[1].(XMessage))
 	})
 	return _c
 }
@@ -45,14 +50,14 @@ func (_c *MockSessionManager_Broadcast_Call) Return() *MockSessionManager_Broadc
 	return _c
 }
 
-func (_c *MockSessionManager_Broadcast_Call) RunAndReturn(run func(XMessage)) *MockSessionManager_Broadcast_Call {
+func (_c *MockSessionManager_Broadcast_Call) RunAndReturn(run func(context.Context, XMessage)) *MockSessionManager_Broadcast_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// BroadcastExcept provides a mock function with given fields: except, msg
-func (_m *MockSessionManager) BroadcastExcept(except *Session, msg XMessage) {
-	_m.Called(except, msg)
+// BroadcastExcept provides a mock function with given fields: ctx, except, msg
+func (_m *MockSessionManager) BroadcastExcept(ctx context.Context, except *Session, msg XMessage) {
+	_m.Called(ctx, except, msg)
 }
 
 // MockSessionManager_BroadcastExcept_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'BroadcastExcept'
@@ -61,15 +66,16 @@ type MockSessionManager_BroadcastExcept_Call struct {
 }
 
 // BroadcastExcept is a helper method to define mock.On call
+//   - ctx context.Context
 //   - except *Session
 //   - msg XMessage
-func (_e *MockSessionManager_Expecter) BroadcastExcept(except interface{}, msg interface{}) *MockSessionManager_BroadcastExcept_Call {
-	return &MockSessionManager_BroadcastExcept_Call{Call: _e.mock.On("BroadcastExcept", except, msg)}
+func (_e *MockSessionManager_Expecter) BroadcastExcept(ctx interface{}, except interface{}, msg interface{}) *MockSessionManager_BroadcastExcept_Call {
+	return &MockSessionManager_BroadcastExcept_Call{Call: _e.mock.On("BroadcastExcept", ctx, except, msg)}
 }
 
-func (_c *MockSessionManager_BroadcastExcept_Call) Run(run func(except *Session, msg XMessage)) *MockSessionManager_BroadcastExcept_Call {
+func (_c *MockSessionManager_BroadcastExcept_Call) Run(run func(ctx context.Context, except *Session, msg XMessage)) *MockSessionManager_BroadcastExcept_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(*Session), args[1].(XMessage))
+		run(args[0].(context.Context), args[1].(*Session), args[2].(XMessage))
 	})
 	return _c
 }
@@ -79,14 +85,14 @@ func (_c *MockSessionManager_BroadcastExcept_Call) Return() *MockSessionManager_
 	return _c
 }
 
-func (_c *MockSessionManager_BroadcastExcept_Call) RunAndReturn(run func(*Session, XMessage)) *MockSessionManager_BroadcastExcept_Call {
+func (_c *MockSessionManager_BroadcastExcept_Call) RunAndReturn(run func(context.Context, *Session, XMessage)) *MockSessionManager_BroadcastExcept_Call {
 	_c.Call.Return(run)
 	return _c
 }
 
-// BroadcastToScreenNames provides a mock function with given fields: screenNames, msg
-func (_m *MockSessionManager) BroadcastToScreenNames(screenNames []string, msg XMessage) {
-	_m.Called(screenNames, msg)
+// BroadcastToScreenNames provides a mock function with given fields: ctx, screenNames, msg
+func (_m *MockSessionManager) BroadcastToScreenNames(ctx context.Context, screenNames []string, msg XMessage) {
+	_m.Called(ctx, screenNames, msg)
 }
 
 // MockSessionManager_BroadcastToScreenNames_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'BroadcastToScreenNames'
@@ -95,15 +101,16 @@ type MockSessionManager_BroadcastToScreenNames_Call struct {
 }
 
 // BroadcastToScreenNames is a helper method to define mock.On call
+//   - ctx context.Context
 //   - screenNames []string
 //   - msg XMessage
-func (_e *MockSessionManager_Expecter) BroadcastToScreenNames(screenNames interface{}, msg interface{}) *MockSessionManager_BroadcastToScreenNames_Call {
-	return &MockSessionManager_BroadcastToScreenNames_Call{Call: _e.mock.On("BroadcastToScreenNames", screenNames, msg)}
+func (_e *MockSessionManager_Expecter) BroadcastToScreenNames(ctx interface{}, screenNames interface{}, msg interface{}) *MockSessionManager_BroadcastToScreenNames_Call {
+	return &MockSessionManager_BroadcastToScreenNames_Call{Call: _e.mock.On("BroadcastToScreenNames", ctx, screenNames, msg)}
 }
 
-func (_c *MockSessionManager_BroadcastToScreenNames_Call) Run(run func(screenNames []string, msg XMessage)) *MockSessionManager_BroadcastToScreenNames_Call {
+func (_c *MockSessionManager_BroadcastToScreenNames_Call) Run(run func(ctx context.Context, screenNames []string, msg XMessage)) *MockSessionManager_BroadcastToScreenNames_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].([]string), args[1].(XMessage))
+		run(args[0].(context.Context), args[1].([]string), args[2].(XMessage))
 	})
 	return _c
 }
@@ -113,7 +120,7 @@ func (_c *MockSessionManager_BroadcastToScreenNames_Call) Return() *MockSessionM
 	return _c
 }
 
-func (_c *MockSessionManager_BroadcastToScreenNames_Call) RunAndReturn(run func([]string, XMessage)) *MockSessionManager_BroadcastToScreenNames_Call {
+func (_c *MockSessionManager_BroadcastToScreenNames_Call) RunAndReturn(run func(context.Context, []string, XMessage)) *MockSessionManager_BroadcastToScreenNames_Call {
 	_c.Call.Return(run)
 	return _c
 }
@@ -388,9 +395,9 @@ func (_c *MockSessionManager_RetrieveByScreenName_Call) RunAndReturn(run func(st
 	return _c
 }
 
-// SendToScreenName provides a mock function with given fields: screenName, msg
-func (_m *MockSessionManager) SendToScreenName(screenName string, msg XMessage) {
-	_m.Called(screenName, msg)
+// SendToScreenName provides a mock function with given fields: ctx, screenName, msg
+func (_m *MockSessionManager) SendToScreenName(ctx context.Context, screenName string, msg XMessage) {
+	_m.Called(ctx, screenName, msg)
 }
 
 // MockSessionManager_SendToScreenName_Call is a *mock.Call that shadows Run/Return methods with type explicit version for method 'SendToScreenName'
@@ -399,15 +406,16 @@ type MockSessionManager_SendToScreenName_Call struct {
 }
 
 // SendToScreenName is a helper method to define mock.On call
+//   - ctx context.Context
 //   - screenName string
 //   - msg XMessage
-func (_e *MockSessionManager_Expecter) SendToScreenName(screenName interface{}, msg interface{}) *MockSessionManager_SendToScreenName_Call {
-	return &MockSessionManager_SendToScreenName_Call{Call: _e.mock.On("SendToScreenName", screenName, msg)}
+func (_e *MockSessionManager_Expecter) SendToScreenName(ctx interface{}, screenName interface{}, msg interface{}) *MockSessionManager_SendToScreenName_Call {
+	return &MockSessionManager_SendToScreenName_Call{Call: _e.mock.On("SendToScreenName", ctx, screenName, msg)}
 }
 
-func (_c *MockSessionManager_SendToScreenName_Call) Run(run func(screenName string, msg XMessage)) *MockSessionManager_SendToScreenName_Call {
+func (_c *MockSessionManager_SendToScreenName_Call) Run(run func(ctx context.Context, screenName string, msg XMessage)) *MockSessionManager_SendToScreenName_Call {
 	_c.Call.Run(func(args mock.Arguments) {
-		run(args[0].(string), args[1].(XMessage))
+		run(args[0].(context.Context), args[1].(string), args[2].(XMessage))
 	})
 	return _c
 }
@@ -417,7 +425,7 @@ func (_c *MockSessionManager_SendToScreenName_Call) Return() *MockSessionManager
 	return _c
 }
 
-func (_c *MockSessionManager_SendToScreenName_Call) RunAndReturn(run func(string, XMessage)) *MockSessionManager_SendToScreenName_Call {
+func (_c *MockSessionManager_SendToScreenName_Call) RunAndReturn(run func(context.Context, string, XMessage)) *MockSessionManager_SendToScreenName_Call {
 	_c.Call.Return(run)
 	return _c
 }