Skip to content

GitLab

Commit bc23e0c5 authored by Sietse Ringers's avatar Sietse Ringers
Browse files

Structure log output using fields

parent beba3348
Hide whitespace changes
Inline Side-by-side
Showing with 92 additions and 38 deletions
Gopkg.lock
View file @ bc23e0c5
......@@ -203,6 +203,22 @@
revision = "c2353362d570a7bfa228149c62842019201cfb71"
version = "v1.8.0"
[[projects]]
digest = "1:c658e84ad3916da105a761660dcaeb01e63416c8ec7bc62256a9b411a05fcd67"
name = "github.com/mattn/go-colorable"
packages = ["."]
pruneopts = "UT"
revision = "167de6bfdfba052fa6b2d3664c8f5272e23c9072"
version = "v0.0.9"
[[projects]]
digest = "1:0981502f9816113c9c8c4ac301583841855c8cf4da8c72f696b3ebedf6d0e4e5"
name = "github.com/mattn/go-isatty"
packages = ["."]
pruneopts = "UT"
revision = "6ca4dbf54d38eea1a992b3c722a76a5d1c4cb25c"
version = "v0.0.4"
[[projects]]
digest = "1:0e42db95481686c820de449ddf7c4ce58ab28f06353bdbdce63219938aac971c"
name = "github.com/mdp/qrterminal"
......@@ -211,6 +227,14 @@
revision = "6967d3624af633162b77160078e12a4c14174470"
version = "v1.0.1"
[[projects]]
branch = "master"
digest = "1:2b32af4d2a529083275afc192d1067d8126b578c7a9613b26600e4df9c735155"
name = "github.com/mgutz/ansi"
packages = ["."]
pruneopts = "UT"
revision = "9520e82c474b0a04dd04f8a40959027271bab992"
[[projects]]
digest = "1:53bc4cd4914cd7cd52139990d5170d6dc99067ae31c56530621b18b35fc30318"
name = "github.com/mitchellh/mapstructure"
......@@ -367,6 +391,14 @@
pruneopts = "UT"
revision = "525de816b1a2c1cfbb67b5e9936a6b76e0c7f3e6"
[[projects]]
digest = "1:39a425f98fb19427061a693fe6bf0683c9bddec4b25b17067e34fdb465e39cb9"
name = "github.com/x-cray/logrus-prefixed-formatter"
packages = ["."]
pruneopts = "UT"
revision = "bb2702d423886830dee131692131d35648c382e2"
version = "v0.5.2"
[[projects]]
branch = "master"
digest = "1:f1bc26f108b7694625d4388dc0bf5c10f5d06ad11e92abff90bfe8b2175b4ee8"
......@@ -454,6 +486,7 @@
"github.com/spf13/cobra",
"github.com/spf13/viper",
"github.com/stretchr/testify/require",
"github.com/x-cray/logrus-prefixed-formatter",
"gopkg.in/antage/eventsource.v1",
]
solver-name = "gps-cdcl"
......
messages.go
View file @ bc23e0c5
......@@ -108,11 +108,11 @@ type SessionError struct {
// RemoteError is an error message returned by the API server on errors.
type RemoteError struct {
Status int `json:"status"`
ErrorName string `json:"error"`
Description string `json:"description"`
Message string `json:"message"`
Stacktrace string `json:"stacktrace"`
Status int `json:"status,omitempty"`
ErrorName string `json:"error,omitempty"`
Description string `json:"description,omitempty"`
Message string `json:"message,omitempty"`
Stacktrace string `json:"stacktrace,omitempty"`
}
type Validator interface {
......
server/api.go
View file @ bc23e0c5
......@@ -71,8 +71,17 @@ func (status Status) Finished() bool {
// 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.Warnf("Session error: %d %s %s\n%s", err.Status, err.Type, message, stack)
var stack string
Logger.WithFields(logrus.Fields{
"status": err.Status,
"description": err.Description,
"error": err.Type,
"message": message,
}).Warnf("Sending session error")
if Logger.IsLevelEnabled(logrus.TraceLevel) {
stack = string(debug.Stack())
Logger.Warn(stack)
}
return &irma.RemoteError{
Status: err.Status,
Description: err.Description,
......@@ -240,22 +249,27 @@ func Verbosity(level int) logrus.Level {
}
}
func TypeString(x interface{}) string {
return reflect.TypeOf(x).String()
}
func log(level logrus.Level, err error) error {
writer := Logger.WriterLevel(level)
writer := Logger.WithFields(logrus.Fields{"err": TypeString(err)}).WriterLevel(level)
if e, ok := err.(*errors.Error); ok && Logger.IsLevelEnabled(logrus.TraceLevel) {
_, _ = writer.Write([]byte(e.ErrorStack()))
} else {
_, _ = writer.Write([]byte(fmt.Sprintf("%s %s", reflect.TypeOf(err).String(), err.Error())))
_, _ = writer.Write([]byte(fmt.Sprintf("%s", err.Error())))
}
return err
}
func LogFatal(err error) error {
logger := Logger.WithFields(logrus.Fields{"err": TypeString(err)})
// using log() for this doesn't seem to do anything
if e, ok := err.(*errors.Error); ok && Logger.IsLevelEnabled(logrus.TraceLevel) {
Logger.Fatal(e.ErrorStack())
logger.Fatal(e.ErrorStack())
} else {
Logger.Fatalf("%s %s", reflect.TypeOf(err).String(), err.Error())
logger.Fatalf("%s", err.Error())
}
return err
}
......
server/core/api.go
View file @ bc23e0c5
......@@ -107,23 +107,23 @@ func Initialize(configuration *server.Configuration) error {
func StartSession(req interface{}) (*irma.Qr, string, error) {
rrequest, err := server.ParseSessionRequest(req)
if err != nil {
return nil, "", server.LogError(err)
return nil, "", err
}
request := rrequest.SessionRequest()
action := request.Action()
if action == irma.ActionIssuing {
if err := validateIssuanceRequest(request.(*irma.IssuanceRequest)); err != nil {
return nil, "", server.LogError(err)
return nil, "", err
}
}
session := newSession(action, rrequest)
conf.Logger.Infof("%s session started, token %s", action, session.token)
conf.Logger.WithFields(logrus.Fields{"action": action, "session": session.token}).Infof("Session started")
if conf.Logger.IsLevelEnabled(logrus.DebugLevel) {
conf.Logger.Debug("Session request: ", server.ToJson(rrequest))
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Info("Session request: ", server.ToJson(rrequest))
} else {
logPurgedRequest(rrequest)
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Info("Session request (purged of attribute values): ", server.ToJson(purgeRequest(rrequest)))
}
return &irma.Qr{
Type: action,
......@@ -198,7 +198,7 @@ func HandleProtocolMessage(
}
}
conf.Logger.Debugf("Routing protocol message: %s %s", method, path)
conf.Logger.WithFields(logrus.Fields{"method": method, "path": path}).Debugf("Routing protocol message")
if len(message) > 0 {
conf.Logger.Trace("POST body: ", string(message))
}
......
server/core/handle.go
View file @ bc23e0c5
......@@ -4,6 +4,7 @@ import (
"github.com/privacybydesign/gabi"
"github.com/privacybydesign/irmago"
"github.com/privacybydesign/irmago/server"
"github.com/sirupsen/logrus"
)
// This file contains the handler functions for the protocol messages, receiving and returning normally
......@@ -33,7 +34,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)
conf.Logger.WithFields(logrus.Fields{"session": session.token, "version": session.version.String()}).Debugf("Protocol version negotiated")
session.request.SetVersion(session.version)
session.setStatus(server.StatusConnected)
......
server/core/helpers.go
View file @ bc23e0c5
......@@ -11,6 +11,7 @@ import (
"github.com/privacybydesign/gabi"
"github.com/privacybydesign/irmago"
"github.com/privacybydesign/irmago/server"
"github.com/sirupsen/logrus"
"gopkg.in/antage/eventsource.v1"
)
......@@ -18,11 +19,12 @@ import (
func (session *session) markAlive() {
session.lastActive = time.Now()
conf.Logger.Debugf("session %s marked active at %s", session.token, session.lastActive.String())
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Debugf("Session marked active, expiry delayed")
}
func (session *session) setStatus(status server.Status) {
conf.Logger.Debugf("Status of session %s updated from %s to %s", session.token, session.status, status)
conf.Logger.WithFields(logrus.Fields{"session": session.token, "prevStatus": session.prevStatus, "status": status}).
Info("Session status updated")
session.status = status
session.result.Status = status
sessions.update(session)
......@@ -30,7 +32,8 @@ func (session *session) setStatus(status server.Status) {
func (session *session) onUpdate() {
if session.evtSource != nil {
conf.Logger.Tracef("Sending %s to SSE listeners of session %s", session.status, session.token)
conf.Logger.WithFields(logrus.Fields{"session": session.token, "status": session.status}).
Debug("Sending status to SSE listeners")
session.evtSource.SendEventMessage(string(session.status), "", "")
}
}
......@@ -102,7 +105,7 @@ 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)
conf.Logger.Debug("Parsing keyshare ProofP JWT: ", str)
claims := &struct {
jwt.StandardClaims
ProofP *gabi.ProofP
......@@ -127,7 +130,7 @@ func (session *session) eventSource() eventsource.EventSource {
return session.evtSource
}
conf.Logger.Trace("Making server sent event source for session ", session.token)
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Debug("Making server sent event source")
session.evtSource = eventsource.New(nil, func(_ *http.Request) [][]byte { return eventHeaders })
return session.evtSource
}
......@@ -145,8 +148,8 @@ func chooseProtocolVersion(min, max *irma.ProtocolVersion) (*irma.ProtocolVersio
}
}
// logPurgedRequest logs the request excluding any attribute values.
func logPurgedRequest(request irma.RequestorRequest) {
// purgeRequest logs the request excluding any attribute values.
func purgeRequest(request irma.RequestorRequest) irma.RequestorRequest {
// 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.
......@@ -168,6 +171,6 @@ func logPurgedRequest(request irma.RequestorRequest) {
cred.Attributes = nil
}
}
// Convert back to JSON to log
conf.Logger.Info("Session request (purged of attribute values): ", server.ToJson(cpy))
return cpy.(irma.RequestorRequest)
}
server/core/sessions.go
View file @ bc23e0c5
......@@ -10,6 +10,7 @@ import (
"github.com/privacybydesign/gabi/big"
"github.com/privacybydesign/irmago"
"github.com/privacybydesign/irmago/server"
"github.com/sirupsen/logrus"
"gopkg.in/antage/eventsource.v1"
)
......@@ -98,11 +99,11 @@ func (s memorySessionStore) deleteExpired() {
if session.lastActive.Add(timeout).Before(time.Now()) {
if !session.status.Finished() {
conf.Logger.Infof("Session %s expired", token)
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Infof("Session expired")
session.markAlive()
session.setStatus(server.StatusTimeout)
} else {
conf.Logger.Infof("Deleting %s", token)
conf.Logger.WithFields(logrus.Fields{"session": session.token}).Infof("Deleting session")
expired = append(expired, token)
}
}
......@@ -141,7 +142,7 @@ func newSession(action irma.Action, request irma.RequestorRequest) *session {
},
}
conf.Logger.Debug("New session started: ", token)
conf.Logger.WithFields(logrus.Fields{"session": s.token}).Debug("New session started")
nonce, _ := gabi.RandomBigInt(gabi.DefaultSystemParameters[2048].Lstatzk)
s.request.SetNonce(nonce)
s.request.SetContext(one)
......
server/irmaserver/irmad/main.go
View file @ bc23e0c5
......@@ -13,6 +13,7 @@ import (
"github.com/sirupsen/logrus"
"github.com/spf13/cobra"
"github.com/spf13/viper"
"github.com/x-cray/logrus-prefixed-formatter"
)
var logger = logrus.StandardLogger()
......@@ -65,7 +66,7 @@ Specify -v to see the configuration.`,
func main() {
logger.Level = logrus.InfoLevel
logger.SetFormatter(&logrus.TextFormatter{
logger.SetFormatter(&prefixed.TextFormatter{
FullTimestamp: true,
})
......
server/irmaserver/server.go
View file @ bc23e0c5
......@@ -18,6 +18,7 @@ import (
"github.com/privacybydesign/irmago"
"github.com/privacybydesign/irmago/server"
"github.com/privacybydesign/irmago/server/irmarequestor"
"github.com/sirupsen/logrus"
)
var (
......@@ -189,8 +190,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))
conf.Logger.WithFields(logrus.Fields{"requestor": requestor, "id": reason}).
Warn("Requestor not authorized to issue credential; full request: ", server.ToJson(request))
server.WriteError(w, server.ErrorUnauthorized, reason)
return
}
......@@ -199,14 +200,14 @@ 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))
conf.Logger.WithFields(logrus.Fields{"requestor": requestor, "id": reason}).
Warn("Requestor not authorized to verify attribute; full request: ", server.ToJson(request))
server.WriteError(w, server.ErrorUnauthorized, reason)
return
}
}
if rrequest.Base().CallbackUrl != "" && conf.jwtPrivateKey == nil {
conf.Logger.Warn("Requestor %s provided callbackUrl but no JWT private key is installed")
conf.Logger.WithFields(logrus.Fields{"requestor": requestor}).Warn("Requestor provided callbackUrl but no JWT private key is installed")
server.WriteError(w, server.ErrorUnsupported, "")
return
}
......@@ -232,7 +233,7 @@ func handleStatus(w http.ResponseWriter, r *http.Request) {
func handleStatusEvents(w http.ResponseWriter, r *http.Request) {
token := chi.URLParam(r, "token")
conf.Logger.Debug("new client subscribed to server sent events of session " + token)
conf.Logger.WithFields(logrus.Fields{"session": token}).Debug("new client subscribed to server sent events")
if err := irmarequestor.SubscribeServerSentEvents(w, r, token); err != nil {
server.WriteError(w, server.ErrorUnexpectedRequest, err.Error())
}
......@@ -383,7 +384,7 @@ func doResultCallback(result *server.SessionResult) {
if callbackUrl == "" || conf.jwtPrivateKey == nil {
return
}
conf.Logger.Debug("POSTing session result to ", callbackUrl)
conf.Logger.WithFields(logrus.Fields{"session": result.Token, "callbackUrl": callbackUrl}).Debug("POSTing session result")
j, err := resultJwt(result)
if err != nil {
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment