Switch to more flexible go-logging
authorJan Dittberner <jandd@cacert.org>
Sat, 22 Apr 2017 18:07:39 +0000 (20:07 +0200)
committerJan Dittberner <jandd@cacert.org>
Sat, 22 Apr 2017 18:07:39 +0000 (20:07 +0200)
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
boardvoting.go
jobs.go
models.go
notifications.go
templates/closed_motion_mail.txt

index 848c586..5f67428 100644 (file)
@@ -1,5 +1,6 @@
 *.crt
 *.key
+*.log
 *.pem
 *.sqlite
 .*.swp
index 1e62908..28278c0 100644 (file)
@@ -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("<root>=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 (file)
--- 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 {
index 35511ed..1c8bd7a 100644 (file)
--- 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
index 5061a2a..02d814d 100644 (file)
@@ -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 := &notificationClosedDecision{voteSums: *voteSums}
+func NewNotificationClosedDecision(decision *Decision, voteSums *VoteSums, reasoning string) NotificationMail {
+       notification := &notificationClosedDecision{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()},
index ee6bd45..b1b6a24 100644 (file)
@@ -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}}