326 lines
8.7 KiB
Go
326 lines
8.7 KiB
Go
package middleware
|
|
|
|
import (
|
|
"amuz.es/src/go/eighty"
|
|
"amuz.es/src/go/eighty/routing"
|
|
"amuz.es/src/go/logging"
|
|
"amuz.es/src/go/misc/q"
|
|
"amuz.es/src/go/misc/strutil"
|
|
"bytes"
|
|
"context"
|
|
"github.com/valyala/fasthttp"
|
|
"io"
|
|
"io/ioutil"
|
|
"net"
|
|
"runtime"
|
|
"strconv"
|
|
"strings"
|
|
"sync"
|
|
"time"
|
|
)
|
|
|
|
const (
|
|
dateFormat = "02/Jan/2006:15:04:05 -0700"
|
|
)
|
|
|
|
type accessLogMiddleware struct {
|
|
writer io.WriteCloser
|
|
|
|
apiUrlPrefix string
|
|
|
|
logInChan chan<- string
|
|
logOutChan <-chan string
|
|
|
|
logger logging.Logger
|
|
logWaiter sync.Mutex
|
|
waitGroup sync.WaitGroup
|
|
ctx context.Context
|
|
closer func()
|
|
|
|
errorViewTemplateRenderer eighty.PageRenderer
|
|
}
|
|
|
|
func (m *accessLogMiddleware) Handle(h routing.Router) routing.Router {
|
|
return func(ctx *fasthttp.RequestCtx) {
|
|
m.waitGroup.Add(1)
|
|
defer m.waitGroup.Done()
|
|
// access log 기록
|
|
defer m.recordAccess()(ctx)
|
|
// 내부 panic 해소
|
|
defer m.handlePanic(ctx)
|
|
m.writeBasicHeader(&ctx.Response)
|
|
h(ctx)
|
|
}
|
|
}
|
|
|
|
// source returns a space-trimmed slice of the n'th line.
|
|
func (m *accessLogMiddleware) source(buf *strings.Builder, lines [][]byte, n int) {
|
|
n-- // in stack trace, lines are 1-indexed but our array is 0-indexed
|
|
if n < 0 || n >= len(lines) {
|
|
buf.WriteString("???")
|
|
} else {
|
|
buf.Write(lines[n])
|
|
}
|
|
}
|
|
|
|
// function returns, if possible, the name of the function containing the PC.
|
|
func (m *accessLogMiddleware) function(buf *strings.Builder, pc uintptr) {
|
|
fn := runtime.FuncForPC(pc)
|
|
if fn == nil {
|
|
buf.WriteString("???")
|
|
}
|
|
name := fn.Name()
|
|
// The name include the path name to the package, which is unnecessary
|
|
// since the file name is already included. Plus, it has center dots.
|
|
// That is, we see
|
|
// runtime/debug.*T·ptrmethod
|
|
// and want
|
|
// *T.ptrmethod
|
|
// Also the package path might contains dot (e.g. code.google.com/...),
|
|
// so first eliminate the path prefix
|
|
if lastslash := strings.LastIndexByte(name, '/'); lastslash >= 0 {
|
|
name = name[lastslash+1:]
|
|
}
|
|
if period := strings.IndexByte(name, '.'); period >= 0 {
|
|
name = name[period+1:]
|
|
}
|
|
buf.WriteString(strings.Replace(name, "·", ".", -1))
|
|
}
|
|
|
|
// 라우팅 로직에서 panic이 발생 했을경우 해당 스택을 보여준다.
|
|
// stack returns a nicely formated stack frame, skipping skip frames
|
|
func (m *accessLogMiddleware) getStack(buf *strings.Builder, skip int) {
|
|
// As we loop, we open files and read them. These variables record the currently
|
|
// loaded file.
|
|
var lines [][]byte
|
|
var lastFile string
|
|
for i := skip; ; i++ {
|
|
// Skip the expected number of frames
|
|
pc, file, line, ok := runtime.Caller(i)
|
|
if !ok {
|
|
break
|
|
} else if i > skip {
|
|
buf.WriteByte('\n')
|
|
}
|
|
if paths := strings.SplitN(file, "src/", 2); len(paths) == 1 {
|
|
// Print this much at least. If we can't find the source, it won't show.
|
|
//_, _ = fmt.Fprintf(buf, "%s:%d (0x%x)\n", file, line, pc)
|
|
buf.WriteString(file)
|
|
} else if vendors := strings.SplitN(paths[1], "vendor/", 2); len(vendors) == 1 {
|
|
// Print this much at least. If we can't find the source, it won't show.
|
|
//_, _ = fmt.Fprintf(buf, "%s:%d (0x%x)\n", paths[1], line, pc)
|
|
buf.WriteString(paths[1])
|
|
} else {
|
|
// Print this much at least. If we can't find the source, it won't show.
|
|
//_, _ = fmt.Fprintf(buf, "%s:%d (0x%x)\n", vendors[1], line, pc)
|
|
buf.WriteString(vendors[1])
|
|
}
|
|
buf.WriteByte(':')
|
|
buf.WriteString(strconv.FormatInt(int64(line), 10))
|
|
buf.WriteString(" (0x")
|
|
buf.WriteString(strconv.FormatInt(int64(pc), 16))
|
|
buf.WriteString(")\n")
|
|
|
|
// -----
|
|
//_, _ = fmt.Fprintf(buf, "\t%s: %s\n", function(pc), source(lines, line))
|
|
buf.WriteByte('\t')
|
|
m.function(buf, pc)
|
|
buf.WriteString(": ")
|
|
if file == lastFile {
|
|
buf.WriteString("???")
|
|
} else if data, err := ioutil.ReadFile(file); err != nil {
|
|
buf.WriteString("???")
|
|
} else {
|
|
lines = bytes.Split(data, []byte{'\n'})
|
|
lastFile = file
|
|
m.source(buf, lines, line)
|
|
}
|
|
}
|
|
}
|
|
|
|
func (m *accessLogMiddleware) handlePanic(ctx *fasthttp.RequestCtx) {
|
|
panicObj := recover()
|
|
if panicObj == nil {
|
|
return
|
|
}
|
|
errorType, err := eighty.WrapHandledError(panicObj)
|
|
if err != nil {
|
|
var buf strings.Builder
|
|
buf.WriteString("PANIC! ")
|
|
buf.WriteString(err.Error())
|
|
buf.WriteString("\n--------\nREQUEST\n")
|
|
_, _ = ctx.Request.WriteTo(&buf)
|
|
buf.WriteString("\n--------\nSTACK\n")
|
|
m.getStack(&buf, 3)
|
|
buf.WriteString("\n--------")
|
|
m.logger.Error(buf.String())
|
|
}
|
|
isAPI := bytes.HasPrefix(ctx.RequestURI(), []byte(m.apiUrlPrefix))
|
|
if isAPI {
|
|
errorType.RenderAPI(ctx, err)
|
|
} else {
|
|
errorType.RenderPage(ctx, m.errorViewTemplateRenderer, err)
|
|
}
|
|
}
|
|
|
|
func (m *accessLogMiddleware) writeBasicHeader(w *fasthttp.Response) {
|
|
w.Header.Set(eighty.FrameOptionHeader, eighty.FrameOptionSameOrigin[0])
|
|
w.Header.Set(eighty.ContentTypeOptionHeader, eighty.ContentTypeOptionNoSniffing[0])
|
|
w.Header.Set(eighty.XssProtectionHeader, eighty.XssProtectionBlocking[0])
|
|
}
|
|
|
|
func (m *accessLogMiddleware) recordAccess() routing.Router {
|
|
now := time.Now()
|
|
return func(ctx *fasthttp.RequestCtx) {
|
|
var (
|
|
dur = time.Since(now)
|
|
builder strings.Builder
|
|
)
|
|
_, _ = builder.Write(m.remoteAddr(ctx.RemoteAddr(), &ctx.Request))
|
|
_, _ = builder.WriteString(` - - [`)
|
|
_, _ = builder.WriteString(now.Format(dateFormat))
|
|
_, _ = builder.WriteString(`] "`)
|
|
_, _ = builder.Write(ctx.Method())
|
|
_ = builder.WriteByte(' ')
|
|
_, _ = builder.Write(ctx.RequestURI())
|
|
_ = builder.WriteByte(' ')
|
|
if ctx.Request.Header.IsHTTP11() {
|
|
_, _ = builder.WriteString("HTTP/1.1")
|
|
} else {
|
|
_, _ = builder.WriteString("HTTP/1.0")
|
|
}
|
|
_, _ = builder.WriteString(`" `)
|
|
_, _ = builder.Write(strutil.FormatIntToBytes(ctx.Response.StatusCode()))
|
|
_ = builder.WriteByte(' ')
|
|
_, _ = builder.Write(strutil.FormatIntToBytes(ctx.Response.Header.ContentLength()))
|
|
_, _ = builder.WriteString(` "`)
|
|
_, _ = builder.Write(ctx.Request.Header.Referer())
|
|
_, _ = builder.WriteString(`" "`)
|
|
_, _ = builder.Write(ctx.Request.Header.UserAgent())
|
|
_, _ = builder.WriteString(`" `)
|
|
_, _ = builder.Write(strutil.FormatIntToBytes(int(dur.Nanoseconds() / time.Millisecond.Nanoseconds())))
|
|
_ = builder.WriteByte(' ')
|
|
_, _ = builder.Write(ctx.Request.Host())
|
|
_ = builder.WriteByte('\n')
|
|
|
|
select {
|
|
case <-m.ctx.Done():
|
|
m.logger.Error("cannot accesslog record: ", builder.String())
|
|
default:
|
|
m.logInChan <- builder.String()
|
|
}
|
|
}
|
|
}
|
|
|
|
func (m *accessLogMiddleware) Close() {
|
|
defer m.writer.Close()
|
|
m.closer()
|
|
close(m.logInChan)
|
|
m.logWaiter.Lock()
|
|
defer m.logWaiter.Unlock()
|
|
}
|
|
|
|
func (m *accessLogMiddleware) lineByLineWriter() {
|
|
var (
|
|
ticker = time.NewTicker(200 * time.Millisecond)
|
|
maxsz = 1024 * 1024
|
|
sz = 0
|
|
rcvsz = 0
|
|
buf = make([]byte, maxsz)
|
|
flusher = func() {
|
|
if sz > 0 {
|
|
if _, err := m.writer.Write(buf[:sz]); err != nil {
|
|
m.logger.Error("cannot write accesslog chunk : ", err)
|
|
}
|
|
//reset
|
|
sz = 0
|
|
}
|
|
}
|
|
)
|
|
|
|
m.logWaiter.Lock()
|
|
defer func() {
|
|
defer m.logWaiter.Unlock()
|
|
ticker.Stop()
|
|
flusher()
|
|
}()
|
|
for {
|
|
select {
|
|
case logItem, ok := <-m.logOutChan:
|
|
//or do the next job
|
|
if !ok {
|
|
return
|
|
}
|
|
rcvsz = len(logItem)
|
|
if maxsz < sz+rcvsz {
|
|
flusher()
|
|
}
|
|
if rcvsz > 0 {
|
|
// append
|
|
copy(buf[sz:], logItem)
|
|
sz += rcvsz
|
|
}
|
|
case <-ticker.C:
|
|
// if deadline exceeded write
|
|
flusher()
|
|
}
|
|
}
|
|
}
|
|
|
|
// strip port from addresses with hostname, ipv4 or ipv6
|
|
func (m *accessLogMiddleware) stripPort(address string) string {
|
|
if h, _, err := net.SplitHostPort(address); err == nil {
|
|
return h
|
|
}
|
|
|
|
return address
|
|
}
|
|
|
|
// The remote address of the client. When the 'X-Forwarded-For'
|
|
// header is set, then it is used instead.
|
|
func (m *accessLogMiddleware) remoteAddr(remoteAddr net.Addr, r *fasthttp.Request) (ret []byte) {
|
|
if ret = r.Header.Peek(eighty.ForwardedForIPHeader); ret == nil {
|
|
ret = []byte(remoteAddr.String())
|
|
}
|
|
return
|
|
}
|
|
|
|
func (m *accessLogMiddleware) remoteHost(remoteAddr net.Addr, r *fasthttp.Request) string {
|
|
a := m.remoteAddr(remoteAddr, r)
|
|
h := m.stripPort(strutil.B2S(a))
|
|
if h != "" {
|
|
return h
|
|
}
|
|
|
|
return "-"
|
|
}
|
|
|
|
// AccessLogMiddleware returns a routing.Middleware that handles error handling and access logging.
|
|
func AccessLogMiddleware(
|
|
apiUrlPrefix string,
|
|
logWriter io.WriteCloser,
|
|
templateRenderer eighty.PageRenderer,
|
|
logger logging.Logger) (handler routing.Middleware, closer func(), err error) {
|
|
ctx, canceler := context.WithCancel(context.Background())
|
|
inchan, outchan := q.NewStringQueue()
|
|
impl := &accessLogMiddleware{
|
|
writer: logWriter,
|
|
apiUrlPrefix: apiUrlPrefix,
|
|
logInChan: inchan,
|
|
logOutChan: outchan,
|
|
logger: logger,
|
|
ctx: ctx,
|
|
errorViewTemplateRenderer: templateRenderer,
|
|
}
|
|
impl.closer = func() {
|
|
if ctx.Err() == nil {
|
|
canceler()
|
|
}
|
|
impl.waitGroup.Wait()
|
|
}
|
|
|
|
go impl.lineByLineWriter()
|
|
|
|
return impl.Handle, impl.Close, nil
|
|
}
|