Switch to more flexible go-logging
[cacert-boardvoting.git] / boardvoting.go
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)
        }
 }