diff --git a/cli/start.go b/cli/start.go index e639d57a..2d41b0ce 100644 --- a/cli/start.go +++ b/cli/start.go @@ -20,6 +20,7 @@ import ( "github.com/abcum/surreal/db" "github.com/abcum/surreal/kvs" "github.com/abcum/surreal/log" + "github.com/abcum/surreal/trc" "github.com/abcum/surreal/web" ) @@ -31,6 +32,11 @@ var startCmd = &cobra.Command{ }, RunE: func(cmd *cobra.Command, args []string) (err error) { + if err = trc.Setup(opts); err != nil { + log.Fatal(err) + return + } + if err = kvs.Setup(opts); err != nil { log.Fatal(err) return diff --git a/db/db.go b/db/db.go index f8722887..f7099b51 100644 --- a/db/db.go +++ b/db/db.go @@ -186,6 +186,12 @@ func Process(fib *fibre.Context, ast *sql.Query, vars map[string]interface{}) (o defer quit() + // Assign the Fibre http request data to the + // context so that we can trace all subsequent + // queries to alongside the http request. + + ctx = context.WithValue(ctx, ctxKeyFibre, fib) + // Assign the authentication data to the // context so that we can log the auth kind // and the auth variable data to the request. diff --git a/db/executor.go b/db/executor.go index 4ba10f26..ac9de430 100644 --- a/db/executor.go +++ b/db/executor.go @@ -22,10 +22,12 @@ import ( "runtime/debug" + "github.com/abcum/fibre" "github.com/abcum/surreal/cnf" "github.com/abcum/surreal/kvs" "github.com/abcum/surreal/log" "github.com/abcum/surreal/sql" + "github.com/abcum/surreal/trc" "github.com/abcum/surreal/txn" ) @@ -67,6 +69,13 @@ func newExecutor(id, ns, db string) (e *executor) { func (e *executor) execute(ctx context.Context, ast *sql.Query) { + // Create a new trace span so we can analyse + // the execution time of this method, and + // detect problems with long-running queries. + + ctx, span := trc.Start(ctx, "db::execute") + defer span.End() + // Ensure that the executor is added back into // the executor pool when the executor has // finished processing the request. @@ -99,7 +108,11 @@ func (e *executor) execute(ctx context.Context, ast *sql.Query) { if err := recover(); err != nil { if log.IsError() { log.WithPrefix(logKeyDB).WithFields(map[string]interface{}{ - logKeyId: e.id, logKeyStack: string(debug.Stack()), + logKeyId: e.id, + logKeySpan: span.SpanContext().SpanID.String(), + logKeyTrace: span.SpanContext().TraceID.String(), + logKeyStack: string(debug.Stack()), + logKeyFibre: ctx.Value(ctxKeyFibre).(*fibre.Context), }).Errorln(err) } } @@ -125,6 +138,13 @@ func (e *executor) conduct(ctx context.Context, stm sql.Statement) { var rsp *Response var res []interface{} + // Create a new trace span so we can analyse + // the execution time of this method, and + // detect problems with long-running queries. + + ctx, span := trc.Start(ctx, "db::execute") + defer span.End() + // If we are not inside a global transaction // then reset the error to nil so that the // next statement is not ignored. @@ -189,12 +209,15 @@ func (e *executor) conduct(ctx context.Context, stm sql.Statement) { default: if log.IsDebug() { log.WithPrefix(logKeySql).WithFields(map[string]interface{}{ - logKeyId: e.id, - logKeyNS: e.ns, - logKeyDB: e.db, - logKeyKind: ctx.Value(ctxKeyKind), - logKeyVars: ctx.Value(ctxKeyVars), - logKeyTime: time.Since(e.time).String(), + logKeyId: e.id, + logKeyNS: e.ns, + logKeyDB: e.db, + logKeyKind: ctx.Value(ctxKeyKind), + logKeyVars: ctx.Value(ctxKeyVars), + logKeyTime: time.Since(e.time).String(), + logKeySpan: span.SpanContext().SpanID.String(), + logKeyTrace: span.SpanContext().TraceID.String(), + logKeyFibre: ctx.Value(ctxKeyFibre).(*fibre.Context), }).Debugln(stm) } case error: @@ -206,6 +229,9 @@ func (e *executor) conduct(ctx context.Context, stm sql.Statement) { logKeyKind: ctx.Value(ctxKeyKind), logKeyVars: ctx.Value(ctxKeyVars), logKeyTime: time.Since(e.time).String(), + logKeySpan: span.SpanContext().SpanID.String(), + logKeyTrace: span.SpanContext().TraceID.String(), + logKeyFibre: ctx.Value(ctxKeyFibre).(*fibre.Context), logKeyError: detail(e.err), }).Errorln(stm) } @@ -244,6 +270,13 @@ func (e *executor) operate(ctx context.Context, stm sql.Statement) (res []interf var trw bool var canc context.CancelFunc + // Create a new trace span so we can analyse + // the execution time of this method, and + // detect problems with long-running queries. + + ctx, span := trc.Start(ctx, "db::operate") + defer span.End() + // If we are not inside a global transaction // then grab a new transaction, ensuring that // it is closed at the end. diff --git a/db/vars.go b/db/vars.go index 0491f63a..ebb3b34a 100644 --- a/db/vars.go +++ b/db/vars.go @@ -50,8 +50,11 @@ const ( logKeyKind = "kind" logKeyVars = "vars" logKeyTime = "time" + logKeySpan = "span" + logKeyTrace = "trace" logKeyError = "error" logKeyStack = "stack" + logKeyFibre = "fibre" ) const ( @@ -63,6 +66,7 @@ const ( ctxKeyAuth = "auth" ctxKeyKind = "kind" ctxKeyForce = "force" + ctxKeyFibre = "fibre" ctxKeyVersion = "version" ) diff --git a/go.mod b/go.mod index fa2506ff..d40c4afe 100644 --- a/go.mod +++ b/go.mod @@ -5,6 +5,7 @@ go 1.15 require ( cloud.google.com/go v0.72.0 cloud.google.com/go/logging v1.1.2 + contrib.go.opencensus.io/exporter/stackdriver v0.13.4 github.com/abcum/bump v0.0.0-20201116071400-31a74cba5f19 github.com/abcum/cork v0.0.0-20201116072055-6b3677fdfab1 github.com/abcum/fibre v0.0.0-20201123182515-d9eac7ca56b5 @@ -29,6 +30,7 @@ require ( github.com/spf13/cobra v1.1.1 github.com/ugorji/go/codec v1.2.0 github.com/ugorji/go/codec/codecgen v1.2.0 // indirect + go.opencensus.io v0.22.5 golang.org/x/crypto v0.0.0-20201124201722-c8d3bf9c5392 golang.org/x/net v0.0.0-20201110031124-69a78807bb2b golang.org/x/oauth2 v0.0.0-20201109201403-9fd604954f58 // indirect diff --git a/go.sum b/go.sum index 439d3c65..d88b9a16 100644 --- a/go.sum +++ b/go.sum @@ -36,6 +36,8 @@ cloud.google.com/go/storage v1.5.0/go.mod h1:tpKbwo567HUNpVclU5sGELwQWBDZ8gh0Zeo cloud.google.com/go/storage v1.6.0/go.mod h1:N7U0C8pVQ/+NIKOBQyamJIeKQKkZ+mxpohlUTyfDhBk= cloud.google.com/go/storage v1.8.0/go.mod h1:Wv1Oy7z6Yz3DshWRJFhqM/UCfaWIRTdp0RXyy7KQOVs= cloud.google.com/go/storage v1.10.0/go.mod h1:FLPqc6j+Ki4BU591ie1oL6qBQGu2Bl/tZ9ullr3+Kg0= +contrib.go.opencensus.io/exporter/stackdriver v0.13.4 h1:ksUxwH3OD5sxkjzEqGxNTl+Xjsmu3BnC/300MhSVTSc= +contrib.go.opencensus.io/exporter/stackdriver v0.13.4/go.mod h1:aXENhDJ1Y4lIg4EUaVTwzvYETVNZk10Pu26tevFKLUc= dmitri.shuralyov.com/gpu/mtl v0.0.0-20190408044501-666a987793e9/go.mod h1:H6x//7gZCb22OMCxBHrMx7a5I7Hp++hsVxbQ4BYO7hU= github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU= github.com/BurntSushi/xgb v0.0.0-20160522181843-27f122750802/go.mod h1:IVnqGOEym/WlBOVXweHU+Q+/VP0lqqI8lqeDx9IjBqo= @@ -55,10 +57,13 @@ github.com/alecthomas/units v0.0.0-20151022065526-2efee857e7cf/go.mod h1:ybxpYRF github.com/armon/circbuf v0.0.0-20150827004946-bbbad097214e/go.mod h1:3U/XgcO3hCbHZ8TKRvWD2dDTCfh9M9ya+I9JpbB7O8o= github.com/armon/go-metrics v0.0.0-20180917152333-f0300d1749da/go.mod h1:Q73ZrmVTwzkszR9V5SSuryQ31EELlFMUz1kKyl939pY= github.com/armon/go-radix v0.0.0-20180808171621-7fddfc383310/go.mod h1:ufUuZ+zHj4x4TnLV4JWEpy2hxWSpsRywHrMgIH9cCH8= +github.com/aws/aws-sdk-go v1.23.20 h1:2CBuL21P0yKdZN5urf2NxKa1ha8fhnY+A3pBCHFeZoA= +github.com/aws/aws-sdk-go v1.23.20/go.mod h1:KmX6BPdI08NWTb3/sm4ZGu5ShLoqVDhKgpiN924inxo= github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q= github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8= github.com/bgentry/speakeasy v0.1.0/go.mod h1:+zsyZBPWlz7T6j88CTgSN5bM796AkVf0kBD4zp0CCIs= github.com/bketelsen/crypt v0.0.3-0.20200106085610-5cbc8cc4026c/go.mod h1:MKsuJmJgSg28kpZDP6UIiPt0e0Oz0kqKNGyRaWEPv84= +github.com/census-instrumentation/opencensus-proto v0.2.1 h1:glEXhBS5PSLLv4IXzLA5yPRVX4bilULVyxxbrfOtDAk= github.com/census-instrumentation/opencensus-proto v0.2.1/go.mod h1:f6KPmirojxKA12rnyqOA5BBL4O983OfeGPqjHWSTneU= github.com/cespare/xxhash v1.1.0 h1:a6HrQnmkObjyL+Gs60czilIUGqrzKutQD6XZog3p+ko= github.com/cespare/xxhash v1.1.0/go.mod h1:XrSqR1VqqWfGrhpAt58auRo0WTKS1nRRg3ghfAqPWnc= @@ -195,6 +200,8 @@ github.com/ianlancetaylor/demangle v0.0.0-20181102032728-5e5cf60278f6/go.mod h1: github.com/ianlancetaylor/demangle v0.0.0-20200824232613-28f6c0f3b639/go.mod h1:aSSvb/t6k1mPoxDqO4vJh6VOCGPwU4O0C2/Eqndh1Sc= github.com/inconshreveable/mousetrap v1.0.0 h1:Z8tu5sraLXCXIcARxBp/8cbvlwVa7Z1NHg9XEKhtSvM= github.com/inconshreveable/mousetrap v1.0.0/go.mod h1:PxqpIevigyE2G7u3NXJIT2ANytuPF1OarO4DADm73n8= +github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af h1:pmfjZENx5imkbgOkpRUYLnmbU7UEFbjtDA2hxJ1ichM= +github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af/go.mod h1:Nht3zPeWKUH0NzdCt2Blrr5ys8VGpn0CEB0cQHVjt7k= github.com/jonboulle/clockwork v0.1.0/go.mod h1:Ii8DK3G1RaLaWxj9trq07+26W01tbo22gdxWY5EU2bo= github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCVDaaPEHmU= github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU= @@ -380,6 +387,7 @@ golang.org/x/net v0.0.0-20190603091049-60506f45cf65/go.mod h1:HSz+uSET+XFnRR8LxR golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20190628185345-da137c7871d7/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20190724013045-ca1201d0de80/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= +golang.org/x/net v0.0.0-20190923162816-aa69164e4478/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20191209160850-c0dbc17a3553/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20200114155413-6afb5195e5aa/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20200202094626-16171245cfb2/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= @@ -487,6 +495,7 @@ golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgw golang.org/x/tools v0.0.0-20190628153133-6cdbf07be9d0/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc= golang.org/x/tools v0.0.0-20190816200558-6889da9d5479/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20190911174233-4f2ddba30aff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= +golang.org/x/tools v0.0.0-20191010075000-0337d82405ff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191112195655-aa38f8e97acc/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= golang.org/x/tools v0.0.0-20191113191852-77e3bb0ad9e7/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= @@ -531,6 +540,7 @@ google.golang.org/api v0.4.0/go.mod h1:8k5glujaEP+g9n7WNsDg8QP6cUVNI86fCNMcbazEt google.golang.org/api v0.7.0/go.mod h1:WtwebWUNSVBH/HAw79HIFXZNqEvBhG+Ra+ax0hx3E3M= google.golang.org/api v0.8.0/go.mod h1:o4eAsZoiT+ibD93RtjEohWalFOjRDx6CVaqeizhEnKg= google.golang.org/api v0.9.0/go.mod h1:o4eAsZoiT+ibD93RtjEohWalFOjRDx6CVaqeizhEnKg= +google.golang.org/api v0.10.0/go.mod h1:o4eAsZoiT+ibD93RtjEohWalFOjRDx6CVaqeizhEnKg= google.golang.org/api v0.13.0/go.mod h1:iLdEw5Ide6rF15KTC1Kkl0iskquN2gFfn9o9XIsbkAI= google.golang.org/api v0.14.0/go.mod h1:iLdEw5Ide6rF15KTC1Kkl0iskquN2gFfn9o9XIsbkAI= google.golang.org/api v0.15.0/go.mod h1:iLdEw5Ide6rF15KTC1Kkl0iskquN2gFfn9o9XIsbkAI= @@ -550,6 +560,7 @@ google.golang.org/appengine v1.1.0/go.mod h1:EbEs0AVv82hx2wNQdGPgUI5lhzA/G0D9Ywl google.golang.org/appengine v1.4.0/go.mod h1:xpcJRLb0r/rnEns0DIKYYv+WjYCduHsrkT7/EB5XEv4= google.golang.org/appengine v1.5.0/go.mod h1:xpcJRLb0r/rnEns0DIKYYv+WjYCduHsrkT7/EB5XEv4= google.golang.org/appengine v1.6.1/go.mod h1:i06prIuMbXzDqacNJfV5OdTW448YApPu5ww/cMBSeb0= +google.golang.org/appengine v1.6.2/go.mod h1:i06prIuMbXzDqacNJfV5OdTW448YApPu5ww/cMBSeb0= google.golang.org/appengine v1.6.5/go.mod h1:8WjMMxjGQR8xUklV/ARdw2HLXBOI7O7uCIDZVag1xfc= google.golang.org/appengine v1.6.6 h1:lMO5rYAqUxkmaj76jAkRUvt5JZgFymx/+Q5Mzfivuhc= google.golang.org/appengine v1.6.6/go.mod h1:8WjMMxjGQR8xUklV/ARdw2HLXBOI7O7uCIDZVag1xfc= @@ -595,6 +606,7 @@ google.golang.org/grpc v1.19.0/go.mod h1:mqu4LbDTu4XGKhr4mRzUsmM4RtVoemTSY81AxZi google.golang.org/grpc v1.20.1/go.mod h1:10oTOabMzJvdu6/UiuZezV6QK5dSlG84ov/aaiqXj38= google.golang.org/grpc v1.21.1/go.mod h1:oYelfM1adQP15Ek0mdvEgi9Df8B9CZIaU1084ijfRaM= google.golang.org/grpc v1.23.0/go.mod h1:Y5yQAOtifL1yxbo5wqy6BxZv8vAUGQwXBOALyacEbxg= +google.golang.org/grpc v1.23.1/go.mod h1:Y5yQAOtifL1yxbo5wqy6BxZv8vAUGQwXBOALyacEbxg= google.golang.org/grpc v1.25.1/go.mod h1:c3i+UQWmh7LiEpx4sFZnkU36qjEYZ0imhYfXVyQciAY= google.golang.org/grpc v1.26.0/go.mod h1:qbnxyOmOxrQa7FizSgH+ReBfzJrCY1pSN7KXBS8abTk= google.golang.org/grpc v1.27.0/go.mod h1:qbnxyOmOxrQa7FizSgH+ReBfzJrCY1pSN7KXBS8abTk= diff --git a/log/hook.go b/log/hook.go index 657f2c25..a1e54ff5 100644 --- a/log/hook.go +++ b/log/hook.go @@ -81,7 +81,10 @@ func (h *DefaultHook) SetFormat(v string) { h.f = &JSONFormatter{ IgnoreFields: []string{ "ctx", - "vars", + "span", + "trace", + "fibre", + "prefix", }, TimestampFormat: time.RFC3339, } @@ -90,6 +93,10 @@ func (h *DefaultHook) SetFormat(v string) { IgnoreFields: []string{ "ctx", "vars", + "span", + "trace", + "fibre", + "prefix", }, TimestampFormat: time.RFC3339, } diff --git a/log/log.go b/log/log.go index f14b2b0b..35042636 100644 --- a/log/log.go +++ b/log/log.go @@ -178,7 +178,10 @@ func SetFormat(v string) { log.Logger.SetFormatter(&JSONFormatter{ IgnoreFields: []string{ "ctx", - "vars", + "span", + "trace", + "fibre", + "prefix", }, TimestampFormat: time.RFC3339, }) @@ -187,6 +190,10 @@ func SetFormat(v string) { IgnoreFields: []string{ "ctx", "vars", + "span", + "trace", + "fibre", + "prefix", }, TimestampFormat: time.RFC3339, }) diff --git a/log/stackdriver.go b/log/stackdriver.go index bdce4b50..8f8bfb4e 100644 --- a/log/stackdriver.go +++ b/log/stackdriver.go @@ -154,6 +154,14 @@ func (h *StackdriverLogger) Fire(entry *logrus.Entry) error { Severity: logging.ParseSeverity(entry.Level.String()), } + if v, ok := entry.Data["trace"].(string); ok { + e.Trace = fmt.Sprintf("projects/%s/traces/%s", proj, v) + } + + if v, ok := entry.Data["span"].(string); ok { + e.SpanID = v + } + if p, ok := entry.Data["prefix"]; ok && p == "sql" { e.Payload = map[string]interface{}{ "sql": entry.Message, diff --git a/log/text.go b/log/text.go index 7822e2a3..b7e27efa 100644 --- a/log/text.go +++ b/log/text.go @@ -61,9 +61,7 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { for k := range entry.Data { if f.include(k) { - if k != "prefix" { - keys = append(keys, k) - } + keys = append(keys, k) } } diff --git a/trc/main.go b/trc/main.go new file mode 100644 index 00000000..85feb1df --- /dev/null +++ b/trc/main.go @@ -0,0 +1,61 @@ +// 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 trc + +import ( + "context" + + "go.opencensus.io/trace" + + "github.com/abcum/surreal/cnf" + "github.com/abcum/surreal/log" + + "contrib.go.opencensus.io/exporter/stackdriver" +) + +func Setup(opts *cnf.Options) (err error) { + + log.WithPrefix("log").Infof("Starting open tracing framework") + + var exporter *stackdriver.Exporter + + opt := stackdriver.Options{ + ProjectID: "surreal-io", + OnError: func(error) {}, + } + + exporter, err = stackdriver.NewExporter(opt) + if err != nil { + return err + } + + err = exporter.StartMetricsExporter() + if err != nil { + return err + } + + trace.ApplyConfig(trace.Config{ + DefaultSampler: trace.AlwaysSample(), + }) + + trace.RegisterExporter(exporter) + + return + +} + +func Start(ctx context.Context, name string) (context.Context, *trace.Span) { + return trace.StartSpan(ctx, name) +}