diff --git a/server/main.go b/server/main.go
index b8e12d5..2d797d1 100644
--- a/server/main.go
+++ b/server/main.go
@@ -8,7 +8,7 @@
// * However, it is presumed that a home page or profile page might contain a element analogous to the kind used to specify RSS feeds. A client scanning a web page for an associated board should look for elements with the type attribute set to text/board+html.
//
// * scan for links as specified in the spec
-// * implement event logs
+// * add unique request ID
package main
@@ -25,16 +25,20 @@ import (
"fmt"
"io/fs"
"io/ioutil"
- "log"
"math"
"net/http"
"os"
"regexp"
+ "runtime"
+ "runtime/debug"
"strings"
+ "syscall"
"text/template"
"time"
_ "github.com/mattn/go-sqlite3"
+ "github.com/rs/zerolog"
+ "github.com/rs/zerolog/log"
)
const MAX_KEY_64 = (1 << 64) - 1
@@ -48,6 +52,15 @@ var (
//go:embed templates/*
templateFS embed.FS
+
+ // information about the process, for logging
+ process = os.Args[0]
+ pid = syscall.Getpid()
+ goversion = runtime.Version()
+
+ // set by initRuntimeValues
+ vcsRevision string
+ vcsTime string
)
// getenv returns the environment variable given by the key if present,
@@ -60,20 +73,20 @@ func getenv(key string, adefault string) string {
return val
}
-func must(err error) {
+func must(err error, log zerolog.Logger) {
if err != nil {
- log.Fatal(err)
+ log.Fatal().Err(err).Msg("")
}
}
-func initDB() *sql.DB {
+func initDB(log zerolog.Logger) *sql.DB {
dbName := "./spring83.db"
// if the db doesn't exist, create it
if _, err := os.Stat(dbName); errors.Is(err, os.ErrNotExist) {
- log.Printf("initializing new database")
+ log.Info().Msg("initializing new database")
db, err := sql.Open("sqlite3", dbName)
- must(err)
+ must(err, log)
initSQL := `
CREATE TABLE boards (
@@ -86,20 +99,117 @@ func initDB() *sql.DB {
_, err = db.Exec(initSQL)
if err != nil {
- log.Fatal("%q: %s\n", err, initSQL)
+ log.Fatal().Msgf("%q: %s\n", err, initSQL)
}
return db
}
db, err := sql.Open("sqlite3", dbName)
- must(err)
+ must(err, log)
return db
}
+func initLog() zerolog.Logger {
+ logLevel := getenv("LOG_LEVEL", "info")
+ level, err := zerolog.ParseLevel(logLevel)
+ if err != nil {
+ log.Panic().Err(err).Msg("")
+ }
+
+ log := zerolog.New(os.Stderr).With().Timestamp().Logger().Level(level)
+ if getenv("PRETTY_LOGGING", "") != "" {
+ log = log.Output(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339})
+ }
+
+ return log
+}
+
+type responseRecorder struct {
+ http.ResponseWriter
+ status int
+}
+
+func (rec *responseRecorder) WriteHeader(code int) {
+ rec.status = code
+ rec.ResponseWriter.WriteHeader(code)
+}
+
+func requestLogger(log zerolog.Logger, next http.Handler) http.Handler {
+ return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+ rec := &responseRecorder{w, http.StatusOK}
+ t := time.Now()
+ next.ServeHTTP(rec, r)
+ log.Info().
+ Dur("duration", time.Since(t)).
+ Int("status", rec.status).
+ Str("method", r.Method).
+ Str("path", r.URL.Path).
+ Str("process", process).
+ Int("pid", pid).
+ Str("goversion", goversion).
+ Str("peer-ip", r.RemoteAddr).
+ Str("difficulty", w.Header().Get("Spring-Difficulty")).
+ Str("vcsRevision", vcsRevision).
+ Str("vcsTime", vcsTime).
+ Msg("Request served")
+ })
+}
+
+func initRuntimeValues(log zerolog.Logger) {
+ if bi, ok := debug.ReadBuildInfo(); !ok {
+ log.Fatal().Msg("Unable to get build info")
+ } else {
+ for i := range bi.Settings {
+ switch bi.Settings[i].Key {
+ case "vcs.revision":
+ vcsRevision = bi.Settings[i].Value
+ case "vcs.time":
+ vcsTime = bi.Settings[i].Value
+ }
+ }
+ }
+}
+
+func removeExpiredBoards(db *sql.DB, log zerolog.Logger) {
+ t := time.Now()
+ dt := t.Format(time.RFC3339)
+
+ // This should work because ISO datetimes are lexicographically ordered
+ res, err := db.Exec(`
+ DELETE FROM boards
+ WHERE expiry_datetime < ?
+ `, dt)
+ if err != nil {
+ log.Error().Err(err).Msg("Error inserting board")
+ }
+
+ rows, err := res.RowsAffected()
+ if err != nil {
+ log.Error().Err(err).Msg("Error inserting board")
+ }
+
+ log.Info().Int64("deleted", rows).Dur("duration", time.Since(t)).Msg("entries cleaned")
+}
+
+// initCleaner starts a goroutine that will delete any expired entries every 5 minutes
+func initCleaner(db *sql.DB, log zerolog.Logger) {
+ removeExpiredBoards(db, log)
+ ticker := time.NewTicker(5 * time.Minute)
+ go func() {
+ for {
+ <-ticker.C
+ removeExpiredBoards(db, log)
+ }
+ }()
+}
+
func main() {
- db := initDB()
+ log := initLog()
+ db := initDB(log)
+ initRuntimeValues(log)
+ initCleaner(db, log)
- server := newSpring83Server(db)
+ server := newSpring83Server(db, log)
host := getenv("HOST", "")
port := getenv("PORT", "8000")
@@ -112,11 +222,13 @@ func main() {
WriteTimeout: 1 * time.Second,
IdleTimeout: 30 * time.Second,
ReadHeaderTimeout: 2 * time.Second,
- Handler: http.TimeoutHandler(server, 2*time.Second, timeoutMsg),
+ Handler: requestLogger(log, http.TimeoutHandler(server, 2*time.Second, timeoutMsg)),
}
- log.Printf("starting helloserver on %s", addr)
- log.Fatal(srv.ListenAndServe())
+ log.Info().Str("addr", addr).Msg("starting helloserver on")
+ if err := srv.ListenAndServe(); err != http.ErrServerClosed {
+ log.Err(err).Msg("Error received from server")
+ }
}
func readTemplate(name string, fsys fs.FS) (string, error) {
@@ -141,14 +253,23 @@ func mustTemplate(name string, fsys fs.FS) *template.Template {
return t
}
+type Board struct {
+ Key string
+ Board string
+ Creation time.Time
+ Expiry time.Time
+}
+
type Spring83Server struct {
db *sql.DB
+ log zerolog.Logger
homeTemplate *template.Template
}
-func newSpring83Server(db *sql.DB) *Spring83Server {
+func newSpring83Server(db *sql.DB, log zerolog.Logger) *Spring83Server {
return &Spring83Server{
db: db,
+ log: log,
homeTemplate: mustTemplate("templates/index.html", templateFS),
}
}
@@ -249,7 +370,7 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
// curBoard is nil if there is no existing board for this key, and a Board object otherwise
curBoard, err := s.getBoard(keyStr)
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to get board")
http.Error(w, "internal error", http.StatusInternalServerError)
return
}
@@ -260,11 +381,12 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
if curBoard == nil {
difficultyFactor, keyThreshold, err := s.getDifficulty()
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to get difficulty")
http.Error(w, "internal error", http.StatusInternalServerError)
return
}
+ s.log.Info().Float64("diff", difficultyFactor).Msg("difficulty")
w.Header().Add("Spring-Difficulty", fmt.Sprintf("%f", difficultyFactor))
// If the server doesn't yet have any board stored for the key, then it
@@ -340,7 +462,7 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
last4 := string(keyStr[60:64])
last4Time, err := time.Parse("0106", last4)
if err != nil {
- log.Printf("Failed parsing last4 %s", last4)
+ s.log.Error().Str("last4", last4).Msg("Failed parsing last4")
http.Error(w, "Key must end with 83eMMYY", http.StatusBadRequest)
return
}
@@ -351,17 +473,17 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
twoYearsInHours := (365 * 2 * 24.0) + 31*24.0
timeDiff := time.Until(last4Time).Hours()
if keyStr[57:60] != "83e" {
- log.Printf("Expected 83e %s", string(keyStr[57:60]))
+ s.log.Error().Str("keyStr", keyStr[57:60]).Msg("Expected 83e")
http.Error(w, "Key must end with 83eMMYY", http.StatusBadRequest)
return
}
if timeDiff > twoYearsInHours {
- log.Printf("Too far in future %f", timeDiff)
+ s.log.Error().Float64("timeDiff", timeDiff).Msg("Key too far in future")
http.Error(w, "Key is not yet valid", http.StatusBadRequest)
return
}
if timeDiff < 0 {
- log.Printf("Key expired %f", timeDiff)
+ s.log.Error().Float64("timeDiff", timeDiff).Msg("Key expired")
http.Error(w, "Key is expired", http.StatusBadRequest)
return
}
@@ -383,28 +505,29 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
// future.
match := TIME_RE.Find(body)
if match == nil {
- log.Printf("no time element in body: %s %v", body, body)
+ s.log.Error().Bytes("body", body).Msg("No time element in body")
http.Error(w, "Missing time element in body", http.StatusBadRequest)
return
}
if len(match) != 38 {
- log.Printf("match: %s len %d != 38", match, len(match))
+ s.log.Error().Bytes("match", match).Int("len", len(match)).Msg("invalid match length")
http.Error(w, "Invalid time element in body", http.StatusBadRequest)
return
}
bodyTime, err := time.Parse(time.RFC3339, string(match[16:36]))
if err != nil {
- log.Printf("Unable to parse: %s", match[16:36])
+ s.log.Error().Bytes("matchtime", match[16:36]).Msg("Unable to parse")
http.Error(w, "Invalid time element in body", http.StatusBadRequest)
return
}
if time.Now().Before(bodyTime) {
- log.Printf("Future time: %v", bodyTime)
+ s.log.Error().Time("bodyTime", bodyTime).Msg("Future time")
http.Error(w, "Future times are not allowed", http.StatusBadRequest)
return
}
if curBoard != nil && bodyTime.Before(curBoard.Creation) {
+ s.log.Error().Time("bodyTime", bodyTime).Msg("Old content")
http.Error(w, "Old content", http.StatusConflict)
return
}
@@ -421,18 +544,11 @@ func (s *Spring83Server) publishBoard(w http.ResponseWriter, r *http.Request) {
`, keyStr, body, bodyTimeISO, expiry, body, bodyTimeISO, expiry)
if err != nil {
- log.Printf("%s", err)
+ s.log.Error().Err(err).Msg("Error inserting board")
http.Error(w, "Server error", http.StatusInternalServerError)
}
}
-type Board struct {
- Key string
- Board string
- Creation time.Time
- Expiry time.Time
-}
-
func (s *Spring83Server) loadBoards() ([]Board, error) {
query := `
SELECT key, board, creation_datetime, expiry_datetime
@@ -488,14 +604,14 @@ func randstr() string {
func (s *Spring83Server) showAllBoards(w http.ResponseWriter, r *http.Request) {
boards, err := s.loadBoards()
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to load boards")
http.Error(w, "Unable to load boards", http.StatusInternalServerError)
return
}
difficultyFactor, _, err := s.getDifficulty()
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to get difficulty")
http.Error(w, "internal error", http.StatusInternalServerError)
return
}
@@ -517,7 +633,7 @@ func (s *Spring83Server) showAllBoards(w http.ResponseWriter, r *http.Request) {
boardBytes, err := json.Marshal(boards)
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to marshal boards")
http.Error(w, "Unable to marshal boards", http.StatusInternalServerError)
return
}
@@ -536,7 +652,7 @@ func (s *Spring83Server) showAllBoards(w http.ResponseWriter, r *http.Request) {
func (s *Spring83Server) showBoard(w http.ResponseWriter, r *http.Request) {
board, err := s.getBoard(r.URL.Path[1:])
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Str("path: ", r.URL.Path).Msg("Unable to get board")
http.Error(w, "Unable to load boards", http.StatusInternalServerError)
return
}
@@ -550,7 +666,7 @@ func (s *Spring83Server) showBoard(w http.ResponseWriter, r *http.Request) {
difficultyFactor, _, err := s.getDifficulty()
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to get difficulty")
http.Error(w, "internal error", http.StatusInternalServerError)
return
}
@@ -566,7 +682,7 @@ func (s *Spring83Server) showBoard(w http.ResponseWriter, r *http.Request) {
boardBytes, err := json.Marshal([]*Board{board})
if err != nil {
- log.Print(err.Error())
+ s.log.Err(err).Msg("Unable to marshal board")
http.Error(w, "Unable to marshal boards", http.StatusInternalServerError)
return
}