Add query historizer to troubleshoot when a query takes too long.

Author: clems4ever

cmd/go-graphkb/main.go

@@ -123,7 +123,7 @@ func listen(cmd *cobra.Command, args []string) {
 
 	listenInterface := viper.GetString("server_listen")
 
-	server.StartServer(listenInterface, Database, Database, Database, eventBus)
+	server.StartServer(listenInterface, Database, Database, Database, Database, eventBus)
 
 	close(eventBus)
 }
@@ -142,7 +142,7 @@ func queryFunc(cmd *cobra.Command, args []string) {
 	ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
 	defer cancel()
 
-	q := knowledge.NewQuerier(Database)
+	q := knowledge.NewQuerier(Database, Database)
 
 	r, err := q.Query(ctx, args[0])
 	if err != nil {

internal/database/mariadb.go

@@ -12,7 +12,6 @@ import (
 
 	"github.com/cheggaaa/pb"
 	"github.com/clems4ever/go-graphkb/internal/knowledge"
-	"github.com/clems4ever/go-graphkb/internal/query"
 	"github.com/clems4ever/go-graphkb/internal/schema"
 	"github.com/clems4ever/go-graphkb/internal/utils"
 	mapset "github.com/deckarep/golang-set"
@@ -111,6 +110,23 @@ CREATE TABLE IF NOT EXISTS importers (
 		return err
 	}
 	defer q.Close()
+
+	// Create the table storing importers tokens
+	q, err = m.db.QueryContext(context.Background(), `
+		CREATE TABLE IF NOT EXISTS query_history (
+			id INTEGER AUTO_INCREMENT NOT NULL,
+			timestamp TIMESTAMP,
+			query_cypher TEXT NOT NULL,
+			query_sql TEXT NOT NULL,
+			execution_time_ms INT,
+			status ENUM('SUCCESS', 'FAILURE'),
+			error TEXT,
+			CONSTRAINT pk_history PRIMARY KEY (id)
+		)`)
+	if err != nil {
+		return err
+	}
+	defer q.Close()
 	return nil
 }
 
@@ -494,12 +510,7 @@ func (m *MariaDB) Close() error {
 }
 
 // Query the database with provided intermediate query representation
-func (m *MariaDB) Query(ctx context.Context, query *query.QueryCypher) (*knowledge.GraphQueryResult, error) {
-	sql, err := knowledge.NewSQLQueryTranslator().Translate(query)
-	if err != nil {
-		return nil, err
-	}
-
+func (m *MariaDB) Query(ctx context.Context, sql knowledge.SQLTranslation) (*knowledge.GraphQueryResult, error) {
 	deadline, ok := ctx.Deadline()
 	// If there is a deadline, we make sure the query stops right after it has been reached.
 	if ok {
@@ -522,6 +533,24 @@ func (m *MariaDB) Query(ctx context.Context, query *query.QueryCypher) (*knowled
 	return res, nil
 }
 
+func (m *MariaDB) SaveSuccessfulQuery(ctx context.Context, cypher, sql string, duration time.Duration) error {
+	_, err := m.db.ExecContext(ctx, "INSERT INTO query_history (id, timestamp, query_cypher, query_sql, status, execution_time_ms) VALUES (NULL, CURRENT_TIMESTAMP(), ?, ?, 'SUCCESS', ?)",
+		cypher, sql, duration)
+	if err != nil {
+		return err
+	}
+	return err
+}
+
+func (m *MariaDB) SaveFailedQuery(ctx context.Context, cypher, sql string, err error) error {
+	_, inErr := m.db.ExecContext(ctx, "INSERT INTO query_history (id, timestamp, query_cypher, query_sql, status, error) VALUES (NULL, CURRENT_TIMESTAMP(), ?, ?, 'FAILURE', ?)",
+		cypher, sql, err.Error())
+	if inErr != nil {
+		return inErr
+	}
+	return nil
+}
+
 // SaveSchema save the schema graph in database
 func (m *MariaDB) SaveSchema(ctx context.Context, sourceName string, schema schema.SchemaGraph) error {
 	b, err := json.Marshal(schema)

internal/history/historizer.go

@@ -0,0 +1,18 @@
+package history
+
+import (
+	"context"
+	"time"
+)
+
+type Status int
+
+const (
+	Success Status = iota
+	Failure Status = iota
+)
+
+type Historizer interface {
+	SaveSuccessfulQuery(ctx context.Context, cypher, sql string, duration time.Duration) error
+	SaveFailedQuery(ctx context.Context, cypher, sql string, err error) error
+}

internal/knowledge/graphdb.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"fmt"
 
-	"github.com/clems4ever/go-graphkb/internal/query"
 	"github.com/clems4ever/go-graphkb/internal/schema"
 )
 
@@ -27,7 +26,7 @@ type GraphDB interface {
 	CountAssets() (int64, error)
 	CountRelations() (int64, error)
 
-	Query(ctx context.Context, query *query.QueryCypher) (*GraphQueryResult, error)
+	Query(ctx context.Context, query SQLTranslation) (*GraphQueryResult, error)
 }
 
 // Cursor is a cursor over the results

internal/knowledge/querier.go

@@ -5,11 +5,13 @@ import (
 	"fmt"
 	"time"
 
+	"github.com/clems4ever/go-graphkb/internal/history"
 	"github.com/clems4ever/go-graphkb/internal/query"
 )
 
 type Querier struct {
-	GraphDB GraphDB
+	GraphDB    GraphDB
+	historizer history.Historizer
 }
 
 type QuerierResult struct {
@@ -18,31 +20,53 @@ type QuerierResult struct {
 	Statistics  Statistics
 }
 
-func NewQuerier(db GraphDB) *Querier {
-	return &Querier{GraphDB: db}
+func NewQuerier(db GraphDB, historizer history.Historizer) *Querier {
+	return &Querier{GraphDB: db, historizer: historizer}
 }
 
 func (q *Querier) Query(ctx context.Context, queryString string) (*QuerierResult, error) {
+	qr, sql, err := q.queryInternal(ctx, queryString)
+	if err != nil {
+		saveErr := q.historizer.SaveFailedQuery(ctx, queryString, sql, err)
+		if saveErr != nil {
+			return nil, fmt.Errorf("Unable to save query error in database: %v", saveErr)
+		}
+		return nil, err
+	}
+
+	saveErr := q.historizer.SaveSuccessfulQuery(ctx, queryString, sql, qr.Statistics.Execution/time.Millisecond)
+	if saveErr != nil {
+		return nil, fmt.Errorf("Unable to save query history in database: %v", saveErr)
+	}
+	return qr, nil
+}
+
+func (q *Querier) queryInternal(ctx context.Context, cypherQuery string) (*QuerierResult, string, error) {
 	s := Statistics{}
 
 	var err error
 	var queryCypher *query.QueryCypher
 
 	s.Parsing = MeasureDuration(func() {
-		queryCypher, err = query.TransformCypher(queryString)
+		queryCypher, err = query.TransformCypher(cypherQuery)
 	})
 
 	if err != nil {
-		return nil, err
+		return nil, "", err
+	}
+
+	translation, err := NewSQLQueryTranslator().Translate(queryCypher)
+	if err != nil {
+		return nil, "", err
 	}
 
 	var res *GraphQueryResult
 	s.Execution = MeasureDuration(func() {
-		res, err = q.GraphDB.Query(ctx, queryCypher)
+		res, err = q.GraphDB.Query(ctx, *translation)
 	})
 
 	if err != nil {
-		return nil, err
+		return nil, translation.Query, err
 	}
 
 	fmt.Printf("Found results in %dms\n", s.Execution/time.Millisecond)
@@ -52,7 +76,7 @@ func (q *Querier) Query(ctx context.Context, queryString string) (*QuerierResult
 		Projections: res.Projections,
 		Statistics:  s,
 	}
-	return result, nil
+	return result, translation.Query, nil
 }
 
 type Statistics struct {

internal/server/server.go

@@ -10,6 +10,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/clems4ever/go-graphkb/internal/history"
 	"github.com/clems4ever/go-graphkb/internal/importers"
 
 	auth "github.com/abbot/go-http-auth"
@@ -140,7 +141,7 @@ func getDatabaseDetails(database knowledge.GraphDB) http.HandlerFunc {
 	}
 }
 
-func postQuery(database knowledge.GraphDB) http.HandlerFunc {
+func postQuery(database knowledge.GraphDB, queryHistorizer history.Historizer) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
 		type QueryRequestBody struct {
 			Query string `json:"q"`
@@ -174,7 +175,7 @@ func postQuery(database knowledge.GraphDB) http.HandlerFunc {
 			return
 		}
 
-		querier := knowledge.NewQuerier(database)
+		querier := knowledge.NewQuerier(database, queryHistorizer)
 		ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
 		defer cancel()
 
@@ -356,14 +357,15 @@ func StartServer(listenInterface string,
 	database knowledge.GraphDB,
 	schemaPersistor schema.Persistor,
 	importersRegistry importers.Registry,
+	queryHistorizer history.Historizer,
 	graphUpdatesC chan knowledge.SourceSubGraphUpdates) {
 
 	r := mux.NewRouter()
 
 	listImportersHandler := listImporters(importersRegistry)
 	getSourceGraphHandler := getSourceGraph(importersRegistry, schemaPersistor)
 	getDatabaseDetailsHandler := getDatabaseDetails(database)
-	postQueryHandler := postQuery(database)
+	postQueryHandler := postQuery(database, queryHistorizer)
 	flushDatabaseHandler := flushDatabase(database)
 
 	if viper.GetString("password") != "" {