diff --git a/changelog/unreleased/logging-improvements.md b/changelog/unreleased/logging-improvements.md new file mode 100644 index 000000000..28dd126d5 --- /dev/null +++ b/changelog/unreleased/logging-improvements.md @@ -0,0 +1,5 @@ +Enhancement: Logging improvements + +We improved the logging of several http services. If possible and present, we now log the `X-Request-Id`. + +https://github.com/owncloud/ocis/pull/4815 diff --git a/ocis-pkg/log/log.go b/ocis-pkg/log/log.go index 0c3ea4632..b217c7789 100644 --- a/ocis-pkg/log/log.go +++ b/ocis-pkg/log/log.go @@ -1,11 +1,13 @@ package log import ( + "context" "fmt" "os" "strings" "time" + chimiddleware "github.com/go-chi/chi/v5/middleware" mzlog "github.com/go-micro/plugins/v4/logger/zerolog" "github.com/owncloud/ocis/v2/ocis-pkg/shared" "github.com/rs/zerolog" @@ -13,6 +15,10 @@ import ( "go-micro.dev/v4/logger" ) +var ( + RequestIDString = "request-id" +) + func init() { // this is ugly, but "logger.DefaultLogger" is a global variable and we need to set it _before_ anybody uses it setMicroLogger() @@ -117,3 +123,10 @@ func NewLogger(opts ...Option) Logger { logger, } } + +// SubloggerWithRequestID returns a sublogger with the x-request-id added to all events +func (l Logger) SubloggerWithRequestID(c context.Context) Logger { + return Logger{ + l.With().Str(RequestIDString, chimiddleware.GetReqID(c)).Logger(), + } +} diff --git a/ocis-pkg/middleware/logger.go b/ocis-pkg/middleware/logger.go index c879de63d..465c025de 100644 --- a/ocis-pkg/middleware/logger.go +++ b/ocis-pkg/middleware/logger.go @@ -17,7 +17,7 @@ func Logger(logger log.Logger) func(http.Handler) http.Handler { next.ServeHTTP(wrap, r) logger.Debug(). - Str("request", r.Header.Get("X-Request-ID")). + Str(log.RequestIDString, r.Header.Get("X-Request-ID")). Str("proto", r.Proto). Str("method", r.Method). Int("status", wrap.Status()). diff --git a/services/graph/pkg/identity/cs3.go b/services/graph/pkg/identity/cs3.go index a42bbdbc4..015de1191 100644 --- a/services/graph/pkg/identity/cs3.go +++ b/services/graph/pkg/identity/cs3.go @@ -40,9 +40,11 @@ func (i *CS3) UpdateUser(ctx context.Context, nameOrID string, user libregraph.U } func (i *CS3) GetUser(ctx context.Context, userID string, queryParam url.Values) (*libregraph.User, error) { + logger := i.Logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "cs3").Msg("GetUser") client, err := pool.GetGatewayServiceClient(i.Config.Address) if err != nil { - i.Logger.Error().Err(err).Msg("could not get client") + logger.Error().Str("backend", "cs3").Err(err).Msg("could not get client") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) } @@ -53,22 +55,24 @@ func (i *CS3) GetUser(ctx context.Context, userID string, queryParam url.Values) switch { case err != nil: - i.Logger.Error().Err(err).Str("userid", userID).Msg("error sending get user by claim id grpc request") + logger.Error().Str("backend", "cs3").Err(err).Str("userid", userID).Msg("error sending get user by claim id grpc request: transport error") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) case res.Status.Code != cs3rpc.Code_CODE_OK: if res.Status.Code == cs3rpc.Code_CODE_NOT_FOUND { return nil, errorcode.New(errorcode.ItemNotFound, res.Status.Message) } - i.Logger.Error().Err(err).Str("userid", userID).Msg("error sending get user by claim id grpc request") + logger.Debug().Str("backend", "cs3").Err(err).Str("userid", userID).Msg("error sending get user by claim id grpc request") return nil, errorcode.New(errorcode.GeneralException, res.Status.Message) } return CreateUserModelFromCS3(res.User), nil } func (i *CS3) GetUsers(ctx context.Context, queryParam url.Values) ([]*libregraph.User, error) { + logger := i.Logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "cs3").Msg("GetUsers") client, err := pool.GetGatewayServiceClient(i.Config.Address) if err != nil { - i.Logger.Error().Err(err).Msg("could not get client") + logger.Error().Str("backend", "cs3").Err(err).Msg("could not get client") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) } @@ -84,13 +88,13 @@ func (i *CS3) GetUsers(ctx context.Context, queryParam url.Values) ([]*libregrap }) switch { case err != nil: - i.Logger.Error().Err(err).Str("search", search).Msg("error sending find users grpc request") + logger.Error().Str("backend", "cs3").Err(err).Str("search", search).Msg("error sending find users grpc request: transport error") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) case res.Status.Code != cs3rpc.Code_CODE_OK: if res.Status.Code == cs3rpc.Code_CODE_NOT_FOUND { return nil, errorcode.New(errorcode.ItemNotFound, res.Status.Message) } - i.Logger.Error().Err(err).Str("search", search).Msg("error sending find users grpc request") + logger.Debug().Str("backend", "cs3").Err(err).Str("search", search).Msg("error sending find users grpc request") return nil, errorcode.New(errorcode.GeneralException, res.Status.Message) } @@ -104,9 +108,11 @@ func (i *CS3) GetUsers(ctx context.Context, queryParam url.Values) ([]*libregrap } func (i *CS3) GetGroups(ctx context.Context, queryParam url.Values) ([]*libregraph.Group, error) { + logger := i.Logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "cs3").Msg("GetGroups") client, err := pool.GetGatewayServiceClient(i.Config.Address) if err != nil { - i.Logger.Error().Err(err).Msg("could not get client") + logger.Error().Str("backend", "cs3").Err(err).Msg("could not get client") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) } @@ -123,13 +129,13 @@ func (i *CS3) GetGroups(ctx context.Context, queryParam url.Values) ([]*libregra switch { case err != nil: - i.Logger.Error().Err(err).Str("search", search).Msg("error sending find groups grpc request") + logger.Error().Str("backend", "cs3").Err(err).Str("search", search).Msg("error sending find groups grpc request: transport error") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) case res.Status.Code != cs3rpc.Code_CODE_OK: if res.Status.Code == cs3rpc.Code_CODE_NOT_FOUND { return nil, errorcode.New(errorcode.ItemNotFound, res.Status.Message) } - i.Logger.Error().Err(err).Str("search", search).Msg("error sending find groups grpc request") + logger.Debug().Str("backend", "cs3").Err(err).Str("search", search).Msg("error sending find groups grpc request") return nil, errorcode.New(errorcode.GeneralException, res.Status.Message) } @@ -148,9 +154,11 @@ func (i *CS3) CreateGroup(ctx context.Context, group libregraph.Group) (*libregr } func (i *CS3) GetGroup(ctx context.Context, groupID string, queryParam url.Values) (*libregraph.Group, error) { + logger := i.Logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "cs3").Msg("GetGroup") client, err := pool.GetGatewayServiceClient(i.Config.Address) if err != nil { - i.Logger.Error().Err(err).Msg("could not get client") + logger.Error().Str("backend", "cs3").Err(err).Msg("could not get client") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) } @@ -161,13 +169,13 @@ func (i *CS3) GetGroup(ctx context.Context, groupID string, queryParam url.Value switch { case err != nil: - i.Logger.Error().Err(err).Str("groupid", groupID).Msg("error sending get group by claim id grpc request") + logger.Error().Str("backend", "cs3").Err(err).Str("groupid", groupID).Msg("error sending get group by claim id grpc request: transport error") return nil, errorcode.New(errorcode.ServiceNotAvailable, err.Error()) case res.Status.Code != cs3rpc.Code_CODE_OK: if res.Status.Code == cs3rpc.Code_CODE_NOT_FOUND { return nil, errorcode.New(errorcode.ItemNotFound, res.Status.Message) } - i.Logger.Error().Err(err).Str("groupid", groupID).Msg("error sending get group by claim id grpc request") + logger.Debug().Str("backend", "cs3").Err(err).Str("groupid", groupID).Msg("error sending get group by claim id grpc request") return nil, errorcode.New(errorcode.GeneralException, res.Status.Message) } diff --git a/services/graph/pkg/identity/ldap.go b/services/graph/pkg/identity/ldap.go index 24f8678c6..f9a3d1afa 100644 --- a/services/graph/pkg/identity/ldap.go +++ b/services/graph/pkg/identity/ldap.go @@ -113,6 +113,8 @@ func NewLDAPBackend(lc ldap.Client, config config.LDAP, logger *log.Logger) (*LD // LDAP User Entry (using the inetOrgPerson LDAP Objectclass) add adds that to the // configured LDAP server func (i *LDAP) CreateUser(ctx context.Context, user libregraph.User) (*libregraph.User, error) { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("CreateUser") if !i.writeEnabled { return nil, errReadOnly } @@ -165,7 +167,7 @@ func (i *LDAP) CreateUser(ctx context.Context, user libregraph.User) (*libregrap if err := i.conn.Add(&ar); err != nil { var lerr *ldap.Error - i.logger.Debug().Err(err).Msg("error adding user") + logger.Debug().Err(err).Msg("error adding user") if errors.As(err, &lerr) { if lerr.ResultCode == ldap.LDAPResultEntryAlreadyExists { err = errorcode.New(errorcode.NameAlreadyExists, lerr.Error()) @@ -175,7 +177,7 @@ func (i *LDAP) CreateUser(ctx context.Context, user libregraph.User) (*libregrap } if i.usePwModifyExOp && user.PasswordProfile != nil && user.PasswordProfile.Password != nil { - if err := i.updateUserPassowrd(ar.DN, user.PasswordProfile.GetPassword()); err != nil { + if err := i.updateUserPassowrd(ctx, ar.DN, user.PasswordProfile.GetPassword()); err != nil { return nil, err } } @@ -191,6 +193,8 @@ func (i *LDAP) CreateUser(ctx context.Context, user libregraph.User) (*libregrap // DeleteUser implements the Backend Interface. It permanently deletes a User identified // by name or id from the LDAP server func (i *LDAP) DeleteUser(ctx context.Context, nameOrID string) error { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("DeleteUser") if !i.writeEnabled { return errReadOnly } @@ -209,13 +213,13 @@ func (i *LDAP) DeleteUser(ctx context.Context, nameOrID string) error { return err } for _, group := range groupEntries { - i.logger.Debug().Str("group", group.DN).Str("user", e.DN).Msg("Cleaning up group membership") + logger.Debug().Str("group", group.DN).Str("user", e.DN).Msg("Cleaning up group membership") if mr, err := i.removeMemberFromGroupEntry(group, e.DN); err == nil && mr != nil { if err = i.conn.Modify(mr); err != nil { // Errors when deleting the memberships are only logged as warnings but not returned // to the user as we already successfully deleted the users itself - i.logger.Warn().Str("group", group.DN).Str("user", e.DN).Err(err).Msg("failed to remove member") + logger.Warn().Str("group", group.DN).Str("user", e.DN).Err(err).Msg("failed to remove member") } } } @@ -224,6 +228,8 @@ func (i *LDAP) DeleteUser(ctx context.Context, nameOrID string) error { // UpdateUser implements the Backend Interface for the LDAP Backend func (i *LDAP) UpdateUser(ctx context.Context, nameOrID string, user libregraph.User) (*libregraph.User, error) { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("UpdateUser") if !i.writeEnabled { return nil, errReadOnly } @@ -264,7 +270,7 @@ func (i *LDAP) UpdateUser(ctx context.Context, nameOrID string, user libregraph. } if user.PasswordProfile != nil && user.PasswordProfile.Password != nil && *user.PasswordProfile.Password != "" { if i.usePwModifyExOp { - if err := i.updateUserPassowrd(e.DN, user.PasswordProfile.GetPassword()); err != nil { + if err := i.updateUserPassowrd(ctx, e.DN, user.PasswordProfile.GetPassword()); err != nil { return nil, err } } else { @@ -387,7 +393,8 @@ func (i *LDAP) getLDAPUserByFilter(filter string) (*ldap.Entry, error) { } func (i *LDAP) GetUser(ctx context.Context, nameOrID string, queryParam url.Values) (*libregraph.User, error) { - i.logger.Debug().Str("backend", "ldap").Msg("GetUser") + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("GetUser") e, err := i.getLDAPUserByNameOrID(nameOrID) if err != nil { return nil, err @@ -412,7 +419,8 @@ func (i *LDAP) GetUser(ctx context.Context, nameOrID string, queryParam url.Valu } func (i *LDAP) GetUsers(ctx context.Context, queryParam url.Values) ([]*libregraph.User, error) { - i.logger.Debug().Str("backend", "ldap").Msg("GetUsers") + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("GetUsers") search := queryParam.Get("search") if search == "" { @@ -440,7 +448,7 @@ func (i *LDAP) GetUsers(ctx context.Context, queryParam url.Values) ([]*libregra }, nil, ) - i.logger.Debug().Str("backend", "ldap"). + logger.Debug().Str("backend", "ldap"). Str("base", searchRequest.BaseDN). Str("filter", searchRequest.Filter). Int("scope", searchRequest.Scope). @@ -494,7 +502,8 @@ func (i *LDAP) getGroupsForUser(dn string) ([]*ldap.Entry, error) { } func (i *LDAP) GetGroup(ctx context.Context, nameOrID string, queryParam url.Values) (*libregraph.Group, error) { - i.logger.Debug().Str("backend", "ldap").Msg("GetGroup") + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("GetGroup") e, err := i.getLDAPGroupByNameOrID(nameOrID, true) if err != nil { return nil, err @@ -632,7 +641,8 @@ func (i *LDAP) removeMemberFromGroupEntry(group *ldap.Entry, memberDN string) (* } func (i *LDAP) GetGroups(ctx context.Context, queryParam url.Values) ([]*libregraph.Group, error) { - i.logger.Debug().Str("backend", "ldap").Msg("GetGroups") + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("GetGroups") search := queryParam.Get("search") if search == "" { @@ -671,7 +681,7 @@ func (i *LDAP) GetGroups(ctx context.Context, queryParam url.Values) ([]*libregr groupAttrs, nil, ) - i.logger.Debug().Str("backend", "ldap"). + logger.Debug().Str("backend", "ldap"). Str("base", searchRequest.BaseDN). Str("filter", searchRequest.Filter). Int("scope", searchRequest.Scope). @@ -712,6 +722,8 @@ func (i *LDAP) GetGroups(ctx context.Context, queryParam url.Values) ([]*libregr // GetGroupMembers implements the Backend Interface for the LDAP Backend func (i *LDAP) GetGroupMembers(ctx context.Context, groupID string) ([]*libregraph.User, error) { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("GetGroupMembers") e, err := i.getLDAPGroupByNameOrID(groupID, true) if err != nil { return nil, err @@ -732,17 +744,19 @@ func (i *LDAP) GetGroupMembers(ctx context.Context, groupID string) ([]*libregra } func (i *LDAP) expandLDAPGroupMembers(ctx context.Context, e *ldap.Entry) ([]*ldap.Entry, error) { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("expandLDAPGroupMembers") result := []*ldap.Entry{} for _, memberDN := range e.GetEqualFoldAttributeValues(i.groupAttributeMap.member) { if memberDN == "" { continue } - i.logger.Debug().Str("memberDN", memberDN).Msg("lookup") + logger.Debug().Str("memberDN", memberDN).Msg("lookup") ue, err := i.getUserByDN(memberDN) if err != nil { // Ignore errors when reading a specific member fails, just log them and continue - i.logger.Warn().Err(err).Str("member", memberDN).Msg("error reading group member") + logger.Debug().Err(err).Str("member", memberDN).Msg("error reading group member") continue } result = append(result, ue) @@ -756,6 +770,8 @@ func (i *LDAP) expandLDAPGroupMembers(ctx context.Context, e *ldap.Entry) ([]*ld // As "groupOfNames" requires a "member" Attribute to be present. Empty Groups (groups // without a member) a represented by adding an empty DN as the single member. func (i *LDAP) CreateGroup(ctx context.Context, group libregraph.Group) (*libregraph.Group, error) { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("create group") if !i.writeEnabled { return nil, errorcode.New(errorcode.NotAllowed, "server is configured read-only") } @@ -803,6 +819,8 @@ func (i *LDAP) CreateGroup(ctx context.Context, group libregraph.Group) (*libreg // DeleteGroup implements the Backend Interface. func (i *LDAP) DeleteGroup(ctx context.Context, id string) error { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("DeleteGroup") if !i.writeEnabled { return errorcode.New(errorcode.NotAllowed, "server is configured read-only") } @@ -821,6 +839,8 @@ func (i *LDAP) DeleteGroup(ctx context.Context, id string) error { // Currently it is limited to adding Users as Group members. Adding other groups // as members is not yet implemented func (i *LDAP) AddMembersToGroup(ctx context.Context, groupID string, memberIDs []string) error { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("AddMembersToGroup") ge, err := i.getLDAPGroupByID(groupID, true) if err != nil { return err @@ -843,7 +863,7 @@ func (i *LDAP) AddMembersToGroup(ctx context.Context, groupID string, memberIDs nCurrentMember, err := ldapdn.ParseNormalize(currentMember) if err != nil { // We couldn't parse the member value as a DN. Let's skip it, but log a warning - i.logger.Warn().Str("memberDN", currentMember).Err(err).Msg("Couldn't parse DN") + logger.Warn().Str("memberDN", currentMember).Err(err).Msg("Couldn't parse DN") continue } currentSet[nCurrentMember] = struct{}{} @@ -857,13 +877,13 @@ func (i *LDAP) AddMembersToGroup(ctx context.Context, groupID string, memberIDs } nDN, err := ldapdn.ParseNormalize(me.DN) if err != nil { - i.logger.Error().Str("new member", me.DN).Err(err).Msg("Couldn't parse DN") + logger.Error().Str("new member", me.DN).Err(err).Msg("Couldn't parse DN") return err } if _, present := currentSet[nDN]; !present { newMemberDNs = append(newMemberDNs, me.DN) } else { - i.logger.Debug().Str("memberDN", me.DN).Msg("Member already present in group. Skipping") + logger.Debug().Str("memberDN", me.DN).Msg("Member already present in group. Skipping") } } @@ -879,17 +899,19 @@ func (i *LDAP) AddMembersToGroup(ctx context.Context, groupID string, memberIDs // RemoveMemberFromGroup implements the Backend Interface. func (i *LDAP) RemoveMemberFromGroup(ctx context.Context, groupID string, memberID string) error { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("RemoveMemberFromGroup") ge, err := i.getLDAPGroupByID(groupID, true) if err != nil { - i.logger.Warn().Str("backend", "ldap").Str("groupID", groupID).Msg("Error looking up group") + logger.Debug().Str("backend", "ldap").Str("groupID", groupID).Msg("Error looking up group") return err } me, err := i.getLDAPUserByID(memberID) if err != nil { - i.logger.Warn().Str("backend", "ldap").Str("memberID", memberID).Msg("Error looking up group member") + logger.Debug().Str("backend", "ldap").Str("memberID", memberID).Msg("Error looking up group member") return err } - i.logger.Debug().Str("backend", "ldap").Str("groupdn", ge.DN).Str("member", me.DN).Msg("remove member") + logger.Debug().Str("backend", "ldap").Str("groupdn", ge.DN).Str("member", me.DN).Msg("remove member") if mr, err := i.removeMemberFromGroupEntry(ge, me.DN); err == nil && mr != nil { return i.conn.Modify(mr) @@ -897,7 +919,9 @@ func (i *LDAP) RemoveMemberFromGroup(ctx context.Context, groupID string, member return nil } -func (i *LDAP) updateUserPassowrd(dn, password string) error { +func (i *LDAP) updateUserPassowrd(ctx context.Context, dn, password string) error { + logger := i.logger.SubloggerWithRequestID(ctx) + logger.Debug().Str("backend", "ldap").Msg("updateUserPassowrd") pwMod := ldap.PasswordModifyRequest{ UserIdentity: dn, NewPassword: password, @@ -907,7 +931,7 @@ func (i *LDAP) updateUserPassowrd(dn, password string) error { _, err := i.conn.PasswordModify(&pwMod) if err != nil { var lerr *ldap.Error - i.logger.Debug().Err(err).Msg("error setting password for user") + logger.Debug().Err(err).Msg("error setting password for user") if errors.As(err, &lerr) { if lerr.ResultCode == ldap.LDAPResultEntryAlreadyExists { err = errorcode.New(errorcode.NameAlreadyExists, lerr.Error()) diff --git a/services/graph/pkg/middleware/auth.go b/services/graph/pkg/middleware/auth.go index fc6c487f7..6becccf90 100644 --- a/services/graph/pkg/middleware/auth.go +++ b/services/graph/pkg/middleware/auth.go @@ -7,6 +7,7 @@ import ( revactx "github.com/cs3org/reva/v2/pkg/ctx" "github.com/cs3org/reva/v2/pkg/token/manager/jwt" "github.com/owncloud/ocis/v2/ocis-pkg/account" + "github.com/owncloud/ocis/v2/ocis-pkg/log" opkgm "github.com/owncloud/ocis/v2/ocis-pkg/middleware" "github.com/owncloud/ocis/v2/services/graph/pkg/service/v0/errorcode" gmmetadata "go-micro.dev/v4/metadata" @@ -66,7 +67,7 @@ func Auth(opts ...account.Option) func(http.Handler) http.Handler { return } if ok, err := scope.VerifyScope(ctx, tokenScope, r); err != nil || !ok { - opt.Logger.Error().Err(err).Msg("verifying scope failed") + opt.Logger.Error().Str(log.RequestIDString, r.Header.Get("X-Request-ID")).Err(err).Msg("verifying scope failed") errorcode.InvalidAuthenticationToken.Render(w, r, http.StatusUnauthorized, "verifying scope failed") return } diff --git a/services/graph/pkg/service/v0/drives.go b/services/graph/pkg/service/v0/drives.go index 963501a57..05dd0aeb3 100644 --- a/services/graph/pkg/service/v0/drives.go +++ b/services/graph/pkg/service/v0/drives.go @@ -29,6 +29,7 @@ import ( settingssvc "github.com/owncloud/ocis/v2/protogen/gen/ocis/services/settings/v0" "github.com/owncloud/ocis/v2/services/graph/pkg/service/v0/errorcode" settingsServiceExt "github.com/owncloud/ocis/v2/services/settings/pkg/service/v0" + "github.com/pkg/errors" merrors "go-micro.dev/v4/errors" ) @@ -45,30 +46,36 @@ func (g Graph) GetAllDrives(w http.ResponseWriter, r *http.Request) { // getDrives implements the Service interface. func (g Graph) getDrives(w http.ResponseWriter, r *http.Request, unrestricted bool) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info(). + Interface("query", r.URL.Query()). + Bool("unrestricted", unrestricted). + Msg("calling get drives") sanitizedPath := strings.TrimPrefix(r.URL.Path, "/graph/v1.0/") // Parse the request with odata parser odataReq, err := godata.ParseRequest(r.Context(), sanitizedPath, r.URL.Query()) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("query error") + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("could not get drives: query error") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } - g.logger.Debug(). - Interface("query", r.URL.Query()). - Bool("unrestricted", unrestricted). - Msg("Calling getDrives") ctx := r.Context() filters, err := generateCs3Filters(odataReq) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("query error") + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("could not get drives: error parsing filters") errorcode.NotSupported.Render(w, r, http.StatusNotImplemented, err.Error()) return } + + logger.Debug(). + Interface("filters", filters). + Bool("unrestricted", unrestricted). + Msg("calling list storage spaces on backend") res, err := g.ListStorageSpacesWithFilters(ctx, filters, unrestricted) switch { case err != nil: - g.logger.Error().Err(err).Msg(ListStorageSpacesTransportErr) + logger.Error().Err(err).Msg("could not get drives: transport error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return case res.Status.Code != cs3rpc.Code_CODE_OK: @@ -78,27 +85,28 @@ func (g Graph) getDrives(w http.ResponseWriter, r *http.Request, unrestricted bo render.JSON(w, r, &listResponse{}) return } - g.logger.Error().Err(err).Msg(ListStorageSpacesReturnsErr) + logger.Debug().Str("message", res.GetStatus().GetMessage()).Msg("could not get drives: grpc error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, res.Status.Message) return } - wdu, err := url.Parse(g.config.Spaces.WebDavBase + g.config.Spaces.WebDavPath) + webDavBaseURL, err := g.getWebDavBaseURL() if err != nil { - g.logger.Error().Err(err).Msg("error parsing url") + logger.Error().Err(err).Str("url", webDavBaseURL.String()).Msg("could not get drives: error parsing url") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } - spaces, err := g.formatDrives(ctx, wdu, res.StorageSpaces) + + spaces, err := g.formatDrives(ctx, webDavBaseURL, res.StorageSpaces) if err != nil { - g.logger.Error().Err(err).Msg("error encoding response as json") + logger.Debug().Err(err).Msg("could not get drives: error parsing grpc response") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } spaces, err = sortSpaces(odataReq, spaces) if err != nil { - g.logger.Error().Err(err).Msg("error sorting the spaces list") + logger.Debug().Err(err).Msg("could not get drives: error sorting the spaces list according to query") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } @@ -109,60 +117,71 @@ func (g Graph) getDrives(w http.ResponseWriter, r *http.Request, unrestricted bo // GetSingleDrive does a lookup of a single space by spaceId func (g Graph) GetSingleDrive(w http.ResponseWriter, r *http.Request) { - driveID, _ := url.PathUnescape(chi.URLParam(r, "driveID")) - if driveID == "" { - err := fmt.Errorf("no valid space id retrieved") - g.logger.Err(err) - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Interface("query", r.URL.Query()).Msg("calling get drive") + driveID, err := url.PathUnescape(chi.URLParam(r, "driveID")) + + if err != nil { + logger.Debug().Err(err).Str("driveID", chi.URLParam(r, "driveID")).Msg("could not get drive: unescaping drive id failed") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping drive id failed") return } - g.logger.Info().Str("driveID", driveID).Msg("Calling GetSingleDrive") + if driveID == "" { + logger.Debug().Msg("could not get drive: missing drive id") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing drive id") + return + } + + logger.Debug().Str("driveID", driveID).Msg("calling list storage spaces with id filter") ctx := r.Context() filters := []*storageprovider.ListStorageSpacesRequest_Filter{listStorageSpacesIDFilter(driveID)} res, err := g.ListStorageSpacesWithFilters(ctx, filters, true) switch { case err != nil: - g.logger.Error().Err(err).Msg(ListStorageSpacesTransportErr) - errorcode.ServiceNotAvailable.Render(w, r, http.StatusInternalServerError, err.Error()) + logger.Error().Err(err).Msg("could not get drive: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return case res.Status.Code != cs3rpc.Code_CODE_OK: if res.Status.Code == cs3rpc.Code_CODE_NOT_FOUND { // the client is doing a lookup for a specific space, therefore we need to return // not found to the caller - g.logger.Error().Str("driveID", driveID).Msg(fmt.Sprintf(NoSpaceFoundMessage, driveID)) - errorcode.ItemNotFound.Render(w, r, http.StatusNotFound, fmt.Sprintf(NoSpaceFoundMessage, driveID)) + logger.Debug().Str("driveID", driveID).Msg("could not get drive: not found") + errorcode.ItemNotFound.Render(w, r, http.StatusNotFound, "drive not found") return } - g.logger.Error().Err(err).Msg(ListStorageSpacesReturnsErr) + logger.Debug(). + Str("id", driveID). + Str("grpcmessage", res.GetStatus().GetMessage()). + Msg("could not get drive: grpc error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, res.Status.Message) return } - wdu, err := url.Parse(g.config.Spaces.WebDavBase + g.config.Spaces.WebDavPath) + webDavBaseURL, err := g.getWebDavBaseURL() if err != nil { - g.logger.Error().Err(err).Msg("error parsing url") + logger.Error().Err(err).Str("url", webDavBaseURL.String()).Msg("could not get drive: error parsing webdav base url") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } - spaces, err := g.formatDrives(ctx, wdu, res.StorageSpaces) + spaces, err := g.formatDrives(ctx, webDavBaseURL, res.StorageSpaces) if err != nil { - g.logger.Error().Err(err).Msg("error encoding response") + logger.Debug().Err(err).Msg("could not get drive: error parsing grpc response") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } switch num := len(spaces); { case num == 0: - g.logger.Error().Str("driveID", driveID).Msg("no space found") - errorcode.ItemNotFound.Render(w, r, http.StatusNotFound, fmt.Sprintf(NoSpaceFoundMessage, driveID)) + logger.Debug().Str("id", driveID).Msg("could not get drive: no drive returned from storage") + errorcode.ItemNotFound.Render(w, r, http.StatusNotFound, "no drive returned from storage") return case num == 1: render.Status(r, http.StatusOK) render.JSON(w, r, spaces[0]) default: - g.logger.Error().Int("number", num).Msg("expected to find a single space but found more") - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "expected to find a single space but found more") + logger.Debug().Int("number", num).Msg("could not get drive: expected to find a single drive but fetched more") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "could not get drive: expected to find a single drive but fetched more") return } } @@ -185,28 +204,35 @@ func canCreateSpace(ctx context.Context, ownPersonalHome bool) bool { // CreateDrive creates a storage drive (space). func (g Graph) CreateDrive(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling create drive") us, ok := ctxpkg.ContextGetUser(r.Context()) if !ok { - errorcode.GeneralException.Render(w, r, http.StatusUnauthorized, "invalid user") + logger.Debug().Msg("could not create drive: invalid user") + errorcode.NotAllowed.Render(w, r, http.StatusUnauthorized, "invalid user") return } // TODO determine if the user tries to create his own personal space and pass that as a boolean - if !canCreateSpace(r.Context(), false) { + canCreateSpace := canCreateSpace(r.Context(), false) + if !canCreateSpace { + logger.Debug().Bool("cancreatespace", canCreateSpace).Msg("could not create drive: insufficient permissions") // if the permission is not existing for the user in context we can assume we don't have it. Return 401. - errorcode.GeneralException.Render(w, r, http.StatusUnauthorized, "insufficient permissions to create a space.") + errorcode.NotAllowed.Render(w, r, http.StatusUnauthorized, "insufficient permissions to create a space.") return } client := g.GetGatewayClient() drive := libregraph.Drive{} if err := json.NewDecoder(r.Body).Decode(&drive); err != nil { - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, "invalid schema definition") + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not create drive: invalid body schema definition") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "invalid body schema definition") return } spaceName := *drive.Name if spaceName == "" { - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "invalid name") + logger.Debug().Str("name", spaceName).Msg("could not create drive: invalid name") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "invalid name") return } @@ -218,7 +244,8 @@ func (g Graph) CreateDrive(w http.ResponseWriter, r *http.Request) { case "", "project": driveType = "project" default: - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, fmt.Sprintf("drives of type %s cannot be created via this api", driveType)) + logger.Debug().Str("type", driveType).Msg("could not create drive: drives of this type cannot be created via this api") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "drives of this type cannot be created via this api") return } @@ -242,25 +269,32 @@ func (g Graph) CreateDrive(w http.ResponseWriter, r *http.Request) { resp, err := client.CreateStorageSpace(r.Context(), &csr) if err != nil { + logger.Error().Err(err).Msg("could not create drive: transport error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } if resp.GetStatus().GetCode() != cs3rpc.Code_CODE_OK { - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "") + if resp.GetStatus().GetCode() == cs3rpc.Code_CODE_PERMISSION_DENIED { + logger.Debug().Str("grpcmessage", resp.GetStatus().GetMessage()).Msg("could not create drive: permission denied") + errorcode.NotAllowed.Render(w, r, http.StatusForbidden, "permission denied") + return + } + logger.Debug().Interface("grpcmessage", csr).Str("grpc", resp.GetStatus().GetMessage()).Msg("could not create drive: grpc error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, resp.GetStatus().GetMessage()) return } - wdu, err := url.Parse(g.config.Spaces.WebDavBase + g.config.Spaces.WebDavPath) + webDavBaseURL, err := g.getWebDavBaseURL() if err != nil { - g.logger.Error().Err(err).Msg("error parsing url") + logger.Error().Str("url", webDavBaseURL.String()).Err(err).Msg("could not create drive: error parsing webdav base url") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } - newDrive, err := g.cs3StorageSpaceToDrive(r.Context(), wdu, resp.StorageSpace) + newDrive, err := g.cs3StorageSpaceToDrive(r.Context(), webDavBaseURL, resp.StorageSpace) if err != nil { - g.logger.Error().Err(err).Msg("error parsing space") + logger.Debug().Err(err).Msg("could not create drive: error parsing drive") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } @@ -269,20 +303,25 @@ func (g Graph) CreateDrive(w http.ResponseWriter, r *http.Request) { } func (g Graph) UpdateDrive(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling update drive") driveID, err := url.PathUnescape(chi.URLParam(r, "driveID")) if err != nil { + logger.Debug().Err(err).Str("id", chi.URLParam(r, "driveID")).Msg("could not update drive, unescaping drive id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping drive id failed") return } if driveID == "" { + logger.Debug().Msg("Could not update drive, missing drive id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing drive id") return } drive := libregraph.Drive{} if err = json.NewDecoder(r.Body).Decode(&drive); err != nil { - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: %v", r.Body)) + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not update drive, invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: error: %v", err.Error())) return } @@ -290,7 +329,8 @@ func (g Graph) UpdateDrive(w http.ResponseWriter, r *http.Request) { rid, err := storagespace.ParseID(driveID) if err != nil { - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid resource id: %v", rid)) + logger.Debug().Err(err).Interface("id", rid).Msg("could not update drive, invalid resource id") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "invalid resource id") w.WriteHeader(http.StatusInternalServerError) return } @@ -343,11 +383,15 @@ func (g Graph) UpdateDrive(w http.ResponseWriter, r *http.Request) { user := ctxpkg.ContextMustGetUser(r.Context()) canSetSpaceQuota, err := canSetSpaceQuota(r.Context(), user) if err != nil { + logger.Error().Err(err).Msg("could not update drive: failed to check if the user can set space quota") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } if !canSetSpaceQuota { - errorcode.GeneralException.Render(w, r, http.StatusUnauthorized, "user is not allowed to set the space quota") + logger.Debug(). + Bool("cansetspacequota", canSetSpaceQuota). + Msg("could not update drive: user is not allowed to set the space quota") + errorcode.NotAllowed.Render(w, r, http.StatusUnauthorized, "user is not allowed to set the space quota") return } updateSpaceRequest.StorageSpace.Quota = &storageprovider.Quota{ @@ -355,36 +399,41 @@ func (g Graph) UpdateDrive(w http.ResponseWriter, r *http.Request) { } } + logger.Debug().Interface("payload", updateSpaceRequest).Msg("calling update space on backend") resp, err := client.UpdateStorageSpace(r.Context(), updateSpaceRequest) if err != nil { - w.WriteHeader(http.StatusInternalServerError) + logger.Error().Err(err).Msg("could not update drive: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "transport error") return } if resp.GetStatus().GetCode() != cs3rpc.Code_CODE_OK { switch resp.Status.GetCode() { case cs3rpc.Code_CODE_NOT_FOUND: + logger.Debug().Interface("id", rid).Msg("could not update drive: drive not found") errorcode.ItemNotFound.Render(w, r, http.StatusNotFound, resp.GetStatus().GetMessage()) return case cs3rpc.Code_CODE_PERMISSION_DENIED: + logger.Debug().Interface("id", rid).Msg("could not update drive, permission denied") errorcode.NotAllowed.Render(w, r, http.StatusForbidden, resp.GetStatus().GetMessage()) return default: + logger.Debug().Interface("id", rid).Str("grpc", resp.GetStatus().GetMessage()).Msg("could not update drive: grpc error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, resp.GetStatus().GetMessage()) return } } - wdu, err := url.Parse(g.config.Spaces.WebDavBase + g.config.Spaces.WebDavPath) + webDavBaseURL, err := g.getWebDavBaseURL() if err != nil { - g.logger.Error().Err(err).Msg("error parsing url") + logger.Error().Err(err).Interface("url", webDavBaseURL.String()).Msg("could not update drive: error parsing url") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } - spaces, err := g.formatDrives(r.Context(), wdu, []*storageprovider.StorageSpace{resp.StorageSpace}) + spaces, err := g.formatDrives(r.Context(), webDavBaseURL, []*storageprovider.StorageSpace{resp.StorageSpace}) if err != nil { - g.logger.Error().Err(err).Msg("error parsing space") + logger.Debug().Err(err).Msg("could not update drive: error parsing grpc response") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } @@ -452,8 +501,10 @@ func (g Graph) ListStorageSpacesWithFilters(ctx context.Context, filters []*stor } func (g Graph) cs3StorageSpaceToDrive(ctx context.Context, baseURL *url.URL, space *storageprovider.StorageSpace) (*libregraph.Drive, error) { + logger := g.logger.SubloggerWithRequestID(ctx) if space.Root == nil { - return nil, fmt.Errorf("space has no root") + logger.Error().Msg("unable to parse space: space has no root") + return nil, errors.New("space has no root") } spaceRid := *space.Root if space.Root.GetSpaceId() == space.Root.GetOpaqueId() { @@ -468,10 +519,11 @@ func (g Graph) cs3StorageSpaceToDrive(ctx context.Context, baseURL *url.URL, spa if ok { err := json.Unmarshal(entry.Value, &m) if err != nil { - g.logger.Error(). + logger.Debug(). Err(err). - Str("space", space.Root.OpaqueId). - Msg("failed to read spaces grants") + Interface("space", space.Root). + Bytes("grants", entry.Value). + Msg("unable to parse space: failed to read spaces grants") } } if len(m) != 0 { @@ -542,7 +594,7 @@ func (g Graph) cs3StorageSpaceToDrive(ctx context.Context, baseURL *url.URL, spa var err error remoteItem, err = g.getRemoteItem(ctx, &grantID, baseURL) if err != nil { - g.logger.Debug().Err(err).Msg(err.Error()) + logger.Debug().Err(err).Interface("id", grantID).Msg("could not fetch remote item for space, continue") } } if remoteItem != nil { @@ -578,10 +630,10 @@ func (g Graph) cs3StorageSpaceToDrive(ctx context.Context, baseURL *url.URL, spa webURL, err := url.Parse(g.config.Spaces.WebDavBase) if err != nil { - g.logger.Error(). + logger.Error(). Err(err). Str("url", g.config.Spaces.WebDavBase). - Msg("failed to parse base url") + Msg("failed to parse webURL base url") return nil, err } @@ -616,6 +668,7 @@ func (g Graph) cs3StorageSpaceToDrive(ctx context.Context, baseURL *url.URL, spa } func (g Graph) getDriveQuota(ctx context.Context, space *storageprovider.StorageSpace) (*libregraph.Quota, error) { + logger := g.logger.SubloggerWithRequestID(ctx) client := g.GetGatewayClient() req := &gateway.GetQuotaRequest{ @@ -627,13 +680,13 @@ func (g Graph) getDriveQuota(ctx context.Context, space *storageprovider.Storage res, err := client.GetQuota(ctx, req) switch { case err != nil: - g.logger.Error().Err(err).Msg("could not call GetQuota") + logger.Error().Err(err).Interface("ref", req.Ref).Msg("could not call GetQuota: transport error") return nil, nil - case res.Status.Code == cs3rpc.Code_CODE_UNIMPLEMENTED: - // TODO well duh + case res.GetStatus().GetCode() == cs3rpc.Code_CODE_UNIMPLEMENTED: + logger.Debug().Msg("get quota is not implemented on the storage driver") return nil, nil - case res.Status.Code != cs3rpc.Code_CODE_OK: - g.logger.Error().Err(err).Msg("error sending get quota grpc request") + case res.GetStatus().GetCode() != cs3rpc.Code_CODE_OK: + logger.Debug().Str("grpc", res.GetStatus().GetMessage()).Msg("error sending get quota grpc request") return nil, err } @@ -723,7 +776,7 @@ func generateCs3Filters(request *godata.GoDataRequest) ([]*storageprovider.ListS filters = append(filters, listStorageSpacesIDFilter(strings.Trim(request.Query.Filter.Tree.Children[1].Token.Value, "'"))) } } else { - err := fmt.Errorf("unsupported filter operand: %s", request.Query.Filter.Tree.Token.Value) + err := errors.Errorf("unsupported filter operand: %s", request.Query.Filter.Tree.Token.Value) return nil, err } } @@ -762,21 +815,25 @@ func listStorageSpacesTypeFilter(spaceType string) *storageprovider.ListStorageS } func (g Graph) DeleteDrive(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling delete drive") driveID, err := url.PathUnescape(chi.URLParam(r, "driveID")) if err != nil { + logger.Debug().Err(err).Str("id", chi.URLParam(r, "driveID")).Msg("could not delete drive: unescaping drive id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping drive id failed") return } if driveID == "" { + logger.Debug().Msg("could not delete drive: missing drive id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing drive id") return } rid, err := storagespace.ParseID(driveID) if err != nil { - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid resource id: %v", rid)) - w.WriteHeader(http.StatusInternalServerError) + logger.Debug().Interface("id", rid).Err(err).Msg("could not delete drive: invalid resource id") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "invalid resource id") return } @@ -798,8 +855,8 @@ func (g Graph) DeleteDrive(w http.ResponseWriter, r *http.Request) { }, }) if err != nil { - g.logger.Error().Err(err).Msg("error deleting storage space") - w.WriteHeader(http.StatusInternalServerError) + logger.Error().Err(err).Interface("id", rid).Msg("could not delete drive: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "transport error") return } @@ -808,16 +865,17 @@ func (g Graph) DeleteDrive(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusNoContent) return case cs3rpc.Code_CODE_INVALID_ARGUMENT: - errorcode.GeneralException.Render(w, r, http.StatusBadRequest, dRes.Status.Message) - w.WriteHeader(http.StatusBadRequest) + logger.Debug().Interface("id", rid).Str("grpc", dRes.GetStatus().GetMessage()).Msg("could not delete drive: invalid argument") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, dRes.Status.Message) return case cs3rpc.Code_CODE_PERMISSION_DENIED: - w.WriteHeader(http.StatusForbidden) + logger.Debug().Interface("id", rid).Msg("could not delete drive: permission denied") + errorcode.NotAllowed.Render(w, r, http.StatusForbidden, "permission denied to delete drive") return // don't expose internal error codes to the outside world default: - g.logger.Error().Err(err).Msg("error deleting storage space") - w.WriteHeader(http.StatusInternalServerError) + logger.Debug().Str("grpc", dRes.GetStatus().GetMessage()).Interface("id", rid).Msg("could not delete drive: grpc error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "grpc error") return } @@ -834,7 +892,7 @@ func sortSpaces(req *godata.GoDataRequest, spaces []*libregraph.Drive) ([]*libre case "lastModifiedDateTime": sorter = spacesByLastModifiedDateTime{spaces} default: - return nil, fmt.Errorf("we do not support <%s> as a order parameter", req.Query.OrderBy.OrderByItems[0].Field.Value) + return nil, errors.Errorf("we do not support <%s> as a order parameter", req.Query.OrderBy.OrderByItems[0].Field.Value) } if req.Query.OrderBy.OrderByItems[0].Order == "desc" { diff --git a/services/graph/pkg/service/v0/errorcode/errorcode.go b/services/graph/pkg/service/v0/errorcode/errorcode.go index b39a70046..28887c8a5 100644 --- a/services/graph/pkg/service/v0/errorcode/errorcode.go +++ b/services/graph/pkg/service/v0/errorcode/errorcode.go @@ -50,6 +50,8 @@ const ( QuotaLimitReached // Unauthenticated the caller is not authenticated. Unauthenticated + // PreconditionFailed the request cannot be made and this error response is sent back + PreconditionFailed ) var errorCodes = [...]string{ @@ -69,6 +71,7 @@ var errorCodes = [...]string{ "serviceNotAvailable", "quotaLimitReached", "unauthenticated", + "preconditionFailed", } func New(e ErrorCode, msg string) Error { @@ -82,7 +85,6 @@ func New(e ErrorCode, msg string) Error { func (e ErrorCode) Render(w http.ResponseWriter, r *http.Request, status int, msg string) { innererror := map[string]interface{}{ "date": time.Now().UTC().Format(time.RFC3339), - // TODO return client-request-id? } innererror["request-id"] = middleware.GetReqID(r.Context()) diff --git a/services/graph/pkg/service/v0/graph.go b/services/graph/pkg/service/v0/graph.go index 02112ce49..45f6ab68a 100644 --- a/services/graph/pkg/service/v0/graph.go +++ b/services/graph/pkg/service/v0/graph.go @@ -3,6 +3,8 @@ package svc import ( "context" "net/http" + "net/url" + "path" gateway "github.com/cs3org/go-cs3apis/cs3/gateway/v1beta1" provider "github.com/cs3org/go-cs3apis/cs3/storage/provider/v1beta1" @@ -100,14 +102,20 @@ func (g Graph) publishEvent(ev interface{}) { } } +func (g Graph) getWebDavBaseURL() (*url.URL, error) { + webDavBaseURL, err := url.Parse(g.config.Spaces.WebDavBase) + if err != nil { + return nil, err + } + webDavBaseURL.Path = path.Join(webDavBaseURL.Path, g.config.Spaces.WebDavPath) + return webDavBaseURL, nil +} + type listResponse struct { Value interface{} `json:"value,omitempty"` } const ( - NoSpaceFoundMessage = "space with id `%s` not found" - ListStorageSpacesTransportErr = "transport error sending list storage spaces grpc request" - ListStorageSpacesReturnsErr = "list storage spaces grpc request returns an errorcode in the response" - ReadmeSpecialFolderName = "readme" - SpaceImageSpecialFolderName = "image" + ReadmeSpecialFolderName = "readme" + SpaceImageSpecialFolderName = "image" ) diff --git a/services/graph/pkg/service/v0/groups.go b/services/graph/pkg/service/v0/groups.go index 8afdf65a0..48c657b73 100644 --- a/services/graph/pkg/service/v0/groups.go +++ b/services/graph/pkg/service/v0/groups.go @@ -23,17 +23,19 @@ const memberRefsLimit = 20 // GetGroups implements the Service interface. func (g Graph) GetGroups(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Interface("query", r.URL.Query()).Msg("calling get groups") sanitizedPath := strings.TrimPrefix(r.URL.Path, "/graph/v1.0/") odataReq, err := godata.ParseRequest(r.Context(), sanitizedPath, r.URL.Query()) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("query error") + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("could not get groups: query error") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } groups, err := g.identityBackend.GetGroups(r.Context(), r.URL.Query()) - if err != nil { + logger.Debug().Err(err).Msg("could not get groups: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -44,12 +46,8 @@ func (g Graph) GetGroups(w http.ResponseWriter, r *http.Request) { groups, err = sortGroups(odataReq, groups) if err != nil { - var errcode errorcode.Error - if errors.As(err, &errcode) { - errcode.Render(w, r) - } else { - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) - } + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("cannot get groups: could not sort groups according to query") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } render.Status(r, http.StatusOK) @@ -58,14 +56,18 @@ func (g Graph) GetGroups(w http.ResponseWriter, r *http.Request) { // PostGroup implements the Service interface. func (g Graph) PostGroup(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling post group") grp := libregraph.NewGroup() err := json.NewDecoder(r.Body).Decode(grp) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not create group: invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: %s", err.Error())) return } if _, ok := grp.GetDisplayNameOk(); !ok { + logger.Debug().Err(err).Interface("group", grp).Msg("could not create group: missing required attribute") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "Missing Required Attribute") return } @@ -74,11 +76,13 @@ func (g Graph) PostGroup(w http.ResponseWriter, r *http.Request) { // generating them in the backend ourselves or rely on the Backend's // storage (e.g. LDAP) to provide a unique ID. if _, ok := grp.GetIdOk(); ok { + logger.Debug().Msg("could not create group: id is a read-only attribute") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "group id is a read-only attribute") return } if grp, err = g.identityBackend.CreateGroup(r.Context(), *grp); err != nil { + logger.Debug().Interface("group", grp).Msg("could not create group: backend error") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) return } @@ -93,29 +97,37 @@ func (g Graph) PostGroup(w http.ResponseWriter, r *http.Request) { // PatchGroup implements the Service interface. func (g Graph) PatchGroup(w http.ResponseWriter, r *http.Request) { - g.logger.Debug().Msg("Calling PatchGroup") + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling patch group") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug().Str("id", groupID).Msg("could not change group: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if groupID == "" { + logger.Debug().Msg("could not change group: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } changes := libregraph.NewGroup() err = json.NewDecoder(r.Body).Decode(changes) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not change group: invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: %s", err.Error())) return } if memberRefs, ok := changes.GetMembersodataBindOk(); ok { // The spec defines a limit of 20 members maxium per Request if len(memberRefs) > memberRefsLimit { - errorcode.NotAllowed.Render(w, r, http.StatusInternalServerError, + logger.Debug(). + Int("number", len(memberRefs)). + Int("limit", memberRefsLimit). + Msg("could not create group, exceeded members limit") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("Request is limited to %d members", memberRefsLimit)) return } @@ -123,14 +135,20 @@ func (g Graph) PatchGroup(w http.ResponseWriter, r *http.Request) { for _, memberRef := range memberRefs { memberType, id, err := g.parseMemberRef(memberRef) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "Error parsing member@odata.bind values") + logger.Debug(). + Str("memberref", memberRef). + Msg("could not change group: Error parsing member@odata.bind values") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "Error parsing member@odata.bind values") return } - g.logger.Debug().Str("memberType", memberType).Str("memberid", id).Msg("Add Member") + logger.Debug().Str("membertype", memberType).Str("memberid", id).Msg("add group member") // The MS Graph spec allows "directoryObject", "user", "group" and "organizational Contact" // we restrict this to users for now. Might add Groups as members later if memberType != "users" { - errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "Only user are allowed as group members") + logger.Debug(). + Str("type", memberType). + Msg("could not change group: could not add member, only user type is allowed") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "Only user are allowed as group members") return } memberIDs = append(memberIDs, id) @@ -139,6 +157,7 @@ func (g Graph) PatchGroup(w http.ResponseWriter, r *http.Request) { } if err != nil { + logger.Debug().Err(err).Msg("could not change group: backend could not add members") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -153,19 +172,28 @@ func (g Graph) PatchGroup(w http.ResponseWriter, r *http.Request) { // GetGroup implements the Service interface. func (g Graph) GetGroup(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling get group") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug().Str("id", groupID).Msg("could not get group: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") } if groupID == "" { + logger.Debug().Msg("could not get group: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } + logger.Debug(). + Str("id", groupID). + Interface("query", r.URL.Query()). + Msg("calling get group on backend") group, err := g.identityBackend.GetGroup(r.Context(), groupID, r.URL.Query()) if err != nil { + logger.Debug().Err(err).Msg("could not get group: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -180,21 +208,27 @@ func (g Graph) GetGroup(w http.ResponseWriter, r *http.Request) { // DeleteGroup implements the Service interface. func (g Graph) DeleteGroup(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling delete group") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug().Err(err).Str("id", groupID).Msg("could not delete group: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if groupID == "" { + logger.Debug().Msg("could not delete group: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } + logger.Debug().Str("id", groupID).Msg("calling delete group on backend") err = g.identityBackend.DeleteGroup(r.Context(), groupID) if err != nil { + logger.Debug().Err(err).Msg("could not delete group: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -211,20 +245,26 @@ func (g Graph) DeleteGroup(w http.ResponseWriter, r *http.Request) { } func (g Graph) GetGroupMembers(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling get group members") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug().Str("id", groupID).Msg("could not get group members: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if groupID == "" { + logger.Debug().Msg("could not get group members: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } + logger.Debug().Str("id", groupID).Msg("calling get group members on backend") members, err := g.identityBackend.GetGroupMembers(r.Context(), groupID) if err != nil { + logger.Debug().Err(err).Msg("could not get group members: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -240,46 +280,60 @@ func (g Graph) GetGroupMembers(w http.ResponseWriter, r *http.Request) { // PostGroupMember implements the Service interface. func (g Graph) PostGroupMember(w http.ResponseWriter, r *http.Request) { - g.logger.Info().Msg("Calling PostGroupMember") + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("Calling post group member") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug(). + Err(err). + Str("id", groupID). + Msg("could not add member to group: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if groupID == "" { + logger.Debug().Msg("could not add group member: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } memberRef := libregraph.NewMemberReference() err = json.NewDecoder(r.Body).Decode(memberRef) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) + logger.Debug(). + Err(err). + Interface("body", r.Body). + Msg("could not add group member: invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: %s", err.Error())) return } memberRefURL, ok := memberRef.GetOdataIdOk() if !ok { - errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "@odata.id refernce is missing") + logger.Debug().Msg("could not add group member: @odata.id reference is missing") + errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "@odata.id reference is missing") return } memberType, id, err := g.parseMemberRef(*memberRefURL) if err != nil { + logger.Debug().Err(err).Msg("could not add group member: error parsing @odata.id url") errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "Error parsing @odata.id url") return } // The MS Graph spec allows "directoryObject", "user", "group" and "organizational Contact" // we restrict this to users for now. Might add Groups as members later if memberType != "users" { - errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "Only user are allowed as group members") + logger.Debug().Str("type", memberType).Msg("could not add group member: Only users are allowed as group members") + errorcode.InvalidRequest.Render(w, r, http.StatusInternalServerError, "Only users are allowed as group members") return } - g.logger.Debug().Str("memberType", memberType).Str("id", id).Msg("Add Member") + logger.Debug().Str("memberType", memberType).Str("id", id).Msg("calling add member on backend") err = g.identityBackend.AddMembersToGroup(r.Context(), groupID, []string{id}) if err != nil { + logger.Debug().Err(err).Msg("could not add group member: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -297,16 +351,19 @@ func (g Graph) PostGroupMember(w http.ResponseWriter, r *http.Request) { // DeleteGroupMember implements the Service interface. func (g Graph) DeleteGroupMember(w http.ResponseWriter, r *http.Request) { - g.logger.Info().Msg("Calling DeleteGroupMember") + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling delete group member") groupID := chi.URLParam(r, "groupID") groupID, err := url.PathUnescape(groupID) if err != nil { + logger.Debug().Err(err).Str("id", groupID).Msg("could not delete group member: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if groupID == "" { + logger.Debug().Msg("could not delete group member: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } @@ -314,18 +371,21 @@ func (g Graph) DeleteGroupMember(w http.ResponseWriter, r *http.Request) { memberID := chi.URLParam(r, "memberID") memberID, err = url.PathUnescape(memberID) if err != nil { + logger.Debug().Err(err).Str("id", memberID).Msg("could not delete group member: unescaping group id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping group id failed") return } if memberID == "" { + logger.Debug().Msg("could not delete group member: missing group id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing group id") return } - g.logger.Debug().Str("groupID", groupID).Str("memberID", memberID).Msg("DeleteGroupMember") + logger.Debug().Str("groupID", groupID).Str("memberID", memberID).Msg("calling delete member on backend") err = g.identityBackend.RemoveMemberFromGroup(r.Context(), groupID, memberID) if err != nil { + logger.Debug().Err(err).Msg("could not delete group member: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) diff --git a/services/graph/pkg/service/v0/users.go b/services/graph/pkg/service/v0/users.go index 0efcf0f92..82521085a 100644 --- a/services/graph/pkg/service/v0/users.go +++ b/services/graph/pkg/service/v0/users.go @@ -30,15 +30,15 @@ import ( // GetMe implements the Service interface. func (g Graph) GetMe(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling get user in /me") u, ok := revactx.ContextGetUser(r.Context()) if !ok { - g.logger.Error().Msg("user not in context") - errorcode.ServiceNotAvailable.Render(w, r, http.StatusInternalServerError, "user not in context") + logger.Debug().Msg("could not get user: user not in context") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "user not in context") return } - - g.logger.Info().Interface("user", u).Msg("User in /me") exp := strings.Split(r.URL.Query().Get("$expand"), ",") var me *libregraph.User // We can just return the user from context unless we need to expand the group memberships @@ -46,8 +46,10 @@ func (g Graph) GetMe(w http.ResponseWriter, r *http.Request) { me = identity.CreateUserModelFromCS3(u) } else { var err error + logger.Debug().Msg("calling get user on backend") me, err = g.identityBackend.GetUser(r.Context(), u.GetId().GetOpaqueId(), r.URL.Query()) if err != nil { + logger.Debug().Err(err).Interface("user", u).Msg("could not get user from backend") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -63,15 +65,20 @@ func (g Graph) GetMe(w http.ResponseWriter, r *http.Request) { // GetUsers implements the Service interface. func (g Graph) GetUsers(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Interface("query", r.URL.Query()).Msg("calling get users") sanitizedPath := strings.TrimPrefix(r.URL.Path, "/graph/v1.0/") odataReq, err := godata.ParseRequest(r.Context(), sanitizedPath, r.URL.Query()) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("query error") + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("could not get users: query error") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } + + logger.Debug().Interface("query", r.URL.Query()).Msg("calling get users on backend") users, err := g.identityBackend.GetUsers(r.Context(), r.URL.Query()) if err != nil { + logger.Debug().Err(err).Interface("query", r.URL.Query()).Msg("could not get users from backend") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -83,12 +90,8 @@ func (g Graph) GetUsers(w http.ResponseWriter, r *http.Request) { users, err = sortUsers(odataReq, users) if err != nil { - var errcode errorcode.Error - if errors.As(err, &errcode) { - errcode.Render(w, r) - } else { - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, err.Error()) - } + logger.Debug().Interface("query", odataReq).Msg("error while sorting users according to query") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) return } render.Status(r, http.StatusOK) @@ -96,35 +99,41 @@ func (g Graph) GetUsers(w http.ResponseWriter, r *http.Request) { } func (g Graph) PostUser(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Interface("body", r.Body).Msg("calling create user") u := libregraph.NewUser() err := json.NewDecoder(r.Body).Decode(u) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not create user: invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("invalid request body: %v", err.Error())) return } if _, ok := u.GetDisplayNameOk(); !ok { + logger.Debug().Err(err).Interface("user", u).Msg("could not create user: missing required Attribute: 'displayName'") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing required Attribute: 'displayName'") return } if accountName, ok := u.GetOnPremisesSamAccountNameOk(); ok { if !isValidUsername(*accountName) { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, - fmt.Sprintf("username '%s' must be at least the local part of an email", *u.OnPremisesSamAccountName)) + logger.Debug().Str("username", *accountName).Msg("could not create user: username must be at least the local part of an email") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("username %s must be at least the local part of an email", *u.OnPremisesSamAccountName)) return } } else { + logger.Debug().Interface("user", u).Msg("could not create user: missing required Attribute: 'onPremisesSamAccountName'") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing required Attribute: 'onPremisesSamAccountName'") return } if mail, ok := u.GetMailOk(); ok { if !isValidEmail(*mail) { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, - fmt.Sprintf("'%s' is not a valid email address", *u.Mail)) + logger.Debug().Str("mail", *u.Mail).Msg("could not create user: invalid email address") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("%v is not a valid email address", *u.Mail)) return } } else { + logger.Debug().Interface("user", u).Msg("could not create user: missing required Attribute: 'mail'") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing required Attribute: 'mail'") return } @@ -133,11 +142,14 @@ func (g Graph) PostUser(w http.ResponseWriter, r *http.Request) { // generating them in the backend ourselves or rely on the Backend's // storage (e.g. LDAP) to provide a unique ID. if _, ok := u.GetIdOk(); ok { + logger.Debug().Interface("user", u).Msg("could not create user: user id is a read-only attribute") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "user id is a read-only attribute") return } + logger.Debug().Interface("user", u).Msg("calling create user on backend") if u, err = g.identityBackend.CreateUser(r.Context(), *u); err != nil { + logger.Debug().Err(err).Msg("could not create user: backend error") var ecErr errorcode.Error if errors.As(err, &ecErr) { ecErr.Render(w, r) @@ -150,6 +162,8 @@ func (g Graph) PostUser(w http.ResponseWriter, r *http.Request) { // All users get the user role by default currently. // to all new users for now, as create Account request does not have any role field if g.roleService == nil { + // log as error, admin needs to do something about it + logger.Error().Str("id", *u.Id).Msg("could not create user: role service not configured") errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "could not assign role to account: roleService not configured") return } @@ -157,7 +171,9 @@ func (g Graph) PostUser(w http.ResponseWriter, r *http.Request) { AccountUuid: *u.Id, RoleId: settingssvc.BundleUUIDRoleUser, }); err != nil { - errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, fmt.Sprintf("could not assign role to account %s", err.Error())) + // log as error, admin eventually needs to do something + logger.Error().Err(err).Str("id", *u.Id).Str("role", settingssvc.BundleUUIDRoleUser).Msg("could not create user: role assignment failed") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "role assignment failed") return } @@ -170,21 +186,27 @@ func (g Graph) PostUser(w http.ResponseWriter, r *http.Request) { // GetUser implements the Service interface. func (g Graph) GetUser(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling get user") userID := chi.URLParam(r, "userID") userID, err := url.PathUnescape(userID) if err != nil { + logger.Debug().Err(err).Str("id", userID).Msg("could not get user: unescaping user id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping user id failed") return } if userID == "" { + logger.Debug().Msg("could not get user: missing user id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing user id") return } + logger.Debug().Str("id", userID).Msg("calling get user from backend") user, err := g.identityBackend.GetUser(r.Context(), userID, r.URL.Query()) if err != nil { + logger.Debug().Err(err).Msg("could not get user: error fetching user from backend") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -196,15 +218,18 @@ func (g Graph) GetUser(w http.ResponseWriter, r *http.Request) { sel := strings.Split(r.URL.Query().Get("$select"), ",") exp := strings.Split(r.URL.Query().Get("$expand"), ",") if slices.Contains(sel, "drive") || slices.Contains(sel, "drives") || slices.Contains(exp, "drive") || slices.Contains(exp, "drives") { - wdu, err := url.Parse(g.config.Spaces.WebDavBase + g.config.Spaces.WebDavPath) + wdu, err := g.getWebDavBaseURL() if err != nil { - g.logger.Err(err). + // log error, wrong configuration + logger.Error(). + Err(err). Str("webdav_base", g.config.Spaces.WebDavBase). Str("webdav_path", g.config.Spaces.WebDavPath). Msg("error parsing webdav URL") render.Status(r, http.StatusInternalServerError) return } + logger.Debug().Str("id", user.GetId()).Msg("calling list storage spaces with user id filter") f := listStorageSpacesUserFilter(user.GetId()) // use the unrestricted flag to get all possible spaces // users with the canListAllSpaces permission should see all spaces @@ -214,12 +239,14 @@ func (g Graph) GetUser(w http.ResponseWriter, r *http.Request) { Filters: []*storageprovider.ListStorageSpacesRequest_Filter{f}, }) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("error getting storages") + // transport error, needs to be fixed by admin + logger.Error().Err(err).Interface("query", r.URL.Query()).Msg("error getting storages: transport error") render.Status(r, http.StatusInternalServerError) render.JSON(w, r, user) return } - if lspr.Status.Code != cs3rpc.Code_CODE_OK { + if lspr.GetStatus().GetCode() != cs3rpc.Code_CODE_OK { + logger.Debug().Str("grpc", lspr.GetStatus().GetMessage()).Msg("could not get drive for user") // in case of NOT_OK, we can just return the user object with empty drives render.Status(r, status.HTTPStatusFromCode(http.StatusOK)) render.JSON(w, r, user) @@ -229,11 +256,11 @@ func (g Graph) GetUser(w http.ResponseWriter, r *http.Request) { for _, sp := range lspr.GetStorageSpaces() { d, err := g.cs3StorageSpaceToDrive(r.Context(), wdu, sp) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("error converting space to drive") + logger.Debug().Err(err).Interface("id", sp.Id).Msg("error converting space to drive") } quota, err := g.getDriveQuota(r.Context(), sp) if err != nil { - g.logger.Err(err).Interface("query", r.URL.Query()).Msg("error calling get quota") + logger.Debug().Err(err).Interface("id", sp.Id).Msg("error calling get quota on drive") } d.Quota = quota if slices.Contains(sel, "drive") || slices.Contains(exp, "drive") { @@ -252,21 +279,25 @@ func (g Graph) GetUser(w http.ResponseWriter, r *http.Request) { } func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling delete user") userID := chi.URLParam(r, "userID") userID, err := url.PathUnescape(userID) if err != nil { - g.logger.Debug().Err(err).Msg("unescaping user id failed") + logger.Debug().Err(err).Str("id", userID).Msg("could not delete user: unescaping user id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping user id failed") return } if userID == "" { + logger.Debug().Msg("could not delete user: missing user id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing user id") return } + logger.Debug().Str("id", userID).Msg("calling get user on user backend") user, err := g.identityBackend.GetUser(r.Context(), userID, r.URL.Query()) if err != nil { - g.logger.Debug().Err(err).Str("userID", userID).Msg("failed to get user") + logger.Debug().Err(err).Str("userID", userID).Msg("failed to get user from backend") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -279,11 +310,14 @@ func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { currentUser := ctxpkg.ContextMustGetUser(r.Context()) if currentUser.GetId().GetOpaqueId() == user.GetId() { - g.logger.Debug().Msg("self deletion forbidden") + logger.Debug().Msg("could not delete user: self deletion forbidden") errorcode.NotAllowed.Render(w, r, http.StatusForbidden, "self deletion forbidden") return } + logger.Debug(). + Str("user", user.GetId()). + Msg("calling list spaces with user filter to fetch the personal space for deletion") opaque := utils.AppendPlainToOpaque(nil, "unrestricted", "T") f := listStorageSpacesUserFilter(user.GetId()) lspr, err := g.gatewayClient.ListStorageSpaces(r.Context(), &storageprovider.ListStorageSpacesRequest{ @@ -291,8 +325,9 @@ func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { Filters: []*storageprovider.ListStorageSpacesRequest_Filter{f}, }) if err != nil { - g.logger.Debug().Err(err).Msg("could not read spaces") - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "could not read spaces") + // transport error, log as error + logger.Error().Err(err).Msg("could not fetch spaces: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "could not fetch spaces for deletion, aborting") return } for _, sp := range lspr.GetStorageSpaces() { @@ -312,8 +347,8 @@ func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { }, }) if err != nil { - g.logger.Debug().Err(err).Msg("could not disable homespace") - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "could not disable homespace") + logger.Error().Err(err).Msg("could not disable homespace: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "could not disable homespace, aborting") return } } @@ -325,16 +360,19 @@ func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { }, }) if err != nil { - g.logger.Debug().Err(err).Msg("could not delete homespace") - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "could not delete homespace") + // transport error, log as error + logger.Error().Err(err).Msg("could not delete homespace: transport error") + errorcode.GeneralException.Render(w, r, http.StatusInternalServerError, "could not delete homespace, aborting") return } break } + logger.Debug().Str("id", user.GetId()).Msg("calling delete user on backend") err = g.identityBackend.DeleteUser(r.Context(), user.GetId()) if err != nil { + logger.Debug().Err(err).Msg("could not delete user: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) @@ -353,27 +391,34 @@ func (g Graph) DeleteUser(w http.ResponseWriter, r *http.Request) { // PatchUser implements the Service Interface. Updates the specified attributes of an // ExistingUser func (g Graph) PatchUser(w http.ResponseWriter, r *http.Request) { + logger := g.logger.SubloggerWithRequestID(r.Context()) + logger.Info().Msg("calling patch user") nameOrID := chi.URLParam(r, "userID") nameOrID, err := url.PathUnescape(nameOrID) if err != nil { + logger.Debug().Err(err).Str("id", nameOrID).Msg("could not update user: unescaping user id failed") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "unescaping user id failed") return } if nameOrID == "" { + logger.Debug().Msg("could not update user: missing user id") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, "missing user id") return } changes := libregraph.NewUser() err = json.NewDecoder(r.Body).Decode(changes) if err != nil { - errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, err.Error()) + logger.Debug().Err(err).Interface("body", r.Body).Msg("could not update user: invalid request body") + errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, + fmt.Sprintf("invalid request body: %s", err.Error())) return } var features []events.UserFeature if mail, ok := changes.GetMailOk(); ok { if !isValidEmail(*mail) { + logger.Debug().Str("mail", *mail).Msg("could not update user: email is not a valid email address") errorcode.InvalidRequest.Render(w, r, http.StatusBadRequest, fmt.Sprintf("'%s' is not a valid email address", *mail)) return @@ -385,8 +430,10 @@ func (g Graph) PatchUser(w http.ResponseWriter, r *http.Request) { features = append(features, events.UserFeature{Name: "displayname", Value: *name}) } + logger.Debug().Str("nameid", nameOrID).Interface("changes", *changes).Msg("calling update user on backend") u, err := g.identityBackend.UpdateUser(r.Context(), nameOrID, *changes) if err != nil { + logger.Debug().Err(err).Str("id", nameOrID).Msg("could not update user: backend error") var errcode errorcode.Error if errors.As(err, &errcode) { errcode.Render(w, r) diff --git a/services/proxy/pkg/middleware/accesslog.go b/services/proxy/pkg/middleware/accesslog.go index 43d96e41b..ff5508f47 100644 --- a/services/proxy/pkg/middleware/accesslog.go +++ b/services/proxy/pkg/middleware/accesslog.go @@ -19,7 +19,7 @@ func AccessLog(logger log.Logger) func(http.Handler) http.Handler { logger.Info(). Str("proto", r.Proto). - Str("request", chimiddleware.GetReqID(r.Context())). + Str(log.RequestIDString, chimiddleware.GetReqID(r.Context())). Str("remote-addr", r.RemoteAddr). Str("method", r.Method). Int("status", wrap.Status()). diff --git a/services/thumbnails/pkg/service/http/v0/service.go b/services/thumbnails/pkg/service/http/v0/service.go index 8b201658c..428986a3a 100644 --- a/services/thumbnails/pkg/service/http/v0/service.go +++ b/services/thumbnails/pkg/service/http/v0/service.go @@ -73,11 +73,12 @@ func (s Thumbnails) ServeHTTP(w http.ResponseWriter, r *http.Request) { // GetThumbnail implements the Service interface. func (s Thumbnails) GetThumbnail(w http.ResponseWriter, r *http.Request) { + logger := s.logger.SubloggerWithRequestID(r.Context()) key := r.Context().Value(keyContextKey).(string) thumbnail, err := s.manager.GetThumbnail(key) if err != nil { - s.logger.Error(). + logger.Debug(). Err(err). Str("key", key). Msg("could not get the thumbnail") @@ -88,7 +89,7 @@ func (s Thumbnails) GetThumbnail(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) w.Header().Set("Content-Length", strconv.Itoa(len(thumbnail))) if _, err = w.Write(thumbnail); err != nil { - s.logger.Error(). + logger.Error(). Err(err). Str("key", key). Msg("could not write the thumbnail response") @@ -97,6 +98,7 @@ func (s Thumbnails) GetThumbnail(w http.ResponseWriter, r *http.Request) { func (s Thumbnails) TransferTokenValidator(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + logger := s.logger.SubloggerWithRequestID(r.Context()) tokenString := r.Header.Get("Transfer-Token") token, err := jwt.ParseWithClaims(tokenString, &tjwt.ThumbnailClaims{}, func(token *jwt.Token) (interface{}, error) { if _, ok := token.Method.(*jwt.SigningMethodHMAC); !ok { @@ -105,7 +107,7 @@ func (s Thumbnails) TransferTokenValidator(next http.Handler) http.Handler { return []byte(s.config.Thumbnail.TransferSecret), nil }) if err != nil { - s.logger.Error(). + logger.Debug(). Err(err). Str("transfer-token", tokenString). Msg("failed to parse transfer token") @@ -118,6 +120,7 @@ func (s Thumbnails) TransferTokenValidator(next http.Handler) http.Handler { next.ServeHTTP(w, r.WithContext(ctx)) return } + logger.Debug().Msg("invalid transfer token") w.WriteHeader(http.StatusUnauthorized) }) } diff --git a/services/webdav/pkg/service/v0/search.go b/services/webdav/pkg/service/v0/search.go index 6c5a3d66c..d53969fe5 100644 --- a/services/webdav/pkg/service/v0/search.go +++ b/services/webdav/pkg/service/v0/search.go @@ -31,16 +31,17 @@ const ( // Search is the endpoint for retrieving search results for REPORT requests func (g Webdav) Search(w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) rep, err := readReport(r.Body) if err != nil { renderError(w, r, errBadRequest(err.Error())) - g.log.Error().Err(err).Msg("error reading report") + logger.Debug().Err(err).Msg("error reading report") return } if rep.SearchFiles == nil { renderError(w, r, errBadRequest("missing search-files tag")) - g.log.Error().Err(err).Msg("error reading report") + logger.Debug().Err(err).Msg("error reading report") return } @@ -58,7 +59,7 @@ func (g Webdav) Search(w http.ResponseWriter, r *http.Request) { space := strings.TrimPrefix(r.URL.Path, "/dav/spaces/") rid, err := storagespace.ParseID(space) if err != nil { - g.log.Error().Err(err).Msg("error parsing the space id for filtering") + logger.Debug().Err(err).Msg("error parsing the space id for filtering") } else { req.Ref = &searchmsg.Reference{ ResourceId: &searchmsg.ResourceID{ @@ -79,7 +80,7 @@ func (g Webdav) Search(w http.ResponseWriter, r *http.Request) { default: renderError(w, r, errInternalError(err.Error())) } - g.log.Error().Err(err).Msg("could not get search results") + logger.Error().Err(err).Msg("could not get search results") return } @@ -87,9 +88,10 @@ func (g Webdav) Search(w http.ResponseWriter, r *http.Request) { } func (g Webdav) sendSearchResponse(rsp *searchsvc.SearchResponse, w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) responsesXML, err := multistatusResponse(r.Context(), rsp.Matches) if err != nil { - g.log.Error().Err(err).Msg("error formatting propfind") + logger.Error().Err(err).Msg("error formatting propfind") w.WriteHeader(http.StatusInternalServerError) return } @@ -100,7 +102,7 @@ func (g Webdav) sendSearchResponse(rsp *searchsvc.SearchResponse, w http.Respons } w.WriteHeader(http.StatusMultiStatus) if _, err := w.Write(responsesXML); err != nil { - g.log.Err(err).Msg("error writing response") + logger.Err(err).Msg("error writing response") } } diff --git a/services/webdav/pkg/service/v0/service.go b/services/webdav/pkg/service/v0/service.go index 13e74c906..1daa30deb 100644 --- a/services/webdav/pkg/service/v0/service.go +++ b/services/webdav/pkg/service/v0/service.go @@ -209,9 +209,10 @@ func (g Webdav) WebDAVContext() func(next http.Handler) http.Handler { // SpacesThumbnail is the endpoint for retrieving thumbnails inside of spaces. func (g Webdav) SpacesThumbnail(w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) tr, err := requests.ParseThumbnailRequest(r) if err != nil { - g.log.Error().Err(err).Msg("could not create Request") + logger.Debug().Err(err).Msg("could not create Request") renderError(w, r, errBadRequest(err.Error())) return } @@ -242,7 +243,7 @@ func (g Webdav) SpacesThumbnail(w http.ResponseWriter, r *http.Request) { default: renderError(w, r, errInternalError(err.Error())) } - g.log.Error().Err(err).Msg("could not get thumbnail") + logger.Debug().Err(err).Msg("could not get thumbnail") return } @@ -251,9 +252,10 @@ func (g Webdav) SpacesThumbnail(w http.ResponseWriter, r *http.Request) { // Thumbnail implements the Service interface. func (g Webdav) Thumbnail(w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) tr, err := requests.ParseThumbnailRequest(r) if err != nil { - g.log.Error().Err(err).Msg("could not create Request") + logger.Debug().Err(err).Msg("could not create Request") renderError(w, r, errBadRequest(err.Error())) return } @@ -267,8 +269,13 @@ func (g Webdav) Thumbnail(w http.ResponseWriter, r *http.Request) { userRes, err := g.revaClient.WhoAmI(r.Context(), &gatewayv1beta1.WhoAmIRequest{ Token: t, }) - if err != nil || userRes.Status.Code != rpcv1beta1.Code_CODE_OK { - g.log.Error().Err(err).Msg("could not get user") + if err != nil { + logger.Error().Err(err).Msg("could not get user: transport error") + renderError(w, r, errInternalError("could not get user")) + return + } + if userRes.Status.Code != rpcv1beta1.Code_CODE_OK { + logger.Debug().Str("grpcmessage", userRes.GetStatus().GetMessage()).Msg("could not get user") renderError(w, r, errInternalError("could not get user")) return } @@ -280,8 +287,13 @@ func (g Webdav) Thumbnail(w http.ResponseWriter, r *http.Request) { Claim: "username", Value: tr.Identifier, }) - if err != nil || userRes.Status.Code != rpcv1beta1.Code_CODE_OK { - g.log.Error().Err(err).Msg("could not get user") + if err != nil { + logger.Error().Err(err).Msg("could not get user: transport error") + renderError(w, r, errInternalError("could not get user")) + return + } + if userRes.Status.Code != rpcv1beta1.Code_CODE_OK { + logger.Debug().Str("grpcmessage", userRes.GetStatus().GetMessage()).Msg("could not get user") renderError(w, r, errInternalError("could not get user")) return } @@ -321,9 +333,10 @@ func (g Webdav) Thumbnail(w http.ResponseWriter, r *http.Request) { } func (g Webdav) PublicThumbnail(w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) tr, err := requests.ParseThumbnailRequest(r) if err != nil { - g.log.Error().Err(err).Msg("could not create Request") + logger.Debug().Err(err).Msg("could not create Request") renderError(w, r, errBadRequest(err.Error())) return } @@ -361,9 +374,10 @@ func (g Webdav) PublicThumbnail(w http.ResponseWriter, r *http.Request) { } func (g Webdav) PublicThumbnailHead(w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) tr, err := requests.ParseThumbnailRequest(r) if err != nil { - g.log.Error().Err(err).Msg("could not create Request") + logger.Debug().Err(err).Msg("could not create Request") renderError(w, r, errBadRequest(err.Error())) return } @@ -393,7 +407,7 @@ func (g Webdav) PublicThumbnailHead(w http.ResponseWriter, r *http.Request) { default: renderError(w, r, errInternalError(err.Error())) } - g.log.Error().Err(err).Msg("could not get thumbnail") + logger.Debug().Err(err).Msg("could not get thumbnail") return } @@ -401,6 +415,7 @@ func (g Webdav) PublicThumbnailHead(w http.ResponseWriter, r *http.Request) { } func (g Webdav) sendThumbnailResponse(rsp *thumbnailssvc.GetThumbnailResponse, w http.ResponseWriter, r *http.Request) { + logger := g.log.SubloggerWithRequestID(r.Context()) client := &http.Client{ // Timeout: time.Second * 5, } @@ -408,7 +423,7 @@ func (g Webdav) sendThumbnailResponse(rsp *thumbnailssvc.GetThumbnailResponse, w dlReq, err := http.NewRequest(http.MethodGet, rsp.DataEndpoint, http.NoBody) if err != nil { renderError(w, r, errInternalError(err.Error())) - g.log.Error().Err(err).Msg("could not download thumbnail") + logger.Error().Err(err).Msg("could not create download thumbnail request") return } dlReq.Header.Set("Transfer-Token", rsp.TransferToken) @@ -416,13 +431,13 @@ func (g Webdav) sendThumbnailResponse(rsp *thumbnailssvc.GetThumbnailResponse, w dlRsp, err := client.Do(dlReq) if err != nil { renderError(w, r, errInternalError(err.Error())) - g.log.Error().Err(err).Msg("could not download thumbnail") + logger.Error().Err(err).Msg("could not download thumbnail: transport error") return } defer dlRsp.Body.Close() if dlRsp.StatusCode != http.StatusOK { - g.log.Error(). + logger.Debug(). Str("transfer_token", rsp.TransferToken). Str("data_endpoint", rsp.DataEndpoint). Str("response_status", dlRsp.Status). @@ -435,7 +450,7 @@ func (g Webdav) sendThumbnailResponse(rsp *thumbnailssvc.GetThumbnailResponse, w w.Header().Set("Content-Type", rsp.Mimetype) _, err = io.Copy(w, dlRsp.Body) if err != nil { - g.log.Error().Err(err).Msg("failed to write thumbnail to response writer") + logger.Error().Err(err).Msg("failed to write thumbnail to response writer") } }