CROSSLINK-209 lms/ncip event logging

broker/events/eventmodels.go

@@ -45,6 +45,8 @@ const (
 	EventNameConfirmSupplierMsg   EventName = "confirm-supplier-msg"
 	EventNameInvokeAction         EventName = "invoke-action"
 	EventNamePatronRequestMessage EventName = "patron-request-message"
+	EventNameLmsRequesterMessage  EventName = "lms-requester-message"
+	EventNameLmsSupplierMessage   EventName = "lms-supplier-message"
 )
 
 type Signal string

broker/lms/lms_adapter.go

@@ -1,8 +1,12 @@
 package lms
 
+import "github.com/indexdata/crosslink/broker/ncipclient"
+
 // LmsAdapter is an interface defining methods for interacting with a Library Management System (LMS)
 // https://github.com/openlibraryenvironment/mod-rs/blob/master/service/src/main/groovy/org/olf/rs/lms/HostLMSActions.groovy
 type LmsAdapter interface {
+	SetLogFunc(logFunc ncipclient.NcipLogFunc)
+
 	LookupUser(patron string) (string, error)
 
 	AcceptItem(

broker/lms/lms_adapter_manual.go

@@ -1,8 +1,13 @@
 package lms
 
+import "github.com/indexdata/crosslink/broker/ncipclient"
+
 type LmsAdapterManual struct {
 }
 
+func (l *LmsAdapterManual) SetLogFunc(logFunc ncipclient.NcipLogFunc) {
+}
+
 func (l *LmsAdapterManual) LookupUser(patron string) (string, error) {
 	return patron, nil
 }

broker/lms/lms_adapter_ncip.go

@@ -52,6 +52,10 @@ func CreateLmsAdapterNcip(lmsConfig directory.LmsConfig) (LmsAdapter, error) {
 	return l, nil
 }
 
+func (l *LmsAdapterNcip) SetLogFunc(logFunc ncipclient.NcipLogFunc) {
+	l.ncipClient.SetLogFunc(logFunc)
+}
+
 func (l *LmsAdapterNcip) LookupUser(patron string) (string, error) {
 	if l.config.LookupUserEnabled != nil && !*l.config.LookupUserEnabled {
 		return patron, nil // could even be empty

broker/lms/lms_adapter_test.go

@@ -366,6 +366,10 @@ type ncipClientMock struct {
 	lastRequest any
 }
 
+func (n *ncipClientMock) SetLogFunc(logFunc ncipclient.NcipLogFunc) {
+	// no-op
+}
+
 func (n *ncipClientMock) LookupUser(lookup ncip.LookupUser) (*ncip.LookupUserResponse, error) {
 	n.lastRequest = lookup
 	if lookup.UserId != nil {

broker/migrations/017_add_lms_events.down.sql

@@ -0,0 +1,3 @@
+DELETE FROM event_config WHERE event_name ='lms-requester-message';
+DELETE FROM event_config WHERE event_name ='lms-supplier-message';
+

broker/migrations/017_add_lms_events.up.sql

@@ -0,0 +1,4 @@
+INSERT INTO event_config (event_name, event_type, retry_count)
+VALUES ('lms-requester-message', 'NOTICE', 1);
+INSERT INTO event_config (event_name, event_type, retry_count)
+VALUES ('lms-supplier-message', 'NOTICE', 1);

broker/ncipclient/ncipclient.go

@@ -2,7 +2,11 @@ package ncipclient
 
 import "github.com/indexdata/crosslink/ncip"
 
+type NcipLogFunc func(outgoing []byte, incoming []byte, err error)
+
 type NcipClient interface {
+	SetLogFunc(logFunc NcipLogFunc)
+
 	LookupUser(arg ncip.LookupUser) (*ncip.LookupUserResponse, error)
 
 	AcceptItem(arg ncip.AcceptItem) (*ncip.AcceptItemResponse, error)

broker/ncipclient/ncipclient_impl.go

@@ -4,6 +4,7 @@ import (
 	"encoding/xml"
 	"fmt"
 	"net/http"
+	"reflect"
 
 	"github.com/indexdata/crosslink/httpclient"
 	"github.com/indexdata/crosslink/ncip"
@@ -15,6 +16,7 @@ type NcipClientImpl struct {
 	fromAgency               string
 	toAgency                 string
 	fromAgencyAuthentication string
+	logFunc                  NcipLogFunc
 }
 
 func NewNcipClient(client *http.Client, address string, fromAgency string, toAgency string, fromAgencyAuthentication string) NcipClient {
@@ -27,6 +29,10 @@ func NewNcipClient(client *http.Client, address string, fromAgency string, toAge
 	}
 }
 
+func (n *NcipClientImpl) SetLogFunc(logFunc NcipLogFunc) {
+	n.logFunc = logFunc
+}
+
 func (n *NcipClientImpl) LookupUser(lookup ncip.LookupUser) (*ncip.LookupUserResponse, error) {
 	lookup.InitiationHeader = n.prepareHeader(lookup.InitiationHeader)
 
@@ -188,8 +194,29 @@ func (n *NcipClientImpl) sendReceiveMessage(message *ncip.NCIPMessage) (*ncip.NC
 	message.Version = ncip.NCIP_V2_02_XSD
 
 	var respMessage ncip.NCIPMessage
+
 	err := httpclient.NewClient().RequestResponse(n.client, http.MethodPost, []string{httpclient.ContentTypeApplicationXml},
 		n.address, message, &respMessage, xml.Marshal, xml.Unmarshal)
+	if n.logFunc != nil {
+		hideSensitive(message)
+		var outgoing []byte
+		var err1 error
+		outgoing, err1 = xml.MarshalIndent(message, "", "  ")
+
+		hideSensitive(&respMessage)
+		var incoming []byte
+		var err2 error
+		incoming, err2 = xml.MarshalIndent(&respMessage, "", "  ")
+
+		logErr := err
+		if logErr == nil {
+			logErr = err1
+		}
+		if logErr == nil {
+			logErr = err2
+		}
+		n.logFunc(outgoing, incoming, logErr)
+	}
 	if err != nil {
 		return nil, fmt.Errorf("NCIP message exchange failed: %s", err.Error())
 	}
@@ -201,3 +228,57 @@ func (n *NcipClientImpl) sendReceiveMessage(message *ncip.NCIPMessage) (*ncip.NC
 	}
 	return &respMessage, nil
 }
+
+func hideSensitive(message *ncip.NCIPMessage) {
+	traverse(reflect.ValueOf(message), 0)
+}
+
+// removes values from the FromAgencyAuthentication and FromSystemAuthentication fields
+// as well as AuthenticationInput fields except if type is "username"
+func traverse(v reflect.Value, level int) {
+	if level > 20 {
+		return
+	}
+	level = level + 1
+	if !v.IsValid() {
+		return
+	}
+	if v.Kind() == reflect.Ptr {
+		if v.IsNil() {
+			return
+		}
+		traverse(v.Elem(), level)
+		return
+	}
+	if v.Kind() == reflect.Slice {
+		if v.IsNil() {
+			return
+		}
+		for i := 0; i < v.Len(); i++ {
+			traverse(v.Index(i), level)
+		}
+		return
+	}
+	if v.Kind() != reflect.Struct {
+		return
+	}
+	t := v.Type()
+	if t == reflect.TypeOf(ncip.AuthenticationInput{}) {
+		ncipAuthenticationInput := v.Interface().(ncip.AuthenticationInput)
+		exclude := ncipAuthenticationInput.AuthenticationInputType.Text != "username"
+		if exclude {
+			ncipAuthenticationInput.AuthenticationInputData = "***"
+			v.Set(reflect.ValueOf(ncipAuthenticationInput))
+		}
+		return
+	}
+	for i := 0; i < t.NumField(); i++ {
+		field := t.Field(i)
+		if field.Type.Kind() == reflect.String &&
+			(field.Name == "FromAgencyAuthentication" || field.Name == "FromSystemAuthentication") {
+			v.Field(i).SetString("***")
+		} else {
+			traverse(v.Field(i), level)
+		}
+	}
+}

broker/ncipclient/ncipclient_test.go

@@ -5,6 +5,7 @@ import (
 	"net/http"
 	"net/http/httptest"
 	"os"
+	"reflect"
 	"strconv"
 	"testing"
 
@@ -184,6 +185,16 @@ func TestEmptyNcipResponse(t *testing.T) {
 	ncipClient.fromAgencyAuthentication = "pass"
 	ncipClient.toAgency = "ILL-MOCK"
 	ncipClient.address = server.URL
+	var logOutgoing []byte
+	var logIncoming []byte
+	var logError error
+
+	ncipClient.SetLogFunc(func(outgoing []byte, incoming []byte, err error) {
+		logOutgoing = outgoing
+		logIncoming = incoming
+		logError = err
+	})
+
 	lookup := ncip.LookupUser{
 		UserId: &ncip.UserId{
 			UserIdentifierValue: "validuser",
@@ -192,6 +203,9 @@ func TestEmptyNcipResponse(t *testing.T) {
 	_, err := ncipClient.LookupUser(lookup)
 	assert.Error(t, err)
 	assert.Equal(t, "invalid NCIP response: missing LookupUserResponse", err.Error())
+	assert.NotNil(t, logOutgoing)
+	assert.NotNil(t, logIncoming)
+	assert.Nil(t, logError)
 
 	accept := ncip.AcceptItem{
 		RequestId: ncip.RequestId{
@@ -442,3 +456,72 @@ func TestCreateUserFiscalTransactionOK(t *testing.T) {
 	assert.NoError(t, err)
 	assert.NotNil(t, res)
 }
+
+func TestHideSensitive(t *testing.T) {
+	sampleMessage := &ncip.NCIPMessage{
+		Version: ncip.NCIP_V2_02_XSD,
+		LookupUser: &ncip.LookupUser{
+			InitiationHeader: &ncip.InitiationHeader{
+				ToAgencyId:               ncip.ToAgencyId{AgencyId: ncip.SchemeValuePair{Text: "ILL-MOCK"}},
+				FromAgencyAuthentication: "supersecret",
+				FromSystemAuthentication: "othersecret",
+			},
+			UserId: &ncip.UserId{
+				UserIdentifierValue: "validuser",
+			},
+			AuthenticationInput: []ncip.AuthenticationInput{
+				{
+					AuthenticationInputType: ncip.SchemeValuePair{Text: "PIN"},
+					AuthenticationInputData: "1234",
+				},
+				{
+					AuthenticationInputType: ncip.SchemeValuePair{Text: "username"},
+					AuthenticationInputData: "myuser",
+				},
+			},
+		},
+	}
+	hideSensitive(sampleMessage)
+	assert.Equal(t, "ILL-MOCK", sampleMessage.LookupUser.InitiationHeader.ToAgencyId.AgencyId.Text)
+	assert.Equal(t, "***", sampleMessage.LookupUser.InitiationHeader.FromAgencyAuthentication)
+	assert.Equal(t, "***", sampleMessage.LookupUser.InitiationHeader.FromSystemAuthentication)
+	assert.Equal(t, "validuser", sampleMessage.LookupUser.UserId.UserIdentifierValue)
+	assert.Equal(t, "***", sampleMessage.LookupUser.AuthenticationInput[0].AuthenticationInputData)
+	assert.Equal(t, "myuser", sampleMessage.LookupUser.AuthenticationInput[1].AuthenticationInputData)
+}
+
+func TestHideSensitiveLevel(t *testing.T) {
+	sampleMessage := &ncip.NCIPMessage{}
+	traverse(reflect.ValueOf(sampleMessage), 30)
+}
+
+func TestHideSensitiveInvalid(t *testing.T) {
+	invalid := reflect.Value{}
+	traverse(invalid, 0)
+}
+
+func TestSetLogFunc(t *testing.T) {
+	ncipClient := createTestClient()
+	var logOutgoing []byte
+	var logIncoming []byte
+
+	ncipClient.SetLogFunc(func(outgoing []byte, incoming []byte, err error) {
+		logOutgoing = outgoing
+		logIncoming = incoming
+	})
+
+	userMessage := ncip.LookupUser{
+		InitiationHeader: &ncip.InitiationHeader{
+			FromAgencyAuthentication: "supersecret",
+		},
+		UserId: &ncip.UserId{
+			UserIdentifierValue: "validuser",
+		},
+	}
+
+	_, err := ncipClient.LookupUser(userMessage)
+	assert.NoError(t, err)
+	assert.NotNil(t, logOutgoing)
+	assert.NotNil(t, logIncoming)
+	assert.Contains(t, string(logOutgoing), "***")
+}

broker/patron_request/service/action.go

@@ -130,6 +130,20 @@ func (a *PatronRequestActionService) handleBorrowingAction(ctx common.ExtendedCo
 	if err != nil {
 		return events.LogErrorAndReturnResult(ctx, "failed to create LMS adapter", err)
 	}
+	lmsAdapter.SetLogFunc(func(outgoing []byte, incoming []byte, err error) {
+		status := events.EventStatusSuccess
+		if err != nil {
+			status = events.EventStatusError
+		}
+		var customData = make(map[string]any)
+		customData["lmsOutgoingMessage"] = string(outgoing)
+		customData["lmsIncomingMessage"] = string(incoming)
+		eventData := events.EventData{CustomData: customData}
+		_, createErr := a.eventBus.CreateNotice(pr.ID, events.EventNameLmsRequesterMessage, eventData, status, events.EventDomainPatronRequest)
+		if createErr != nil {
+			ctx.Logger().Error("failed to create LMS log event", "error", createErr)
+		}
+	})
 	switch action {
 	case BorrowerActionValidate:
 		return a.validateBorrowingRequest(ctx, pr, lmsAdapter)
@@ -162,6 +176,20 @@ func (a *PatronRequestActionService) handleLenderAction(ctx common.ExtendedConte
 	if err != nil {
 		return events.LogErrorAndReturnResult(ctx, "failed to create LMS adapter", err)
 	}
+	lms.SetLogFunc(func(outgoing []byte, incoming []byte, err error) {
+		status := events.EventStatusSuccess
+		if err != nil {
+			status = events.EventStatusError
+		}
+		var customData = make(map[string]any)
+		customData["lmsOutgoingMessage"] = string(outgoing)
+		customData["lmsIncomingMessage"] = string(incoming)
+		eventData := events.EventData{CustomData: customData}
+		_, createErr := a.eventBus.CreateNotice(pr.ID, events.EventNameLmsSupplierMessage, eventData, status, events.EventDomainPatronRequest)
+		if createErr != nil {
+			ctx.Logger().Error("failed to create LMS log event", "error", err)
+		}
+	})
 	switch action {
 	case LenderActionValidate:
 		return a.validateLenderRequest(ctx, pr, lms)

broker/patron_request/service/action_test.go

@@ -12,6 +12,7 @@ import (
 	"github.com/indexdata/crosslink/broker/events"
 	"github.com/indexdata/crosslink/broker/handler"
 	"github.com/indexdata/crosslink/broker/lms"
+	"github.com/indexdata/crosslink/broker/ncipclient"
 	pr_db "github.com/indexdata/crosslink/broker/patron_request/db"
 	"github.com/indexdata/crosslink/iso18626"
 	"github.com/jackc/pgx/v5/pgtype"
@@ -776,6 +777,9 @@ func createLmsAdapterMockFail() lms.LmsAdapter {
 type MockLmsAdapterFail struct {
 }
 
+func (l *MockLmsAdapterFail) SetLogFunc(logFunc ncipclient.NcipLogFunc) {
+}
+
 func (l *MockLmsAdapterFail) LookupUser(patron string) (string, error) {
 	return "", errors.New("LookupUser failed")
 }

broker/patron_request/service/message-handler.go

@@ -4,6 +4,9 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"strings"
+	"time"
+
 	"github.com/google/uuid"
 	"github.com/indexdata/crosslink/broker/common"
 	"github.com/indexdata/crosslink/broker/events"
@@ -13,8 +16,6 @@ import (
 	"github.com/indexdata/go-utils/utils"
 	"github.com/jackc/pgx/v5"
 	"github.com/jackc/pgx/v5/pgtype"
-	"strings"
-	"time"
 )
 
 var SUPPLIER_PATRON_PATTERN = utils.GetEnv("SUPPLIER_PATRON_PATTERN", "%v_user")