diff --git a/app.go b/app.go
index 79b7145..4b9e840 100644
--- a/app.go
+++ b/app.go
@@ -1,760 +1,766 @@
 /*
  * Copyright © 2018-2019 A Bunch Tell LLC.
  *
  * This file is part of WriteFreely.
  *
  * WriteFreely is free software: you can redistribute it and/or modify
  * it under the terms of the GNU Affero General Public License, included
  * in the LICENSE file in this source code package.
  */
 
 package writefreely
 
 import (
 	"database/sql"
 	"fmt"
 	"html/template"
 	"io/ioutil"
 	"net/http"
 	"net/url"
 	"os"
 	"os/signal"
 	"path/filepath"
 	"regexp"
 	"strings"
 	"syscall"
 	"time"
 
 	"github.com/gorilla/mux"
 	"github.com/gorilla/schema"
 	"github.com/gorilla/sessions"
 	"github.com/manifoldco/promptui"
 	"github.com/writeas/go-strip-markdown"
 	"github.com/writeas/impart"
 	"github.com/writeas/web-core/auth"
 	"github.com/writeas/web-core/converter"
 	"github.com/writeas/web-core/log"
 	"github.com/writeas/writefreely/author"
 	"github.com/writeas/writefreely/config"
 	"github.com/writeas/writefreely/key"
 	"github.com/writeas/writefreely/migrations"
 	"github.com/writeas/writefreely/page"
 )
 
 const (
 	staticDir       = "static"
 	assumedTitleLen = 80
 	postsPerPage    = 10
 
 	serverSoftware = "WriteFreely"
 	softwareURL    = "https://writefreely.org"
 )
 
 var (
 	debugging bool
 
 	// Software version can be set from git env using -ldflags
 	softwareVer = "0.10.0"
 
 	// DEPRECATED VARS
 	isSingleUser bool
 )
 
 // App holds data and configuration for an individual WriteFreely instance.
 type App struct {
 	router       *mux.Router
 	shttp        *http.ServeMux
 	db           *datastore
 	cfg          *config.Config
 	cfgFile      string
 	keys         *key.Keychain
 	sessionStore *sessions.CookieStore
 	formDecoder  *schema.Decoder
 
 	timeline *localTimeline
 }
 
 // DB returns the App's datastore
 func (app *App) DB() *datastore {
 	return app.db
 }
 
 // Router returns the App's router
 func (app *App) Router() *mux.Router {
 	return app.router
 }
 
 // Config returns the App's current configuration.
 func (app *App) Config() *config.Config {
 	return app.cfg
 }
 
 // SetConfig updates the App's Config to the given value.
 func (app *App) SetConfig(cfg *config.Config) {
 	app.cfg = cfg
 }
 
 // SetKeys updates the App's Keychain to the given value.
 func (app *App) SetKeys(k *key.Keychain) {
 	app.keys = k
 }
 
 // Apper is the interface for getting data into and out of a WriteFreely
 // instance (or "App").
 //
 // App returns the App for the current instance.
 //
 // LoadConfig reads an app configuration into the App, returning any error
 // encountered.
 //
 // SaveConfig persists the current App configuration.
 //
 // LoadKeys reads the App's encryption keys and loads them into its
 // key.Keychain.
 type Apper interface {
 	App() *App
 
 	LoadConfig() error
 	SaveConfig(*config.Config) error
 
 	LoadKeys() error
+
+	ReqLog(r *http.Request, status int, timeSince time.Duration) string
 }
 
 // App returns the App
 func (app *App) App() *App {
 	return app
 }
 
 // LoadConfig loads and parses a config file.
 func (app *App) LoadConfig() error {
 	log.Info("Loading %s configuration...", app.cfgFile)
 	cfg, err := config.Load(app.cfgFile)
 	if err != nil {
 		log.Error("Unable to load configuration: %v", err)
 		os.Exit(1)
 		return err
 	}
 	app.cfg = cfg
 	return nil
 }
 
 // SaveConfig saves the given Config to disk -- namely, to the App's cfgFile.
 func (app *App) SaveConfig(c *config.Config) error {
 	return config.Save(c, app.cfgFile)
 }
 
 // LoadKeys reads all needed keys from disk into the App. In order to use the
 // configured `Server.KeysParentDir`, you must call initKeyPaths(App) before
 // this.
 func (app *App) LoadKeys() error {
 	var err error
 	app.keys = &key.Keychain{}
 
 	if debugging {
 		log.Info("  %s", emailKeyPath)
 	}
 	app.keys.EmailKey, err = ioutil.ReadFile(emailKeyPath)
 	if err != nil {
 		return err
 	}
 
 	if debugging {
 		log.Info("  %s", cookieAuthKeyPath)
 	}
 	app.keys.CookieAuthKey, err = ioutil.ReadFile(cookieAuthKeyPath)
 	if err != nil {
 		return err
 	}
 
 	if debugging {
 		log.Info("  %s", cookieKeyPath)
 	}
 	app.keys.CookieKey, err = ioutil.ReadFile(cookieKeyPath)
 	if err != nil {
 		return err
 	}
 
 	return nil
 }
 
+func (app *App) ReqLog(r *http.Request, status int, timeSince time.Duration) string {
+	return fmt.Sprintf("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, timeSince, r.UserAgent())
+}
+
 // handleViewHome shows page at root path. Will be the Pad if logged in and the
 // catch-all landing page otherwise.
 func handleViewHome(app *App, w http.ResponseWriter, r *http.Request) error {
 	if app.cfg.App.SingleUser {
 		// Render blog index
 		return handleViewCollection(app, w, r)
 	}
 
 	// Multi-user instance
 	forceLanding := r.FormValue("landing") == "1"
 	if !forceLanding {
 		// Show correct page based on user auth status and configured landing path
 		u := getUserSession(app, r)
 		if u != nil {
 			// User is logged in, so show the Pad
 			return handleViewPad(app, w, r)
 		}
 
 		if land := app.cfg.App.LandingPath(); land != "/" {
 			return impart.HTTPError{http.StatusFound, land}
 		}
 	}
 
 	p := struct {
 		page.StaticPage
 		Flashes []template.HTML
 		Banner  template.HTML
 		Content template.HTML
 
 		ForcedLanding bool
 	}{
 		StaticPage:    pageForReq(app, r),
 		ForcedLanding: forceLanding,
 	}
 
 	banner, err := getLandingBanner(app)
 	if err != nil {
 		log.Error("unable to get landing banner: %v", err)
 		return impart.HTTPError{http.StatusInternalServerError, fmt.Sprintf("Could not get banner: %v", err)}
 	}
 	p.Banner = template.HTML(applyMarkdown([]byte(banner.Content), ""))
 
 	content, err := getLandingBody(app)
 	if err != nil {
 		log.Error("unable to get landing content: %v", err)
 		return impart.HTTPError{http.StatusInternalServerError, fmt.Sprintf("Could not get content: %v", err)}
 	}
 	p.Content = template.HTML(applyMarkdown([]byte(content.Content), ""))
 
 	// Get error messages
 	session, err := app.sessionStore.Get(r, cookieName)
 	if err != nil {
 		// Ignore this
 		log.Error("Unable to get session in handleViewHome; ignoring: %v", err)
 	}
 	flashes, _ := getSessionFlashes(app, w, r, session)
 	for _, flash := range flashes {
 		p.Flashes = append(p.Flashes, template.HTML(flash))
 	}
 
 	// Show landing page
 	return renderPage(w, "landing.tmpl", p)
 }
 
 func handleTemplatedPage(app *App, w http.ResponseWriter, r *http.Request, t *template.Template) error {
 	p := struct {
 		page.StaticPage
 		ContentTitle string
 		Content      template.HTML
 		PlainContent string
 		Updated      string
 
 		AboutStats *InstanceStats
 	}{
 		StaticPage: pageForReq(app, r),
 	}
 	if r.URL.Path == "/about" || r.URL.Path == "/privacy" {
 		var c *instanceContent
 		var err error
 
 		if r.URL.Path == "/about" {
 			c, err = getAboutPage(app)
 
 			// Fetch stats
 			p.AboutStats = &InstanceStats{}
 			p.AboutStats.NumPosts, _ = app.db.GetTotalPosts()
 			p.AboutStats.NumBlogs, _ = app.db.GetTotalCollections()
 		} else {
 			c, err = getPrivacyPage(app)
 		}
 
 		if err != nil {
 			return err
 		}
 		p.ContentTitle = c.Title.String
 		p.Content = template.HTML(applyMarkdown([]byte(c.Content), ""))
 		p.PlainContent = shortPostDescription(stripmd.Strip(c.Content))
 		if !c.Updated.IsZero() {
 			p.Updated = c.Updated.Format("January 2, 2006")
 		}
 	}
 
 	// Serve templated page
 	err := t.ExecuteTemplate(w, "base", p)
 	if err != nil {
 		log.Error("Unable to render page: %v", err)
 	}
 	return nil
 }
 
 func pageForReq(app *App, r *http.Request) page.StaticPage {
 	p := page.StaticPage{
 		AppCfg:  app.cfg.App,
 		Path:    r.URL.Path,
 		Version: "v" + softwareVer,
 	}
 
 	// Add user information, if given
 	var u *User
 	accessToken := r.FormValue("t")
 	if accessToken != "" {
 		userID := app.db.GetUserID(accessToken)
 		if userID != -1 {
 			var err error
 			u, err = app.db.GetUserByID(userID)
 			if err == nil {
 				p.Username = u.Username
 			}
 		}
 	} else {
 		u = getUserSession(app, r)
 		if u != nil {
 			p.Username = u.Username
 		}
 	}
 	p.CanViewReader = !app.cfg.App.Private || u != nil
 
 	return p
 }
 
 var fileRegex = regexp.MustCompile("/([^/]*\\.[^/]*)$")
 
 // Initialize loads the app configuration and initializes templates, keys,
 // session, route handlers, and the database connection.
 func Initialize(apper Apper, debug bool) (*App, error) {
 	debugging = debug
 
 	apper.LoadConfig()
 
 	// Load templates
 	err := InitTemplates(apper.App().Config())
 	if err != nil {
 		return nil, fmt.Errorf("load templates: %s", err)
 	}
 
 	// Load keys and set up session
 	initKeyPaths(apper.App()) // TODO: find a better way to do this, since it's unneeded in all Apper implementations
 	err = InitKeys(apper)
 	if err != nil {
 		return nil, fmt.Errorf("init keys: %s", err)
 	}
 	apper.App().InitSession()
 
 	apper.App().InitDecoder()
 
 	err = ConnectToDatabase(apper.App())
 	if err != nil {
 		return nil, fmt.Errorf("connect to DB: %s", err)
 	}
 
 	// Handle local timeline, if enabled
 	if apper.App().cfg.App.LocalTimeline {
 		log.Info("Initializing local timeline...")
 		initLocalTimeline(apper.App())
 	}
 
 	return apper.App(), nil
 }
 
 func Serve(app *App, r *mux.Router) {
 	log.Info("Going to serve...")
 
 	isSingleUser = app.cfg.App.SingleUser
 	app.cfg.Server.Dev = debugging
 
 	// Handle shutdown
 	c := make(chan os.Signal, 2)
 	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
 	go func() {
 		<-c
 		log.Info("Shutting down...")
 		shutdown(app)
 		log.Info("Done.")
 		os.Exit(0)
 	}()
 
 	// Start web application server
 	var bindAddress = app.cfg.Server.Bind
 	if bindAddress == "" {
 		bindAddress = "localhost"
 	}
 	var err error
 	if app.cfg.IsSecureStandalone() {
 		log.Info("Serving redirects on http://%s:80", bindAddress)
 		go func() {
 			err = http.ListenAndServe(
 				fmt.Sprintf("%s:80", bindAddress), http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 					http.Redirect(w, r, app.cfg.App.Host, http.StatusMovedPermanently)
 				}))
 			log.Error("Unable to start redirect server: %v", err)
 		}()
 
 		log.Info("Serving on https://%s:443", bindAddress)
 		log.Info("---")
 		err = http.ListenAndServeTLS(
 			fmt.Sprintf("%s:443", bindAddress), app.cfg.Server.TLSCertPath, app.cfg.Server.TLSKeyPath, r)
 	} else {
 		log.Info("Serving on http://%s:%d\n", bindAddress, app.cfg.Server.Port)
 		log.Info("---")
 		err = http.ListenAndServe(fmt.Sprintf("%s:%d", bindAddress, app.cfg.Server.Port), r)
 	}
 	if err != nil {
 		log.Error("Unable to start: %v", err)
 		os.Exit(1)
 	}
 }
 
 func (app *App) InitDecoder() {
 	// TODO: do this at the package level, instead of the App level
 	// Initialize modules
 	app.formDecoder = schema.NewDecoder()
 	app.formDecoder.RegisterConverter(converter.NullJSONString{}, converter.ConvertJSONNullString)
 	app.formDecoder.RegisterConverter(converter.NullJSONBool{}, converter.ConvertJSONNullBool)
 	app.formDecoder.RegisterConverter(sql.NullString{}, converter.ConvertSQLNullString)
 	app.formDecoder.RegisterConverter(sql.NullBool{}, converter.ConvertSQLNullBool)
 	app.formDecoder.RegisterConverter(sql.NullInt64{}, converter.ConvertSQLNullInt64)
 	app.formDecoder.RegisterConverter(sql.NullFloat64{}, converter.ConvertSQLNullFloat64)
 }
 
 // ConnectToDatabase validates and connects to the configured database, then
 // tests the connection.
 func ConnectToDatabase(app *App) error {
 	// Check database configuration
 	if app.cfg.Database.Type == driverMySQL && (app.cfg.Database.User == "" || app.cfg.Database.Password == "") {
 		return fmt.Errorf("Database user or password not set.")
 	}
 	if app.cfg.Database.Host == "" {
 		app.cfg.Database.Host = "localhost"
 	}
 	if app.cfg.Database.Database == "" {
 		app.cfg.Database.Database = "writefreely"
 	}
 
 	// TODO: check err
 	connectToDatabase(app)
 
 	// Test database connection
 	err := app.db.Ping()
 	if err != nil {
 		return fmt.Errorf("Database ping failed: %s", err)
 	}
 
 	return nil
 }
 
 // OutputVersion prints out the version of the application.
 func OutputVersion() {
 	fmt.Println(serverSoftware + " " + softwareVer)
 }
 
 // NewApp creates a new app instance.
 func NewApp(cfgFile string) *App {
 	return &App{
 		cfgFile: cfgFile,
 	}
 }
 
 // CreateConfig creates a default configuration and saves it to the app's cfgFile.
 func CreateConfig(app *App) error {
 	log.Info("Creating configuration...")
 	c := config.New()
 	log.Info("Saving configuration %s...", app.cfgFile)
 	err := config.Save(c, app.cfgFile)
 	if err != nil {
 		return fmt.Errorf("Unable to save configuration: %v", err)
 	}
 	return nil
 }
 
 // DoConfig runs the interactive configuration process.
 func DoConfig(app *App, configSections string) {
 	if configSections == "" {
 		configSections = "server db app"
 	}
 	// let's check there aren't any garbage in the list
 	configSectionsArray := strings.Split(configSections, " ")
 	for _, element := range configSectionsArray {
 		if element != "server" && element != "db" && element != "app" {
 			log.Error("Invalid argument to --sections. Valid arguments are only \"server\", \"db\" and \"app\"")
 			os.Exit(1)
 		}
 	}
 	d, err := config.Configure(app.cfgFile, configSections)
 	if err != nil {
 		log.Error("Unable to configure: %v", err)
 		os.Exit(1)
 	}
 	app.cfg = d.Config
 	connectToDatabase(app)
 	defer shutdown(app)
 
 	if !app.db.DatabaseInitialized() {
 		err = adminInitDatabase(app)
 		if err != nil {
 			log.Error(err.Error())
 			os.Exit(1)
 		}
 	} else {
 		log.Info("Database already initialized.")
 	}
 
 	if d.User != nil {
 		u := &User{
 			Username:   d.User.Username,
 			HashedPass: d.User.HashedPass,
 			Created:    time.Now().Truncate(time.Second).UTC(),
 		}
 
 		// Create blog
 		log.Info("Creating user %s...\n", u.Username)
 		err = app.db.CreateUser(u, app.cfg.App.SiteName)
 		if err != nil {
 			log.Error("Unable to create user: %s", err)
 			os.Exit(1)
 		}
 		log.Info("Done!")
 	}
 	os.Exit(0)
 }
 
 // GenerateKeyFiles creates app encryption keys and saves them into the configured KeysParentDir.
 func GenerateKeyFiles(app *App) error {
 	// Read keys path from config
 	app.LoadConfig()
 
 	// Create keys dir if it doesn't exist yet
 	fullKeysDir := filepath.Join(app.cfg.Server.KeysParentDir, keysDir)
 	if _, err := os.Stat(fullKeysDir); os.IsNotExist(err) {
 		err = os.Mkdir(fullKeysDir, 0700)
 		if err != nil {
 			return err
 		}
 	}
 
 	// Generate keys
 	initKeyPaths(app)
 	// TODO: use something like https://github.com/hashicorp/go-multierror to return errors
 	var keyErrs error
 	err := generateKey(emailKeyPath)
 	if err != nil {
 		keyErrs = err
 	}
 	err = generateKey(cookieAuthKeyPath)
 	if err != nil {
 		keyErrs = err
 	}
 	err = generateKey(cookieKeyPath)
 	if err != nil {
 		keyErrs = err
 	}
 
 	return keyErrs
 }
 
 // CreateSchema creates all database tables needed for the application.
 func CreateSchema(apper Apper) error {
 	apper.LoadConfig()
 	connectToDatabase(apper.App())
 	defer shutdown(apper.App())
 	err := adminInitDatabase(apper.App())
 	if err != nil {
 		return err
 	}
 	return nil
 }
 
 // Migrate runs all necessary database migrations.
 func Migrate(apper Apper) error {
 	apper.LoadConfig()
 	connectToDatabase(apper.App())
 	defer shutdown(apper.App())
 
 	err := migrations.Migrate(migrations.NewDatastore(apper.App().db.DB, apper.App().db.driverName))
 	if err != nil {
 		return fmt.Errorf("migrate: %s", err)
 	}
 	return nil
 }
 
 // ResetPassword runs the interactive password reset process.
 func ResetPassword(apper Apper, username string) error {
 	// Connect to the database
 	apper.LoadConfig()
 	connectToDatabase(apper.App())
 	defer shutdown(apper.App())
 
 	// Fetch user
 	u, err := apper.App().db.GetUserForAuth(username)
 	if err != nil {
 		log.Error("Get user: %s", err)
 		os.Exit(1)
 	}
 
 	// Prompt for new password
 	prompt := promptui.Prompt{
 		Templates: &promptui.PromptTemplates{
 			Success: "{{ . | bold | faint }}: ",
 		},
 		Label: "New password",
 		Mask:  '*',
 	}
 	newPass, err := prompt.Run()
 	if err != nil {
 		log.Error("%s", err)
 		os.Exit(1)
 	}
 
 	// Do the update
 	log.Info("Updating...")
 	err = adminResetPassword(apper.App(), u, newPass)
 	if err != nil {
 		log.Error("%s", err)
 		os.Exit(1)
 	}
 	log.Info("Success.")
 	return nil
 }
 
 func connectToDatabase(app *App) {
 	log.Info("Connecting to %s database...", app.cfg.Database.Type)
 
 	var db *sql.DB
 	var err error
 	if app.cfg.Database.Type == driverMySQL {
 		db, err = sql.Open(app.cfg.Database.Type, fmt.Sprintf("%s:%s@tcp(%s:%d)/%s?charset=utf8mb4&parseTime=true&loc=%s", app.cfg.Database.User, app.cfg.Database.Password, app.cfg.Database.Host, app.cfg.Database.Port, app.cfg.Database.Database, url.QueryEscape(time.Local.String())))
 		db.SetMaxOpenConns(50)
 	} else if app.cfg.Database.Type == driverSQLite {
 		if !SQLiteEnabled {
 			log.Error("Invalid database type '%s'. Binary wasn't compiled with SQLite3 support.", app.cfg.Database.Type)
 			os.Exit(1)
 		}
 		if app.cfg.Database.FileName == "" {
 			log.Error("SQLite database filename value in config.ini is empty.")
 			os.Exit(1)
 		}
 		db, err = sql.Open("sqlite3_with_regex", app.cfg.Database.FileName+"?parseTime=true&cached=shared")
 		db.SetMaxOpenConns(1)
 	} else {
 		log.Error("Invalid database type '%s'. Only 'mysql' and 'sqlite3' are supported right now.", app.cfg.Database.Type)
 		os.Exit(1)
 	}
 	if err != nil {
 		log.Error("%s", err)
 		os.Exit(1)
 	}
 	app.db = &datastore{db, app.cfg.Database.Type}
 }
 
 func shutdown(app *App) {
 	log.Info("Closing database connection...")
 	app.db.Close()
 }
 
 // CreateUser creates a new admin or normal user from the given credentials.
 func CreateUser(apper Apper, username, password string, isAdmin bool) error {
 	// Create an admin user with --create-admin
 	apper.LoadConfig()
 	connectToDatabase(apper.App())
 	defer shutdown(apper.App())
 
 	// Ensure an admin / first user doesn't already exist
 	firstUser, _ := apper.App().db.GetUserByID(1)
 	if isAdmin {
 		// Abort if trying to create admin user, but one already exists
 		if firstUser != nil {
 			return fmt.Errorf("Admin user already exists (%s). Create a regular user with: writefreely --create-user", firstUser.Username)
 		}
 	} else {
 		// Abort if trying to create regular user, but no admin exists yet
 		if firstUser == nil {
 			return fmt.Errorf("No admin user exists yet. Create an admin first with: writefreely --create-admin")
 		}
 	}
 
 	// Create the user
 	// Normalize and validate username
 	desiredUsername := username
 	username = getSlug(username, "")
 
 	usernameDesc := username
 	if username != desiredUsername {
 		usernameDesc += " (originally: " + desiredUsername + ")"
 	}
 
 	if !author.IsValidUsername(apper.App().cfg, username) {
 		return fmt.Errorf("Username %s is invalid, reserved, or shorter than configured minimum length (%d characters).", usernameDesc, apper.App().cfg.App.MinUsernameLen)
 	}
 
 	// Hash the password
 	hashedPass, err := auth.HashPass([]byte(password))
 	if err != nil {
 		return fmt.Errorf("Unable to hash password: %v", err)
 	}
 
 	u := &User{
 		Username:   username,
 		HashedPass: hashedPass,
 		Created:    time.Now().Truncate(time.Second).UTC(),
 	}
 
 	userType := "user"
 	if isAdmin {
 		userType = "admin"
 	}
 	log.Info("Creating %s %s...", userType, usernameDesc)
 	err = apper.App().db.CreateUser(u, desiredUsername)
 	if err != nil {
 		return fmt.Errorf("Unable to create user: %s", err)
 	}
 	log.Info("Done!")
 	return nil
 }
 
 func adminInitDatabase(app *App) error {
 	schemaFileName := "schema.sql"
 	if app.cfg.Database.Type == driverSQLite {
 		schemaFileName = "sqlite.sql"
 	}
 
 	schema, err := Asset(schemaFileName)
 	if err != nil {
 		return fmt.Errorf("Unable to load schema file: %v", err)
 	}
 
 	tblReg := regexp.MustCompile("CREATE TABLE (IF NOT EXISTS )?`([a-z_]+)`")
 
 	queries := strings.Split(string(schema), ";\n")
 	for _, q := range queries {
 		if strings.TrimSpace(q) == "" {
 			continue
 		}
 		parts := tblReg.FindStringSubmatch(q)
 		if len(parts) >= 3 {
 			log.Info("Creating table %s...", parts[2])
 		} else {
 			log.Info("Creating table ??? (Weird query) No match in: %v", parts)
 		}
 		_, err = app.db.Exec(q)
 		if err != nil {
 			log.Error("%s", err)
 		} else {
 			log.Info("Created.")
 		}
 	}
 
 	// Set up migrations table
 	log.Info("Initializing appmigrations table...")
 	err = migrations.SetInitialMigrations(migrations.NewDatastore(app.db.DB, app.db.driverName))
 	if err != nil {
 		return fmt.Errorf("Unable to set initial migrations: %v", err)
 	}
 
 	log.Info("Running migrations...")
 	err = migrations.Migrate(migrations.NewDatastore(app.db.DB, app.db.driverName))
 	if err != nil {
 		return fmt.Errorf("migrate: %s", err)
 	}
 
 	log.Info("Done.")
 	return nil
 }
diff --git a/handle.go b/handle.go
index 4f137b9..1e5e8f6 100644
--- a/handle.go
+++ b/handle.go
@@ -1,844 +1,844 @@
 /*
  * Copyright © 2018-2019 A Bunch Tell LLC.
  *
  * This file is part of WriteFreely.
  *
  * WriteFreely is free software: you can redistribute it and/or modify
  * it under the terms of the GNU Affero General Public License, included
  * in the LICENSE file in this source code package.
  */
 
 package writefreely
 
 import (
 	"fmt"
 	"html/template"
 	"net/http"
 	"net/url"
 	"runtime/debug"
 	"strconv"
 	"strings"
 	"time"
 
 	"github.com/gorilla/sessions"
 	"github.com/writeas/impart"
 	"github.com/writeas/web-core/log"
 	"github.com/writeas/writefreely/config"
 	"github.com/writeas/writefreely/page"
 )
 
 // UserLevel represents the required user level for accessing an endpoint
 type UserLevel int
 
 const (
 	UserLevelNoneType         UserLevel = iota // user or not -- ignored
 	UserLevelOptionalType                      // user or not -- object fetched if user
 	UserLevelNoneRequiredType                  // non-user (required)
 	UserLevelUserType                          // user (required)
 )
 
 func UserLevelNone(cfg *config.Config) UserLevel {
 	return UserLevelNoneType
 }
 
 func UserLevelOptional(cfg *config.Config) UserLevel {
 	return UserLevelOptionalType
 }
 
 func UserLevelNoneRequired(cfg *config.Config) UserLevel {
 	return UserLevelNoneRequiredType
 }
 
 func UserLevelUser(cfg *config.Config) UserLevel {
 	return UserLevelUserType
 }
 
 // UserLevelReader returns the permission level required for any route where
 // users can read published content.
 func UserLevelReader(cfg *config.Config) UserLevel {
 	if cfg.App.Private {
 		return UserLevelUserType
 	}
 	return UserLevelOptionalType
 }
 
 type (
 	handlerFunc          func(app *App, w http.ResponseWriter, r *http.Request) error
 	userHandlerFunc      func(app *App, u *User, w http.ResponseWriter, r *http.Request) error
 	userApperHandlerFunc func(apper Apper, u *User, w http.ResponseWriter, r *http.Request) error
 	dataHandlerFunc      func(app *App, w http.ResponseWriter, r *http.Request) ([]byte, string, error)
 	authFunc             func(app *App, r *http.Request) (*User, error)
 	UserLevelFunc        func(cfg *config.Config) UserLevel
 )
 
 type Handler struct {
 	errors       *ErrorPages
 	sessionStore *sessions.CookieStore
 	app          Apper
 }
 
 // ErrorPages hold template HTML error pages for displaying errors to the user.
 // In each, there should be a defined template named "base".
 type ErrorPages struct {
 	NotFound            *template.Template
 	Gone                *template.Template
 	InternalServerError *template.Template
 	Blank               *template.Template
 }
 
 // NewHandler returns a new Handler instance, using the given StaticPage data,
 // and saving alias to the application's CookieStore.
 func NewHandler(apper Apper) *Handler {
 	h := &Handler{
 		errors: &ErrorPages{
 			NotFound:            template.Must(template.New("").Parse("{{define \"base\"}}<html><head><title>404</title></head><body><p>Not found.</p></body></html>{{end}}")),
 			Gone:                template.Must(template.New("").Parse("{{define \"base\"}}<html><head><title>410</title></head><body><p>Gone.</p></body></html>{{end}}")),
 			InternalServerError: template.Must(template.New("").Parse("{{define \"base\"}}<html><head><title>500</title></head><body><p>Internal server error.</p></body></html>{{end}}")),
 			Blank:               template.Must(template.New("").Parse("{{define \"base\"}}<html><head><title>{{.Title}}</title></head><body><p>{{.Content}}</p></body></html>{{end}}")),
 		},
 		sessionStore: apper.App().sessionStore,
 		app:          apper,
 	}
 
 	return h
 }
 
 // NewWFHandler returns a new Handler instance, using WriteFreely template files.
 // You MUST call writefreely.InitTemplates() before this.
 func NewWFHandler(apper Apper) *Handler {
 	h := NewHandler(apper)
 	h.SetErrorPages(&ErrorPages{
 		NotFound:            pages["404-general.tmpl"],
 		Gone:                pages["410.tmpl"],
 		InternalServerError: pages["500.tmpl"],
 		Blank:               pages["blank.tmpl"],
 	})
 	return h
 }
 
 // SetErrorPages sets the given set of ErrorPages as templates for any errors
 // that come up.
 func (h *Handler) SetErrorPages(e *ErrorPages) {
 	h.errors = e
 }
 
 // User handles requests made in the web application by the authenticated user.
 // This provides user-friendly HTML pages and actions that work in the browser.
 func (h *Handler) User(f userHandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s: %s", e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = http.StatusInternalServerError
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			u := getUserSession(h.app.App(), r)
 			if u == nil {
 				err := ErrNotLoggedIn
 				status = err.Status
 				return err
 			}
 
 			err := f(h.app.App(), u, w, r)
 			if err == nil {
 				status = http.StatusOK
 			} else if err, ok := err.(impart.HTTPError); ok {
 				status = err.Status
 			} else {
 				status = http.StatusInternalServerError
 			}
 
 			return err
 		}())
 	}
 }
 
 // Admin handles requests on /admin routes
 func (h *Handler) Admin(f userHandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s: %s", e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = http.StatusInternalServerError
 				}
 
-				log.Info(fmt.Sprintf("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent()))
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			u := getUserSession(h.app.App(), r)
 			if u == nil || !u.IsAdmin() {
 				err := impart.HTTPError{http.StatusNotFound, ""}
 				status = err.Status
 				return err
 			}
 
 			err := f(h.app.App(), u, w, r)
 			if err == nil {
 				status = http.StatusOK
 			} else if err, ok := err.(impart.HTTPError); ok {
 				status = err.Status
 			} else {
 				status = http.StatusInternalServerError
 			}
 
 			return err
 		}())
 	}
 }
 
 // AdminApper handles requests on /admin routes that require an Apper.
 func (h *Handler) AdminApper(f userApperHandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s: %s", e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = http.StatusInternalServerError
 				}
 
-				log.Info(fmt.Sprintf("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent()))
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			u := getUserSession(h.app.App(), r)
 			if u == nil || !u.IsAdmin() {
 				err := impart.HTTPError{http.StatusNotFound, ""}
 				status = err.Status
 				return err
 			}
 
 			err := f(h.app, u, w, r)
 			if err == nil {
 				status = http.StatusOK
 			} else if err, ok := err.(impart.HTTPError); ok {
 				status = err.Status
 			} else {
 				status = http.StatusInternalServerError
 			}
 
 			return err
 		}())
 	}
 }
 
 func apiAuth(app *App, r *http.Request) (*User, error) {
 	// Authorize user from Authorization header
 	t := r.Header.Get("Authorization")
 	if t == "" {
 		return nil, ErrNoAccessToken
 	}
 	u := &User{ID: app.db.GetUserID(t)}
 	if u.ID == -1 {
 		return nil, ErrBadAccessToken
 	}
 
 	return u, nil
 }
 
 // optionaAPIAuth is used for endpoints that accept authenticated requests via
 // Authorization header or cookie, unlike apiAuth. It returns a different err
 // in the case where no Authorization header is present.
 func optionalAPIAuth(app *App, r *http.Request) (*User, error) {
 	// Authorize user from Authorization header
 	t := r.Header.Get("Authorization")
 	if t == "" {
 		return nil, ErrNotLoggedIn
 	}
 	u := &User{ID: app.db.GetUserID(t)}
 	if u.ID == -1 {
 		return nil, ErrBadAccessToken
 	}
 
 	return u, nil
 }
 
 func webAuth(app *App, r *http.Request) (*User, error) {
 	u := getUserSession(app, r)
 	if u == nil {
 		return nil, ErrNotLoggedIn
 	}
 	return u, nil
 }
 
 // UserAPI handles requests made in the API by the authenticated user.
 // This provides user-friendly HTML pages and actions that work in the browser.
 func (h *Handler) UserAPI(f userHandlerFunc) http.HandlerFunc {
 	return h.UserAll(false, f, apiAuth)
 }
 
 func (h *Handler) UserAll(web bool, f userHandlerFunc, a authFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		handleFunc := func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s: %s", e, debug.Stack())
 					impart.WriteError(w, impart.HTTPError{http.StatusInternalServerError, "Something didn't work quite right."})
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			u, err := a(h.app.App(), r)
 			if err != nil {
 				if err, ok := err.(impart.HTTPError); ok {
 					status = err.Status
 				} else {
 					status = 500
 				}
 				return err
 			}
 
 			err = f(h.app.App(), u, w, r)
 			if err == nil {
 				status = 200
 			} else if err, ok := err.(impart.HTTPError); ok {
 				status = err.Status
 			} else {
 				status = 500
 			}
 
 			return err
 		}
 
 		if web {
 			h.handleHTTPError(w, r, handleFunc())
 		} else {
 			h.handleError(w, r, handleFunc())
 		}
 	}
 }
 
 func (h *Handler) RedirectOnErr(f handlerFunc, loc string) handlerFunc {
 	return func(app *App, w http.ResponseWriter, r *http.Request) error {
 		err := f(app, w, r)
 		if err != nil {
 			if ie, ok := err.(impart.HTTPError); ok {
 				// Override default redirect with returned error's, if it's a
 				// redirect error.
 				if ie.Status == http.StatusFound {
 					return ie
 				}
 			}
 			return impart.HTTPError{http.StatusFound, loc}
 		}
 		return nil
 	}
 }
 
 func (h *Handler) Page(n string) http.HandlerFunc {
 	return h.Web(func(app *App, w http.ResponseWriter, r *http.Request) error {
 		t, ok := pages[n]
 		if !ok {
 			return impart.HTTPError{http.StatusNotFound, "Page not found."}
 		}
 
 		sp := pageForReq(app, r)
 
 		err := t.ExecuteTemplate(w, "base", sp)
 		if err != nil {
 			log.Error("Unable to render page: %v", err)
 		}
 		return err
 	}, UserLevelOptional)
 }
 
 func (h *Handler) WebErrors(f handlerFunc, ul UserLevelFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		// TODO: factor out this logic shared with Web()
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					u := getUserSession(h.app.App(), r)
 					username := "None"
 					if u != nil {
 						username = u.Username
 					}
 					log.Error("User: %s\n\n%s: %s", username, e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			var session *sessions.Session
 			var err error
 			if ul(h.app.App().cfg) != UserLevelNoneType {
 				session, err = h.sessionStore.Get(r, cookieName)
 				if err != nil && (ul(h.app.App().cfg) == UserLevelNoneRequiredType || ul(h.app.App().cfg) == UserLevelUserType) {
 					// Cookie is required, but we can ignore this error
 					log.Error("Handler: Unable to get session (for user permission %d); ignoring: %v", ul(h.app.App().cfg), err)
 				}
 
 				_, gotUser := session.Values[cookieUserVal].(*User)
 				if ul(h.app.App().cfg) == UserLevelNoneRequiredType && gotUser {
 					to := correctPageFromLoginAttempt(r)
 					log.Info("Handler: Required NO user, but got one. Redirecting to %s", to)
 					err := impart.HTTPError{http.StatusFound, to}
 					status = err.Status
 					return err
 				} else if ul(h.app.App().cfg) == UserLevelUserType && !gotUser {
 					log.Info("Handler: Required a user, but DIDN'T get one. Sending not logged in.")
 					err := ErrNotLoggedIn
 					status = err.Status
 					return err
 				}
 			}
 
 			// TODO: pass User object to function
 			err = f(h.app.App(), w, r)
 			if err == nil {
 				status = 200
 			} else if httpErr, ok := err.(impart.HTTPError); ok {
 				status = httpErr.Status
 				if status < 300 || status > 399 {
 					addSessionFlash(h.app.App(), w, r, httpErr.Message, session)
 					return impart.HTTPError{http.StatusFound, r.Referer()}
 				}
 			} else {
 				e := fmt.Sprintf("[Web handler] 500: %v", err)
 				if !strings.HasSuffix(e, "write: broken pipe") {
 					log.Error(e)
 				} else {
 					log.Error(e)
 				}
 				log.Info("Web handler internal error render")
 				h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 				status = 500
 			}
 
 			return err
 		}())
 	}
 }
 
 func (h *Handler) CollectionPostOrStatic(w http.ResponseWriter, r *http.Request) {
 	if strings.Contains(r.URL.Path, ".") && !isRaw(r) {
 		start := time.Now()
 		status := 200
 		defer func() {
-			log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+			log.Info(h.app.ReqLog(r, status, time.Since(start)))
 		}()
 
 		// Serve static file
 		h.app.App().shttp.ServeHTTP(w, r)
 		return
 	}
 
 	h.Web(viewCollectionPost, UserLevelReader)(w, r)
 }
 
 // Web handles requests made in the web application. This provides user-
 // friendly HTML pages and actions that work in the browser.
 func (h *Handler) Web(f handlerFunc, ul UserLevelFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					u := getUserSession(h.app.App(), r)
 					username := "None"
 					if u != nil {
 						username = u.Username
 					}
 					log.Error("User: %s\n\n%s: %s", username, e, debug.Stack())
 					log.Info("Web deferred internal error render")
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			if ul(h.app.App().cfg) != UserLevelNoneType {
 				session, err := h.sessionStore.Get(r, cookieName)
 				if err != nil && (ul(h.app.App().cfg) == UserLevelNoneRequiredType || ul(h.app.App().cfg) == UserLevelUserType) {
 					// Cookie is required, but we can ignore this error
 					log.Error("Handler: Unable to get session (for user permission %d); ignoring: %v", ul(h.app.App().cfg), err)
 				}
 
 				_, gotUser := session.Values[cookieUserVal].(*User)
 				if ul(h.app.App().cfg) == UserLevelNoneRequiredType && gotUser {
 					to := correctPageFromLoginAttempt(r)
 					log.Info("Handler: Required NO user, but got one. Redirecting to %s", to)
 					err := impart.HTTPError{http.StatusFound, to}
 					status = err.Status
 					return err
 				} else if ul(h.app.App().cfg) == UserLevelUserType && !gotUser {
 					log.Info("Handler: Required a user, but DIDN'T get one. Sending not logged in.")
 					err := ErrNotLoggedIn
 					status = err.Status
 					return err
 				}
 			}
 
 			// TODO: pass User object to function
 			err := f(h.app.App(), w, r)
 			if err == nil {
 				status = 200
 			} else if httpErr, ok := err.(impart.HTTPError); ok {
 				status = httpErr.Status
 			} else {
 				e := fmt.Sprintf("[Web handler] 500: %v", err)
 				log.Error(e)
 				log.Info("Web internal error render")
 				h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 				status = 500
 			}
 
 			return err
 		}())
 	}
 }
 
 func (h *Handler) All(f handlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleError(w, r, func() error {
 			// TODO: return correct "success" status
 			status := 200
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s:\n%s", e, debug.Stack())
 					impart.WriteError(w, impart.HTTPError{http.StatusInternalServerError, "Something didn't work quite right."})
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			// TODO: do any needed authentication
 
 			err := f(h.app.App(), w, r)
 			if err != nil {
 				if err, ok := err.(impart.HTTPError); ok {
 					status = err.Status
 				} else {
 					status = 500
 				}
 			}
 
 			return err
 		}())
 	}
 }
 
 func (h *Handler) AllReader(f handlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleError(w, r, func() error {
 			status := 200
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s:\n%s", e, debug.Stack())
 					impart.WriteError(w, impart.HTTPError{http.StatusInternalServerError, "Something didn't work quite right."})
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			if h.app.App().cfg.App.Private {
 				// This instance is private, so ensure it's being accessed by a valid user
 				// Check if authenticated with an access token
 				_, apiErr := optionalAPIAuth(h.app.App(), r)
 				if apiErr != nil {
 					if err, ok := apiErr.(impart.HTTPError); ok {
 						status = err.Status
 					} else {
 						status = 500
 					}
 
 					if apiErr == ErrNotLoggedIn {
 						// Fall back to web auth since there was no access token given
 						_, err := webAuth(h.app.App(), r)
 						if err != nil {
 							if err, ok := apiErr.(impart.HTTPError); ok {
 								status = err.Status
 							} else {
 								status = 500
 							}
 							return err
 						}
 					} else {
 						return apiErr
 					}
 				}
 			}
 
 			err := f(h.app.App(), w, r)
 			if err != nil {
 				if err, ok := err.(impart.HTTPError); ok {
 					status = err.Status
 				} else {
 					status = 500
 				}
 			}
 
 			return err
 		}())
 	}
 }
 
 func (h *Handler) Download(f dataHandlerFunc, ul UserLevelFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			var status int
 			start := time.Now()
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("%s: %s", e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = 500
 				}
 
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			data, filename, err := f(h.app.App(), w, r)
 			if err != nil {
 				if err, ok := err.(impart.HTTPError); ok {
 					status = err.Status
 				} else {
 					status = 500
 				}
 				return err
 			}
 
 			ext := ".json"
 			ct := "application/json"
 			if strings.HasSuffix(r.URL.Path, ".csv") {
 				ext = ".csv"
 				ct = "text/csv"
 			} else if strings.HasSuffix(r.URL.Path, ".zip") {
 				ext = ".zip"
 				ct = "application/zip"
 			}
 			w.Header().Set("Content-Disposition", fmt.Sprintf("attachment; filename=%s%s", filename, ext))
 			w.Header().Set("Content-Type", ct)
 			w.Header().Set("Content-Length", strconv.Itoa(len(data)))
 			fmt.Fprint(w, string(data))
 
 			status = 200
 			return nil
 		}())
 	}
 }
 
 func (h *Handler) Redirect(url string, ul UserLevelFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			start := time.Now()
 
 			var status int
 			if ul(h.app.App().cfg) != UserLevelNoneType {
 				session, err := h.sessionStore.Get(r, cookieName)
 				if err != nil && (ul(h.app.App().cfg) == UserLevelNoneRequiredType || ul(h.app.App().cfg) == UserLevelUserType) {
 					// Cookie is required, but we can ignore this error
 					log.Error("Handler: Unable to get session (for user permission %d); ignoring: %v", ul(h.app.App().cfg), err)
 				}
 
 				_, gotUser := session.Values[cookieUserVal].(*User)
 				if ul(h.app.App().cfg) == UserLevelNoneRequiredType && gotUser {
 					to := correctPageFromLoginAttempt(r)
 					log.Info("Handler: Required NO user, but got one. Redirecting to %s", to)
 					err := impart.HTTPError{http.StatusFound, to}
 					status = err.Status
 					return err
 				} else if ul(h.app.App().cfg) == UserLevelUserType && !gotUser {
 					log.Info("Handler: Required a user, but DIDN'T get one. Sending not logged in.")
 					err := ErrNotLoggedIn
 					status = err.Status
 					return err
 				}
 			}
 
 			status = sendRedirect(w, http.StatusFound, url)
 
-			log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+			log.Info(h.app.ReqLog(r, status, time.Since(start)))
 
 			return nil
 		}())
 	}
 }
 
 func (h *Handler) handleHTTPError(w http.ResponseWriter, r *http.Request, err error) {
 	if err == nil {
 		return
 	}
 
 	if err, ok := err.(impart.HTTPError); ok {
 		if err.Status >= 300 && err.Status < 400 {
 			sendRedirect(w, err.Status, err.Message)
 			return
 		} else if err.Status == http.StatusUnauthorized {
 			q := ""
 			if r.URL.RawQuery != "" {
 				q = url.QueryEscape("?" + r.URL.RawQuery)
 			}
 			sendRedirect(w, http.StatusFound, "/login?to="+r.URL.Path+q)
 			return
 		} else if err.Status == http.StatusGone {
 			w.WriteHeader(err.Status)
 			p := &struct {
 				page.StaticPage
 				Content *template.HTML
 			}{
 				StaticPage: pageForReq(h.app.App(), r),
 			}
 			if err.Message != "" {
 				co := template.HTML(err.Message)
 				p.Content = &co
 			}
 			h.errors.Gone.ExecuteTemplate(w, "base", p)
 			return
 		} else if err.Status == http.StatusNotFound {
 			w.WriteHeader(err.Status)
 			h.errors.NotFound.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 			return
 		} else if err.Status == http.StatusInternalServerError {
 			w.WriteHeader(err.Status)
 			log.Info("handleHTTPErorr internal error render")
 			h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 			return
 		} else if err.Status == http.StatusAccepted {
 			impart.WriteSuccess(w, "", err.Status)
 			return
 		} else {
 			p := &struct {
 				page.StaticPage
 				Title   string
 				Content template.HTML
 			}{
 				pageForReq(h.app.App(), r),
 				fmt.Sprintf("Uh oh (%d)", err.Status),
 				template.HTML(fmt.Sprintf("<p style=\"text-align: center\" class=\"introduction\">%s</p>", err.Message)),
 			}
 			h.errors.Blank.ExecuteTemplate(w, "base", p)
 			return
 		}
 		impart.WriteError(w, err)
 		return
 	}
 
 	impart.WriteError(w, impart.HTTPError{http.StatusInternalServerError, "This is an unhelpful error message for a miscellaneous internal error."})
 }
 
 func (h *Handler) handleError(w http.ResponseWriter, r *http.Request, err error) {
 	if err == nil {
 		return
 	}
 
 	if err, ok := err.(impart.HTTPError); ok {
 		if err.Status >= 300 && err.Status < 400 {
 			sendRedirect(w, err.Status, err.Message)
 			return
 		}
 
 		//		if strings.Contains(r.Header.Get("Accept"), "text/html") {
 		impart.WriteError(w, err)
 		//		}
 		return
 	}
 
 	if IsJSON(r.Header.Get("Content-Type")) {
 		impart.WriteError(w, impart.HTTPError{http.StatusInternalServerError, "This is an unhelpful error message for a miscellaneous internal error."})
 		return
 	}
 	h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 }
 
 func correctPageFromLoginAttempt(r *http.Request) string {
 	to := r.FormValue("to")
 	if to == "" {
 		to = "/"
 	} else if !strings.HasPrefix(to, "/") {
 		to = "/" + to
 	}
 	return to
 }
 
 func (h *Handler) LogHandlerFunc(f http.HandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		h.handleHTTPError(w, r, func() error {
 			status := 200
 			start := time.Now()
 
 			defer func() {
 				if e := recover(); e != nil {
 					log.Error("Handler.LogHandlerFunc\n\n%s: %s", e, debug.Stack())
 					h.errors.InternalServerError.ExecuteTemplate(w, "base", pageForReq(h.app.App(), r))
 					status = 500
 				}
 
 				// TODO: log actual status code returned
-				log.Info("\"%s %s\" %d %s \"%s\"", r.Method, r.RequestURI, status, time.Since(start), r.UserAgent())
+				log.Info(h.app.ReqLog(r, status, time.Since(start)))
 			}()
 
 			if h.app.App().cfg.App.Private {
 				// This instance is private, so ensure it's being accessed by a valid user
 				// Check if authenticated with an access token
 				_, apiErr := optionalAPIAuth(h.app.App(), r)
 				if apiErr != nil {
 					if err, ok := apiErr.(impart.HTTPError); ok {
 						status = err.Status
 					} else {
 						status = 500
 					}
 
 					if apiErr == ErrNotLoggedIn {
 						// Fall back to web auth since there was no access token given
 						_, err := webAuth(h.app.App(), r)
 						if err != nil {
 							if err, ok := apiErr.(impart.HTTPError); ok {
 								status = err.Status
 							} else {
 								status = 500
 							}
 							return err
 						}
 					} else {
 						return apiErr
 					}
 				}
 			}
 
 			f(w, r)
 
 			return nil
 		}())
 	}
 }
 
 func sendRedirect(w http.ResponseWriter, code int, location string) int {
 	w.Header().Set("Location", location)
 	w.WriteHeader(code)
 	return code
 }