ston1th/docstore
1
1
Fork 0
Code Issues 3 Releases Activity

improved logging

Browse source
This commit is contained in:
ston1th 2022-09-19 22:52:40 +02:00
commit 05b41cedce
81 changed files with 9802 additions and 279 deletions
Download patch file Download diff file Expand all files Collapse all files

38
pkg/server/context.go
View file

@ -4,10 +4,6 @@ package server
import (
"errors"
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/docstore/pkg/log"
"git.giftfish.de/ston1th/jwt/v3"
"github.com/gorilla/mux"
"html/template"
"io"
"net/http"
@ -15,6 +11,10 @@ import (
"reflect"
"strconv"
"time"
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/jwt/v3"
"github.com/gorilla/mux"
)
const (
@ -93,7 +93,7 @@ func (c *Context) Exec() {
c.Err = errors.New("template is nil")
return
}
c.Data.Token = newXsrf(c.Token.RawSig()[:keySize])
c.Data.Token, c.Err = newXsrf(c.Token.RawSig()[:keySize])
c.Data.Version = c.Srv.Config.Version
if c.Data.BodyTitle == "" {
@ -123,10 +123,20 @@ func (c *Context) Log() {
c.HTTPStatus = int(reflect.Indirect(reflect.ValueOf(c.Response)).FieldByName("status").Int())
}
if c.Err != nil {
log.Printf("%s %s %s %d error: %s\n", c.Request.RemoteAddr, c.Request.Method, c.Request.URL, c.HTTPStatus, c.Err)
c.Srv.Log.Error(c.Err, "access",
"client", c.Request.RemoteAddr,
"method", c.Request.Method,
"status", c.HTTPStatus,
"uri", c.Request.URL.Path,
)
return
}
log.Printf("%s %s %s %d\n", c.Request.RemoteAddr, c.Request.Method, c.Request.URL, c.HTTPStatus)
c.Srv.Log.Info("access",
"client", c.Request.RemoteAddr,
"method", c.Request.Method,
"status", c.HTTPStatus,
"uri", c.Request.URL.Path,
)
}
func (c *Context) Error(i interface{}) {
@ -154,7 +164,7 @@ func (c *Context) Forbidden() {
}
func (c *Context) SwitchHandler() {
log.Debug("server: switching to normal handler")
c.Srv.Log.V(2).Info("switching to normal handler")
c.Srv.srv.Handler = c.Srv.handler
c.Redirect(core.IndexURI, http.StatusFound)
}
@ -181,7 +191,13 @@ func (c *Context) Redirect(uri string, code int) {
if len(uri) > 0 && uri[0] != '/' {
uri = "/" + uri
}
log.Printf("%s %s %s %d %s\n", c.Request.RemoteAddr, c.Request.Method, c.Request.URL, code, uri)
c.Srv.Log.Info("access",
"client", c.Request.RemoteAddr,
"method", c.Request.Method,
"status", code,
"uri", c.Request.URL.Path,
"redirect", uri,
)
http.Redirect(c.Response, c.Request, uri, code)
}
@ -244,7 +260,7 @@ func (c *Context) LoggedOn() (ok bool) {
}
func (c *Context) LogSetCookie(msg string, err error) {
log.Printf("ctx: %s %s\n", msg, err)
c.Srv.Log.Error(err, msg)
c.SetCookie(nil, 0)
}
@ -266,7 +282,7 @@ func (c *Context) setCookie(t *jwt.Token, d time.Duration) {
}
t.Claims[jwt.ExpClaim] = jwt.NewExp(d)
if err := c.Srv.JWT.Sign(t); err != nil {
log.Println(err)
c.Srv.Log.Error(err, "jwt sign")
return
}
c.Token = *t

86
pkg/server/handler.go
View file

@ -3,16 +3,16 @@
package server
import (
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/docstore/pkg/fs"
"git.giftfish.de/ston1th/docstore/pkg/log"
"git.giftfish.de/ston1th/docstore/pkg/otp"
"git.giftfish.de/ston1th/jwt/v3"
"html/template"
"net/http"
"path/filepath"
"strings"
"time"
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/docstore/pkg/fs"
"git.giftfish.de/ston1th/docstore/pkg/otp"
"git.giftfish.de/ston1th/jwt/v3"
)
const noSuchFile = "no such file or directory"
@ -146,10 +146,7 @@ func rawHandler(ctx *Context) {
f, fi, err := ctx.Srv.FS.GetFile(path)
if err != nil {
ctx.Status(http.StatusNotFound)
err = ctx.Write([]byte(noSuchFile))
if err != nil {
log.Println("file:", err)
}
ctx.Err = ctx.Write([]byte(noSuchFile))
return
}
ctx.Response.Header().Del("Content-Security-Policy")
@ -157,6 +154,7 @@ func rawHandler(ctx *Context) {
}
func indexHandler(ctx *Context) {
log := ctx.Srv.Log
switch ctx.Method() {
case "GET":
var (
@ -166,20 +164,28 @@ func indexHandler(ctx *Context) {
)
path := ctx.Path()
if fpath, ok = hasTrimPrefix(path, core.IndexPrefix); ok {
log = log.WithValues("file", fpath)
log.V(2).Info("started indexing file")
err = scanFile(ctx.Srv, fpath)
if err != nil {
ctx.Srv.Log.Printf("index: %s", err)
log.Error(err, "error indexing file")
}
} else if fpath, ok = hasTrimPrefix(path, core.RetagPrefix); ok {
if fpath == "" {
log.V(2).Info("started retagging all files")
go func() {
err := ctx.Srv.DB.RetagAll()
if err != nil {
ctx.Srv.Log.Printf("retagAll: %s", err)
log.Error(err, "error retagging all files")
}
}()
} else {
log = log.WithValues("file", fpath)
log.V(2).Info("started retagging file")
err = ctx.Srv.DB.Retag(fpath, nil)
if err != nil {
log.Error(err, "error retagging file")
}
}
}
p, _ := filepath.Split(fpath)
@ -201,6 +207,7 @@ func indexHandler(ctx *Context) {
return
}
if m, c, ok := ctx.Srv.DB.IndexMutex.Lock(); ok {
log.V(2).Info("started indexing all files")
go func() {
defer ctx.Srv.DB.IndexMutex.Unlock()
files := ctx.Srv.FS.RecursiveFiles("/")
@ -209,14 +216,14 @@ func indexHandler(ctx *Context) {
if !ctx.Srv.DB.IsIndexed(f) {
err := scanFile(ctx.Srv, f)
if err != nil {
ctx.Srv.Log.Printf("indexAll: %s", err)
log.Error(err, "error indexing file", "file", f)
}
}
ctx.Srv.DB.IndexMutex.Inc()
}
}()
} else {
ctx.Srv.Log.Printf("indexAll: indexing already in progress: %d/%d", c, m)
log.Info("indexing of all files is already in progress", "indexed", c, "remaning", m)
}
ctx.Redirect(core.IndexURI, http.StatusFound)
}
@ -276,6 +283,7 @@ func newDirHandler(ctx *Context) {
}
func moveHandler(ctx *Context) {
log := ctx.Srv.Log
path := strings.TrimPrefix(ctx.Path(), core.MovePrefix)
mode, _, err := ctx.Srv.FS.Mode(path)
if err != nil {
@ -320,18 +328,19 @@ func moveHandler(ctx *Context) {
return
}
for _, m := range moved {
log.V(2).Info("moving file", "old", m.Old, "new", m.New)
err = ctx.Srv.DB.MoveFile(m.Old, m.New)
if err != nil {
log.Printf("move: %s: %s", m, err)
log.Error(err, "moving file failed", "old", m.Old, "new", m.New)
continue
}
log.Debugf("move: %s to %s", m.Old, m.New)
}
ctx.Redirect(newfile, http.StatusFound)
}
}
func deleteHandler(ctx *Context) {
log := ctx.Srv.Log
path := strings.TrimPrefix(ctx.Path(), core.DeletePrefix)
mode, enoent, err := ctx.Srv.FS.Mode(path)
if !enoent && err != nil {
@ -374,18 +383,21 @@ func deleteHandler(ctx *Context) {
clean := ctx.Form("clean")
if clean == "true" {
f := fs.Clean(path)
log = log.WithValues("file", f)
log.V(2).Info("deleting file from DB")
id, _, err := ctx.Srv.DB.DeleteFile(f)
if err != nil {
log.Printf("db: delete: %s %s", f, err)
log.Error(err, "delete from DB failed")
}
if id == "" {
ctx.Redirect(p, http.StatusFound)
return
}
log.Debugf("delete %s id: %s from index", f, id)
log = log.WithValues("id", id)
log.V(2).Info("deleting file from index")
err = ctx.Srv.DB.Index.Delete(id)
if err != nil {
log.Printf("index: delete: %s %s", f, err)
log.Error(err, "delete from index failed")
}
ctx.Redirect(p, http.StatusFound)
return
@ -396,17 +408,18 @@ func deleteHandler(ctx *Context) {
return
}
for _, f := range files {
log.V(2).Info("deleting file from DB", "file", f)
id, _, err := ctx.Srv.DB.DeleteFile(f)
if err != nil {
log.Printf("db: delete: %s %s", f, err)
log.Error(err, "delete from DB failed", "file", f)
}
if id == "" {
continue
}
log.Debugf("delete %s id: %s from index", f, id)
log.V(2).Info("deleting file from index", "file", f, "id", id)
err = ctx.Srv.DB.Index.Delete(id)
if err != nil {
log.Printf("index: delete: %s %s", f, err)
log.Error(err, "delete from index failed", "file", f, "id", id)
}
}
ctx.Redirect(p, http.StatusFound)
@ -488,6 +501,7 @@ func loginHandler(ctx *Context) {
Title: "Login",
BodyTitle: "Login",
}
log := ctx.Srv.Log
var data loginData
switch ctx.Method() {
case "GET":
@ -511,12 +525,12 @@ func loginHandler(ctx *Context) {
}
u, err := ctx.Srv.DB.Login(data.User, password)
if err != nil {
log.Println("login:", data.User, err)
log.Error(err, "login failed", "user", data.User)
ctx.Error("bad username or password")
return
}
if u.Secret == "" {
log.Println("login:", u.Username)
log.Info("login successful", "user", u.Username)
ctx.Login(u, ctx.Form("remember"))
ctx.Redirect(data.Referer, http.StatusFound)
return
@ -540,6 +554,7 @@ func loginTotpHandler(ctx *Context) {
Title: "TOTP Verification",
BodyTitle: "TOTP Veriftcation",
}
log := ctx.Srv.Log
switch ctx.Method() {
case "GET":
ctx.Exec()
@ -558,7 +573,7 @@ func loginTotpHandler(ctx *Context) {
return
}
ref := ctx.Referer()
log.Println("login:", u.Username)
log.Info("login successful", "user", u.Username)
ctx.Login(u, ctx.Remember())
ctx.Redirect(ref, http.StatusFound)
}
@ -598,6 +613,7 @@ func userEditHandler(ctx *Context) {
Title: "Edit User",
BodyTitle: "Edit User",
}
log := ctx.Srv.Log
u, err := ctx.Srv.DB.GetUserWithoutPassword()
if err != nil {
ctx.Error(err)
@ -622,7 +638,7 @@ func userEditHandler(ctx *Context) {
ctx.Error(err)
return
}
log.Printf("update: %s updated\n", ctx.User())
log.Info("user updated", "user", ctx.User())
ctx.Redirect(core.IndexURI, http.StatusFound)
}
}
@ -633,6 +649,7 @@ func userTotpHandler(ctx *Context) {
Title: "TOTP",
BodyTitle: "TOTP",
}
log := ctx.Srv.Log
req := otp.Request{Username: ctx.User()}
u, err := ctx.Srv.DB.GetUser()
if err != nil {
@ -686,9 +703,9 @@ func userTotpHandler(ctx *Context) {
return
}
if req.Secret == "" {
log.Printf("totp: disabled for %s\n", user)
log.Info("totp disabled", "user", user)
} else {
log.Printf("totp: enabled for %s\n", user)
log.Info("totp enabled", "user", user)
}
ctx.Redirect("/user/edit", http.StatusFound)
}
@ -701,7 +718,8 @@ func logsHandler(ctx *Context) {
BodyTitle: "Logs",
}
if ctx.Method() == "GET" {
ctx.Data.Data = ctx.Srv.Log.Logs()
// TODO remove
//ctx.Data.Data = ctx.Srv.Log.Logs()
ctx.Exec()
}
}
@ -729,6 +747,7 @@ func tagsNewHandler(ctx *Context) {
Title: "New Tag",
BodyTitle: "New Tag",
}
log := ctx.Srv.Log
switch ctx.Method() {
case "GET":
ctx.Data.Data = core.Tag{}
@ -753,7 +772,7 @@ func tagsNewHandler(ctx *Context) {
ctx.Error(err)
return
}
log.Printf("tag %s created by: %s\n", t.Name, ctx.User())
log.Info("new tag created", "user", ctx.User(), "tag", t.Name)
ctx.Redirect(core.TagsURI, http.StatusFound)
}
}
@ -764,6 +783,7 @@ func tagsEditHandler(ctx *Context) {
Title: "Edit Tag",
BodyTitle: "Edit Tag",
}
log := ctx.Srv.Log
name := ctx.Var("tag")
switch ctx.Method() {
case "GET":
@ -790,7 +810,7 @@ func tagsEditHandler(ctx *Context) {
ctx.Error(err)
return
}
log.Printf("tag %s updated by: %s\n", t.Name, ctx.User())
log.Info("tag updated", "user", ctx.User(), "tag", t.Name)
ctx.Redirect(core.TagsURI, http.StatusFound)
}
}
@ -801,6 +821,7 @@ func tagsDelHandler(ctx *Context) {
Title: "Delete Tag",
BodyTitle: "Delete Tag",
}
log := ctx.Srv.Log
name := ctx.Var("tag")
ctx.Data.Data = name
switch ctx.Method() {
@ -814,7 +835,7 @@ func tagsDelHandler(ctx *Context) {
ctx.Error(err)
return
}
log.Printf("tag %s deleted by: %s\n", name, ctx.User())
log.Info("tag deleted", "user", ctx.User(), "tag", name)
ctx.Redirect(core.TagsURI, http.StatusFound)
}
}
@ -832,11 +853,12 @@ func statsHandler(ctx *Context) {
}
func logoutHandler(ctx *Context) {
log := ctx.Srv.Log
user := ctx.User()
if user == "" {
user = ctx.Totp() + " (totp)"
}
log.Println("logout:", user)
log.Info("user logged out", "user", user)
ctx.Srv.JWT.Invalidate(&ctx.Token)
ctx.SetCookie(nil, 0)
ctx.Redirect(core.LoginURI, http.StatusFound)

10
pkg/server/helper.go
View file

@ -35,25 +35,25 @@ func scanFile(srv *HTTPServer, path string) (err error) {
}
go func() {
defer srv.FS.RemoveScan(path)
l := srv.Log
log := srv.Log.WithValues("file", path)
file, txt, err := srv.Scanner.Scan(path)
if err != nil {
l.Printf("scanner: %s: %s", path, err)
log.Error(err, "error scanning file")
return
}
tags, err := srv.DB.GetAllRTags()
if err != nil {
l.Printf("getTags: %s: %s", path, err)
log.Error(err, "error getting tags")
}
found := tags.Match(txt)
id, err := srv.DB.Index.Add(txt, found)
if err != nil {
l.Printf("index: %s: %s", path, err)
log.Error(err, "error adding file to index")
return
}
err = srv.DB.NewFile(id, file, found)
if err != nil {
l.Printf("newFile: %s: %s", path, err)
log.Error(err, "error adding file to DB")
}
}()
return

50
pkg/server/server.go
View file

@ -7,20 +7,21 @@ import (
"context"
"embed"
"errors"
"git.giftfish.de/ston1th/authdav"
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/docstore/pkg/db"
"git.giftfish.de/ston1th/docstore/pkg/fs"
"git.giftfish.de/ston1th/docstore/pkg/log"
"git.giftfish.de/ston1th/docstore/pkg/scan"
"git.giftfish.de/ston1th/godrop/v2"
"git.giftfish.de/ston1th/jwt/v3"
"github.com/gorilla/mux"
"golang.org/x/net/webdav"
"html/template"
"net"
"net/http"
"time"
"git.giftfish.de/ston1th/authdav"
"git.giftfish.de/ston1th/docstore/pkg/core"
"git.giftfish.de/ston1th/docstore/pkg/db"
"git.giftfish.de/ston1th/docstore/pkg/fs"
"git.giftfish.de/ston1th/docstore/pkg/scan"
"git.giftfish.de/ston1th/godrop/v2"
"git.giftfish.de/ston1th/jwt/v3"
"github.com/go-logr/logr"
"github.com/gorilla/mux"
"golang.org/x/net/webdav"
)
const (
@ -38,18 +39,20 @@ type HTTPServer struct {
JWT *jwt.JWT
Scanner *scan.Scanner
FS *fs.Filesystem
Log *log.ScanLog
Log logr.Logger
plain logr.Logger
templ map[string]*template.Template
res map[string][]byte
}
func NewHTTPServer(cfg *core.Config, l net.Listener, s *scan.Scanner) (srv *HTTPServer) {
func NewHTTPServer(log logr.Logger, cfg *core.Config, l net.Listener, s *scan.Scanner) (srv *HTTPServer) {
srv = &HTTPServer{
Config: cfg,
listener: l,
Scanner: s,
Log: log.NewScanLog(0),
Log: log.WithName("server"),
plain: log,
}
srv.loadTemplates()
srv.srv = &http.Server{}
@ -57,11 +60,12 @@ func NewHTTPServer(cfg *core.Config, l net.Listener, s *scan.Scanner) (srv *HTTP
}
func (s *HTTPServer) Start() (err error) {
s.FS, err = fs.NewFilesystem(s.Config.DataDir)
log := s.Log
s.FS, err = fs.NewFilesystem(s.plain.WithName("fs"), s.Config.DataDir)
if err != nil {
return errors.New("fs: " + err.Error())
}
s.DB, err = db.New(s.Config)
s.DB, err = db.New(s.plain.WithName("db"), s.Config)
if err != nil {
return errors.New("db: " + err.Error())
}
@ -79,13 +83,16 @@ func (s *HTTPServer) Start() (err error) {
}
s.handler = s.buildRoutes()
if !s.DB.UserExists() {
log.Debug("server: starting register handler")
log.V(2).Info("starting register handler")
s.srv.Handler = s.register()
} else {
s.srv.Handler = s.handler
}
go func() {
log.Println(s.srv.Serve(s.listener))
err = s.srv.Serve(s.listener)
if err != nil {
log.Error(err, "http server error")
}
}()
return
}
@ -117,7 +124,14 @@ func (s *HTTPServer) buildRoutes() http.Handler {
if s.Config.WebDav {
dav := authdav.NewWriteOnlyOnceFileSystem(webdav.Dir(s.Config.DataDir))
dav.Filters = []authdav.Filter{authdav.NewMacOSFilter()}
h := authdav.NewWebdavBasicAuth(core.WebDavPrefix, dav, nil, webdavLogger, s.DB, "DocStore WebDav")
h := authdav.NewWebdavBasicAuth(
core.WebDavPrefix,
dav,
nil,
webdavLogger(s.plain.WithName("webdav")),
s.DB,
"DocStore WebDav",
)
r.PathPrefix(core.WebDavPrefix).Handler(h)
}
r.Handle("/static/{file}", http.StripPrefix("/", http.FileServer(http.FS(static))))

10
pkg/server/templates.go
View file

@ -5,7 +5,6 @@ package server
import (
"embed"
"errors"
"git.giftfish.de/ston1th/docstore/pkg/log"
"html/template"
"io/fs"
)
@ -13,19 +12,19 @@ import (
//go:embed templates/*
var templates embed.FS
func (s *HTTPServer) loadTemplates() {
func (s *HTTPServer) loadTemplates() error {
var fatal bool
s.templ = make(map[string]*template.Template)
s.res = make(map[string][]byte)
tfs, err := fs.Sub(templates, "templates")
if err != nil {
log.Fatal("parse: ", err)
return err
}
parse := func(html ...string) (temp *template.Template) {
var err error
temp, err = template.ParseFS(tfs, html...)
if err != nil {
log.Println("parse:", err)
s.Log.Error(err, "template parser")
fatal = true
}
return
@ -61,6 +60,7 @@ func (s *HTTPServer) loadTemplates() {
s.templ["logsHandler"] = parse("index.html", "menu.html", "logs.html")
if fatal {
log.Fatal("parse: ", errors.New("parsing templates failed"))
return errors.New("parsing templates failed")
}
return nil
}

25
pkg/server/webdav.go
View file

@ -1,16 +1,27 @@
// Copyright (C) 2021 Marius Schellenberger
// Copyright (C) 2022 Marius Schellenberger
package server
import (
"git.giftfish.de/ston1th/docstore/pkg/log"
"net/http"
"github.com/go-logr/logr"
)
func webdavLogger(r *http.Request, err error) {
if err != nil {
log.Printf("webdav: %s %s %s error: %s\n", r.RemoteAddr, r.Method, r.URL, err)
return
func webdavLogger(log logr.Logger) func(r *http.Request, err error) {
return func(r *http.Request, err error) {
if err != nil {
log.Error(err, "access",
"client", r.RemoteAddr,
"method", r.Method,
"uri", r.URL.Path,
)
return
}
log.Info("access",
"client", r.RemoteAddr,
"method", r.Method,
"uri", r.URL.Path,
)
}
log.Printf("webdav: %s %s %s\n", r.RemoteAddr, r.Method, r.URL)
}

17
pkg/server/xsrf.go
View file

@ -6,23 +6,22 @@ import (
"crypto/rand"
"crypto/subtle"
"encoding/base64"
"git.giftfish.de/ston1th/docstore/pkg/log"
"git.giftfish.de/ston1th/jwt/v3"
)
const keySize = jwt.KeySize / 2
func genKey(length int) (bytes []byte) {
bytes = make([]byte, length)
if _, err := rand.Reader.Read(bytes); err != nil {
log.Println("genKey:", err)
}
func genKey(size int) (b []byte, err error) {
b = make([]byte, size)
_, err = rand.Reader.Read(b)
return
}
func newXsrf(secret []byte) string {
rnd := genKey(keySize)
return base64.RawURLEncoding.EncodeToString(append(rnd, xor(rnd, secret)...))
func newXsrf(secret []byte) (s string, err error) {
rnd, err := genKey(keySize)
s = base64.RawURLEncoding.EncodeToString(append(rnd, xor(rnd, secret)...))
return
}
func checkXsrf(xsrf string, secret []byte) bool {

6
pkg/server/xsrf_test.go
View file

@ -7,11 +7,11 @@ import (
)
func TestXsrf(t *testing.T) {
sec := genKey(keySize)
sec, _ := genKey(keySize)
if len(sec) != keySize {
t.Fatal("len(sec) != keySize")
}
xsrf := newXsrf(sec)
xsrf, _ := newXsrf(sec)
if xsrf == "" {
t.Fatal("xsrf is empty")
}
@ -24,7 +24,7 @@ func TestXsrf(t *testing.T) {
t.Fatal("invalid xsrf check succeeded")
}
rnd := genKey(keySize)
rnd, _ := genKey(keySize)
if checkXsrf(xsrf, rnd) {
t.Fatal("invalid xsrf check succeeded")
}