diff --git a/CHANGELOG.md b/CHANGELOG.md index ad991e71..f4f49cb7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -49,6 +49,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed - Sending the account expiry email is done when user has only valid e-mail addresses +- Strip unnecessary details from database errors ### Fixed - User account expiry continues when one or more e-mail addresses are marked for revalidation diff --git a/irma/cmd/keyshare-myirma.go b/irma/cmd/keyshare-myirma.go index e0def7cc..64da4ca5 100644 --- a/irma/cmd/keyshare-myirma.go +++ b/irma/cmd/keyshare-myirma.go @@ -111,7 +111,7 @@ func configureMyirmaServer(cmd *cobra.Command) (*myirmaserver.Configuration, err DBType: myirmaserver.DBType(viper.GetString("db_type")), DBConnStr: viper.GetString("db_str"), DBConnMaxIdle: viper.GetInt("db_max_idle"), - DBMConnMaxOpen: viper.GetInt("db_max_open"), + DBConnMaxOpen: viper.GetInt("db_max_open"), DBConnMaxIdleTime: viper.GetInt("db_max_idle_time"), DBConnMaxOpenTime: viper.GetInt("db_max_open_time"), diff --git a/revocation_db.go b/revocation_db.go index 20dd601a..36947ab9 100644 --- a/revocation_db.go +++ b/revocation_db.go @@ -21,6 +21,8 @@ import ( "gorm.io/gorm/schema" ) +var errRevocationDB = errors.New("revocation database error") + type ( revocationUpdateHead struct { SignedAccumulator *revocation.SignedAccumulator @@ -178,6 +180,10 @@ func (s sqlRevStorage) Close() error { func (s sqlRevStorage) Exists(id CredentialTypeIdentifier, pkCounter uint) (bool, error) { var c int64 err := s.gorm.Model((*AccumulatorRecord)(nil)).Where(map[string]interface{}{"cred_type": id, "pk_counter": pkCounter}).Count(&c).Error + if err != nil { + Logger.WithError(err).Error("Failed to check if accumulator exists in database") + return false, errRevocationDB + } return c > 0, err } @@ -188,7 +194,8 @@ func (s sqlRevStorage) Events(id CredentialTypeIdentifier, pkCounter uint, from, "cred_type = ? and pk_counter = ? and eventindex >= ? and eventindex < ?", id, pkCounter, from, to, ).Error; err != nil { - return nil, err + Logger.WithError(err).Error("Failed to retrieve revocation events from database") + return nil, errRevocationDB } if len(records) == 0 { return nil, ErrRevocationStateNotFound @@ -236,7 +243,8 @@ func (s sqlRevStorage) LatestAccumulatorUpdates(id CredentialTypeIdentifier, pkC } return nil }); err != nil { - return nil, err + Logger.WithError(err).Error("Failed to retrieve latest accumulator updates from database") + return nil, errRevocationDB } return newUpdates(accsMap, eventsMap), nil @@ -271,7 +279,7 @@ func (s sqlRevStorage) AppendAccumulatorUpdate( id CredentialTypeIdentifier, handler func(heads map[uint]revocationUpdateHead) (map[uint]*revocation.Update, error), ) error { - return s.gorm.Transaction(func(tx *gorm.DB) error { + if err := s.gorm.Transaction(func(tx *gorm.DB) error { // Retrieve the current accumulator state for every public key of the credential and lock the rows for update. var accs []*AccumulatorRecord @@ -317,12 +325,20 @@ func (s sqlRevStorage) AppendAccumulatorUpdate( } } return nil - }) + }); err != nil { + Logger.WithError(err).Error("Failed to append accumulator update to database") + return errRevocationDB + } + return nil } // AddIssuanceRecord implements revocationRecordStorage interface. func (s sqlRevStorage) AddIssuanceRecord(r *IssuanceRecord) error { - return s.gorm.Create(r).Error + if err := s.gorm.Create(r).Error; err != nil { + Logger.WithError(err).Error("Failed to add issuance record to database") + return errRevocationDB + } + return nil } // IssuanceRecord implements revocationRecordStorage interface. @@ -345,7 +361,8 @@ func (s sqlRevStorage) UpdateIssuanceRecord(id CredentialTypeIdentifier, key str for _, r := range records { if err := tx.Save(r).Error; err != nil { - return err + Logger.WithError(err).Error("Failed to update issuance record in database") + return errRevocationDB } } return nil @@ -354,7 +371,11 @@ func (s sqlRevStorage) UpdateIssuanceRecord(id CredentialTypeIdentifier, key str // DeleteExpiredIssuanceRecords implements revocationRecordStorage interface. func (s sqlRevStorage) DeleteExpiredIssuanceRecords() error { - return s.gorm.Delete(IssuanceRecord{}, "valid_until < ?", time.Now().UnixNano()).Error + if err := s.gorm.Delete(IssuanceRecord{}, "valid_until < ?", time.Now().UnixNano()).Error; err != nil { + Logger.WithError(err).Error("Failed to delete expired issuance records from database") + return errRevocationDB + } + return nil } // txIssuanceRecords returns all issuance records matching the given credential type, revocation key and issuance time within @@ -367,7 +388,8 @@ func txIssuanceRecords(tx *gorm.DB, id CredentialTypeIdentifier, key string, iss var r []*IssuanceRecord if err := tx.Find(&r, where).Error; err != nil { - return nil, err + Logger.WithError(err).Error("Failed to retrieve issuance records from database") + return nil, errRevocationDB } if len(r) == 0 { return nil, ErrUnknownRevocationKey diff --git a/server/api.go b/server/api.go index 8a458af9..7b8e47a2 100644 --- a/server/api.go +++ b/server/api.go @@ -375,8 +375,8 @@ func DoResultCallback(callbackUrl string, result *SessionResult, issuer string, } } -func log(level logrus.Level, err error) error { - writer := Logger.WithFields(logrus.Fields{"err": TypeString(err)}).WriterLevel(level) +func log(level logrus.Level, err error, msg ...string) error { + writer := Logger.WithFields(logrus.Fields{"err": TypeString(err), "msg": strings.Join(msg, " ")}).WriterLevel(level) if e, ok := err.(*errors.Error); ok && Logger.IsLevelEnabled(logrus.DebugLevel) { _, _ = writer.Write([]byte(e.ErrorStack())) } else { @@ -385,8 +385,8 @@ func log(level logrus.Level, err error) error { return err } -func LogFatal(err error) error { - logger := Logger.WithFields(logrus.Fields{"err": TypeString(err)}) +func LogFatal(err error, msg ...string) error { + logger := Logger.WithFields(logrus.Fields{"err": TypeString(err), "msg": strings.Join(msg, " ")}) // using log() for this doesn't seem to do anything if e, ok := err.(*errors.Error); ok && Logger.IsLevelEnabled(logrus.DebugLevel) { logger.Fatal(e.ErrorStack()) @@ -396,12 +396,12 @@ func LogFatal(err error) error { return err } -func LogError(err error) error { - return log(logrus.ErrorLevel, err) +func LogError(err error, msg ...string) error { + return log(logrus.ErrorLevel, err, msg...) } -func LogWarning(err error) error { - return log(logrus.WarnLevel, err) +func LogWarning(err error, msg ...string) error { + return log(logrus.WarnLevel, err, msg...) } func LogRequest(typ, proto, method, url, from string, headers http.Header, message []byte) { diff --git a/server/keyshare/errors.go b/server/keyshare/errors.go index ad5f8983..2e61a657 100644 --- a/server/keyshare/errors.go +++ b/server/keyshare/errors.go @@ -12,6 +12,7 @@ var ( // Database errors: ErrUserNotFound = errors.New("could not find specified user") + ErrDB = errors.New("database error") // Email errors: @@ -31,6 +32,8 @@ func WriteError(w http.ResponseWriter, err error) { switch err { case ErrUserNotFound: serverError = server.ErrorUserNotRegistered + case ErrDB: + serverError = server.ErrorInternal case ErrInvalidEmail: serverError = server.ErrorInvalidRequest case ErrInvalidEmailDomain: diff --git a/server/keyshare/keyshareserver/legacy.go b/server/keyshare/keyshareserver/legacy.go index 9f1e3b96..4eea5f16 100644 --- a/server/keyshare/keyshareserver/legacy.go +++ b/server/keyshare/keyshareserver/legacy.go @@ -13,7 +13,6 @@ import ( "github.com/privacybydesign/irmago/internal/keysharecore" "github.com/privacybydesign/irmago/server" "github.com/privacybydesign/irmago/server/keyshare" - "github.com/sirupsen/logrus" ) // /users/register_publickey @@ -41,7 +40,7 @@ func (s *Server) handleRegisterPublicKey(w http.ResponseWriter, r *http.Request) // Fetch user user, err := s.db.user(r.Context(), claims.Username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": claims.Username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -79,17 +78,13 @@ func (s *Server) registerPublicKey(ctx context.Context, user *User, pin string, } user.Secrets = UserSecrets(secrets) - // Mark pincheck as success, resetting users wait and count - err = s.db.resetPinTries(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not reset users pin check logic") - // Do not send to user - } + // Mark pincheck as success, resetting users wait and count. Do not send error to user. + _ = s.db.resetPinTries(ctx, user) // Write user back err = s.db.updateUser(ctx, user) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not write updated user to database") + // Already logged return irma.KeysharePinStatus{}, err } @@ -127,17 +122,13 @@ func (s *Server) updatePinLegacy(ctx context.Context, user *User, oldPin, newPin } user.Secrets = UserSecrets(secrets) - // Mark pincheck as success, resetting users wait and count - err = s.db.resetPinTries(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not reset users pin check logic") - // Do not send to user - } + // Mark pincheck as success, resetting users wait and count. Do not send error to user. + _ = s.db.resetPinTries(ctx, user) // Write user back err = s.db.updateUser(ctx, user) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not write updated user to database") + // Already logged return irma.KeysharePinStatus{}, err } @@ -148,7 +139,7 @@ func (s *Server) handleChangePinLegacy(ctx context.Context, w http.ResponseWrite username := msg.Username user, err := s.db.user(ctx, username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -156,7 +147,7 @@ func (s *Server) handleChangePinLegacy(ctx context.Context, w http.ResponseWrite result, err := s.updatePinLegacy(ctx, user, msg.OldPin, msg.NewPin) if err != nil { - // already logged + // Already logged keyshare.WriteError(w, err) return } diff --git a/server/keyshare/keyshareserver/postgresdb.go b/server/keyshare/keyshareserver/postgresdb.go index 47d1f0a5..b28a2efd 100644 --- a/server/keyshare/keyshareserver/postgresdb.go +++ b/server/keyshare/keyshareserver/postgresdb.go @@ -8,6 +8,7 @@ import ( "github.com/go-errors/errors" "github.com/privacybydesign/irmago/internal/common" + "github.com/privacybydesign/irmago/server" "github.com/privacybydesign/irmago/server/keyshare" ) @@ -61,19 +62,22 @@ func (db *postgresDB) AddUser(ctx context.Context, user *User) error { user.Secrets, time.Now().Unix()) if err != nil { - return err + server.LogError(err, "Failed to add user") + return keyshare.ErrDB } defer common.Close(res) if !res.Next() { if err = res.Err(); err != nil { - return err + server.LogError(err, "Failed to prepare results of add user query") + return keyshare.ErrDB } return errUserAlreadyExists } var id int64 err = res.Scan(&id) if err != nil { - return err + server.LogError(err, "Failed to scan for user id after adding user") + return keyshare.ErrDB } user.id = id return nil @@ -88,20 +92,31 @@ func (db *postgresDB) user(ctx context.Context, username string) (*User, error) username, ) if err != nil { - return nil, err + server.LogError(err, "Failed to query user") + if err == keyshare.ErrUserNotFound { + return nil, err + } + return nil, keyshare.ErrDB } return &result, nil } func (db *postgresDB) updateUser(ctx context.Context, user *User) error { - return db.db.ExecUserContext( + if err := db.db.ExecUserContext( ctx, "UPDATE irma.users SET username = $1, language = $2, coredata = $3 WHERE id=$4", user.Username, user.Language, user.Secrets, user.id, - ) + ); err != nil { + server.LogError(err, "Failed to update user") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB + } + return nil } func (db *postgresDB) reservePinTry(ctx context.Context, user *User) (bool, int, int64, error) { @@ -120,7 +135,8 @@ func (db *postgresDB) reservePinTry(ctx context.Context, user *User) (bool, int, maxPinTries-1, user.id) if err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to reserve pin try") + return false, 0, 0, keyshare.ErrDB } defer common.Close(uprows) @@ -131,24 +147,28 @@ func (db *postgresDB) reservePinTry(ctx context.Context, user *User) (bool, int, ) if !uprows.Next() { if err = uprows.Err(); err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to prepare results of pin try query") + return false, 0, 0, keyshare.ErrDB } // if no results, then account either does not exist (which would be weird here) or is blocked // so request wait timeout pinrows, err := db.db.QueryContext(ctx, "SELECT pin_block_date FROM irma.users WHERE id=$1 AND coredata IS NOT NULL", user.id) if err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to query pin block date") + return false, 0, 0, keyshare.ErrDB } defer common.Close(pinrows) if !pinrows.Next() { if err = pinrows.Err(); err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to prepare results of pin block date query") + return false, 0, 0, keyshare.ErrDB } return false, 0, 0, keyshare.ErrUserNotFound } err = pinrows.Scan(&wait) if err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to scan for pin block date") + return false, 0, 0, keyshare.ErrDB } } else { // Pin check is allowed (implied since there is a result, so pinBlockDate <= now) @@ -156,7 +176,8 @@ func (db *postgresDB) reservePinTry(ctx context.Context, user *User) (bool, int, allowed = true err = uprows.Scan(&tries, &wait) if err != nil { - return false, 0, 0, err + server.LogError(err, "Failed to scan for pin counter and block date") + return false, 0, 0, keyshare.ErrDB } tries = maxPinTries - tries if tries < 0 { @@ -172,18 +193,25 @@ func (db *postgresDB) reservePinTry(ctx context.Context, user *User) (bool, int, } func (db *postgresDB) resetPinTries(ctx context.Context, user *User) error { - return db.db.ExecUserContext( + if err := db.db.ExecUserContext( ctx, "UPDATE irma.users SET pin_counter = 0, pin_block_date = 0 WHERE id = $1", user.id, - ) + ); err != nil { + server.LogError(err, "Failed to reset pin tries") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB + } + return nil } func (db *postgresDB) setSeen(ctx context.Context, user *User) error { // If the user is scheduled for deletion (delete_on is not null), undo that by resetting // delete_on back to null, but only if the user did not explicitly delete her account herself // in the myIRMA website, in which case coredata is null. - return db.db.ExecUserContext( + if err := db.db.ExecUserContext( ctx, `UPDATE irma.users SET last_seen = $1, @@ -193,7 +221,14 @@ func (db *postgresDB) setSeen(ctx context.Context, user *User) error { END WHERE id = $2`, time.Now().Unix(), user.id, - ) + ); err != nil { + server.LogError(err, "Failed to update last seen") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB + } + return nil } func (db *postgresDB) addLog(ctx context.Context, user *User, eventType eventType, param interface{}) error { @@ -212,7 +247,11 @@ func (db *postgresDB) addLog(ctx context.Context, user *User, eventType eventTyp eventType, encodedParamString, user.id) - return err + if err != nil { + server.LogError(err, "Failed to add log entry") + return keyshare.ErrDB + } + return nil } func (db *postgresDB) addEmailVerification(ctx context.Context, user *User, emailAddress, token string, validity int) error { @@ -224,7 +263,11 @@ func (db *postgresDB) addEmailVerification(ctx context.Context, user *User, emai emailAddress, maxPrevExpiry.Unix()) if err != nil { - return err + server.LogError(err, "Failed to count email verification tokens") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB } if amount >= emailTokenRateLimit { return errTooManyTokens @@ -235,5 +278,9 @@ func (db *postgresDB) addEmailVerification(ctx context.Context, user *User, emai emailAddress, user.id, expiry.Unix()) + if err != nil { + server.LogError(err, "Failed to add email verification token") + return keyshare.ErrDB + } return err } diff --git a/server/keyshare/keyshareserver/server.go b/server/keyshare/keyshareserver/server.go index ce9874af..3ece4252 100644 --- a/server/keyshare/keyshareserver/server.go +++ b/server/keyshare/keyshareserver/server.go @@ -17,7 +17,6 @@ import ( "github.com/privacybydesign/gabi/big" "github.com/privacybydesign/gabi/signed" irma "github.com/privacybydesign/irmago" - "github.com/sirupsen/logrus" "github.com/privacybydesign/irmago/internal/common" "github.com/privacybydesign/irmago/internal/keysharecore" @@ -284,17 +283,13 @@ func (s *Server) generateResponse(ctx context.Context, user *User, authorization return "", errMissingCommitment } - // Indicate activity on user account - err := s.db.setSeen(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not mark user as seen recently") - // Do not send to user - } + // Indicate activity on user account. Do not send error to user. + _ = s.db.setSeen(ctx, user) // Make log entry - err = s.db.addLog(ctx, user, eventTypeIRMASession, nil) + err := s.db.addLog(ctx, user, eventTypeIRMASession, nil) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not add log entry for user") + // Already logged return "", err } @@ -328,7 +323,7 @@ func (s *Server) handleVerifyStart(w http.ResponseWriter, r *http.Request) { // Fetch user user, err := s.db.user(r.Context(), claims.Username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": claims.Username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -389,7 +384,7 @@ func (s *Server) handleVerify(w http.ResponseWriter, r *http.Request) { // Fetch user user, err := s.db.user(r.Context(), username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -433,13 +428,13 @@ func (s *Server) verifyAuth(ctx context.Context, user *User, msg irma.KeyshareAu // Handle invalid pin err = s.db.addLog(ctx, user, eventTypePinCheckFailed, tries) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not add log entry for user") + // Already logged return irma.KeysharePinStatus{}, err } if tries == 0 { err = s.db.addLog(ctx, user, eventTypePinCheckBlocked, wait) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not add log entry for user") + // Already logged return irma.KeysharePinStatus{}, err } return irma.KeysharePinStatus{Status: "error", Message: fmt.Sprintf("%v", wait)}, nil @@ -448,20 +443,14 @@ func (s *Server) verifyAuth(ctx context.Context, user *User, msg irma.KeyshareAu } } - // Handle success - err = s.db.resetPinTries(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not reset users pin check logic") - // Do not send to user - } - err = s.db.setSeen(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not indicate user activity") - // Do not send to user - } + // Handle success. Do not send error to user. + _ = s.db.resetPinTries(ctx, user) + + // Do not send error to user. + _ = s.db.setSeen(ctx, user) + err = s.db.addLog(ctx, user, eventTypePinCheckSuccess, nil) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not add log entry for user") return irma.KeysharePinStatus{}, err } @@ -495,7 +484,7 @@ func (s *Server) handleChangePin(w http.ResponseWriter, r *http.Request) { user, err := s.db.user(r.Context(), claims.Username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": claims.Username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -554,17 +543,13 @@ func (s *Server) updatePin(ctx context.Context, user *User, jwtt string) (irma.K } user.Secrets = UserSecrets(secrets) - // Mark pincheck as success, resetting users wait and count - err = s.db.resetPinTries(ctx, user) - if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not reset users pin check logic") - // Do not send to user - } + // Mark pincheck as success, resetting users wait and count. Do not send error to user. + _ = s.db.resetPinTries(ctx, user) // Write user back err = s.db.updateUser(ctx, user) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not write updated user to database") + // Already logged return irma.KeysharePinStatus{}, err } @@ -631,7 +616,7 @@ func (s *Server) register(ctx context.Context, msg irma.KeyshareEnrollment) (*ir user := &User{Username: username, Language: data.Language, Secrets: UserSecrets(secrets)} err = s.db.AddUser(ctx, user) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not store new user in database") + // Already logged return nil, err } @@ -666,10 +651,7 @@ func (s *Server) sendRegistrationEmail(ctx context.Context, user *User, language // Add it to the database err := s.db.addEmailVerification(ctx, user, email, token, s.conf.EmailTokenValidity) if err != nil { - // Rate limiting errors do not need logging. - if err != errTooManyTokens { - s.conf.Logger.WithField("error", err).Error("Could not generate email verification mail record") - } + // Already logged return err } @@ -691,7 +673,7 @@ func (s *Server) userMiddleware(next http.Handler) http.Handler { // and fetch its information user, err := s.db.user(r.Context(), username) if err != nil { - s.conf.Logger.WithFields(logrus.Fields{"username": username, "error": err}).Warn("Could not find user in db") + // Already logged keyshare.WriteError(w, err) return } @@ -723,13 +705,13 @@ func (s *Server) authorizationMiddleware(next http.Handler) http.Handler { func (s *Server) reservePinCheck(ctx context.Context, user *User) (bool, int, int64, error) { ok, tries, wait, err := s.db.reservePinTry(ctx, user) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not reserve pin check slot") + // Already logged return false, 0, 0, err } if !ok { err = s.db.addLog(ctx, user, eventTypePinCheckRefused, nil) if err != nil { - s.conf.Logger.WithField("error", err).Error("Could not add log entry for user") + // Already logged return false, 0, 0, err } return false, tries, wait, nil diff --git a/server/keyshare/myirmaserver/conf.go b/server/keyshare/myirmaserver/conf.go index 2b329a6d..262b1430 100644 --- a/server/keyshare/myirmaserver/conf.go +++ b/server/keyshare/myirmaserver/conf.go @@ -39,7 +39,7 @@ type Configuration struct { DBType DBType `json:"db_type" mapstructure:"db_type"` DBConnStr string `json:"db_str" mapstructure:"db_str"` DBConnMaxIdle int `json:"db_max_idle" mapstructure:"db_max_idle"` - DBMConnMaxOpen int `json:"db_max_open" mapstructure:"db_max_open"` + DBConnMaxOpen int `json:"db_max_open" mapstructure:"db_max_open"` DBConnMaxIdleTime int `json:"db_max_idle_time" mapstructure:"db_max_idle_time"` DBConnMaxOpenTime int `json:"db_max_open_time" mapstructure:"db_max_open_time"` // DeleteDelay is the delay in days before a user or email address deletion becomes effective. @@ -131,7 +131,7 @@ func processConfiguration(conf *Configuration) error { case DBTypePostgres: conf.DB, err = newPostgresDB(conf.DBConnStr, conf.DBConnMaxIdle, - conf.DBMConnMaxOpen, + conf.DBConnMaxOpen, time.Duration(conf.DBConnMaxIdleTime)*time.Second, time.Duration(conf.DBConnMaxOpenTime)*time.Second, ) diff --git a/server/keyshare/myirmaserver/postgresdb.go b/server/keyshare/myirmaserver/postgresdb.go index c4553765..a9991fc6 100644 --- a/server/keyshare/myirmaserver/postgresdb.go +++ b/server/keyshare/myirmaserver/postgresdb.go @@ -45,7 +45,14 @@ func newPostgresDB(connstring string, maxIdleConns, maxOpenConns int, maxIdleTim func (db *postgresDB) userIDByUsername(ctx context.Context, username string) (int64, error) { var id int64 - return id, db.db.QueryUserContext(ctx, "SELECT id FROM irma.users WHERE username = $1", []interface{}{&id}, username) + if err := db.db.QueryUserContext(ctx, "SELECT id FROM irma.users WHERE username = $1", []interface{}{&id}, username); err != nil { + server.LogError(err, "Failed to query user id by username") + if err == keyshare.ErrUserNotFound { + return 0, err + } + return 0, keyshare.ErrDB + } + return id, nil } func (db *postgresDB) verifyEmailToken(ctx context.Context, token string) (int64, error) { @@ -57,10 +64,12 @@ func (db *postgresDB) verifyEmailToken(ctx context.Context, token string) (int64 []interface{}{&id, &email}, token, time.Now().Unix()) if err == sql.ErrNoRows { + server.Logger.Info("Unknown email verification token") return 0, errTokenNotFound } if err != nil { - return 0, err + server.LogError(err, "Failed to query email verification token") + return 0, keyshare.ErrDB } err = db.addEmail(ctx, id, email) @@ -82,9 +91,17 @@ func (db *postgresDB) verifyEmailToken(ctx context.Context, token string) (int64 } func (db *postgresDB) scheduleUserRemoval(ctx context.Context, id int64, delay time.Duration) error { - return db.db.ExecUserContext(ctx, "UPDATE irma.users SET coredata = NULL, delete_on = $2 WHERE id = $1 AND coredata IS NOT NULL", + if err := db.db.ExecUserContext(ctx, "UPDATE irma.users SET coredata = NULL, delete_on = $2 WHERE id = $1 AND coredata IS NOT NULL", id, - time.Now().Add(delay).Unix()) + time.Now().Add(delay).Unix(), + ); err != nil { + server.LogError(err, "Failed to schedule user removal") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB + } + return nil } func (db *postgresDB) addLoginToken(ctx context.Context, email, token string) error { @@ -95,7 +112,8 @@ func (db *postgresDB) addLoginToken(ctx context.Context, email, token string) er return errEmailNotFound } if err != nil { - return err + server.LogError(err, "Failed to query email address while adding login token") + return keyshare.ErrDB } expiry := time.Now().Add(emailTokenValidity * time.Minute) @@ -106,7 +124,8 @@ func (db *postgresDB) addLoginToken(ctx context.Context, email, token string) er email, maxPrevExpiry.Unix()) if err != nil { - return err + server.LogError(err, "Failed to check rate limiting while adding login token") + return keyshare.ErrDB } if amount > 0 { return errTooManyTokens @@ -118,7 +137,8 @@ func (db *postgresDB) addLoginToken(ctx context.Context, email, token string) er email, expiry.Unix()) if err != nil { - return err + server.LogError(err, "Failed to insert login token") + return keyshare.ErrDB } if aff != 1 { return errors.Errorf("Unexpected number of affected rows %d on token insert", aff) @@ -142,7 +162,8 @@ func (db *postgresDB) loginUserCandidates(ctx context.Context, token string) ([] }, token, time.Now().Unix()) if err != nil { - return nil, err + server.LogError(err, "Failed to query login candidates") + return nil, keyshare.ErrDB } if len(candidates) == 0 { return nil, errTokenNotFound @@ -162,12 +183,14 @@ func (db *postgresDB) verifyLoginToken(ctx context.Context, token, username stri return 0, errTokenNotFound } if err != nil { - return 0, err + server.LogError(err, "Failed to query login token") + return 0, keyshare.ErrDB } aff, err := db.db.ExecCountContext(ctx, "DELETE FROM irma.email_login_tokens WHERE token = $1", token) if err != nil { - return 0, err + server.LogError(err, "Failed to delete login token") + return 0, keyshare.ErrDB } if aff != 1 { return 0, errors.Errorf("Unexpected number of affected rows %d for token removal", aff) @@ -184,7 +207,11 @@ func (db *postgresDB) user(ctx context.Context, id int64) (user, error) { []interface{}{&result.Username, &result.language, &result.DeleteInProgress}, id) if err != nil { - return user{}, err + server.LogError(err, "Failed to query user") + if err == keyshare.ErrUserNotFound { + return user{}, err + } + return user{}, keyshare.ErrDB } query := "SELECT email, (delete_on IS NOT NULL) AS delete_in_progress {{revalidate}} FROM irma.emails WHERE user_id = $1 AND (delete_on >= $2 OR delete_on IS NULL)" @@ -213,7 +240,8 @@ func (db *postgresDB) user(ctx context.Context, id int64) (user, error) { }, id, time.Now().Unix()) if err != nil { - return user{}, err + server.LogError(err, "Failed to query user emails") + return user{}, keyshare.ErrDB } return result, nil } @@ -231,7 +259,8 @@ func (db *postgresDB) logs(ctx context.Context, id int64, offset, amount int) ([ }, id, offset, amount) if err != nil { - return nil, err + server.LogError(err, "Failed to query user logs") + return nil, keyshare.ErrDB } return result, nil } @@ -240,7 +269,8 @@ func (db *postgresDB) addEmail(ctx context.Context, id int64, email string) erro // Try to restore email in process of deletion aff, err := db.db.ExecCountContext(ctx, "UPDATE irma.emails SET delete_on = NULL WHERE user_id = $1 AND email = $2", id, email) if err != nil { - return err + server.LogError(err, "Failed to restore email in process of deletion") + return keyshare.ErrDB } if aff > 1 { return errors.Errorf("Unexpected number of affected rows %d for email adding", aff) @@ -250,8 +280,11 @@ func (db *postgresDB) addEmail(ctx context.Context, id int64, email string) erro } // Fall back to adding new one - _, err = db.db.ExecContext(ctx, "INSERT INTO irma.emails (user_id, email) VALUES ($1, $2)", id, email) - return err + if _, err = db.db.ExecContext(ctx, "INSERT INTO irma.emails (user_id, email) VALUES ($1, $2)", id, email); err != nil { + server.LogError(err, "Failed to add email") + return keyshare.ErrDB + } + return nil } func (db *postgresDB) scheduleEmailRemoval(ctx context.Context, id int64, email string, delay time.Duration) error { @@ -260,7 +293,8 @@ func (db *postgresDB) scheduleEmailRemoval(ctx context.Context, id int64, email email, time.Now().Add(delay).Unix()) if err != nil { - return err + server.LogError(err, "Failed to schedule email removal") + return keyshare.ErrDB } if aff != 1 { return errors.Errorf("Unexpected number of affected rows %d for email removal", aff) @@ -272,7 +306,7 @@ func (db *postgresDB) setSeen(ctx context.Context, id int64) error { // If the user is scheduled for deletion (delete_on is not null), undo that by resetting // delete_on back to null, but only if the user did not explicitly delete her account herself // in the myIRMA website, in which case coredata is null. - return db.db.ExecUserContext( + if err := db.db.ExecUserContext( ctx, `UPDATE irma.users SET last_seen = $1, @@ -282,7 +316,14 @@ func (db *postgresDB) setSeen(ctx context.Context, id int64) error { END WHERE id = $2`, time.Now().Unix(), id, - ) + ); err != nil { + server.LogError(err, "Failed to set user last seen") + if err == keyshare.ErrUserNotFound { + return err + } + return keyshare.ErrDB + } + return nil } func (db *postgresDB) hasEmailRevalidation(ctx context.Context) bool { @@ -295,7 +336,8 @@ func (db *postgresDB) scheduleEmailRevalidation(ctx context.Context, id int64, e id, email) if err != nil { - return err + server.LogError(err, "Failed to schedule email revalidation") + return keyshare.ErrDB } if aff != 1 { return errors.Errorf("Unexpected number of affected rows %d for email revalidation", aff) @@ -308,7 +350,8 @@ func (db *postgresDB) setPinBlockDate(ctx context.Context, id int64, delay time. time.Now().Add(delay).Unix(), id) if err != nil { - return err + server.LogError(err, "Failed to set pin block date") + return keyshare.ErrDB } if aff != 1 { return errors.Errorf("Unexpected number of affected rows %d at setting pin_block_date", aff)