Improve database query logging

cli/setup.go

@@ -216,25 +216,30 @@ func setup() {
 
 	var chk map[string]bool
 
+	// Setup a default logging
+	// hook for cli output
+
+	logger := &log.DefaultHook{}
+
 	// Ensure that the specified
 	// logging level is allowed
 
 	if opts.Logging.Level != "" {
 
 		chk = map[string]bool{
-			"debug":   true,
-			"info":    true,
-			"warning": true,
-			"error":   true,
-			"fatal":   true,
-			"panic":   true,
+			"debug": true,
+			"info":  true,
+			"warn":  true,
+			"error": true,
+			"fatal": true,
+			"panic": true,
 		}
 
 		if _, ok := chk[opts.Logging.Level]; !ok {
 			log.Fatal("Incorrect log level specified")
 		}
 
-		log.SetLevel(opts.Logging.Level)
+		logger.SetLevel(opts.Logging.Level)
 
 	}
 
@@ -252,7 +257,7 @@ func setup() {
 			log.Fatal("Incorrect log format specified")
 		}
 
-		log.SetFormat(opts.Logging.Format)
+		logger.SetFormat(opts.Logging.Format)
 
 	}
 
@@ -271,10 +276,15 @@ func setup() {
 			log.Fatal("Incorrect log output specified")
 		}
 
-		log.SetOutput(opts.Logging.Output)
+		logger.SetOutput(opts.Logging.Output)
 
 	}
 
+	// Add the default logging hook
+	// to the logger instance
+
+	log.Hook(logger)
+
 	// Enable global options object
 
 	cnf.Settings = opts

cli/sql.go

@@ -133,15 +133,6 @@ var sqlCmd = &cobra.Command{
 			return
 		}
 
-		// Otherwise let's output the whole response
-		// body to the terminal, using the output
-		// format specified in the request.
-
-		if bdy, _ := ioutil.ReadAll(res.Body); len(bdy) > 0 {
-			log.SetLevel("INFO")
-			log.Infof("%s", bdy)
-		}
-
 		return
 
 	},

cli/start.go

@@ -15,7 +15,6 @@
 package cli
 
 import (
-	"fmt"
 	"os"
 
 	"github.com/spf13/cobra"
@@ -31,9 +30,7 @@ var startCmd = &cobra.Command{
 	Short: "Start the database and http server",
 	PreRun: func(cmd *cobra.Command, args []string) {
 
-		if opts.Logging.Output != "none" {
-			fmt.Print(logo)
-		}
+		log.Display(logo)
 
 	},
 	RunE: func(cmd *cobra.Command, args []string) (err error) {

db/executor.go

@@ -115,6 +115,8 @@ func (e *executor) execute(ctx context.Context, ast *sql.Query) {
 			log := log.WithPrefix("sql").WithFields(map[string]interface{}{
 				"id":   ctx.Value(ctxKeyId),
 				"kind": ctx.Value(ctxKeyKind),
+				"vars": ctx.Value(ctxKeyVars),
+				"keep": ctx.Value(ctxKeyKeep),
 			})
 
 			if stm, ok := stm.(sql.AuthableStatement); ok {
@@ -124,8 +126,6 @@ func (e *executor) execute(ctx context.Context, ast *sql.Query) {
 				log = log.WithField("ns", ns).WithField("db", db)
 			}
 
-			log.Debugln(stm)
-
 			// If we are not inside a global transaction
 			// then reset the error to nil so that the
 			// next statement is not ignored.
@@ -178,6 +178,22 @@ func (e *executor) execute(ctx context.Context, ast *sql.Query) {
 				Result: append([]interface{}{}, res...),
 			}
 
+			// Log the sql statement along with the
+			// query duration time, and mark it as
+			// an error if the query failed.
+
+			switch err.(type) {
+			default:
+				log.WithFields(map[string]interface{}{
+					"time": time.Since(now).String(),
+				}).Debugln(stm)
+			case error:
+				log.WithFields(map[string]interface{}{
+					"time":  time.Since(now).String(),
+					"error": detail(err),
+				}).Errorln(stm)
+			}
+
 			// If we are not inside a global transaction
 			// then we can output the statement response
 			// immediately to the channel.

kvs/mysql/main.go

@@ -74,6 +74,10 @@ func init() {
 
 		pntr.SetConnMaxLifetime(1 * time.Hour)
 
+		// Output logs to the default logger
+
+		mysql.SetLogger(log.Instance())
+
 		// Set the max number of idle connections
 
 		pntr.SetMaxIdleConns(350)

log/hook.go

@@ -0,0 +1,97 @@
+// Copyright © 2016 Abcum Ltd
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package log
+
+import (
+	"io"
+	"io/ioutil"
+	"os"
+	"time"
+
+	"github.com/sirupsen/logrus"
+)
+
+type DefaultHook struct {
+	w io.Writer
+	l []logrus.Level
+	f logrus.Formatter
+}
+
+func (h *DefaultHook) Levels() []logrus.Level {
+	return h.l
+}
+
+func (h *DefaultHook) Fire(entry *logrus.Entry) error {
+	bit, err := h.f.Format(entry)
+	if err != nil {
+		return err
+	}
+	_, err = h.w.Write(bit)
+	return err
+}
+
+// SetLevel sets the logging level of the logger instance.
+func (h *DefaultHook) SetLevel(v string) {
+	switch v {
+	case "debug":
+		h.l = DebugLevels
+	case "info":
+		h.l = InfoLevels
+	case "warning":
+		h.l = WarnLevels
+	case "error":
+		h.l = ErrorLevels
+	case "fatal":
+		h.l = FatalLevels
+	case "panic":
+		h.l = PanicLevels
+	}
+}
+
+// SetOutput sets the logging output of the logger instance.
+func (h *DefaultHook) SetOutput(v string) {
+	switch v {
+	case "none":
+		h.w = ioutil.Discard
+	case "stdout":
+		h.w = os.Stdout
+	case "stderr":
+		h.w = os.Stderr
+	}
+}
+
+// SetFormat sets the logging format of the logger instance.
+func (h *DefaultHook) SetFormat(v string) {
+	switch v {
+	case "json":
+		h.f = &JSONFormatter{
+			IgnoreFields: []string{
+				"ctx",
+				"vars",
+				"keep",
+			},
+			TimestampFormat: time.RFC3339,
+		}
+	case "text":
+		h.f = &TextFormatter{
+			IgnoreFields: []string{
+				"ctx",
+				"vars",
+				"keep",
+			},
+			TimestampFormat: time.RFC3339,
+		}
+	}
+}

log/log.go

@@ -15,9 +15,7 @@
 package log
 
 import (
-	"os"
-	"time"
-
+	"fmt"
 	"io/ioutil"
 
 	"github.com/sirupsen/logrus"
@@ -32,6 +30,42 @@ const (
 	DebugLevel = logrus.DebugLevel
 )
 
+var (
+	PanicLevels = []logrus.Level{
+		PanicLevel,
+	}
+	FatalLevels = []logrus.Level{
+		PanicLevel,
+		FatalLevel,
+	}
+	ErrorLevels = []logrus.Level{
+		PanicLevel,
+		FatalLevel,
+		ErrorLevel,
+	}
+	WarnLevels = []logrus.Level{
+		PanicLevel,
+		FatalLevel,
+		ErrorLevel,
+		WarnLevel,
+	}
+	InfoLevels = []logrus.Level{
+		PanicLevel,
+		FatalLevel,
+		ErrorLevel,
+		WarnLevel,
+		InfoLevel,
+	}
+	DebugLevels = []logrus.Level{
+		PanicLevel,
+		FatalLevel,
+		ErrorLevel,
+		WarnLevel,
+		InfoLevel,
+		DebugLevel,
+	}
+)
+
 var log *Logger
 
 // Logger ...
@@ -40,7 +74,14 @@ type Logger struct {
 }
 
 func init() {
-	log = New()
+	log = &Logger{
+		&logrus.Logger{
+			Out:       ioutil.Discard,
+			Level:     logrus.DebugLevel,
+			Hooks:     logrus.LevelHooks{},
+			Formatter: &logrus.TextFormatter{},
+		},
+	}
 }
 
 // Instance returns the underlying logger instance
@@ -48,19 +89,15 @@ func Instance() *logrus.Logger {
 	return log.Logger
 }
 
-// SetLevel sets the level of the standard logger
-func SetLevel(v string) {
-	log.SetLevel(v)
+// Hook adds a logging hook to the logger instance
+func Hook(hook logrus.Hook) {
+	log.AddHook(hook)
 }
 
-// SetFormat sets the format of the standard logger
-func SetFormat(v string) {
-	log.SetFormat(v)
-}
-
-// SetOutput sets the output of the standard logger
-func SetOutput(v string) {
-	log.SetOutput(v)
+func Display(v ...interface{}) {
+	if isTerminal {
+		fmt.Print(v...)
+	}
 }
 
 // Debug logs a message at level Debug on the standard logger.
@@ -182,64 +219,3 @@ func WithField(key string, value interface{}) *logrus.Entry {
 func WithFields(fields map[string]interface{}) *logrus.Entry {
 	return log.WithFields(fields)
 }
-
-// New returns a new Logger instance.
-func New() *Logger {
-	return &Logger{
-		&logrus.Logger{
-			Out:   os.Stderr,
-			Level: logrus.ErrorLevel,
-			Hooks: logrus.LevelHooks{},
-			Formatter: &TextFormatter{
-				IgnoreFields:    []string{"ctx"},
-				TimestampFormat: time.RFC3339,
-			},
-		},
-	}
-}
-
-// SetLevel sets the logging level of the logger instance.
-func (l *Logger) SetLevel(v string) {
-	switch v {
-	case "debug", "DEBUG":
-		l.Level = logrus.DebugLevel
-	case "info", "INFO":
-		l.Level = logrus.InfoLevel
-	case "warning", "WARNING":
-		l.Level = logrus.WarnLevel
-	case "error", "ERROR":
-		l.Level = logrus.ErrorLevel
-	case "fatal", "FATAL":
-		l.Level = logrus.FatalLevel
-	case "panic", "PANIC":
-		l.Level = logrus.PanicLevel
-	}
-}
-
-// SetFormat sets the logging format of the logger instance.
-func (l *Logger) SetFormat(v string) {
-	switch v {
-	case "json":
-		l.Formatter = &JSONFormatter{
-			IgnoreFields:    []string{"ctx"},
-			TimestampFormat: time.RFC3339,
-		}
-	case "text":
-		l.Formatter = &TextFormatter{
-			IgnoreFields:    []string{"ctx"},
-			TimestampFormat: time.RFC3339,
-		}
-	}
-}
-
-// SetOutput sets the logging output of the logger instance.
-func (l *Logger) SetOutput(v string) {
-	switch v {
-	case "none":
-		l.Out = ioutil.Discard
-	case "stdout":
-		l.Out = os.Stdout
-	case "stderr":
-		l.Out = os.Stderr
-	}
-}

log/text.go

@@ -17,8 +17,6 @@ package log
 import (
 	"bytes"
 	"fmt"
-	"os"
-	"runtime"
 	"sort"
 	"strings"
 	"time"
@@ -26,22 +24,10 @@ import (
 	"github.com/mgutz/ansi"
 
 	"github.com/sirupsen/logrus"
-
-	"golang.org/x/crypto/ssh/terminal"
 )
 
 const clear = ansi.Reset
 
-var (
-	isTerminal bool
-	isColoured bool
-)
-
-func init() {
-	isTerminal = terminal.IsTerminal(int(os.Stdout.Fd()))
-	isColoured = isTerminal && (runtime.GOOS != "windows")
-}
-
 type TextFormatter struct {
 	IgnoreFields    []string
 	TimestampFormat string

log/tty.go

@@ -0,0 +1,32 @@
+// Copyright © 2016 Abcum Ltd
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package log
+
+import (
+	"os"
+	"runtime"
+
+	"golang.org/x/crypto/ssh/terminal"
+)
+
+var (
+	isTerminal bool
+	isColoured bool
+)
+
+func init() {
+	isTerminal = terminal.IsTerminal(int(os.Stdout.Fd()))
+	isColoured = isTerminal && (runtime.GOOS != "windows")
+}

web/logger.go

@@ -0,0 +1,50 @@
+// Copyright © 2016 Abcum Ltd
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package web
+
+import (
+	"github.com/abcum/fibre"
+	"github.com/abcum/surreal/cnf"
+)
+
+func logger(c *fibre.Context) (err error) {
+
+	if err := c.Upgrade(); err != nil {
+		return err
+	}
+
+	if c.Get("auth").(*cnf.Auth).Kind != cnf.AuthKV {
+		return fibre.NewHTTPError(401)
+	}
+
+	ws := &socket{
+		quit: make(chan struct{}),
+		msgs: make(chan interface{}),
+	}
+
+	streamer.wss.Store(c.Get("id"), ws)
+
+	for v := range ws.msgs {
+		err := c.Socket().SendJSON(v)
+		if err != nil {
+			ws.quit <- struct{}{}
+		}
+	}
+
+	streamer.wss.Delete(c.Get("id"))
+
+	return nil
+
+}

web/routes.go

@@ -81,6 +81,14 @@ func routes(s *fibre.Fibre) {
 	// Endpoints for authentication signup
 	// --------------------------------------------------
 
+	s.Get("/logs", func(c *fibre.Context) error {
+		return logger(c)
+	})
+
+	// --------------------------------------------------
+	// Endpoints for authentication signup
+	// --------------------------------------------------
+
 	s.Options("/signup", func(c *fibre.Context) error {
 		return c.Code(200)
 	})

web/stream.go

@@ -0,0 +1,89 @@
+// Copyright © 2016 Abcum Ltd
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package web
+
+import (
+	"sync"
+
+	"github.com/abcum/surreal/log"
+	"github.com/sirupsen/logrus"
+)
+
+var streamer *stream
+
+type stream struct {
+	wss sync.Map
+}
+
+type socket struct {
+	quit chan struct{}
+	msgs chan interface{}
+}
+
+func init() {
+	streamer = &stream{}
+	log.Instance().AddHook(streamer)
+}
+
+func (h *stream) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (h *stream) Fire(entry *logrus.Entry) error {
+
+	streamer.wss.Range(func(key, val interface{}) bool {
+
+		ws := val.(*socket)
+
+		select {
+		case <-ws.quit:
+			close(ws.msgs)
+			break
+		case ws.msgs <- h.Format(entry):
+			break
+		}
+
+		return true
+
+	})
+
+	return nil
+
+}
+
+func (h *stream) Format(entry *logrus.Entry) interface{} {
+
+	var keys = make(map[string]interface{})
+	var json = make(map[string]interface{})
+
+	for k, v := range entry.Data {
+		if k != "prefix" && k != "ctx" {
+			keys[k] = v
+		}
+	}
+
+	json["keys"] = keys
+
+	json["time"] = entry.Time
+
+	json["level"] = entry.Level.String()
+
+	json["message"] = entry.Message
+
+	json["prefix"], _ = entry.Data["prefix"]
+
+	return json
+
+}