Skip to content

Commit

Permalink
Merge pull request #1007 from Permify/log-improvements
Browse files Browse the repository at this point in the history 
feat: log improvements
  • Loading branch information
@tolgaOzen
tolgaOzen committed Jan 15, 2024
2 parents e0dccfd + 83c3a0a commit 6f3dace
Show file tree
Hide file tree
Showing 17 changed files with 130 additions and 109 deletions.
2 changes: 1 addition & 1 deletion docs/apidocs.swagger.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
"info": {
"title": "Permify API",
"description": "Permify is an open source authorization service for creating fine-grained and scalable authorization systems.",
"version": "v0.6.9",
"version": "v0.7.0",
"contact": {
"name": "API Support",
"url": "https://github.com/Permify/permify/issues",
Expand Down
2 changes: 1 addition & 1 deletion internal/info.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ var Identifier = ""
*/
const (
// Version is the last release of the Permify (e.g. v0.1.0)
Version = "v0.6.9"
Version = "v0.7.0"

// Banner is the view for terminal.
Banner = `
Expand Down
4 changes: 2 additions & 2 deletions internal/servers/error.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,9 +25,9 @@ func GetStatus(err error) codes.Code {
return codes.Unauthenticated
case code > 1999 && code < 2999:
return codes.InvalidArgument
case code > 2999 && code < 3999:
return codes.NotFound
case code > 3999 && code < 4999:
return codes.NotFound
case code > 4999 && code < 5999:
return codes.Internal
default:
return codes.Internal
Expand Down
16 changes: 16 additions & 0 deletions internal/servers/server.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,8 @@ import (
"net/http/pprof"
"time"

"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"

"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/ratelimit"

grpcAuth "github.com/grpc-ecosystem/go-grpc-middleware/auth"
Expand Down Expand Up @@ -100,6 +102,7 @@ func NewContainer(
func (s *Container) Run(
ctx context.Context,
srv *config.Server,
logger *slog.Logger,
dst *config.Distributed,
authentication *config.Authn,
profiler *config.Profiler,
Expand All @@ -109,16 +112,22 @@ func (s *Container) Run(

limiter := middleware.NewRateLimiter(srv.RateLimit) // for example 1000 req/sec

lopts := []logging.Option{
logging.WithLogOnEvents(logging.StartCall, logging.FinishCall),
}

unaryInterceptors := []grpc.UnaryServerInterceptor{
grpcValidator.UnaryServerInterceptor(),
grpcRecovery.UnaryServerInterceptor(),
ratelimit.UnaryServerInterceptor(limiter),
logging.UnaryServerInterceptor(InterceptorLogger(logger), lopts...),
}

streamingInterceptors := []grpc.StreamServerInterceptor{
grpcValidator.StreamServerInterceptor(),
grpcRecovery.StreamServerInterceptor(),
ratelimit.StreamServerInterceptor(limiter),
logging.StreamServerInterceptor(InterceptorLogger(logger), lopts...),
}

// Configure authentication based on the provided method ("preshared" or "oidc").
Expand Down Expand Up @@ -364,3 +373,10 @@ func (s *Container) Run(

return nil
}

// InterceptorLogger adapts slog logger to interceptor logger.
func InterceptorLogger(l *slog.Logger) logging.Logger {
return logging.LoggerFunc(func(ctx context.Context, lvl logging.Level, msg string, fields ...any) {
l.Log(ctx, slog.Level(lvl), msg, fields...)
})
}
6 changes: 3 additions & 3 deletions internal/storage/postgres/bundleReader.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ func (b *BundleReader) Read(ctx context.Context, tenantID, name string) (bundle
ctx, span := tracer.Start(ctx, "bundle-reader.read-bundle")
defer span.End()

slog.Info("Reading bundle: ", slog.Any("tenant_id", tenantID), slog.Any("name", name))
slog.Debug("reading bundle", slog.Any("tenant_id", tenantID), slog.Any("name", name))

builder := b.database.Builder.Select("payload").From(BundlesTable).Where(squirrel.Eq{"name": name, "tenant_id": tenantID})

Expand All @@ -44,7 +44,7 @@ func (b *BundleReader) Read(ctx context.Context, tenantID, name string) (bundle
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Executing SQL query: ", slog.Any("query", query), slog.Any("arguments", args))
slog.Debug("executing sql query", slog.Any("query", query), slog.Any("arguments", args))

var row *sql.Row
row = b.database.DB.QueryRowContext(ctx, query, args...)
Expand All @@ -65,7 +65,7 @@ func (b *BundleReader) Read(ctx context.Context, tenantID, name string) (bundle
span.RecordError(err)
span.SetStatus(codes.Error, err.Error())

slog.Error("Failed to convert the value to bundle: ", slog.Any("error", err))
slog.Error("failed to convert the value to bundle", slog.Any("error", err))

return nil, errors.New(base.ErrorCode_ERROR_CODE_INVALID_ARGUMENT.String())
}
Expand Down
10 changes: 5 additions & 5 deletions internal/storage/postgres/bundleWriter.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ func (b *BundleWriter) Write(ctx context.Context, bundles []storage.Bundle) (nam
ctx, span := tracer.Start(ctx, "bundle-writer.write-bundle")
defer span.End()

slog.Info("Writing bundles to the database", slog.Any("number_of_bundles", len(bundles)))
slog.Debug("writing bundles to the database", slog.Any("number_of_bundles", len(bundles)))

insertBuilder := b.database.Builder.Insert(BundlesTable).
Columns("name, payload, tenant_id").
Expand All @@ -58,14 +58,14 @@ func (b *BundleWriter) Write(ctx context.Context, bundles []storage.Bundle) (nam
return names, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Executing SQL insert query: ", slog.Any("query", query), slog.Any("arguments", args))
slog.Debug("executing sql insert query", slog.Any("query", query), slog.Any("arguments", args))

_, err = b.database.DB.ExecContext(ctx, query, args...)
if err != nil {
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully wrote bundles to the database. ", slog.Any("number_of_bundles", len(bundles)))
slog.Debug("successfully wrote bundles to the database", slog.Any("number_of_bundles", len(bundles)))

return
}
Expand All @@ -74,7 +74,7 @@ func (b *BundleWriter) Delete(ctx context.Context, tenantID, name string) (err e
ctx, span := tracer.Start(ctx, "bundle-writer.delete-bundle")
defer span.End()

slog.Info("Deleting bundle: ", slog.Any("bundle", name))
slog.Debug("deleting bundle", slog.Any("bundle", name))

deleteBuilder := b.database.Builder.Delete(BundlesTable).Where(squirrel.Eq{"name": name, "tenant_id": tenantID})

Expand All @@ -91,7 +91,7 @@ func (b *BundleWriter) Delete(ctx context.Context, tenantID, name string) (err e
return utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully deleted Bundle")
slog.Debug("bundle successfully deleted")

return nil
}
47 changes: 27 additions & 20 deletions internal/storage/postgres/dataReader.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ func (r *DataReader) QueryRelationships(ctx context.Context, tenantID string, fi
ctx, span := tracer.Start(ctx, "data-reader.query-relationships")
defer span.End()

slog.Info("Querying relationships for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("querying relationships for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -78,7 +78,7 @@ func (r *DataReader) QueryRelationships(ctx context.Context, tenantID string, fi
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

// Execute the SQL query and retrieve the result rows.
var rows *sql.Rows
Expand Down Expand Up @@ -108,7 +108,7 @@ func (r *DataReader) QueryRelationships(ctx context.Context, tenantID string, fi
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully retrieved relation tuples from the database.")
slog.Debug("successfully retrieved relation tuples from the database")

// Return a TupleIterator created from the TupleCollection.
return collection.CreateTupleIterator(), nil
Expand All @@ -120,7 +120,7 @@ func (r *DataReader) ReadRelationships(ctx context.Context, tenantID string, fil
ctx, span := tracer.Start(ctx, "data-reader.read-relationships")
defer span.End()

slog.Info("Reading relationships for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("reading relationships for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -170,7 +170,7 @@ func (r *DataReader) ReadRelationships(ctx context.Context, tenantID string, fil
return nil, database.NewNoopContinuousToken().Encode(), utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

// Execute the query and retrieve the rows.
var rows *sql.Rows
Expand Down Expand Up @@ -204,7 +204,7 @@ func (r *DataReader) ReadRelationships(ctx context.Context, tenantID string, fil
return nil, nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully read relation tuples from database.")
slog.Debug("successfully read relation tuples from database")

// Return the results and encoded continuous token for pagination.
if len(tuples) > int(pagination.PageSize()) {
Expand All @@ -219,7 +219,8 @@ func (r *DataReader) QuerySingleAttribute(ctx context.Context, tenantID string,
// Start a new trace span and end it when the function exits.
ctx, span := tracer.Start(ctx, "data-reader.query-single-attribute")
defer span.End()
slog.Info("Querying single attribute for tenantID: ", slog.String("tenant_id", tenantID))

slog.Debug("querying single attribute for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -252,7 +253,7 @@ func (r *DataReader) QuerySingleAttribute(ctx context.Context, tenantID string,
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

row := tx.QueryRowContext(ctx, query, args...)

Expand Down Expand Up @@ -285,7 +286,7 @@ func (r *DataReader) QuerySingleAttribute(ctx context.Context, tenantID string,
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully retrieved Single attribute from the database.")
slog.Debug("successfully retrieved Single attribute from the database")

return rt.ToAttribute(), nil
}
Expand All @@ -296,7 +297,7 @@ func (r *DataReader) QueryAttributes(ctx context.Context, tenantID string, filte
ctx, span := tracer.Start(ctx, "data-reader.query-attributes")
defer span.End()

slog.Info("Querying Attributes for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("querying Attributes for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -329,7 +330,7 @@ func (r *DataReader) QueryAttributes(ctx context.Context, tenantID string, filte
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

// Execute the SQL query and retrieve the result rows.
var rows *sql.Rows
Expand Down Expand Up @@ -373,7 +374,7 @@ func (r *DataReader) QueryAttributes(ctx context.Context, tenantID string, filte
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully retrieved attributes tuples from the database.")
slog.Debug("successfully retrieved attributes tuples from the database")

// Return a TupleIterator created from the TupleCollection.
return collection.CreateAttributeIterator(), nil
Expand All @@ -385,7 +386,7 @@ func (r *DataReader) ReadAttributes(ctx context.Context, tenantID string, filter
ctx, span := tracer.Start(ctx, "data-reader.read-attributes")
defer span.End()

slog.Info("Reading attributes for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("reading attributes for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -435,7 +436,7 @@ func (r *DataReader) ReadAttributes(ctx context.Context, tenantID string, filter
return nil, database.NewNoopContinuousToken().Encode(), utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

// Execute the query and retrieve the rows.
var rows *sql.Rows
Expand Down Expand Up @@ -483,7 +484,7 @@ func (r *DataReader) ReadAttributes(ctx context.Context, tenantID string, filter
return nil, nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully read attributes from the database.")
slog.Debug("successfully read attributes from the database")

// Return the results and encoded continuous token for pagination.
if len(attributes) > int(pagination.PageSize()) {
Expand All @@ -499,6 +500,8 @@ func (r *DataReader) QueryUniqueEntities(ctx context.Context, tenantID, name, sn
ctx, span := tracer.Start(ctx, "data-reader.query-unique-entities")
defer span.End()

slog.Debug("querying unique entities for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
st, err = snapshot.EncodedToken{Value: snap}.Decode()
Expand Down Expand Up @@ -538,6 +541,8 @@ func (r *DataReader) QueryUniqueEntities(ctx context.Context, tenantID, name, sn
// Append ORDER BY and LIMIT clauses.
query = fmt.Sprintf("%s ORDER BY id LIMIT %d", query, pagination.PageSize()+1)

slog.Debug("generated sql query", slog.String("query", query))

// Execute the query and retrieve the rows.
var rows *sql.Rows
rows, err = tx.QueryContext(ctx, query)
Expand Down Expand Up @@ -571,6 +576,8 @@ func (r *DataReader) QueryUniqueEntities(ctx context.Context, tenantID, name, sn
return nil, nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Debug("successfully retrieved unique entities from the database")

// Return the results and encoded continuous token for pagination.
if len(entityIDs) > int(pagination.PageSize()) {
return entityIDs[:pagination.PageSize()], utils.NewContinuousToken(strconv.FormatUint(lastID, 10)).Encode(), nil
Expand All @@ -585,7 +592,7 @@ func (r *DataReader) QueryUniqueSubjectReferences(ctx context.Context, tenantID
ctx, span := tracer.Start(ctx, "data-reader.query-unique-subject-reference")
defer span.End()

slog.Info("Querying unique subject references for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("querying unique subject references for tenant_id", slog.String("tenant_id", tenantID))

// Decode the snapshot value.
var st token.SnapToken
Expand Down Expand Up @@ -639,7 +646,7 @@ func (r *DataReader) QueryUniqueSubjectReferences(ctx context.Context, tenantID
return nil, database.NewNoopContinuousToken().Encode(), utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SQL_BUILDER)
}

slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))

// Execute the query and retrieve the rows.
var rows *sql.Rows
Expand Down Expand Up @@ -672,7 +679,7 @@ func (r *DataReader) QueryUniqueSubjectReferences(ctx context.Context, tenantID
return nil, nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
}

slog.Info("Successfully retrieved unique subject references from the database.")
slog.Debug("successfully retrieved unique subject references from the database")

// Return the results and encoded continuous token for pagination.
if len(subjectIDs) > int(pagination.PageSize()) {
Expand All @@ -688,7 +695,7 @@ func (r *DataReader) HeadSnapshot(ctx context.Context, tenantID string) (token.S
ctx, span := tracer.Start(ctx, "data-reader.head-snapshot")
defer span.End()

slog.Info("Getting head snapshot for tenantID: ", slog.String("tenant_id", tenantID))
slog.Debug("getting head snapshot for tenant_id", slog.String("tenant_id", tenantID))

var xid types.XID8

Expand All @@ -709,7 +716,7 @@ func (r *DataReader) HeadSnapshot(ctx context.Context, tenantID string) (token.S
return nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_SCAN)
}

slog.Info("Successfully retrieved latest snapshot token")
slog.Debug("successfully retrieved latest snapshot token")

// Return the latest snapshot token associated with the tenant.
return snapshot.Token{Value: xid}, nil
Expand Down
Loading

0 comments on commit 6f3dace

Please sign in to comment.