Implement structured logging (#232)

* Implement structured logging

* Remove debug

* Log additional information for ncoming requests

pkg/server/api/handlers/auth.go

@@ -53,8 +53,6 @@ type Session struct {
 func makeSession(user database.User, account database.Account) Session {
 	legacy := account.AuthKeyHash == ""
 
-	log.Printf("account is %+v", account)
-
 	return Session{
 		// TODO: remove ID and use UUID
 		ID:              user.ID,
@@ -75,7 +73,7 @@ func makeSession(user database.User, account database.Account) Session {
 func (a *App) getMe(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -83,7 +81,7 @@ func (a *App) getMe(w http.ResponseWriter, r *http.Request) {
 
 	var account database.Account
 	if err := db.Where("user_id = ?", user.ID).First(&account).Error; err != nil {
-		http.Error(w, "finding account", http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -103,18 +101,14 @@ func (a *App) getMe(w http.ResponseWriter, r *http.Request) {
 	}
 	tx.Commit()
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, response)
 }
 
 // OauthCallbackHandler handler
 func (a *App) oauthCallbackHandler(w http.ResponseWriter, r *http.Request) {
 	githubUser, err := gothic.CompleteUserAuth(w, r)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "completing user uath").Error(), http.StatusInternalServerError)
+		handleError(w, "completing user uath", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -124,13 +118,13 @@ func (a *App) oauthCallbackHandler(w http.ResponseWriter, r *http.Request) {
 	currentUser, err := findUserFromOauth(githubUser, tx)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "Failed to upsert user").Error(), http.StatusInternalServerError)
+		handleError(w, "Failed to upsert user", err, http.StatusInternalServerError)
 		return
 	}
 	err = operations.TouchLastLoginAt(currentUser, tx)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "touching login timestamp").Error(), http.StatusInternalServerError)
+		handleError(w, "touching login timestamp", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -182,7 +176,7 @@ func (a *App) legacyPasswordLogin(w http.ResponseWriter, r *http.Request) {
 	var params legacyPasswordLoginPayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -192,7 +186,7 @@ func (a *App) legacyPasswordLogin(w http.ResponseWriter, r *http.Request) {
 		http.Error(w, "Wrong email and password combination", http.StatusUnauthorized)
 		return
 	} else if conn.Error != nil {
-		http.Error(w, errors.Wrap(err, "getting user").Error(), http.StatusInternalServerError)
+		handleError(w, "getting user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -206,7 +200,7 @@ func (a *App) legacyPasswordLogin(w http.ResponseWriter, r *http.Request) {
 	var user database.User
 	err = db.Where("id = ?", account.UserID).First(&user).Error
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -215,7 +209,7 @@ func (a *App) legacyPasswordLogin(w http.ResponseWriter, r *http.Request) {
 	err = operations.TouchLastLoginAt(user, tx)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "touching login timestamp").Error(), http.StatusInternalServerError)
+		handleError(w, "touching login timestamp", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -229,11 +223,7 @@ func (a *App) legacyPasswordLogin(w http.ResponseWriter, r *http.Request) {
 	}
 
 	setAuthCookie(w, user)
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, response)
 }
 
 type legacyRegisterPayload struct {
@@ -263,7 +253,7 @@ func validateLegacyRegisterPayload(p legacyRegisterPayload) error {
 func (a *App) legacyRegister(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -271,11 +261,11 @@ func (a *App) legacyRegister(w http.ResponseWriter, r *http.Request) {
 
 	var params legacyRegisterPayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 	if err := validateLegacyRegisterPayload(params); err != nil {
-		http.Error(w, errors.Wrap(err, "validating payload").Error(), http.StatusBadRequest)
+		handleError(w, "validating payload", err, http.StatusBadRequest)
 		return
 	}
 
@@ -284,7 +274,7 @@ func (a *App) legacyRegister(w http.ResponseWriter, r *http.Request) {
 	err := operations.LegacyRegisterUser(tx, user.ID, params.Email, params.AuthKey, params.CipherKeyEnc, params.Iteration)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, "creating user", http.StatusBadRequest)
+		handleError(w, "creating user", err, http.StatusBadRequest)
 		return
 	}
 
@@ -292,7 +282,7 @@ func (a *App) legacyRegister(w http.ResponseWriter, r *http.Request) {
 
 	var account database.Account
 	if err := db.Where("user_id = ?", user.ID).First(&account).Error; err != nil {
-		http.Error(w, "finding account", http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -302,14 +292,14 @@ func (a *App) legacyRegister(w http.ResponseWriter, r *http.Request) {
 func (a *App) legacyMigrate(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	db := database.DBConn
 
 	if err := db.Model(&user).Update("encrypted = ?", true).Error; err != nil {
-		http.Error(w, "updating user", http.StatusInternalServerError)
+		handleError(w, "updating user", err, http.StatusInternalServerError)
 		return
 	}
 }

pkg/server/api/handlers/digests.go

@@ -19,12 +19,10 @@
 package handlers
 
 import (
-	"encoding/json"
 	"net/http"
 	"strconv"
 
 	"github.com/dnote/dnote/pkg/server/api/helpers"
-	"github.com/dnote/dnote/pkg/server/api/logger"
 	"github.com/dnote/dnote/pkg/server/api/presenters"
 	"github.com/dnote/dnote/pkg/server/database"
 	"github.com/gorilla/mux"
@@ -37,26 +35,22 @@ func respondWithDigest(w http.ResponseWriter, userID int, digestUUID string) {
 	var digest database.Digest
 	conn := db.Preload("Notes.Book").Where("user_id = ? AND uuid = ? ", userID, digestUUID).First(&digest)
 	if conn.RecordNotFound() {
-		http.Error(w, "finding digest", http.StatusNotFound)
+		handleError(w, "digest not found", nil, http.StatusNotFound)
 		return
 	} else if err := conn.Error; err != nil {
-		logger.Err("finding digest %s", err.Error())
-		http.Error(w, "finding digest", http.StatusInternalServerError)
+
+		handleError(w, "finding digest", err, http.StatusInternalServerError)
 		return
 	}
 
-	w.Header().Set("Content-Type", "application/json")
 	presented := presenters.PresentDigest(digest)
-	if err := json.NewEncoder(w).Encode(presented); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, presented)
 }
 
 func (a App) getDigest(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -69,7 +63,7 @@ func (a App) getDigest(w http.ResponseWriter, r *http.Request) {
 func (a App) getDemoDigest(w http.ResponseWriter, r *http.Request) {
 	userID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -108,7 +102,7 @@ func respondWithDigests(w http.ResponseWriter, r *http.Request, userID int) {
 
 	page, err := parseGetDigestsParams(r)
 	if err != nil {
-		http.Error(w, "parsing params", http.StatusBadRequest)
+		handleError(w, "parsing params", err, http.StatusBadRequest)
 		return
 	}
 	perPage := 25
@@ -117,15 +111,13 @@ func respondWithDigests(w http.ResponseWriter, r *http.Request, userID int) {
 	var digests []database.Digest
 	conn := db.Where("user_id = ?", userID).Order("created_at DESC").Offset(offset).Limit(perPage)
 	if err := conn.Find(&digests).Error; err != nil {
-		logger.Err("finding digests %s", err.Error())
-		http.Error(w, "finding digests", http.StatusInternalServerError)
+		handleError(w, "finding digests", err, http.StatusInternalServerError)
 		return
 	}
 
 	var total int
 	if err := db.Model(database.Digest{}).Where("user_id = ?", userID).Count(&total).Error; err != nil {
-		logger.Err("counting digests %s", err.Error())
-		http.Error(w, "finding digests", http.StatusInternalServerError)
+		handleError(w, "counting digests", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -133,17 +125,13 @@ func respondWithDigests(w http.ResponseWriter, r *http.Request, userID int) {
 		Total:   total,
 		Digests: presenters.PresentDigests(digests),
 	}
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(res); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, res)
 }
 
 func (a *App) getDigests(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -153,7 +141,7 @@ func (a *App) getDigests(w http.ResponseWriter, r *http.Request) {
 func (a *App) getDemoDigests(w http.ResponseWriter, r *http.Request) {
 	userID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user", err, http.StatusInternalServerError)
 		return
 	}
 

pkg/server/api/handlers/helpers.go

@@ -21,11 +21,12 @@ package handlers
 import (
 	crand "crypto/rand"
 	"encoding/base64"
+	"encoding/json"
 	"net/http"
 	"strings"
 
-	"github.com/dnote/dnote/pkg/server/api/logger"
 	"github.com/dnote/dnote/pkg/server/database"
+	"github.com/dnote/dnote/pkg/server/log"
 	"github.com/jinzhu/gorm"
 	"github.com/pkg/errors"
 )
@@ -108,9 +109,26 @@ func getClientType(origin string) string {
 }
 
 // handleError logs the error and responds with the given status code with a generic status text
-func handleError(w http.ResponseWriter, logMessage string, err error, statusCode int) {
-	logger.Err("[%d] %s: %v\n", statusCode, logMessage, err)
+func handleError(w http.ResponseWriter, msg string, err error, statusCode int) {
+	var message string
+	if err == nil {
+		message = msg
+	} else {
+		message = errors.Wrap(err, msg).Error()
+	}
+
+	log.WithFields(log.Fields{
+		"statusCode": statusCode,
+	}).Error(message)
 
 	statusText := http.StatusText(statusCode)
 	http.Error(w, statusText, statusCode)
 }
+
+// respondJSON encodes the given payload into a JSON format and writes it to the given response writer
+func respondJSON(w http.ResponseWriter, payload interface{}) {
+	w.Header().Set("Content-Type", "application/json")
+	if err := json.NewEncoder(w).Encode(payload); err != nil {
+		handleError(w, "encoding response", err, http.StatusInternalServerError)
+	}
+}

pkg/server/api/handlers/limit.go

@@ -24,6 +24,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/dnote/dnote/pkg/server/log"
 	"golang.org/x/time/rate"
 )
 
@@ -112,6 +113,9 @@ func limit(next http.Handler) http.HandlerFunc {
 
 		if !limiter.Allow() {
 			http.Error(w, "Too many requests", http.StatusTooManyRequests)
+			log.WithFields(log.Fields{
+				"ip": identifier,
+			}).Warn("Too many requests")
 			return
 		}
 

pkg/server/api/handlers/notes.go

@@ -19,7 +19,6 @@
 package handlers
 
 import (
-	"encoding/json"
 	"net/http"
 	"net/url"
 	"strconv"
@@ -37,11 +36,7 @@ import (
 func respondWithNote(w http.ResponseWriter, note database.Note) {
 	presentedNote := presenters.PresentNote(note)
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(presentedNote); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, presentedNote)
 }
 
 func preloadNote(conn *gorm.DB) *gorm.DB {
@@ -55,7 +50,7 @@ func (a *App) getDemoNote(w http.ResponseWriter, r *http.Request) {
 
 	demoUserID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -65,10 +60,10 @@ func (a *App) getDemoNote(w http.ResponseWriter, r *http.Request) {
 	conn.Find(&note)
 
 	if conn.RecordNotFound() {
-		http.Error(w, "not found", http.StatusNotFound)
+		handleError(w, "not found", nil, http.StatusNotFound)
 		return
 	} else if err := conn.Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding note").Error(), http.StatusInternalServerError)
+		handleError(w, "finding note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -78,7 +73,7 @@ func (a *App) getDemoNote(w http.ResponseWriter, r *http.Request) {
 func (a *App) getNote(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -87,15 +82,15 @@ func (a *App) getNote(w http.ResponseWriter, r *http.Request) {
 	noteUUID := vars["noteUUID"]
 
 	var note database.Note
-	conn := db.Debug().Where("uuid = ? AND user_id = ?", noteUUID, user.ID)
+	conn := db.Where("uuid = ? AND user_id = ?", noteUUID, user.ID)
 	conn = preloadNote(conn)
 	conn.Find(&note)
 
 	if conn.RecordNotFound() {
-		http.Error(w, "not found", http.StatusNotFound)
+		handleError(w, "not found", nil, http.StatusNotFound)
 		return
 	} else if err := conn.Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding note").Error(), http.StatusInternalServerError)
+		handleError(w, "finding note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -114,7 +109,7 @@ type GetNotesResponse struct {
 func (a *App) getDemoNotes(w http.ResponseWriter, r *http.Request) {
 	userID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user id").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user id", err, http.StatusInternalServerError)
 		return
 	}
 	query := r.URL.Query()
@@ -125,7 +120,7 @@ func (a *App) getDemoNotes(w http.ResponseWriter, r *http.Request) {
 func (a *App) getNotes(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 	query := r.URL.Query()
@@ -136,13 +131,13 @@ func (a *App) getNotes(w http.ResponseWriter, r *http.Request) {
 func respondGetNotes(userID int, query url.Values, w http.ResponseWriter) {
 	err := validateGetNotesQuery(query)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "validating query parameters").Error(), http.StatusBadRequest)
+		handleError(w, "validating query parameters", err, http.StatusBadRequest)
 		return
 	}
 
 	q, err := parseGetNotesQuery(query)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "parsing query parameters").Error(), http.StatusBadRequest)
+		handleError(w, "parsing query parameters", err, http.StatusBadRequest)
 		return
 	}
 
@@ -152,9 +147,9 @@ func respondGetNotes(userID int, query url.Values, w http.ResponseWriter) {
 	conn := baseConn.Where("notes.added_on >= ? AND notes.added_on < ?", dateLowerbound, dateUpperbound)
 
 	var total int
-	err = conn.Debug().Model(database.Note{}).Count(&total).Error
+	err = conn.Model(database.Note{}).Count(&total).Error
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "counting total").Error(), http.StatusInternalServerError)
+		handleError(w, "counting total", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -166,7 +161,7 @@ func respondGetNotes(userID int, query url.Values, w http.ResponseWriter) {
 
 		err = conn.Find(&notes).Error
 		if err != nil {
-			http.Error(w, errors.Wrap(err, "finding notes").Error(), http.StatusInternalServerError)
+			handleError(w, "finding notes", err, http.StatusInternalServerError)
 			return
 		}
 	}
@@ -182,7 +177,7 @@ func respondGetNotes(userID int, query url.Values, w http.ResponseWriter) {
 
 	prevDate, err := getPrevDate(baseConn, prevDateUpperbound)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "getting prevDate").Error(), http.StatusInternalServerError)
+		handleError(w, "getting prevDate", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -193,12 +188,7 @@ func respondGetNotes(userID int, query url.Values, w http.ResponseWriter) {
 		Total:    total,
 		PrevDate: prevDate,
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, response)
 }
 
 func getPrevDate(baseConn *gorm.DB, dateUpperbound int64) (*int64, error) {
@@ -328,21 +318,17 @@ func orderGetNotes(conn *gorm.DB) *gorm.DB {
 func (a *App) legacyGetNotes(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var notes []database.Note
 	db := database.DBConn
 	if err := db.Where("user_id = ? AND encrypted = false", user.ID).Find(&notes).Error; err != nil {
-		http.Error(w, "finding notes", http.StatusInternalServerError)
+		handleError(w, "finding notes", err, http.StatusInternalServerError)
 		return
 	}
 
 	presented := presenters.PresentNotes(notes)
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(presented); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, presented)
 }

pkg/server/api/handlers/routes.go

@@ -20,7 +20,7 @@ package handlers
 
 import (
 	"context"
-	"log"
+	"fmt"
 	"net/http"
 	"os"
 	"strings"
@@ -28,8 +28,8 @@ import (
 
 	"github.com/dnote/dnote/pkg/clock"
 	"github.com/dnote/dnote/pkg/server/api/helpers"
-	"github.com/dnote/dnote/pkg/server/api/logger"
 	"github.com/dnote/dnote/pkg/server/database"
+	"github.com/dnote/dnote/pkg/server/log"
 	"github.com/gorilla/mux"
 	"github.com/markbates/goth/gothic"
 	"github.com/pkg/errors"
@@ -153,8 +153,7 @@ func authWithSession(r *http.Request) (database.User, bool, error) {
 
 	sessionKey, err := getCredential(r)
 	if err != nil {
-		logger.Err(errors.Wrap(err, "getting credential").Error())
-		return user, false, err
+		return user, false, errors.Wrap(err, "getting credential")
 	}
 
 	if sessionKey == "" {
@@ -167,8 +166,7 @@ func authWithSession(r *http.Request) (database.User, bool, error) {
 	if conn.RecordNotFound() {
 		return user, false, nil
 	} else if err := conn.Error; err != nil {
-		logger.Err(errors.Wrap(err, "finding session").Error())
-		return user, false, err
+		return user, false, errors.Wrap(err, "finding session")
 	}
 
 	if session.ExpiresAt.Before(time.Now()) {
@@ -180,8 +178,7 @@ func authWithSession(r *http.Request) (database.User, bool, error) {
 	if conn.RecordNotFound() {
 		return user, false, nil
 	} else if err := conn.Error; err != nil {
-		logger.Err(errors.Wrap(err, "finding user from token").Error())
-		return user, false, err
+		return user, false, errors.Wrap(err, "finding user from token")
 	}
 
 	return user, true, nil
@@ -202,8 +199,7 @@ func authWithToken(r *http.Request, tokenType string) (database.User, database.T
 	if conn.RecordNotFound() {
 		return user, token, false, nil
 	} else if err := conn.Error; err != nil {
-		logger.Err(errors.Wrap(err, "finding token").Error())
-		return user, token, false, err
+		return user, token, false, errors.Wrap(err, "finding token")
 	}
 
 	if token.UsedAt != nil && time.Since(*token.UsedAt).Minutes() > 10 {
@@ -211,8 +207,7 @@ func authWithToken(r *http.Request, tokenType string) (database.User, database.T
 	}
 
 	if err := db.Where("id = ?", token.UserID).First(&user).Error; err != nil {
-		logger.Err(errors.Wrap(err, "finding user").Error())
-		return user, token, false, err
+		return user, token, false, errors.Wrap(err, "finding user")
 	}
 
 	return user, token, true, nil
@@ -247,7 +242,7 @@ func tokenAuth(next http.HandlerFunc, tokenType string) http.HandlerFunc {
 		user, token, ok, err := authWithToken(r, tokenType)
 		if err != nil {
 			// log the error and continue
-			logger.Err(errors.Wrap(err, "authenticating with token").Error())
+			log.ErrorWrap(err, "authenticating with token")
 		}
 
 		ctx := r.Context()
@@ -259,7 +254,7 @@ func tokenAuth(next http.HandlerFunc, tokenType string) http.HandlerFunc {
 			user, ok, err = authWithSession(r)
 			if err != nil {
 				// log the error and continue
-				logger.Err(errors.Wrap(err, "authenticating with session").Error())
+				log.ErrorWrap(err, "authenticating with session")
 			}
 
 			if !ok {
@@ -286,18 +281,34 @@ func cors(next http.HandlerFunc) http.HandlerFunc {
 	})
 }
 
+// logResponseWriter wraps http.ResponseWriter to expose HTTP status code for logging.
+// The optional interfaces of http.ResponseWriter are lost because of the wrapping, and
+// such interfaces should be implemented if needed. (i.e. http.Pusher, http.Flusher, etc.)
+type logResponseWriter struct {
+	http.ResponseWriter
+	statusCode int
+}
+
+func (w *logResponseWriter) WriteHeader(code int) {
+	w.statusCode = code
+	w.ResponseWriter.WriteHeader(code)
+}
+
 func logging(inner http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
 
-		inner.ServeHTTP(w, r)
+		lw := logResponseWriter{w, http.StatusOK}
+		inner.ServeHTTP(&lw, r)
 
-		log.Printf(
-			"%s\t%s\t%s",
-			r.Method,
-			r.RequestURI,
-			time.Since(start),
-		)
+		log.WithFields(log.Fields{
+			"remoteAddr": r.RemoteAddr,
+			"uri":        r.RequestURI,
+			"statusCode": lw.statusCode,
+			"method":     r.Method,
+			"duration":   fmt.Sprintf("%dms", time.Since(start)/1000000),
+			"userAgent":  r.Header.Get("User-Agent"),
+		}).Info("incoming request")
 	})
 }
 

pkg/server/api/handlers/subscription.go

@@ -116,7 +116,7 @@ type createSubPayload struct {
 func (a *App) createSub(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -206,11 +206,11 @@ func validateUpdateSubPayload(p updateSubPayload) error {
 func (a *App) updateSub(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 	if user.StripeCustomerID == "" {
-		http.Error(w, "Customer does not exist", http.StatusForbidden)
+		handleError(w, "Customer does not exist", nil, http.StatusForbidden)
 		return
 	}
 
@@ -277,7 +277,7 @@ func respondWithEmptySub(w http.ResponseWriter) {
 func (a *App) getSub(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 	if user.StripeCustomerID == "" {
@@ -319,11 +319,7 @@ func (a *App) getSub(w http.ResponseWriter, r *http.Request) {
 		resp.Items = append(resp.Items, i)
 	}
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		handleError(w, "encoding response", err, http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // GetStripeSourceResponse is a response for getStripeToken
@@ -337,11 +333,7 @@ type GetStripeSourceResponse struct {
 func respondWithEmptyStripeToken(w http.ResponseWriter) {
 	var resp GetStripeSourceResponse
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		handleError(w, "encoding response", err, http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // getStripeCard retrieves card information from stripe and returns a stripe.Card
@@ -397,7 +389,7 @@ func getStripeCard(stripeCustomerID, sourceID string) (*stripe.Card, error) {
 func (a *App) getStripeSource(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 	if user.StripeCustomerID == "" {
@@ -429,11 +421,7 @@ func (a *App) getStripeSource(w http.ResponseWriter, r *http.Request) {
 		ExpYear:  cd.ExpYear,
 	}
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		handleError(w, "encoding response", err, http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 func (a *App) stripeWebhook(w http.ResponseWriter, req *http.Request) {

pkg/server/api/handlers/user.go

@@ -27,9 +27,8 @@ import (
 	"github.com/dnote/dnote/pkg/server/api/helpers"
 	"github.com/dnote/dnote/pkg/server/api/operations"
 	"github.com/dnote/dnote/pkg/server/database"
+	"github.com/dnote/dnote/pkg/server/log"
 	"github.com/dnote/dnote/pkg/server/mailer"
-
-	"github.com/pkg/errors"
 )
 
 type updateProfilePayload struct {
@@ -42,14 +41,14 @@ func (a *App) updateProfile(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var params updateProfilePayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		handleError(w, "decoding params", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -62,7 +61,7 @@ func (a *App) updateProfile(w http.ResponseWriter, r *http.Request) {
 	var account database.Account
 	err = db.Where("user_id = ?", user.ID).First(&account).Error
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding account").Error(), http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -70,24 +69,19 @@ func (a *App) updateProfile(w http.ResponseWriter, r *http.Request) {
 	user.Name = params.Name
 	if err := tx.Save(&user).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "saving user").Error(), http.StatusInternalServerError)
+		handleError(w, "saving user", err, http.StatusInternalServerError)
 		return
 	}
 
 	if err := tx.Save(&account).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "saving user").Error(), http.StatusInternalServerError)
+		handleError(w, "saving user", err, http.StatusInternalServerError)
 		return
 	}
 	tx.Commit()
 
 	session := makeSession(user, account)
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(session); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, session)
 }
 
 type updateEmailPayload struct {
@@ -103,14 +97,14 @@ func (a *App) updateEmail(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var params updateEmailPayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		handleError(w, "decoding params", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -123,7 +117,7 @@ func (a *App) updateEmail(w http.ResponseWriter, r *http.Request) {
 	var account database.Account
 	err = db.Where("user_id = ?", user.ID).First(&account).Error
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding account").Error(), http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -148,18 +142,13 @@ func (a *App) updateEmail(w http.ResponseWriter, r *http.Request) {
 
 	if err := tx.Save(&account).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "saving account").Error(), http.StatusInternalServerError)
+		handleError(w, "saving account", err, http.StatusInternalServerError)
 		return
 	}
 	tx.Commit()
 
 	session := makeSession(user, account)
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(session); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, session)
 }
 
 func respondWithCalendar(w http.ResponseWriter, userID int) {
@@ -171,7 +160,7 @@ func respondWithCalendar(w http.ResponseWriter, userID int) {
 		Order("added_date DESC").Rows()
 
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "Failed to count lessons").Error(), http.StatusInternalServerError)
+		handleError(w, "Failed to count lessons", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -182,22 +171,18 @@ func respondWithCalendar(w http.ResponseWriter, userID int) {
 		var d time.Time
 
 		if err := rows.Scan(&count, &d); err != nil {
-			http.Error(w, errors.Wrap(err, "counting notes").Error(), http.StatusInternalServerError)
+			handleError(w, "counting notes", err, http.StatusInternalServerError)
 		}
 		payload[d.Format("2006-1-2")] = count
 	}
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(payload); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, payload)
 }
 
 func (a *App) getCalendar(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -207,7 +192,7 @@ func (a *App) getCalendar(w http.ResponseWriter, r *http.Request) {
 func (a *App) getDemoCalendar(w http.ResponseWriter, r *http.Request) {
 	userID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -219,14 +204,14 @@ func (a *App) createVerificationToken(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var account database.Account
 	err := db.Where("user_id = ?", user.ID).First(&account).Error
 	if err != nil {
-		http.Error(w, errors.WithMessage(err, "finding account").Error(), http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -241,7 +226,7 @@ func (a *App) createVerificationToken(w http.ResponseWriter, r *http.Request) {
 
 	tokenValue, err := generateVerificationCode()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "generating verification code").Error(), http.StatusInternalServerError)
+		handleError(w, "generating verification code", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -252,7 +237,7 @@ func (a *App) createVerificationToken(w http.ResponseWriter, r *http.Request) {
 	}
 
 	if err := db.Save(&token).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "saving token").Error(), http.StatusInternalServerError)
+		handleError(w, "saving token", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -266,12 +251,12 @@ func (a *App) createVerificationToken(w http.ResponseWriter, r *http.Request) {
 	}
 	email := mailer.NewEmail("noreply@dnote.io", []string{account.Email.String}, subject)
 	if err := email.ParseTemplate(mailer.EmailTypeEmailVerification, data); err != nil {
-		http.Error(w, errors.Wrap(err, "parsing template").Error(), http.StatusInternalServerError)
+		handleError(w, "parsing template", err, http.StatusInternalServerError)
 		return
 	}
 
 	if err := email.Send(); err != nil {
-		http.Error(w, errors.Wrap(err, "sending email").Error(), http.StatusInternalServerError)
+		handleError(w, "sending email", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -287,7 +272,7 @@ func (a *App) verifyEmail(w http.ResponseWriter, r *http.Request) {
 
 	var params verifyEmailPayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -312,7 +297,7 @@ func (a *App) verifyEmail(w http.ResponseWriter, r *http.Request) {
 
 	var account database.Account
 	if err := db.Where("user_id = ?", token.UserID).First(&account).Error; err != nil {
-		http.Error(w, errors.WithMessage(err, "finding account").Error(), http.StatusInternalServerError)
+		handleError(w, "finding account", err, http.StatusInternalServerError)
 		return
 	}
 	if account.EmailVerified {
@@ -324,29 +309,25 @@ func (a *App) verifyEmail(w http.ResponseWriter, r *http.Request) {
 	account.EmailVerified = true
 	if err := tx.Save(&account).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.WithMessage(err, "updating email_verified").Error(), http.StatusInternalServerError)
+		handleError(w, "updating email_verified", err, http.StatusInternalServerError)
 		return
 	}
 	if err := tx.Model(&token).Update("used_at", time.Now()).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.WithMessage(err, "updating reset token").Error(), http.StatusInternalServerError)
+		handleError(w, "updating reset token", err, http.StatusInternalServerError)
 		return
 	}
 	tx.Commit()
 
 	var user database.User
 	if err := db.Where("id = ?", token.UserID).First(&user).Error; err != nil {
-		http.Error(w, errors.WithMessage(err, "finding user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding user", err, http.StatusInternalServerError)
 		return
 	}
 
 	session := makeSession(user, account)
 	setAuthCookie(w, user)
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(session); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, session)
 }
 
 type updateEmailPreferencePayload struct {
@@ -358,19 +339,19 @@ func (a *App) updateEmailPreference(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var params updateEmailPreferencePayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
 	var frequency database.EmailPreference
 	if err := db.Where(database.EmailPreference{UserID: user.ID}).FirstOrCreate(&frequency).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding frequency").Error(), http.StatusInternalServerError)
+		handleError(w, "finding frequency", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -379,7 +360,7 @@ func (a *App) updateEmailPreference(w http.ResponseWriter, r *http.Request) {
 	frequency.DigestWeekly = params.DigestWeekly
 	if err := tx.Save(&frequency).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "saving frequency").Error(), http.StatusInternalServerError)
+		handleError(w, "saving frequency", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -388,18 +369,14 @@ func (a *App) updateEmailPreference(w http.ResponseWriter, r *http.Request) {
 		// Use token if the user was authenticated by token
 		if err := tx.Model(&token).Update("used_at", time.Now()).Error; err != nil {
 			tx.Rollback()
-			http.Error(w, errors.WithMessage(err, "updating reset token").Error(), http.StatusInternalServerError)
+			handleError(w, "updating reset token", err, http.StatusInternalServerError)
 			return
 		}
 	}
 
 	tx.Commit()
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(frequency); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, frequency)
 }
 
 func (a *App) getEmailPreference(w http.ResponseWriter, r *http.Request) {
@@ -407,21 +384,17 @@ func (a *App) getEmailPreference(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var pref database.EmailPreference
 	if err := db.Where(database.EmailPreference{UserID: user.ID}).First(&pref).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding pref").Error(), http.StatusInternalServerError)
+		handleError(w, "finding pref", err, http.StatusInternalServerError)
 		return
 	}
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(pref); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, pref)
 }
 
 type updatePasswordPayload struct {
@@ -436,23 +409,26 @@ func (a *App) updatePassword(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 	var account database.Account
 	if err := db.Where("user_id = ?", user.ID).First(&account).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "getting account").Error(), http.StatusInternalServerError)
+		handleError(w, "getting account", err, http.StatusInternalServerError)
 		return
 	}
 	var params updatePasswordPayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		handleError(w, "decoding params", err, http.StatusInternalServerError)
 		return
 	}
 
 	oldAuthKeyHash := crypt.HashAuthKey(params.OldAuthKey, account.Salt, account.ServerKDFIteration)
 	if oldAuthKeyHash != account.AuthKeyHash {
 		http.Error(w, ErrLoginFailure.Error(), http.StatusUnauthorized)
+		log.WithFields(log.Fields{
+			"account_id": account.ID,
+		}).Error("Existing password mismatch")
 		return
 	}
 
@@ -460,19 +436,18 @@ func (a *App) updatePassword(w http.ResponseWriter, r *http.Request) {
 
 	if err := db.
 		Model(&account).
-		Debug().
 		Updates(map[string]interface{}{
 			"auth_key_hash":        newAuthKeyHash,
 			"client_kdf_iteration": params.NewKDFIteration,
 			"server_kdf_iteration": account.ServerKDFIteration,
 			"cipher_key_enc":       params.NewCipherKeyEnc,
 		}).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "updating account").Error(), http.StatusInternalServerError)
+		handleError(w, "updating account", err, http.StatusInternalServerError)
 		return
 	}
 
 	if err := operations.DeleteUserSessions(db, user.ID); err != nil {
-		http.Error(w, "deleting user sessions", http.StatusBadRequest)
+		handleError(w, "deleting user sessions", err, http.StatusBadRequest)
 		return
 	}
 

pkg/server/api/handlers/v1_auth.go

@@ -23,11 +23,11 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/pkg/errors"
-
 	"github.com/dnote/dnote/pkg/server/api/crypt"
 	"github.com/dnote/dnote/pkg/server/api/operations"
 	"github.com/dnote/dnote/pkg/server/database"
+	"github.com/dnote/dnote/pkg/server/log"
+	"github.com/pkg/errors"
 )
 
 // ErrLoginFailure is an error for failed login
@@ -75,7 +75,7 @@ func (a *App) signin(w http.ResponseWriter, r *http.Request) {
 
 	var params signinPayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -90,12 +90,15 @@ func (a *App) signin(w http.ResponseWriter, r *http.Request) {
 		http.Error(w, ErrLoginFailure.Error(), http.StatusUnauthorized)
 		return
 	} else if err := conn.Error; err != nil {
-		http.Error(w, errors.Wrap(err, "getting user").Error(), http.StatusInternalServerError)
+		handleError(w, "getting user", err, http.StatusInternalServerError)
 		return
 	}
 
 	authKeyHash := crypt.HashAuthKey(params.AuthKey, account.Salt, account.ServerKDFIteration)
 	if account.AuthKeyHash != authKeyHash {
+		log.WithFields(log.Fields{
+			"account_id": account.ID,
+		}).Error("Sign in password mismatch")
 		http.Error(w, ErrLoginFailure.Error(), http.StatusUnauthorized)
 		return
 	}
@@ -111,7 +114,7 @@ func (a *App) signoutOptions(w http.ResponseWriter, r *http.Request) {
 func (a *App) signout(w http.ResponseWriter, r *http.Request) {
 	key, err := getCredential(r)
 	if err != nil {
-		http.Error(w, "getting credential", http.StatusInternalServerError)
+		handleError(w, "getting credential", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -122,7 +125,7 @@ func (a *App) signout(w http.ResponseWriter, r *http.Request) {
 
 	err = operations.DeleteSession(database.DBConn, key)
 	if err != nil {
-		http.Error(w, "deleting session", http.StatusInternalServerError)
+		handleError(w, "deleting session", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -159,17 +162,17 @@ func (a *App) register(w http.ResponseWriter, r *http.Request) {
 
 	var params registerPayload
 	if err := json.NewDecoder(r.Body).Decode(&params); err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 	if err := validateRegisterPayload(params); err != nil {
-		http.Error(w, errors.Wrap(err, "validating payload").Error(), http.StatusBadRequest)
+		handleError(w, "validating payload", err, http.StatusBadRequest)
 		return
 	}
 
 	var count int
 	if err := db.Model(database.Account{}).Where("email = ?", params.Email).Count(&count).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "checking duplicate").Error(), http.StatusInternalServerError)
+		handleError(w, "checking duplicate", err, http.StatusInternalServerError)
 		return
 	}
 	if count > 0 {
@@ -182,14 +185,15 @@ func (a *App) register(w http.ResponseWriter, r *http.Request) {
 	user, err := operations.CreateUser(tx, params.Email, params.AuthKey, params.CipherKeyEnc, params.Iteration)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, "creating user", http.StatusBadRequest)
+
+		handleError(w, "creating user", nil, http.StatusBadRequest)
 		return
 	}
 
 	var account database.Account
 	if err := tx.Where("user_id = ?", user.ID).First(&account).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, "finding account", http.StatusBadRequest)
+		handleError(w, "finding account", nil, http.StatusBadRequest)
 		return
 	}
 
@@ -205,7 +209,7 @@ func respondWithSession(w http.ResponseWriter, userID int, cipherKeyEnc string)
 
 	session, err := operations.CreateSession(db, userID)
 	if err != nil {
-		http.Error(w, "creating session", http.StatusBadRequest)
+		handleError(w, "creating session", nil, http.StatusBadRequest)
 		return
 	}
 
@@ -218,7 +222,7 @@ func respondWithSession(w http.ResponseWriter, userID int, cipherKeyEnc string)
 	}
 	w.Header().Set("Content-Type", "application/json")
 	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		handleError(w, "encoding response", err, http.StatusInternalServerError)
 		return
 	}
 }
@@ -241,7 +245,7 @@ func (a *App) presignin(w http.ResponseWriter, r *http.Request) {
 	var account database.Account
 	conn := db.Where("email = ?", email).First(&account)
 	if !conn.RecordNotFound() && conn.Error != nil {
-		http.Error(w, errors.Wrap(conn.Error, "getting user").Error(), http.StatusInternalServerError)
+		handleError(w, "getting user", conn.Error, http.StatusInternalServerError)
 		return
 	}
 
@@ -258,7 +262,7 @@ func (a *App) presignin(w http.ResponseWriter, r *http.Request) {
 
 	w.Header().Set("Content-Type", "application/json")
 	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		handleError(w, "encoding response", nil, http.StatusInternalServerError)
 		return
 	}
 }

pkg/server/api/handlers/v1_books.go

@@ -56,24 +56,19 @@ func respondWithBooks(userID int, query url.Values, w http.ResponseWriter) {
 	}
 
 	if err := conn.Find(&books).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding books").Error(), http.StatusInternalServerError)
+		handleError(w, "finding books", err, http.StatusInternalServerError)
 		return
 	}
 
 	presentedBooks := presenters.PresentBooks(books)
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(presentedBooks); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, presentedBooks)
 }
 
 // GetDemoBooks returns books for demo
 func (a *App) GetDemoBooks(w http.ResponseWriter, r *http.Request) {
 	demoUserID, err := helpers.GetDemoUserID()
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "finding demo user").Error(), http.StatusInternalServerError)
+		handleError(w, "finding demo user", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -114,16 +109,12 @@ func (a *App) GetBook(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 	if err := conn.Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding book").Error(), http.StatusInternalServerError)
+		handleError(w, "finding book", err, http.StatusInternalServerError)
 		return
 	}
 
 	p := presenters.PresentBook(book)
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(p); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, p)
 }
 
 type createBookPayload struct {
@@ -173,21 +164,21 @@ func (a *App) UpdateBook(w http.ResponseWriter, r *http.Request) {
 
 	var book database.Book
 	if err := tx.Where("user_id = ? AND uuid = ?", user.ID, uuid).First(&book).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding book").Error(), http.StatusInternalServerError)
+		handleError(w, "finding book", err, http.StatusInternalServerError)
 		return
 	}
 
 	var params updateBookPayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
 	book, err = operations.UpdateBook(tx, a.Clock, user, book, params.Name)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "updating a book").Error(), http.StatusInternalServerError)
+		handleError(w, "updating a book", err, http.StatusInternalServerError)
 	}
 
 	tx.Commit()
@@ -195,12 +186,7 @@ func (a *App) UpdateBook(w http.ResponseWriter, r *http.Request) {
 	resp := UpdateBookResp{
 		Book: presenters.PresentBook(book),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // DeleteBookResp is the response from create book api
@@ -224,25 +210,25 @@ func (a *App) DeleteBook(w http.ResponseWriter, r *http.Request) {
 
 	var book database.Book
 	if err := tx.Where("user_id = ? AND uuid = ?", user.ID, uuid).First(&book).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding book").Error(), http.StatusInternalServerError)
+		handleError(w, "finding book", err, http.StatusInternalServerError)
 		return
 	}
 
 	var notes []database.Note
 	if err := tx.Where("book_uuid = ? AND NOT deleted", uuid).Order("usn ASC").Find(&notes).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding notes").Error(), http.StatusInternalServerError)
+		handleError(w, "finding notes", err, http.StatusInternalServerError)
 		return
 	}
 
 	for _, note := range notes {
 		if _, err := operations.DeleteNote(tx, user, note); err != nil {
-			http.Error(w, errors.Wrap(err, "deleting a note").Error(), http.StatusInternalServerError)
+			handleError(w, "deleting a note", err, http.StatusInternalServerError)
 			return
 		}
 	}
 	b, err := operations.DeleteBook(tx, user, book)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "deleting book").Error(), http.StatusInternalServerError)
+		handleError(w, "deleting book", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -252,12 +238,7 @@ func (a *App) DeleteBook(w http.ResponseWriter, r *http.Request) {
 		Status: http.StatusOK,
 		Book:   presenters.PresentBook(b),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // BooksOptions handles OPTIONS endpoint

pkg/server/api/handlers/v1_notes.go

@@ -20,6 +20,7 @@ package handlers
 
 import (
 	"encoding/json"
+	"fmt"
 	"net/http"
 
 	"github.com/dnote/dnote/pkg/server/api/helpers"
@@ -27,7 +28,6 @@ import (
 	"github.com/dnote/dnote/pkg/server/api/presenters"
 	"github.com/dnote/dnote/pkg/server/database"
 	"github.com/gorilla/mux"
-	"github.com/pkg/errors"
 )
 
 // CreateNote creates a note by generating an action and feeding it to the reducer
@@ -64,25 +64,25 @@ func (a *App) UpdateNote(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var params updateNotePayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "decoding params").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding params", err, http.StatusInternalServerError)
 		return
 	}
 
 	if ok := validateUpdateNotePayload(params); !ok {
-		http.Error(w, "Invalid payload", http.StatusBadRequest)
+		handleError(w, "Invalid payload", nil, http.StatusBadRequest)
 		return
 	}
 
 	var note database.Note
 	if err := db.Where("uuid = ? AND user_id = ?", noteUUID, user.ID).First(&note).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding note").Error(), http.StatusInternalServerError)
+		handleError(w, "finding note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -91,14 +91,14 @@ func (a *App) UpdateNote(w http.ResponseWriter, r *http.Request) {
 	note, err = operations.UpdateNote(tx, user, a.Clock, note, params.BookUUID, params.Content)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "updating note").Error(), http.StatusInternalServerError)
+		handleError(w, "updating note", err, http.StatusInternalServerError)
 		return
 	}
 
 	var book database.Book
 	if err := tx.Where("uuid = ? AND user_id = ?", note.BookUUID, user.ID).First(&book).Error; err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrapf(err, "finding book %s to preload", note.BookUUID).Error(), http.StatusInternalServerError)
+		handleError(w, fmt.Sprintf("finding book %s to preload", note.BookUUID), err, http.StatusInternalServerError)
 		return
 	}
 
@@ -112,12 +112,7 @@ func (a *App) UpdateNote(w http.ResponseWriter, r *http.Request) {
 		Status: http.StatusOK,
 		Result: presenters.PresentNote(note),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 type deleteNoteResp struct {
@@ -134,13 +129,13 @@ func (a *App) DeleteNote(w http.ResponseWriter, r *http.Request) {
 
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var note database.Note
 	if err := db.Where("uuid = ? AND user_id = ?", noteUUID, user.ID).Preload("Book").First(&note).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding note").Error(), http.StatusInternalServerError)
+		handleError(w, "finding note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -149,7 +144,7 @@ func (a *App) DeleteNote(w http.ResponseWriter, r *http.Request) {
 	n, err := operations.DeleteNote(tx, user, note)
 	if err != nil {
 		tx.Rollback()
-		http.Error(w, errors.Wrap(err, "deleting note").Error(), http.StatusInternalServerError)
+		handleError(w, "deleting note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -159,10 +154,5 @@ func (a *App) DeleteNote(w http.ResponseWriter, r *http.Request) {
 		Status: http.StatusNoContent,
 		Result: presenters.PresentNote(n),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }

pkg/server/api/handlers/v1_sync.go

@@ -19,7 +19,6 @@
 package handlers
 
 import (
-	"encoding/json"
 	"fmt"
 	"net/http"
 	"net/url"
@@ -29,6 +28,7 @@ import (
 
 	"github.com/dnote/dnote/pkg/server/api/helpers"
 	"github.com/dnote/dnote/pkg/server/database"
+	"github.com/dnote/dnote/pkg/server/log"
 	"github.com/pkg/errors"
 )
 
@@ -252,30 +252,26 @@ type GetSyncFragmentResp struct {
 func (a *App) GetSyncFragment(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	afterUSN, limit, err := parseGetSyncFragmentQuery(r.URL.Query())
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "parsing query params").Error(), http.StatusInternalServerError)
+		handleError(w, "parsing query params", err, http.StatusInternalServerError)
 		return
 	}
 
 	fragment, err := a.newFragment(user.ID, user.MaxUSN, afterUSN, limit)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "getting fragment").Error(), http.StatusInternalServerError)
+		handleError(w, "getting fragment", err, http.StatusInternalServerError)
 		return
 	}
 
 	response := GetSyncFragmentResp{
 		Fragment: fragment,
 	}
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, response)
 }
 
 // GetSyncStateResp represents a response from GetSyncFragment handler
@@ -289,7 +285,7 @@ type GetSyncStateResp struct {
 func (a *App) GetSyncState(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "No authenticated user found", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
@@ -300,11 +296,12 @@ func (a *App) GetSyncState(w http.ResponseWriter, r *http.Request) {
 		CurrentTime: a.Clock.Now().Unix(),
 	}
 
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(response); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	log.WithFields(log.Fields{
+		"user_id": user.ID,
+		"resp":    response,
+	}).Info("getting sync state")
+
+	respondJSON(w, response)
 }
 
 // Sync is a deprecated endpoint that used to support cli versions below v0.5.0

pkg/server/api/handlers/v2_books.go

@@ -56,13 +56,13 @@ func (a *App) CreateBookV2(w http.ResponseWriter, r *http.Request) {
 	var params createBookPayload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
 	err = validateCreateBookPayload(params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "validating payload").Error(), http.StatusBadRequest)
+		handleError(w, "validating payload", err, http.StatusBadRequest)
 		return
 	}
 
@@ -73,7 +73,7 @@ func (a *App) CreateBookV2(w http.ResponseWriter, r *http.Request) {
 		Where("user_id = ? AND label = ?", user.ID, params.Name).
 		Count(&bookCount).Error
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "checking duplicate").Error(), http.StatusInternalServerError)
+		handleError(w, "checking duplicate", err, http.StatusInternalServerError)
 		return
 	}
 	if bookCount > 0 {
@@ -83,17 +83,12 @@ func (a *App) CreateBookV2(w http.ResponseWriter, r *http.Request) {
 
 	book, err := operations.CreateBook(user, a.Clock, params.Name)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "inserting book").Error(), http.StatusInternalServerError)
+		handleError(w, "inserting book", err, http.StatusInternalServerError)
 	}
 	resp := CreateBookResp{
 		Book: presenters.PresentBook(book),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // BooksOptionsV2 is a handler for OPTIONS endpoint for notes

pkg/server/api/handlers/v2_notes.go

@@ -53,33 +53,33 @@ type CreateNoteV2Resp struct {
 func (a *App) CreateNoteV2(w http.ResponseWriter, r *http.Request) {
 	user, ok := r.Context().Value(helpers.KeyUser).(database.User)
 	if !ok {
-		http.Error(w, "Failed to get user", http.StatusInternalServerError)
+		handleError(w, "No authenticated user found", nil, http.StatusInternalServerError)
 		return
 	}
 
 	var params createNoteV2Payload
 	err := json.NewDecoder(r.Body).Decode(&params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "decoding payload").Error(), http.StatusInternalServerError)
+		handleError(w, "decoding payload", err, http.StatusInternalServerError)
 		return
 	}
 
 	err = validateCreateNoteV2Payload(params)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "validating payload").Error(), http.StatusBadRequest)
+		handleError(w, "validating payload", err, http.StatusBadRequest)
 		return
 	}
 
 	var book database.Book
 	db := database.DBConn
 	if err := db.Where("uuid = ? AND user_id = ?", params.BookUUID, user.ID).First(&book).Error; err != nil {
-		http.Error(w, errors.Wrap(err, "finding book").Error(), http.StatusInternalServerError)
+		handleError(w, "finding book", err, http.StatusInternalServerError)
 		return
 	}
 
 	note, err := operations.CreateNote(user, a.Clock, params.BookUUID, params.Content, params.AddedOn, params.EditedOn, false)
 	if err != nil {
-		http.Error(w, errors.Wrap(err, "creating note").Error(), http.StatusInternalServerError)
+		handleError(w, "creating note", err, http.StatusInternalServerError)
 		return
 	}
 
@@ -90,12 +90,7 @@ func (a *App) CreateNoteV2(w http.ResponseWriter, r *http.Request) {
 	resp := CreateNoteV2Resp{
 		Result: presenters.PresentNote(note),
 	}
-
-	w.Header().Set("Content-Type", "application/json")
-	if err := json.NewEncoder(w).Encode(resp); err != nil {
-		http.Error(w, err.Error(), http.StatusInternalServerError)
-		return
-	}
+	respondJSON(w, resp)
 }
 
 // NotesOptionsV2 is a handler for OPTIONS endpoint for notes

pkg/server/api/logger/main.go

@@ -1,108 +0,0 @@
-/* Copyright (C) 2019 Monomax Software Pty Ltd
- *
- * This file is part of Dnote.
- *
- * Dnote is free software: you can redistribute it and/or modify
- * it under the terms of the GNU Affero General Public License as published by
- * the Free Software Foundation, either version 3 of the License, or
- * (at your option) any later version.
- *
- * Dnote is distributed in the hope that it will be useful,
- * but WITHOUT ANY WARRANTY; without even the implied warranty of
- * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- * GNU Affero General Public License for more details.
- *
- * You should have received a copy of the GNU Affero General Public License
- * along with Dnote.  If not, see <https://www.gnu.org/licenses/>.
- */
-
-// Package logger provides an interface to transmit log messages to a system log service
-package logger
-
-import (
-	"fmt"
-	"github.com/pkg/errors"
-	"log"
-	"log/syslog"
-	"os"
-)
-
-var writer *syslog.Writer
-
-// Init initilizes the syslog writer
-func Init() error {
-	var err error
-
-	var endpoint string
-	if os.Getenv("GO_ENV") == "PRODUCTION" {
-		endpoint = os.Getenv("LogEndpoint")
-
-		if endpoint == "" {
-			log.Println("No log endpoint provided. Not aggregating system logs.")
-			return nil
-		}
-
-		writer, err = syslog.Dial("udp", endpoint, syslog.LOG_DEBUG|syslog.LOG_KERN, "dnote-api")
-		if err != nil {
-			return errors.Wrap(err, "dialing syslog manager")
-		}
-	}
-
-	return nil
-}
-
-// Info logs an info message
-func Info(msg string, v ...interface{}) {
-	m := fmt.Sprintf(msg, v...)
-	log.Println(m)
-
-	if writer == nil {
-		return
-	}
-
-	if err := writer.Info(fmt.Sprintf("INFO: %s", m)); err != nil {
-		log.Println(errors.Wrap(err, "transmiting log"))
-	}
-}
-
-// Err logs an error message
-func Err(msg string, v ...interface{}) {
-	m := fmt.Sprintf(msg, v...)
-	log.Println(m)
-
-	if writer == nil {
-		return
-	}
-
-	if err := writer.Err(fmt.Sprintf("ERROR: %s", m)); err != nil {
-		log.Println(errors.Wrap(err, "transmiting log"))
-	}
-}
-
-// Notice logs a notice message
-func Notice(msg string, v ...interface{}) {
-	m := fmt.Sprintf(msg, v...)
-	log.Println(m)
-
-	if writer == nil {
-		return
-	}
-
-	if err := writer.Notice(fmt.Sprintf("NOTICE: %s", m)); err != nil {
-		log.Println(errors.Wrap(err, "transmiting log"))
-	}
-}
-
-// Debug logs a debug message
-func Debug(msg string, v ...interface{}) {
-	m := fmt.Sprintf(msg, v...)
-	log.Println(m)
-
-	if writer == nil {
-		return
-	}
-
-	if err := writer.Debug(fmt.Sprintf("DEBUG: %s", m)); err != nil {
-		log.Println(errors.Wrap(err, "transmiting log"))
-	}
-}

pkg/server/log/log.go

@@ -0,0 +1,113 @@
+// Package log provides interfaces to write structured logs
+package log
+
+import (
+	"encoding/json"
+	"fmt"
+	"os"
+	"time"
+)
+
+const (
+	fieldKeyLevel         = "level"
+	fieldKeyMessage       = "msg"
+	fieldKeyTimestamp     = "ts"
+	fieldKeyUnixTimestamp = "ts_unix"
+
+	levelInfo  = "info"
+	levelWarn  = "warn"
+	levelError = "error"
+)
+
+// Fields represents a set of information to be included in the log
+type Fields map[string]interface{}
+
+// Entry represents a log entry
+type Entry struct {
+	Fields    Fields
+	Timestamp time.Time
+}
+
+func newEntry(fields Fields) Entry {
+	return Entry{
+		Fields:    fields,
+		Timestamp: time.Now().UTC(),
+	}
+}
+
+// WithFields creates a log entry with the given fields
+func WithFields(fields Fields) Entry {
+	return newEntry(fields)
+}
+
+// Info logs the given entry at an info level
+func (e Entry) Info(msg string) {
+	e.write(levelInfo, msg)
+}
+
+// Warn logs the given entry at a warning level
+func (e Entry) Warn(msg string) {
+	e.write(levelWarn, msg)
+}
+
+// Error logs the given entry at an error level
+func (e Entry) Error(msg string) {
+	e.write(levelError, msg)
+}
+
+// ErrorWrap logs the given entry with the error message annotated by the given message
+func (e Entry) ErrorWrap(err error, msg string) {
+	m := fmt.Sprintf("%s: %v", msg, err)
+
+	e.Error(m)
+}
+
+func (e Entry) formatJSON(level, msg string) []byte {
+	data := make(Fields, len(e.Fields)+4)
+
+	data[fieldKeyLevel] = level
+	data[fieldKeyMessage] = msg
+	data[fieldKeyTimestamp] = e.Timestamp
+	data[fieldKeyUnixTimestamp] = e.Timestamp.Unix()
+
+	for k, v := range e.Fields {
+		switch v := v.(type) {
+		case error:
+			data[k] = v.Error()
+		default:
+			data[k] = v
+		}
+	}
+
+	serialized, err := json.Marshal(data)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "formatting JSON: %v\n", err)
+	}
+
+	return serialized
+}
+
+func (e Entry) write(level, msg string) {
+	serialized := e.formatJSON(level, msg)
+
+	_, err := fmt.Fprintln(os.Stderr, string(serialized))
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "writing to stderr: %v\n", err)
+	}
+}
+
+// Info logs an info message without additional fields
+func Info(msg string) {
+	newEntry(Fields{}).Info(msg)
+}
+
+// Error logs an error message without additional fields
+func Error(msg string) {
+	newEntry(Fields{}).Error(msg)
+}
+
+// ErrorWrap logs an error message without additional fields. It annotates the given error's
+// message with the given message
+func ErrorWrap(err error, msg string) {
+	newEntry(Fields{}).ErrorWrap(err, msg)
+}