Skip to content

Commit 6f3dace

Browse files
tolgaozentolgaozen
authored
Merge pull request #1007 from Permify/log-improvements
feat: log improvements
2 parents e0dccfd + 83c3a0a commit 6f3dace

File tree

17 files changed

+130
-109
lines changed

17 files changed

+130
-109
lines changed

‎docs/apidocs.swagger.json‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
"info": {
44
"title": "Permify API",
55
"description": "Permify is an open source authorization service for creating fine-grained and scalable authorization systems.",
6-
"version": "v0.6.9",
6+
"version": "v0.7.0",
77
"contact": {
88
"name": "API Support",
99
"url": "https://github.com/Permify/permify/issues",

‎internal/info.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ var Identifier = ""
1616
*/
1717
const (
1818
// Version is the last release of the Permify (e.g. v0.1.0)
19-
Version = "v0.6.9"
19+
Version = "v0.7.0"
2020

2121
// Banner is the view for terminal.
2222
Banner = `

‎internal/servers/error.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -25,9 +25,9 @@ func GetStatus(err error) codes.Code {
2525
return codes.Unauthenticated
2626
case code > 1999 && code < 2999:
2727
return codes.InvalidArgument
28-
case code > 2999 && code < 3999:
29-
return codes.NotFound
3028
case code > 3999 && code < 4999:
29+
return codes.NotFound
30+
case code > 4999 && code < 5999:
3131
return codes.Internal
3232
default:
3333
return codes.Internal

‎internal/servers/server.go‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,8 @@ import (
1010
"net/http/pprof"
1111
"time"
1212

13+
"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging"
14+
1315
"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/ratelimit"
1416

1517
grpcAuth "github.com/grpc-ecosystem/go-grpc-middleware/auth"
@@ -100,6 +102,7 @@ func NewContainer(
100102
func (s *Container) Run(
101103
ctx context.Context,
102104
srv *config.Server,
105+
logger *slog.Logger,
103106
dst *config.Distributed,
104107
authentication *config.Authn,
105108
profiler *config.Profiler,
@@ -109,16 +112,22 @@ func (s *Container) Run(
109112

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

115+
lopts := []logging.Option{
116+
logging.WithLogOnEvents(logging.StartCall, logging.FinishCall),
117+
}
118+
112119
unaryInterceptors := []grpc.UnaryServerInterceptor{
113120
grpcValidator.UnaryServerInterceptor(),
114121
grpcRecovery.UnaryServerInterceptor(),
115122
ratelimit.UnaryServerInterceptor(limiter),
123+
logging.UnaryServerInterceptor(InterceptorLogger(logger), lopts...),
116124
}
117125

118126
streamingInterceptors := []grpc.StreamServerInterceptor{
119127
grpcValidator.StreamServerInterceptor(),
120128
grpcRecovery.StreamServerInterceptor(),
121129
ratelimit.StreamServerInterceptor(limiter),
130+
logging.StreamServerInterceptor(InterceptorLogger(logger), lopts...),
122131
}
123132

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

365374
return nil
366375
}
376+
377+
// InterceptorLogger adapts slog logger to interceptor logger.
378+
func InterceptorLogger(l *slog.Logger) logging.Logger {
379+
return logging.LoggerFunc(func(ctx context.Context, lvl logging.Level, msg string, fields ...any) {
380+
l.Log(ctx, slog.Level(lvl), msg, fields...)
381+
})
382+
}

‎internal/storage/postgres/bundleReader.go‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ func (b *BundleReader) Read(ctx context.Context, tenantID, name string) (bundle
3232
ctx, span := tracer.Start(ctx, "bundle-reader.read-bundle")
3333
defer span.End()
3434

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

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

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

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

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

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

7070
return nil, errors.New(base.ErrorCode_ERROR_CODE_INVALID_ARGUMENT.String())
7171
}

‎internal/storage/postgres/bundleWriter.go‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,7 @@ func (b *BundleWriter) Write(ctx context.Context, bundles []storage.Bundle) (nam
3131
ctx, span := tracer.Start(ctx, "bundle-writer.write-bundle")
3232
defer span.End()
3333

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

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

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

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

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

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

77-
slog.Info("Deleting bundle: ", slog.Any("bundle", name))
77+
slog.Debug("deleting bundle", slog.Any("bundle", name))
7878

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

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

94-
slog.Info("Successfully deleted Bundle")
94+
slog.Debug("bundle successfully deleted")
9595

9696
return nil
9797
}

‎internal/storage/postgres/dataReader.go‎

Lines changed: 27 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,7 @@ func (r *DataReader) QueryRelationships(ctx context.Context, tenantID string, fi
4545
ctx, span := tracer.Start(ctx, "data-reader.query-relationships")
4646
defer span.End()
4747

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

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

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

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

111-
slog.Info("Successfully retrieved relation tuples from the database.")
111+
slog.Debug("successfully retrieved relation tuples from the database")
112112

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

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

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

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

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

207-
slog.Info("Successfully read relation tuples from database.")
207+
slog.Debug("successfully read relation tuples from database")
208208

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

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

255-
slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
256+
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))
256257

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

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

288-
slog.Info("Successfully retrieved Single attribute from the database.")
289+
slog.Debug("successfully retrieved Single attribute from the database")
289290

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

299-
slog.Info("Querying Attributes for tenantID: ", slog.String("tenant_id", tenantID))
300+
slog.Debug("querying Attributes for tenant_id", slog.String("tenant_id", tenantID))
300301

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

332-
slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
333+
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))
333334

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

376-
slog.Info("Successfully retrieved attributes tuples from the database.")
377+
slog.Debug("successfully retrieved attributes tuples from the database")
377378

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

388-
slog.Info("Reading attributes for tenantID: ", slog.String("tenant_id", tenantID))
389+
slog.Debug("reading attributes for tenant_id", slog.String("tenant_id", tenantID))
389390

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

438-
slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
439+
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))
439440

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

486-
slog.Info("Successfully read attributes from the database.")
487+
slog.Debug("successfully read attributes from the database")
487488

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

503+
slog.Debug("querying unique entities for tenant_id", slog.String("tenant_id", tenantID))
504+
502505
// Decode the snapshot value.
503506
var st token.SnapToken
504507
st, err = snapshot.EncodedToken{Value: snap}.Decode()
@@ -538,6 +541,8 @@ func (r *DataReader) QueryUniqueEntities(ctx context.Context, tenantID, name, sn
538541
// Append ORDER BY and LIMIT clauses.
539542
query = fmt.Sprintf("%s ORDER BY id LIMIT %d", query, pagination.PageSize()+1)
540543

544+
slog.Debug("generated sql query", slog.String("query", query))
545+
541546
// Execute the query and retrieve the rows.
542547
var rows *sql.Rows
543548
rows, err = tx.QueryContext(ctx, query)
@@ -571,6 +576,8 @@ func (r *DataReader) QueryUniqueEntities(ctx context.Context, tenantID, name, sn
571576
return nil, nil, utils.HandleError(span, err, base.ErrorCode_ERROR_CODE_EXECUTION)
572577
}
573578

579+
slog.Debug("successfully retrieved unique entities from the database")
580+
574581
// Return the results and encoded continuous token for pagination.
575582
if len(entityIDs) > int(pagination.PageSize()) {
576583
return entityIDs[:pagination.PageSize()], utils.NewContinuousToken(strconv.FormatUint(lastID, 10)).Encode(), nil
@@ -585,7 +592,7 @@ func (r *DataReader) QueryUniqueSubjectReferences(ctx context.Context, tenantID
585592
ctx, span := tracer.Start(ctx, "data-reader.query-unique-subject-reference")
586593
defer span.End()
587594

588-
slog.Info("Querying unique subject references for tenantID: ", slog.String("tenant_id", tenantID))
595+
slog.Debug("querying unique subject references for tenant_id", slog.String("tenant_id", tenantID))
589596

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

642-
slog.Debug("Generated SQL query: ", slog.String("query", query), "with args", slog.Any("arguments", args))
649+
slog.Debug("generated sql query", slog.String("query", query), "with args", slog.Any("arguments", args))
643650

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

675-
slog.Info("Successfully retrieved unique subject references from the database.")
682+
slog.Debug("successfully retrieved unique subject references from the database")
676683

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

691-
slog.Info("Getting head snapshot for tenantID: ", slog.String("tenant_id", tenantID))
698+
slog.Debug("getting head snapshot for tenant_id", slog.String("tenant_id", tenantID))
692699

693700
var xid types.XID8
694701

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

712-
slog.Info("Successfully retrieved latest snapshot token")
719+
slog.Debug("successfully retrieved latest snapshot token")
713720

714721
// Return the latest snapshot token associated with the tenant.
715722
return snapshot.Token{Value: xid}, nil

0 commit comments

Comments
 (0)