Add programme tracing using Google Cloud

This commit is contained in:
Tobie Morgan Hitchcock 2020-11-27 12:57:22 +00:00
parent f6b75e2de2
commit 5c84421028
11 changed files with 156 additions and 12 deletions

View file

@ -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

View file

@ -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.

View file

@ -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.

View file

@ -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"
)

2
go.mod
View file

@ -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

12
go.sum
View file

@ -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=

View file

@ -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,
}

View file

@ -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,
})

View file

@ -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,

View file

@ -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)
}
}

61
trc/main.go Normal file
View file

@ -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)
}