Add log statements in server and library

server/api.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"os"
 	"path/filepath"
+	"reflect"
 	"runtime"
 	"runtime/debug"
 
@@ -64,7 +65,7 @@ const (
 // RemoteError converts an error and an explaining message to an *irma.RemoteError.
 func RemoteError(err Error, message string) *irma.RemoteError {
 	stack := string(debug.Stack())
-	Logger.Errorf("Error: %d %s %s\n%s", err.Status, err.Type, message, stack)
+	Logger.Warn("Session error: %d %s %s\n%s", err.Status, err.Type, message, stack)
 	return &irma.RemoteError{
 		Status:      err.Status,
 		Description: err.Description,
@@ -88,6 +89,7 @@ func JsonResponse(v interface{}, err *irma.RemoteError) (int, []byte) {
 		Logger.Error("Failed to serialize response:", e.Error())
 		return http.StatusInternalServerError, nil
 	}
+	Logger.Tracef("HTTP JSON response: %d %s", status, string(b))
 	return status, b
 }
 
@@ -111,6 +113,7 @@ func WriteResponse(w http.ResponseWriter, object interface{}, rerr *irma.RemoteE
 
 // WriteString writes the specified string to the http.ResponseWriter.
 func WriteString(w http.ResponseWriter, str string) {
+	Logger.Trace("HTTP text/plain response: ", str)
 	w.Header().Set("Content-Type", "text/plain")
 	w.WriteHeader(http.StatusOK)
 	w.Write([]byte(str))
@@ -132,6 +135,7 @@ func ParseSessionRequest(bts []byte) (request irma.SessionRequest, err error) {
 	if err = irma.UnmarshalValidate(bts, request); err == nil {
 		return request, nil
 	}
+	Logger.Warn("Failed to parse as session request: ", string(bts))
 	return nil, errors.New("Invalid or disabled session type")
 }
 
@@ -205,3 +209,28 @@ func Verbosity(level int) logrus.Level {
 		return logrus.InfoLevel
 	}
 }
+
+func LogError(err error) error {
+	Logger.Error(err.Error())
+	if e, ok := err.(*errors.Error); ok {
+		Logger.Error(e.ErrorStack())
+	} else {
+		Logger.Errorf("%s %s", reflect.TypeOf(err).String(), err.Error())
+	}
+	return err
+}
+
+func LogWarning(err error) error {
+	Logger.Warn(err.Error())
+	if e, ok := err.(*errors.Error); ok {
+		Logger.Warn(e.ErrorStack())
+	} else {
+		Logger.Warn("%s %s", reflect.TypeOf(err).String(), err.Error())
+	}
+	return err
+}
+
+func ToJson(o interface{}) string {
+	bts, _ := json.Marshal(o)
+	return string(bts)
+}

server/core/api.go

@@ -42,20 +42,20 @@ func Initialize(configuration *server.Configuration) error {
 			)
 		}
 		if err != nil {
-			return err
+			return server.LogError(err)
 		}
 		if err = conf.IrmaConfiguration.ParseFolder(); err != nil {
-			return err
+			return server.LogError(err)
 		}
 	}
 
 	if len(conf.IrmaConfiguration.SchemeManagers) == 0 {
 		if conf.DownloadDefaultSchemes {
 			if err := conf.IrmaConfiguration.DownloadDefaultSchemes(); err != nil {
-				return err
+				return server.LogError(err)
 			}
 		} else {
-			return errors.New("no schemes found in irma_configuration folder " + conf.IrmaConfiguration.Path)
+			return server.LogError(errors.New("no schemes found in irma_configuration folder " + conf.IrmaConfiguration.Path))
 		}
 	}
 
@@ -65,17 +65,17 @@ func Initialize(configuration *server.Configuration) error {
 	if conf.IssuerPrivateKeysPath != "" {
 		files, err := ioutil.ReadDir(conf.IssuerPrivateKeysPath)
 		if err != nil {
-			return err
+			return server.LogError(err)
 		}
 		for _, file := range files {
 			filename := file.Name()
 			issid := irma.NewIssuerIdentifier(strings.TrimSuffix(filename, filepath.Ext(filename))) // strip .xml
 			if _, ok := conf.IrmaConfiguration.Issuers[issid]; !ok {
-				return errors.Errorf("Private key %s belongs to an unknown issuer", filename)
+				return server.LogError(errors.Errorf("Private key %s belongs to an unknown issuer", filename))
 			}
 			sk, err := gabi.NewPrivateKeyFromFile(filepath.Join(conf.IssuerPrivateKeysPath, filename))
 			if err != nil {
-				return err
+				return server.LogError(err)
 			}
 			conf.IssuerPrivateKeys[issid] = sk
 		}
@@ -83,13 +83,13 @@ func Initialize(configuration *server.Configuration) error {
 	for issid, sk := range conf.IssuerPrivateKeys {
 		pk, err := conf.IrmaConfiguration.PublicKey(issid, int(sk.Counter))
 		if err != nil {
-			return err
+			return server.LogError(err)
 		}
 		if pk == nil {
-			return errors.Errorf("Missing public key belonging to private key %s-%d", issid.String(), sk.Counter)
+			return server.LogError(errors.Errorf("Missing public key belonging to private key %s-%d", issid.String(), sk.Counter))
 		}
 		if new(big.Int).Mul(sk.P, sk.Q).Cmp(pk.N) != 0 {
-			return errors.Errorf("Private key %s-%d does not belong to corresponding public key", issid.String(), sk.Counter)
+			return server.LogError(errors.Errorf("Private key %s-%d does not belong to corresponding public key", issid.String(), sk.Counter))
 		}
 	}
 
@@ -106,7 +106,7 @@ func Initialize(configuration *server.Configuration) error {
 
 func StartSession(request irma.SessionRequest) (*irma.Qr, string, error) {
 	if err := request.Validate(); err != nil {
-		return nil, "", err
+		return nil, "", server.LogError(err)
 	}
 	action := irma.ActionUnknown
 	switch request.(type) {
@@ -117,15 +117,19 @@ func StartSession(request irma.SessionRequest) (*irma.Qr, string, error) {
 	case *irma.IssuanceRequest:
 		action = irma.ActionIssuing
 		if err := validateIssuanceRequest(request.(*irma.IssuanceRequest)); err != nil {
-			return nil, "", err
+			return nil, "", server.LogError(err)
 		}
 	default:
-		conf.Logger.Warnf("Attempt to start session of invalid type")
-		return nil, "", errors.New("Invalid session type")
+		return nil, "", server.LogError(errors.New("Invalid session type"))
 	}
 
 	session := newSession(action, request)
 	conf.Logger.Infof("%s session started, token %s", action, session.token)
+	if conf.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		conf.Logger.Debug("Session request: ", server.ToJson(request))
+	} else {
+		logPurgedRequest(request)
+	}
 	return &irma.Qr{
 		Type: action,
 		URL:  conf.URL + session.token,
@@ -135,6 +139,7 @@ func StartSession(request irma.SessionRequest) (*irma.Qr, string, error) {
 func GetSessionResult(token string) *server.SessionResult {
 	session := sessions.get(token)
 	if session == nil {
+		conf.Logger.Warn("Session result requested of unknown session ", token)
 		return nil
 	}
 	return session.result
@@ -143,7 +148,7 @@ func GetSessionResult(token string) *server.SessionResult {
 func CancelSession(token string) error {
 	session := sessions.get(token)
 	if session == nil {
-		return errors.New("Unknown session, can't cancel")
+		return server.LogError(errors.Errorf("can't cancel unknown session %s", token))
 	}
 	session.handleDelete()
 	return nil
@@ -166,6 +171,10 @@ func HandleProtocolMessage(
 	}
 
 	conf.Logger.Debugf("Routing protocol message: %s %s", method, path)
+	if len(message) > 0 {
+		conf.Logger.Trace("POST body: ", string(message))
+	}
+	conf.Logger.Trace("HTTP headers: ", server.ToJson(headers))
 	pattern := regexp.MustCompile("(\\w+)/?(|commitments|proofs|status)$")
 	matches := pattern.FindStringSubmatch(path)
 	if len(matches) != 3 {
@@ -193,6 +202,7 @@ func HandleProtocolMessage(
 		if session.finished() && !session.returned {
 			session.returned = true
 			result = session.result
+			conf.Logger.Infof("Session %s done, status %s", session.token, session.result.Status)
 		}
 		sessions.update(token, session)
 	}()

server/core/handle.go

@@ -33,6 +33,7 @@ func (session *session) handleGetRequest(min, max *irma.ProtocolVersion) (irma.S
 	if session.version, err = chooseProtocolVersion(min, max); err != nil {
 		return nil, session.fail(server.ErrorProtocolVersion, "")
 	}
+	conf.Logger.Debugf("Using protocol version %s for session %s", session.version.String(), session.token)
 	session.request.SetVersion(session.version)
 
 	session.setStatus(server.StatusConnected)

server/core/helpers.go

 package core
 
 import (
-	"strconv"
+	"encoding/json"
+	"reflect"
 	"time"
 
 	"github.com/dgrijalva/jwt-go"
@@ -21,9 +22,11 @@ func (session *session) finished() bool {
 
 func (session *session) markAlive() {
 	session.lastActive = time.Now()
+	conf.Logger.Debugf("session %s marked active at %s", session.token, session.lastActive.String())
 }
 
 func (session *session) setStatus(status server.Status) {
+	conf.Logger.Debugf("Status of session %s updated to %s", session.token, status)
 	session.status = status
 	session.result.Status = status
 }
@@ -95,20 +98,12 @@ func (session *session) getProofP(commitments *irma.IssueCommitmentMessage, sche
 		if !contains {
 			return nil, errors.Errorf("no keyshare proof included for scheme %s", scheme.Name())
 		}
+		conf.Logger.Trace("Parsing keyshare ProofP JWT: ", str)
 		claims := &struct {
 			jwt.StandardClaims
 			ProofP *gabi.ProofP
 		}{}
-		token, err := jwt.ParseWithClaims(str, claims, func(t *jwt.Token) (interface{}, error) {
-			var kid int
-			if kidstr, ok := t.Header["kid"].(string); ok {
-				var err error
-				if kid, err = strconv.Atoi(kidstr); err != nil {
-					return nil, err
-				}
-			}
-			return conf.IrmaConfiguration.KeyshareServerPublicKey(scheme, kid)
-		})
+		token, err := jwt.ParseWithClaims(str, claims, conf.IrmaConfiguration.KeyshareServerKeyFunc(scheme))
 		if err != nil {
 			return nil, err
 		}
@@ -125,7 +120,7 @@ func (session *session) getProofP(commitments *irma.IssueCommitmentMessage, sche
 
 func chooseProtocolVersion(min, max *irma.ProtocolVersion) (*irma.ProtocolVersion, error) {
 	if min.AboveVersion(maxProtocolVersion) || max.BelowVersion(minProtocolVersion) || max.BelowVersion(min) {
-		return nil, errors.Errorf("Protocol version negotiation failed, min=%s max=%s", min.String(), max.String())
+		return nil, server.LogWarning(errors.Errorf("Protocol version negotiation failed, min=%s max=%s", min.String(), max.String()))
 	}
 	if max.AboveVersion(maxProtocolVersion) {
 		return maxProtocolVersion, nil
@@ -133,3 +128,31 @@ func chooseProtocolVersion(min, max *irma.ProtocolVersion) (*irma.ProtocolVersio
 		return max, nil
 	}
 }
+
+// logPurgedRequest logs the request excluding any attribute values.
+func logPurgedRequest(request irma.SessionRequest) {
+	// We want to log as much as possible of the request, but no attribute values.
+	// We cannot just remove them from the request parameter as that would break the calling code.
+	// So we create a deep copy of the request from which we can then safely remove whatever we want to.
+	// Ugly hack alert: the easiest way to do this seems to be to convert it to JSON and then back.
+	// As we do not know the precise type of request (may be *irma.DisclosureRequest,
+	// *irma.SignatureRequest, or *irma.IssuanceRequest), we use reflection to create a new instance
+	// of the same type as request, into which we then unmarshal our copy.
+	cpy := reflect.New(reflect.TypeOf(request).Elem()).Interface()
+	bts, _ := json.Marshal(request)
+	_ = json.Unmarshal(bts, cpy)
+
+	// Remove required attribute values from any attributes to be disclosed
+	attrs := cpy.(irma.SessionRequest).ToDisclose()
+	for _, disjunction := range attrs {
+		disjunction.Values = nil
+	}
+	// Remove attribute values from attributes to be issued
+	if isreq, ok := cpy.(*irma.IssuanceRequest); ok {
+		for _, cred := range isreq.Credentials {
+			cred.Attributes = nil
+		}
+	}
+	// Convert back to JSON to log
+	conf.Logger.Info("Session request (purged of attribute values): ", server.ToJson(cpy))
+}

server/irmaserver/conf.go

@@ -135,7 +135,7 @@ func (conf *Configuration) initialize() error {
 	}
 
 	if conf.DisableRequestorAuthentication {
-		conf.Logger.Warn("Authentication of incoming session requests disabled")
+		conf.Logger.Warn("Authentication of incoming session requests disabled: anyone who can reach this server can use it")
 		authenticators = map[AuthenticationMethod]Authenticator{AuthenticationMethodNone: NilAuthenticator{}}
 	} else {
 		authenticators = map[AuthenticationMethod]Authenticator{

server/irmaserver/server.go

@@ -35,7 +35,7 @@ func Start(config *Configuration) error {
 		return nil // Server was closed normally
 	}
 
-	return err
+	return server.LogError(err)
 }
 
 func Stop() {
@@ -47,7 +47,7 @@ func Stop() {
 func Handler(config *Configuration) (http.Handler, error) {
 	conf = config
 	if err := conf.initialize(); err != nil {
-		return nil, err
+		return nil, server.LogError(err)
 	}
 	if err := irmarequestor.Initialize(conf.Configuration); err != nil {
 		return nil, err
@@ -80,6 +80,8 @@ func Handler(config *Configuration) (http.Handler, error) {
 func handleCreate(w http.ResponseWriter, r *http.Request) {
 	body, err := ioutil.ReadAll(r.Body)
 	if err != nil {
+		conf.Logger.Error("Could not read session request HTTP POST body")
+		_ = server.LogError(err)
 		server.WriteError(w, server.ErrorInvalidRequest, err.Error())
 		return
 	}
@@ -100,10 +102,13 @@ func handleCreate(w http.ResponseWriter, r *http.Request) {
 		}
 	}
 	if rerr != nil {
+		_ = server.LogError(rerr)
 		server.WriteResponse(w, nil, rerr)
 		return
 	}
 	if !applies {
+		conf.Logger.Warnf("Session request uses unknown authentication method, HTTP headers: %s, HTTP POST body: %s",
+			server.ToJson(r.Header), string(body))
 		server.WriteError(w, server.ErrorInvalidRequest, "Request could not be authorized")
 		return
 	}
@@ -113,6 +118,8 @@ func handleCreate(w http.ResponseWriter, r *http.Request) {
 	if request.Action() == irma.ActionIssuing {
 		allowed, reason := conf.CanIssue(requestor, request.(*irma.IssuanceRequest).Credentials)
 		if !allowed {
+			conf.Logger.Warn("Requestor %s tried to issue credential %s but it is not authorized to; full request: %s",
+				requestor, reason, server.ToJson(request))
 			server.WriteError(w, server.ErrorUnauthorized, reason)
 			return
 		}
@@ -121,6 +128,8 @@ func handleCreate(w http.ResponseWriter, r *http.Request) {
 	if len(disjunctions) > 0 {
 		allowed, reason := conf.CanVerifyOrSign(requestor, request.Action(), disjunctions)
 		if !allowed {
+			conf.Logger.Warn("Requestor %s tried to verify attribute %s but it is not authorized to; full request: %s",
+				requestor, reason, server.ToJson(request))
 			server.WriteError(w, server.ErrorUnauthorized, reason)
 			return
 		}
@@ -163,6 +172,7 @@ func handleResult(w http.ResponseWriter, r *http.Request) {
 
 func handleJwtResult(w http.ResponseWriter, r *http.Request) {
 	if conf.jwtPrivateKey == nil {
+		conf.Logger.Warn("Session result JWT requested but no JWT private key is configured")
 		server.WriteError(w, server.ErrorUnknown, "JWT signing not supported")
 		return
 	}
@@ -187,6 +197,8 @@ func handleJwtResult(w http.ResponseWriter, r *http.Request) {
 	token := jwt.NewWithClaims(jwt.SigningMethodRS256, claims)
 	resultJwt, err := token.SignedString(conf.jwtPrivateKey)
 	if err != nil {
+		conf.Logger.Error("Failed to sign session result JWT")
+		_ = server.LogError(err)
 		server.WriteError(w, server.ErrorUnknown, err.Error())
 		return
 	}
@@ -195,6 +207,7 @@ func handleJwtResult(w http.ResponseWriter, r *http.Request) {
 
 func handleJwtProofs(w http.ResponseWriter, r *http.Request) {
 	if conf.jwtPrivateKey == nil {
+		conf.Logger.Warn("Session result JWT requested but no JWT private key is configured")
 		server.WriteError(w, server.ErrorUnknown, "JWT signing not supported")
 		return
 	}
@@ -239,6 +252,8 @@ func handleJwtProofs(w http.ResponseWriter, r *http.Request) {
 	token := jwt.NewWithClaims(jwt.SigningMethodRS256, claims)
 	resultJwt, err := token.SignedString(conf.jwtPrivateKey)
 	if err != nil {
+		conf.Logger.Error("Failed to sign session result JWT")
+		_ = server.LogError(err)
 		server.WriteError(w, server.ErrorUnknown, err.Error())
 		return
 	}