From 4d23b6a48f26485f6c33d7948970191bd9357471 Mon Sep 17 00:00:00 2001 From: Jan Dittberner Date: Sat, 22 Apr 2017 20:07:39 +0200 Subject: [PATCH] Switch to more flexible go-logging This commit switches from loggo to the more flexible go-logging framework. Logs of severity INFO or higher are now written to a separate boardvoting.log file. Errors during execution of mail templates are now logged. A reasoning for the vote result is now logged and put into the mail notification when a decision is closed. --- .gitignore | 1 + boardvoting.go | 181 +++++++++------ jobs.go | 26 +-- models.go | 378 ++++++++++++++----------------- notifications.go | 23 +- templates/closed_motion_mail.txt | 6 +- 6 files changed, 309 insertions(+), 306 deletions(-) diff --git a/.gitignore b/.gitignore index 848c586..5f67428 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ *.crt *.key +*.log *.pem *.sqlite .*.swp diff --git a/boardvoting.go b/boardvoting.go index 1e62908..28278c0 100644 --- a/boardvoting.go +++ b/boardvoting.go @@ -11,12 +11,13 @@ import ( "github.com/Masterminds/sprig" "github.com/gorilla/sessions" "github.com/jmoiron/sqlx" - "github.com/juju/loggo" _ "github.com/mattn/go-sqlite3" + "github.com/op/go-logging" "gopkg.in/yaml.v2" "html/template" "io/ioutil" "net/http" + "os" "strconv" "strings" "time" @@ -26,7 +27,7 @@ var config *Config var store *sessions.CookieStore var version = "undefined" var build = "undefined" -var logger loggo.Logger +var log *logging.Logger const sessionCookieName = "votesession" @@ -239,16 +240,16 @@ func getVoteFromRequest(r *http.Request) (vote VoteChoice, ok bool) { type FlashMessageAction struct{} -func (a *FlashMessageAction) AddFlash(w http.ResponseWriter, r *http.Request, message interface{}, tags ...string) (err error) { +func (a *FlashMessageAction) AddFlash(w http.ResponseWriter, r *http.Request, message interface{}, tags ...string) { session, err := store.Get(r, sessionCookieName) if err != nil { - logger.Errorf("getting session failed: %s", err) + log.Errorf("getting session failed: %v", err) return } session.AddFlash(message, tags...) session.Save(r, w) if err != nil { - logger.Errorf("saving session failed: %s", err) + log.Errorf("saving session failed: %v", err) return } return @@ -282,17 +283,14 @@ func (a *withDrawMotionAction) Handle(w http.ResponseWriter, r *http.Request) { decision.Status = voteStatusWithdrawn decision.Modified = time.Now().UTC() if err := decision.UpdateStatus(); err != nil { - logger.Errorf("withdrawing motion failed: %s", err) + log.Errorf("withdrawing motion failed: %v", err) http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) return } NotifyMailChannel <- NewNotificationWithDrawMotion(&(decision.Decision), voter) - if err := a.AddFlash(w, r, fmt.Sprintf("Motion %s has been withdrawn!", decision.Tag)); err != nil { - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - return - } + a.AddFlash(w, r, fmt.Sprintf("Motion %s has been withdrawn!", decision.Tag)) http.Redirect(w, r, "/motions/", http.StatusTemporaryRedirect) default: @@ -335,17 +333,14 @@ func (h *newMotionHandler) Handle(w http.ResponseWriter, r *http.Request) { data.Proposed = time.Now().UTC() data.ProponentId = voter.Id if err := data.Create(); err != nil { - logger.Errorf("saving motion failed: %s", err) - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) + log.Errorf("saving motion failed: %v", err) + http.Error(w, "Saving motion failed", http.StatusInternalServerError) return } NotifyMailChannel <- &NotificationCreateMotion{decision: *data, voter: *voter} - if err := h.AddFlash(w, r, "The motion has been proposed!"); err != nil { - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - return - } + h.AddFlash(w, r, "The motion has been proposed!") http.Redirect(w, r, "/motions/", http.StatusMovedPermanently) } @@ -400,17 +395,14 @@ func (a editMotionAction) Handle(w http.ResponseWriter, r *http.Request) { } else { data.Modified = time.Now().UTC() if err := data.Update(); err != nil { - logger.Errorf("updating motion failed: %s", err) - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) + log.Errorf("updating motion failed: %v", err) + http.Error(w, "Updating the motion failed.", http.StatusInternalServerError) return } NotifyMailChannel <- NewNotificationUpdateMotion(*data, *voter) - if err := a.AddFlash(w, r, "The motion has been modified!"); err != nil { - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - return - } + a.AddFlash(w, r, "The motion has been modified!") http.Redirect(w, r, "/motions/", http.StatusMovedPermanently) } @@ -500,17 +492,14 @@ func (h *directVoteHandler) Handle(w http.ResponseWriter, r *http.Request) { VoterId: voter.Id, Vote: vote, DecisionId: decision.Id, Voted: time.Now().UTC(), Notes: fmt.Sprintf("Direct Vote\n\n%s", getPEMClientCert(r))} if err := voteResult.Save(); err != nil { - logger.Errorf("Problem saving vote: %s", err) - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) + log.Errorf("Problem saving vote: %v", err) + http.Error(w, "Problem saving vote", http.StatusInternalServerError) return } NotifyMailChannel <- NewNotificationDirectVote(&decision.Decision, voter, voteResult) - if err := h.AddFlash(w, r, "Your vote has been registered."); err != nil { - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - return - } + h.AddFlash(w, r, "Your vote has been registered.") http.Redirect(w, r, "/motions/", http.StatusMovedPermanently) default: @@ -569,7 +558,7 @@ func (h *proxyVoteHandler) Handle(w http.ResponseWriter, r *http.Request) { if valid, voter, data, justification := form.Validate(); !valid { templateContext.Form = form templateContext.Decision = decision - if voters, err := GetVotersForProxy(proxy, &decision.Decision); err != nil { + if voters, err := GetVotersForProxy(proxy); err != nil { http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) return } else { @@ -584,17 +573,14 @@ func (h *proxyVoteHandler) Handle(w http.ResponseWriter, r *http.Request) { proxy.Name, justification, getPEMClientCert(r)) if err := data.Save(); err != nil { - logger.Errorf("Error saving vote: %s", err) + log.Errorf("Error saving vote: %s", err) http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) return } NotifyMailChannel <- NewNotificationProxyVote(&decision.Decision, proxy, voter, data, justification) - if err := h.AddFlash(w, r, "The vote has been registered."); err != nil { - http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) - return - } + h.AddFlash(w, r, "The vote has been registered.") http.Redirect(w, r, "/motions/", http.StatusMovedPermanently) } @@ -602,7 +588,7 @@ func (h *proxyVoteHandler) Handle(w http.ResponseWriter, r *http.Request) { default: templateContext.Form = ProxyVoteForm{} templateContext.Decision = decision - if voters, err := GetVotersForProxy(proxy, &decision.Decision); err != nil { + if voters, err := GetVotersForProxy(proxy); err != nil { http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) return } else { @@ -665,86 +651,147 @@ type Config struct { } `yaml:"mail_server"` } -func init() { - loggo.ConfigureLoggers("=ERROR; boardvoting=INFO") - logger = loggo.GetLogger("boardvoting") - logger.Infof("Logger initialized") +func setupLogging(ctx context.Context) { + log = logging.MustGetLogger("boardvoting") + consoleLogFormat := logging.MustStringFormatter(`%{color}%{time:20060102 15:04:05.000-0700} %{longfile} ▶ %{level:s} %{id:05d}%{color:reset} %{message}`) + fileLogFormat := logging.MustStringFormatter(`%{time:20060102 15:04:05.000-0700} %{level:s} %{id:05d} %{message}`) + + consoleBackend := logging.NewLogBackend(os.Stderr, "", 0) + + logfile, err := os.OpenFile("boardvoting.log", os.O_CREATE|os.O_APPEND|os.O_WRONLY, os.FileMode(0640)) + if err != nil { + panic("Could not open logfile") + } + + fileBackend := logging.NewLogBackend(logfile, "", 0) + fileBackendLeveled := logging.AddModuleLevel(logging.NewBackendFormatter(fileBackend, fileLogFormat)) + fileBackendLeveled.SetLevel(logging.INFO, "") + + logging.SetBackend(fileBackendLeveled, + logging.NewBackendFormatter(consoleBackend, consoleLogFormat)) + + go func() { + for range ctx.Done() { + if err = logfile.Close(); err != nil { + fmt.Fprintf(os.Stderr, "Problem closing the log file: %v", err) + } + } + }() + + log.Info("Setup logging") +} +func readConfig() { source, err := ioutil.ReadFile("config.yaml") if err != nil { - logger.Criticalf("Opening configuration file failed: %s", err) - panic(err) + log.Panicf("Opening configuration file failed: %v", err) } if err := yaml.Unmarshal(source, &config); err != nil { - logger.Criticalf("Loading configuration failed: %s", err) - panic(err) + log.Panicf("Loading configuration failed: %v", err) } cookieSecret, err := base64.StdEncoding.DecodeString(config.CookieSecret) if err != nil { - logger.Criticalf("Decoding cookie secret failed: %s", err) + log.Panicf("Decoding cookie secret failed: %v", err) panic(err) } if len(cookieSecret) < 32 { - logger.Criticalf("Cookie secret is less than 32 bytes long") - panic("Cookie secret too short") + log.Panic("Cookie secret is less than 32 bytes long") } store = sessions.NewCookieStore(cookieSecret) - logger.Infof("Read configuration") + log.Info("Read configuration") +} - db, err = sqlx.Open("sqlite3", config.DatabaseFile) +func setupDbConfig(ctx context.Context) { + database, err := sqlx.Open("sqlite3", config.DatabaseFile) if err != nil { - logger.Criticalf("Opening database failed: %s", err) - panic(err) + log.Panicf("Opening database failed: %v", err) } - logger.Infof("opened database connection") -} + db = NewDB(database) -func main() { - logger.Infof("CAcert Board Voting version %s, build %s", version, build) + go func() { + for range ctx.Done() { + if err := db.Close(); err != nil { + fmt.Fprintf(os.Stderr, "Problem closing the database: %v", err) + } + } + }() - defer db.Close() + log.Infof("opened database connection") +} +func setupNotifications(ctx context.Context) { quitMailChannel := make(chan int) go MailNotifier(quitMailChannel) - defer func() { quitMailChannel <- 1 }() + go func() { + for range ctx.Done() { + quitMailChannel <- 1 + } + }() +} + +func setupJobs(ctx context.Context) { quitChannel := make(chan int) go JobScheduler(quitChannel) - defer func() { quitChannel <- 1 }() + go func() { + for range ctx.Done() { + quitChannel <- 1 + } + }() +} + +func setupHandlers() { http.Handle("/motions/", http.StripPrefix("/motions/", motionsHandler{})) http.Handle("/newmotion/", motionsHandler{}) http.Handle("/proxy/", &decisionVoteHandler{}) http.Handle("/vote/", &decisionVoteHandler{}) http.Handle("/static/", http.FileServer(http.Dir("."))) http.Handle("/", http.RedirectHandler("/motions/", http.StatusMovedPermanently)) +} +func setupTLSConfig() (tlsConfig *tls.Config) { // load CA certificates for client authentication caCert, err := ioutil.ReadFile(config.ClientCACertificates) if err != nil { - logger.Criticalf("Error reading client certificate CAs", err) - panic(err) + log.Panicf("Error reading client certificate CAs %v", err) } caCertPool := x509.NewCertPool() if !caCertPool.AppendCertsFromPEM(caCert) { - logger.Criticalf("could not initialize client CA certificate pool") - panic("client certificate CA pool initialization failed") + log.Panic("could not initialize client CA certificate pool") } // setup HTTPS server - tlsConfig := &tls.Config{ + tlsConfig = &tls.Config{ ClientCAs: caCertPool, ClientAuth: tls.VerifyClientCertIfGiven, } tlsConfig.BuildNameToCertificate() + return +} + +func main() { + var stopAll func() + executionContext, stopAll := context.WithCancel(context.Background()) + setupLogging(executionContext) + readConfig() + setupDbConfig(executionContext) + setupNotifications(executionContext) + setupJobs(executionContext) + setupHandlers() + tlsConfig := setupTLSConfig() + + defer stopAll() + + log.Infof("CAcert Board Voting version %s, build %s", version, build) server := &http.Server{ Addr: ":8443", TLSConfig: tlsConfig, } - logger.Infof("Launching application on https://localhost%s/", server.Addr) + log.Infof("Launching application on https://localhost%s/", server.Addr) errs := make(chan error, 1) go func() { @@ -754,12 +801,10 @@ func main() { close(errs) }() - if err = server.ListenAndServeTLS(config.ServerCert, config.ServerKey); err != nil { - logger.Criticalf("ListenAndServerTLS failed: %s", err) - panic(err) + if err := server.ListenAndServeTLS(config.ServerCert, config.ServerKey); err != nil { + log.Panicf("ListenAndServerTLS failed: %v", err) } if err := <-errs; err != nil { - logger.Criticalf("ListenAndServe failed: %s", err) - panic(err) + log.Panicf("ListenAndServe failed: %v", err) } } diff --git a/jobs.go b/jobs.go index 8d0bf13..46ed7dc 100644 --- a/jobs.go +++ b/jobs.go @@ -22,19 +22,19 @@ func JobScheduler(quitChannel chan int) { JobIdCloseDecisions: NewCloseDecisionsJob(), JobIdRemindVotersJob: NewRemindVotersJob(), } - logger.Infof("started job scheduler") + log.Info("started job scheduler") for { select { case jobId := <-rescheduleChannel: job := jobs[jobId] - logger.Infof("reschedule job %s", job) + log.Infof("reschedule job %s", job) job.Schedule() case <-quitChannel: for _, job := range jobs { job.Stop() } - logger.Infof("stop job scheduler") + log.Info("stop job scheduler") return } } @@ -54,7 +54,7 @@ func (j *CloseDecisionsJob) Schedule() { var nextDue *time.Time nextDue, err := GetNextPendingDecisionDue() if err != nil { - logger.Errorf("Could not get next pending due date") + log.Error("Could not get next pending due date") if j.timer != nil { j.timer.Stop() j.timer = nil @@ -62,11 +62,11 @@ func (j *CloseDecisionsJob) Schedule() { return } if nextDue == nil { - logger.Infof("no next planned execution of CloseDecisionsJob") + log.Info("no next planned execution of CloseDecisionsJob") j.Stop() } else { - nextDue := nextDue.Add(time.Minute) - logger.Infof("scheduling CloseDecisionsJob for %s", nextDue) + nextDue := nextDue.Add(time.Second) + log.Infof("scheduling CloseDecisionsJob for %s", nextDue) when := nextDue.Sub(time.Now()) if j.timer != nil { j.timer.Reset(when) @@ -84,10 +84,10 @@ func (j *CloseDecisionsJob) Stop() { } func (j *CloseDecisionsJob) Run() { - logger.Infof("running CloseDecisionsJob") + log.Debug("running CloseDecisionsJob") err := CloseDecisions() if err != nil { - logger.Errorf("closing decisions %s", err) + log.Errorf("closing decisions %v", err) } rescheduleChannel <- JobIdCloseDecisions } @@ -109,7 +109,7 @@ func NewRemindVotersJob() *RemindVotersJob { func (j *RemindVotersJob) Schedule() { year, month, day := time.Now().UTC().Date() nextExecution := time.Date(year, month, day, 0, 0, 0, 0, time.UTC).AddDate(0, 0, 3) - logger.Infof("scheduling RemindVotersJob for %s", nextExecution) + log.Infof("scheduling RemindVotersJob for %s", nextExecution) when := nextExecution.Sub(time.Now()) if j.timer != nil { j.timer.Reset(when) @@ -126,19 +126,19 @@ func (j *RemindVotersJob) Stop() { } func (j *RemindVotersJob) Run() { - logger.Infof("running RemindVotersJob") + log.Info("running RemindVotersJob") defer func() { rescheduleChannel <- JobIdRemindVotersJob }() voters, err := GetReminderVoters() if err != nil { - logger.Errorf("problem getting voters %s", err) + log.Errorf("problem getting voters %v", err) return } for _, voter := range *voters { decisions, err := FindUnvotedDecisionsForVoter(&voter) if err != nil { - logger.Errorf("problem getting unvoted decisions") + log.Errorf("problem getting unvoted decisions: %v", err) return } if len(*decisions) > 0 { diff --git a/models.go b/models.go index 35511ed..1c8bd7a 100644 --- a/models.go +++ b/models.go @@ -106,7 +106,7 @@ WHERE decisions.status=0 AND :now > due`, SELECT due FROM decisions WHERE status=0 ORDER BY due LIMIT 1`, sqlGetVotersForProxy: ` SELECT id, name, reminder -FROM voters WHERE enabled=1 AND id != $1 AND id NOT IN (SELECT voter FROM votes WHERE decision=$2)`, +FROM voters WHERE enabled=1 AND id != $1`, sqlGetReminderVoters: ` SELECT id, name, reminder FROM voters WHERE enabled=1 AND reminder!='' AND reminder IS NOT NULL`, sqlFindUnvotedDecisionsForVoter: ` @@ -123,47 +123,6 @@ FROM votes WHERE decision=$1 AND voter=$2`, } -var db *sqlx.DB - -func init() { - failed_statements := make([]string, 0) - for _, sqlStatement := range sqlStatements { - var stmt *sqlx.Stmt - stmt, err := db.Preparex(sqlStatement) - if err != nil { - logger.Criticalf("ERROR parsing statement %s: %s", sqlStatement, err) - failed_statements = append(failed_statements, sqlStatement) - } - stmt.Close() - } - if len(failed_statements) > 0 { - panic(fmt.Sprintf("%d statements failed", len(failed_statements))) - } - - migrateConf := &goose.DBConf{ - MigrationsDir: config.MigrationsPath, - Env: "production", - Driver: goose.DBDriver{ - Name: "sqlite3", - OpenStr: config.DatabaseFile, - Import: "github.com/mattn/go-sqlite3", - Dialect: &goose.Sqlite3Dialect{}, - }, - } - - latest, err := goose.GetMostRecentDBVersion(migrateConf.MigrationsDir) - if err != nil { - logger.Criticalf("getting the most recent database repository version failed: %s", err) - panic(err) - } - - err = goose.RunMigrationsOnDb(migrateConf, migrateConf.MigrationsDir, latest, db.DB) - if err != nil { - logger.Criticalf("running database migration failed: %s", err) - panic(err) - } -} - type VoteType uint8 type VoteStatus int8 @@ -282,30 +241,86 @@ type Vote struct { Notes string } -func (v *Vote) Save() (err error) { - insertVoteStmt, err := db.PrepareNamed(sqlStatements[sqlCreateVote]) +type dbHandler struct { + db *sqlx.DB +} + +var db *dbHandler + +func NewDB(database *sqlx.DB) *dbHandler { + handler := &dbHandler{db: database} + failed_statements := make([]string, 0) + for _, sqlStatement := range sqlStatements { + var stmt *sqlx.Stmt + stmt, err := database.Preparex(sqlStatement) + if err != nil { + log.Criticalf("ERROR parsing statement %s: %s", sqlStatement, err) + failed_statements = append(failed_statements, sqlStatement) + } + stmt.Close() + } + if len(failed_statements) > 0 { + log.Panicf("%d statements failed to prepare", len(failed_statements)) + } + + migrateConf := &goose.DBConf{ + MigrationsDir: config.MigrationsPath, + Env: "production", + Driver: goose.DBDriver{ + Name: "sqlite3", + OpenStr: config.DatabaseFile, + Import: "github.com/mattn/go-sqlite3", + Dialect: &goose.Sqlite3Dialect{}, + }, + } + + latest, err := goose.GetMostRecentDBVersion(migrateConf.MigrationsDir) if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return + log.Panicf("getting the most recent database repository version failed: %v", err) } - defer insertVoteStmt.Close() - _, err = insertVoteStmt.Exec(v) + err = goose.RunMigrationsOnDb(migrateConf, migrateConf.MigrationsDir, latest, database.DB) if err != nil { - logger.Errorf("saving vote failed: %s", err) - return + log.Panicf("running database migration failed: %v", err) } + return handler +} + +func (d *dbHandler) Close() error { + return d.db.Close() +} + +func (d *dbHandler) getPreparedNamedStatement(statementKey sqlKey) *sqlx.NamedStmt { + statement, err := d.db.PrepareNamed(sqlStatements[statementKey]) + if err != nil { + log.Panicf("Preparing statement failed: %v", err) + } + return statement +} - getVoteStmt, err := db.Preparex(sqlStatements[sqlLoadVote]) +func (d *dbHandler) getPreparedStatement(statementKey sqlKey) *sqlx.Stmt { + statement, err := d.db.Preparex(sqlStatements[statementKey]) if err != nil { - logger.Errorf("preparing statement failed: %s", err) + log.Panicf("Preparing statement failed: %v", err) + } + return statement +} + +func (v *Vote) Save() (err error) { + insertVoteStmt := db.getPreparedNamedStatement(sqlCreateVote) + defer insertVoteStmt.Close() + + if _, err = insertVoteStmt.Exec(v); err != nil { + log.Errorf("saving vote failed: %v", err) return } + + getVoteStmt := db.getPreparedStatement(sqlLoadVote) defer getVoteStmt.Close() - err = getVoteStmt.Get(v, v.DecisionId, v.VoterId) - if err != nil { - logger.Errorf("getting inserted vote failed: %s", err) + if err = getVoteStmt.Get(v, v.DecisionId, v.VoterId); err != nil { + log.Errorf("getting inserted vote failed: %v", err) + return } return @@ -333,6 +348,17 @@ func (v *VoteSums) Percent() int { return v.Ayes * 100 / totalVotes } +func (v *VoteSums) CalculateResult(quorum int, majority int) (status VoteStatus, reasoning string) { + if v.VoteCount() < quorum { + status, reasoning = voteStatusDeclined, fmt.Sprintf("Needed quorum of %d has not been reached.", quorum) + } else if (v.Ayes / v.TotalVotes()) < (majority / 100) { + status, reasoning = voteStatusDeclined, fmt.Sprintf("Needed majority of %d%% has not been reached.", majority) + } else { + status, reasoning = voteStatusApproved, "Quorum and majority have been reached" + } + return +} + type VoteForDisplay struct { Vote Name string @@ -346,11 +372,7 @@ type DecisionForDisplay struct { } func FindDecisionForDisplayByTag(tag string) (decision *DecisionForDisplay, err error) { - decisionStmt, err := db.Preparex(sqlStatements[sqlLoadDecisionByTag]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + decisionStmt := db.getPreparedStatement(sqlLoadDecisionByTag) defer decisionStmt.Close() decision = &DecisionForDisplay{} @@ -359,7 +381,8 @@ func FindDecisionForDisplayByTag(tag string) (decision *DecisionForDisplay, err decision = nil err = nil } else { - logger.Errorf("getting motion %s failed: %v", tag, err) + log.Errorf("getting motion %s failed: %v", tag, err) + return } } decision.VoteSums, err = decision.Decision.VoteSums() @@ -374,13 +397,9 @@ func FindDecisionForDisplayByTag(tag string) (decision *DecisionForDisplay, err func FindDecisionsForDisplayOnPage(page int64, unvoted bool, voter *Voter) (decisions []*DecisionForDisplay, err error) { var decisionsStmt *sqlx.Stmt if unvoted && voter != nil { - decisionsStmt, err = db.Preparex(sqlStatements[sqlLoadUnvotedDecisions]) + decisionsStmt = db.getPreparedStatement(sqlLoadUnvotedDecisions) } else { - decisionsStmt, err = db.Preparex(sqlStatements[sqlLoadDecisions]) - } - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return + decisionsStmt = db.getPreparedStatement(sqlLoadDecisions) } defer decisionsStmt.Close() @@ -391,7 +410,7 @@ func FindDecisionsForDisplayOnPage(page int64, unvoted bool, voter *Voter) (deci rows, err = decisionsStmt.Queryx(page - 1) } if err != nil { - logger.Errorf("loading motions for page %d failed: %v", page, err) + log.Errorf("loading motions for page %d failed: %v", page, err) return } defer rows.Close() @@ -399,7 +418,7 @@ func FindDecisionsForDisplayOnPage(page int64, unvoted bool, voter *Voter) (deci for rows.Next() { var d DecisionForDisplay if err = rows.StructScan(&d); err != nil { - logger.Errorf("loading motions for page %d failed: %v", page, err) + log.Errorf("loading motions for page %d failed: %v", page, err) return } d.VoteSums, err = d.Decision.VoteSums() @@ -412,16 +431,12 @@ func FindDecisionsForDisplayOnPage(page int64, unvoted bool, voter *Voter) (deci } func (d *Decision) VoteSums() (sums *VoteSums, err error) { - votesStmt, err := db.Preparex(sqlStatements[sqlLoadVoteCountsForDecision]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + votesStmt := db.getPreparedStatement(sqlLoadVoteCountsForDecision) defer votesStmt.Close() voteRows, err := votesStmt.Queryx(d.Id) if err != nil { - logger.Errorf("fetching vote sums for motion %s failed: %v", d.Tag, err) + log.Errorf("fetching vote sums for motion %s failed: %v", d.Tag, err) return } defer voteRows.Close() @@ -431,7 +446,7 @@ func (d *Decision) VoteSums() (sums *VoteSums, err error) { var vote VoteChoice var count int if err = voteRows.Scan(&vote, &count); err != nil { - logger.Errorf("fetching vote sums for motion %s failed: %v", d.Tag, err) + log.Errorf("fetching vote sums for motion %s failed: %v", d.Tag, err) return } switch vote { @@ -447,39 +462,33 @@ func (d *Decision) VoteSums() (sums *VoteSums, err error) { } func (d *DecisionForDisplay) LoadVotes() (err error) { - votesStmt, err := db.Preparex(sqlStatements[sqlLoadVotesForDecision]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + votesStmt := db.getPreparedStatement(sqlLoadVotesForDecision) defer votesStmt.Close() + err = votesStmt.Select(&d.Votes, d.Id) if err != nil { - logger.Errorf("selecting votes for motion %s failed: %v", d.Tag, err) + log.Errorf("selecting votes for motion %s failed: %v", d.Tag, err) + return } return } func (d *Decision) OlderExists(unvoted bool, voter *Voter) (result bool, err error) { - var olderStmt *sqlx.Stmt if unvoted && voter != nil { - olderStmt, err = db.Preparex(sqlStatements[sqlCountOlderThanUnvotedDecision]) - } else { - olderStmt, err = db.Preparex(sqlStatements[sqlCountOlderThanDecision]) - } - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } - defer olderStmt.Close() + olderStmt := db.getPreparedStatement(sqlCountOlderThanUnvotedDecision) + defer olderStmt.Close() - if unvoted && voter != nil { if err = olderStmt.Get(&result, d.Proposed, voter.Id); err != nil { - logger.Errorf("finding older motions than %s failed: %v", d.Tag, err) + log.Errorf("finding older motions than %s failed: %v", d.Tag, err) + return } } else { + olderStmt := db.getPreparedStatement(sqlCountOlderThanDecision) + defer olderStmt.Close() + if err = olderStmt.Get(&result, d.Proposed); err != nil { - logger.Errorf("finding older motions than %s failed: %v", d.Tag, err) + log.Errorf("finding older motions than %s failed: %v", d.Tag, err) + return } } @@ -487,76 +496,62 @@ func (d *Decision) OlderExists(unvoted bool, voter *Voter) (result bool, err err } func (d *Decision) Create() (err error) { - insertDecisionStmt, err := db.PrepareNamed(sqlStatements[sqlCreateDecision]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + insertDecisionStmt := db.getPreparedNamedStatement(sqlCreateDecision) defer insertDecisionStmt.Close() result, err := insertDecisionStmt.Exec(d) if err != nil { - logger.Errorf("creating motion failed: %s", err) + log.Errorf("creating motion failed: %v", err) return } lastInsertId, err := result.LastInsertId() if err != nil { - logger.Errorf("getting id of inserted motion failed: %s", err) + log.Errorf("getting id of inserted motion failed: %v", err) return } rescheduleChannel <- JobIdCloseDecisions - getDecisionStmt, err := db.Preparex(sqlStatements[sqlLoadDecisionById]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getDecisionStmt := db.getPreparedStatement(sqlLoadDecisionById) defer getDecisionStmt.Close() err = getDecisionStmt.Get(d, lastInsertId) if err != nil { - logger.Errorf("getting inserted motion failed: %s", err) + log.Errorf("getting inserted motion failed: %v", err) + return } return } func (d *Decision) LoadWithId() (err error) { - getDecisionStmt, err := db.Preparex(sqlStatements[sqlLoadDecisionById]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getDecisionStmt := db.getPreparedStatement(sqlLoadDecisionById) defer getDecisionStmt.Close() err = getDecisionStmt.Get(d, d.Id) if err != nil { - logger.Errorf("loading updated motion failed: %s", err) + log.Errorf("loading updated motion failed: %v", err) + return } return } func (d *Decision) Update() (err error) { - updateDecisionStmt, err := db.PrepareNamed(sqlStatements[sqlUpdateDecision]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + updateDecisionStmt := db.getPreparedNamedStatement(sqlUpdateDecision) defer updateDecisionStmt.Close() result, err := updateDecisionStmt.Exec(d) if err != nil { - logger.Errorf("updating motion failed: %s", err) + log.Errorf("updating motion failed: %v", err) return } affectedRows, err := result.RowsAffected() if err != nil { - logger.Errorf("Problem determining the affected rows") + log.Error("Problem determining the affected rows") return } else if affectedRows != 1 { - logger.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) + log.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) } rescheduleChannel <- JobIdCloseDecisions @@ -565,24 +560,20 @@ func (d *Decision) Update() (err error) { } func (d *Decision) UpdateStatus() (err error) { - updateStatusStmt, err := db.PrepareNamed(sqlStatements[sqlUpdateDecisionStatus]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + updateStatusStmt := db.getPreparedNamedStatement(sqlUpdateDecisionStatus) defer updateStatusStmt.Close() result, err := updateStatusStmt.Exec(d) if err != nil { - logger.Errorf("setting motion status failed: %s", err) + log.Errorf("setting motion status failed: %v", err) return } affectedRows, err := result.RowsAffected() if err != nil { - logger.Errorf("determining the affected rows failed: %s", err) + log.Errorf("determining the affected rows failed: %v", err) return } else if affectedRows != 1 { - logger.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) + log.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) } rescheduleChannel <- JobIdCloseDecisions @@ -595,17 +586,13 @@ func (d *Decision) String() string { } func FindVoterByAddress(emailAddress string) (voter *Voter, err error) { - findVoterStmt, err := db.Preparex(sqlStatements[sqlLoadEnabledVoterByEmail]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + findVoterStmt := db.getPreparedStatement(sqlLoadEnabledVoterByEmail) defer findVoterStmt.Close() voter = &Voter{} if err = findVoterStmt.Get(voter, emailAddress); err != nil { if err != sql.ErrNoRows { - logger.Errorf("getting voter for address %s failed: %v", emailAddress, err) + log.Errorf("getting voter for address %s failed: %v", emailAddress, err) } else { err = nil voter = nil @@ -614,72 +601,56 @@ func FindVoterByAddress(emailAddress string) (voter *Voter, err error) { return } -func (d *Decision) Close() (err error) { +func (d *Decision) Close() error { quorum, majority := d.VoteType.QuorumAndMajority() - voteSums, err := d.VoteSums() - - if err != nil { - logger.Errorf("getting vote sums failed: %s", err) - return - } - votes := voteSums.VoteCount() + var voteSums *VoteSums + var err error - if votes < quorum { - d.Status = voteStatusDeclined - } else { - votes = voteSums.TotalVotes() - if (voteSums.Ayes / votes) > (majority / 100) { - d.Status = voteStatusApproved - } else { - d.Status = voteStatusDeclined - } + if voteSums, err = d.VoteSums(); err != nil { + log.Errorf("getting vote sums failed: %v", err) + return err } + var reasoning string + d.Status, reasoning = voteSums.CalculateResult(quorum, majority) - closeDecisionStmt, err := db.PrepareNamed(sqlStatements[sqlUpdateDecisionStatus]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + closeDecisionStmt := db.getPreparedNamedStatement(sqlUpdateDecisionStatus) defer closeDecisionStmt.Close() result, err := closeDecisionStmt.Exec(d) if err != nil { - logger.Errorf("closing vote failed: %s", err) - return - } - affectedRows, err := result.RowsAffected() - if err != nil { - logger.Errorf("getting affected rows failed: %s", err) + log.Errorf("closing vote failed: %v", err) + return err } - if affectedRows != 1 { - logger.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) + if affectedRows, err := result.RowsAffected(); err != nil { + log.Errorf("getting affected rows failed: %v", err) + return err + } else if affectedRows != 1 { + log.Warningf("wrong number of affected rows: %d (1 expected)", affectedRows) } - NotifyMailChannel <- NewNotificationClosedDecision(d, voteSums) + NotifyMailChannel <- NewNotificationClosedDecision(d, voteSums, reasoning) - return + log.Infof("decision %s closed with result %s: reasoning %s", d.Tag, d.Status, reasoning) + + return nil } func CloseDecisions() (err error) { - getClosableDecisionsStmt, err := db.PrepareNamed(sqlStatements[sqlSelectClosableDecisions]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getClosableDecisionsStmt := db.getPreparedNamedStatement(sqlSelectClosableDecisions) defer getClosableDecisionsStmt.Close() decisions := make([]*Decision, 0) rows, err := getClosableDecisionsStmt.Queryx(struct{ Now time.Time }{time.Now().UTC()}) if err != nil { - logger.Errorf("fetching closable decisions failed: %s", err) + log.Errorf("fetching closable decisions failed: %v", err) return } defer rows.Close() for rows.Next() { decision := &Decision{} if err = rows.StructScan(decision); err != nil { - logger.Errorf("scanning row failed: %s", err) + log.Errorf("scanning row failed: %v", err) return } decisions = append(decisions, decision) @@ -687,9 +658,9 @@ func CloseDecisions() (err error) { rows.Close() for _, decision := range decisions { - logger.Debugf("found closable decision %s", decision.Tag) + log.Debugf("found closable decision %s", decision.Tag) if err = decision.Close(); err != nil { - logger.Errorf("closing decision %s failed: %s", decision.Tag, err) + log.Errorf("closing decision %s failed: %s", decision.Tag, err) return } } @@ -698,41 +669,32 @@ func CloseDecisions() (err error) { } func GetNextPendingDecisionDue() (due *time.Time, err error) { - getNextPendingDecisionDueStmt, err := db.Preparex(sqlStatements[sqlGetNextPendingDecisionDue]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getNextPendingDecisionDueStmt := db.getPreparedStatement(sqlGetNextPendingDecisionDue) defer getNextPendingDecisionDueStmt.Close() row := getNextPendingDecisionDueStmt.QueryRow() - var dueTimestamp time.Time - if err = row.Scan(&dueTimestamp); err != nil { + due = &time.Time{} + if err = row.Scan(due); err != nil { if err == sql.ErrNoRows { - logger.Debugf("No pending decisions") + log.Debug("No pending decisions") return nil, nil } - logger.Errorf("parsing result failed: %s", err) - return + log.Errorf("parsing result failed: %v", err) + return nil, err } - due = &dueTimestamp return } func GetReminderVoters() (voters *[]Voter, err error) { - getReminderVotersStmt, err := db.Preparex(sqlStatements[sqlGetReminderVoters]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getReminderVotersStmt := db.getPreparedStatement(sqlGetReminderVoters) defer getReminderVotersStmt.Close() voterSlice := make([]Voter, 0) if err = getReminderVotersStmt.Select(&voterSlice); err != nil { - logger.Errorf("getting voters failed: %s", err) + log.Errorf("getting voters failed: %v", err) return } voters = &voterSlice @@ -741,17 +703,13 @@ func GetReminderVoters() (voters *[]Voter, err error) { } func FindUnvotedDecisionsForVoter(voter *Voter) (decisions *[]Decision, err error) { - findUnvotedDecisionsForVoterStmt, err := db.Preparex(sqlStatements[sqlFindUnvotedDecisionsForVoter]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + findUnvotedDecisionsForVoterStmt := db.getPreparedStatement(sqlFindUnvotedDecisionsForVoter) defer findUnvotedDecisionsForVoterStmt.Close() decisionsSlice := make([]Decision, 0) if err = findUnvotedDecisionsForVoterStmt.Select(&decisionsSlice, voter.Id); err != nil { - logger.Errorf("getting unvoted decisions failed: %s", err) + log.Errorf("getting unvoted decisions failed: %v", err) return } decisions = &decisionsSlice @@ -760,34 +718,26 @@ func FindUnvotedDecisionsForVoter(voter *Voter) (decisions *[]Decision, err erro } func GetVoterById(id int64) (voter *Voter, err error) { - getVoterByIdStmt, err := db.Preparex(sqlStatements[sqlGetEnabledVoterById]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } + getVoterByIdStmt := db.getPreparedStatement(sqlGetEnabledVoterById) defer getVoterByIdStmt.Close() voter = &Voter{} if err = getVoterByIdStmt.Get(voter, id); err != nil { - logger.Errorf("getting voter failed: %s", err) + log.Errorf("getting voter failed: %v", err) return } return } -func GetVotersForProxy(proxy *Voter, decision *Decision) (voters *[]Voter, err error) { - getVotersForProxyStmt, err := db.Preparex(sqlStatements[sqlGetVotersForProxy]) - if err != nil { - logger.Errorf("preparing statement failed: %s", err) - return - } +func GetVotersForProxy(proxy *Voter) (voters *[]Voter, err error) { + getVotersForProxyStmt := db.getPreparedStatement(sqlGetVotersForProxy) defer getVotersForProxyStmt.Close() votersSlice := make([]Voter, 0) - if err = getVotersForProxyStmt.Select(&votersSlice, proxy.Id, decision.Id); err != nil { - logger.Errorf("Error getting voters for proxy failed: %s", err) + if err = getVotersForProxyStmt.Select(&votersSlice, proxy.Id); err != nil { + log.Errorf("Error getting voters for proxy failed: %v", err) return } voters = &votersSlice diff --git a/notifications.go b/notifications.go index 5061a2a..02d814d 100644 --- a/notifications.go +++ b/notifications.go @@ -34,14 +34,14 @@ type NotificationMail interface { var NotifyMailChannel = make(chan NotificationMail, 1) func MailNotifier(quitMailNotifier chan int) { - logger.Infof("Launched mail notifier") + log.Info("Launched mail notifier") for { select { case notification := <-NotifyMailChannel: content := notification.GetNotificationContent() mailText, err := buildMail(content.template, content.data) if err != nil { - logger.Errorf("building mail failed: %s", err) + log.Errorf("building mail failed: %v", err) continue } @@ -58,10 +58,10 @@ func MailNotifier(quitMailNotifier chan int) { d := gomail.NewDialer(config.MailServer.Host, config.MailServer.Port, "", "") if err := d.DialAndSend(m); err != nil { - logger.Errorf("sending mail failed: %s", err) + log.Errorf("sending mail failed: %v", err) } case <-quitMailNotifier: - logger.Infof("Ending mail notifier") + log.Info("Ending mail notifier") return } } @@ -75,7 +75,10 @@ func buildMail(templateName string, context interface{}) (mailText *bytes.Buffer } mailText = bytes.NewBufferString("") - t.Execute(mailText, context) + if err := t.Execute(mailText, context); err != nil { + log.Errorf("Failed to execute template %s with context %+v: %v", templateName, context, err) + return nil, err + } return } @@ -108,11 +111,12 @@ func (n *decisionReplyBase) getSubject() string { type notificationClosedDecision struct { notificationBase decisionReplyBase - voteSums VoteSums + voteSums VoteSums + reasoning string } -func NewNotificationClosedDecision(decision *Decision, voteSums *VoteSums) NotificationMail { - notification := ¬ificationClosedDecision{voteSums: *voteSums} +func NewNotificationClosedDecision(decision *Decision, voteSums *VoteSums, reasoning string) NotificationMail { + notification := ¬ificationClosedDecision{voteSums: *voteSums, reasoning: reasoning} notification.decision = *decision return notification } @@ -123,7 +127,8 @@ func (n *notificationClosedDecision) GetNotificationContent() *notificationConte data: struct { *Decision *VoteSums - }{&n.decision, &n.voteSums}, + Reasoning string + }{&n.decision, &n.voteSums, n.reasoning}, subject: fmt.Sprintf("Re: %s - %s - finalised", n.decision.Tag, n.decision.Title), headers: n.decisionReplyBase.getHeaders(), recipients: []recipientData{n.notificationBase.getRecipient()}, diff --git a/templates/closed_motion_mail.txt b/templates/closed_motion_mail.txt index ee6bd45..b1b6a24 100644 --- a/templates/closed_motion_mail.txt +++ b/templates/closed_motion_mail.txt @@ -1,8 +1,10 @@ Dear Board, -{{ with .Decision }}The motion with the identifier {{.Tag}} has been {{.Status}}. +{{ with .Decision }}The motion with the identifier {{.Tag}} has been {{.Status}}.{{ end }} -Motion: +The reasoning for this result is: {{ .Reasoning }} + +{{ with .Decision }}Motion: {{.Title}} {{.Content}}