spicedb revisit logs and levels

The spicedb log output is fairly verbose at the info level. We should revisit our log output and improve the operator experience:

all requests are reported at info level
some grpc operations with specific codes are being reported at level warn (example FailedPrecondition when someone tries to interact with a schema type that does not exist).

Aug 18 '22 15:08 vroldanbet

Another user requested that health checking specifically be a higher verbosity than other requests. Perhaps it makes sense it only have that be debug.

Nov 21 '22 20:11 jzelinskie

@jzelinskie we can easily remove logging the health endpoint, grpclog allows customizing that via WithDecider which we already have set up. Unfortunately what I cannot do is change the level for a specific log entry. Another option is "log at info only if code is != OK"

If none of those seem like a reasonable compromise, and if I'm right the module does not give us the customization we need, the option would be to add a custom gRPC interceptor around it.

Nov 23 '22 18:11 vroldanbet

As a user I'd be happy with either option above, our issue is that the health endpoint log is incredibly noisy and obfuscates any other logs coming out of the serve command. As a sidenote, would it be difficult to set up a way for users to specify a log filter regex based on thegrpc.service property? That way users are a bit more free with what they choose to log or not.

Nov 28 '22 14:11 JoaoSouMoreira

Hi guys, any update?

There seem to be too many logs out there with information level For example Health probes and usual permission check requests. These could be debug level logs.

{"level":"info","requestID":"0a4957f3bdb2d9956610a31b7523f1da","protocol":"grpc","grpc.component":"server","grpc.service":"grpc.health.v1.Health","grpc.method":"Check","grpc.method_type":"unary","peer.address":"[::1]:43620","grpc.start_time":"2023-10-09T15:02:06Z","grpc.request.deadline":"2023-10-09T15:02:07Z","grpc.code":"OK","grpc.time_ms":"0.14","time":"2023-10-09T15:02:06Z","message":"finished call"}
{"level":"info","requestID":"4f719244dbd737c04eadabc18cc9fd24","protocol":"grpc","grpc.component":"server","grpc.service":"grpc.health.v1.Health","grpc.method":"Check","grpc.method_type":"unary","peer.address":"[::1]:38090","grpc.start_time":"2023-10-09T15:02:14Z","grpc.request.deadline":"2023-10-09T15:02:15Z","grpc.code":"OK","grpc.time_ms":"0.181","time":"2023-10-09T15:02:14Z","message":"finished call"}
{"level":"info","requestID":"bf095b6be22bb467230959cc47489d56","protocol":"grpc","grpc.component":"server","grpc.service":"grpc.health.v1.Health","grpc.method":"Check","grpc.method_type":"unary","peer.address":"[::1]:43414","grpc.start_time":"2023-10-09T15:02:24Z","grpc.request.deadline":"2023-10-09T15:02:25Z","grpc.code":"OK","grpc.time_ms":"0.102","time":"2023-10-09T15:02:24Z","message":"finished call"}
{"level":"info","requestID":"0948e117e2611e2accb36190f1415c3c","protocol":"grpc","grpc.component":"server","grpc.service":"grpc.health.v1.Health","grpc.method":"Check","grpc.method_type":"unary","peer.address":"[::1]:36842","grpc.start_time":"2023-10-09T15:02:34Z","grpc.request.deadline":"2023-10-09T15:02:35Z","grpc.code":"OK","grpc.time_ms":"0.097","time":"2023-10-09T15:02:34Z","message":"finished call"}
{"level":"info","requestID":"0eaae4160f7aa73d0150b4c9b40568b7","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.SchemaService","grpc.method":"WriteSchema","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:34Z","grpc.code":"OK","grpc.time_ms":"33.053","time":"2023-10-09T15:02:34Z","message":"finished call"}
{"level":"info","requestID":"e899469bad054bff07e03a727dce7e26","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:35Z","grpc.code":"OK","grpc.time_ms":"34.671","time":"2023-10-09T15:02:35Z","message":"finished call"}
{"level":"info","requestID":"8bb28e95f1cce663a8c51661fa327e62","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:35Z","grpc.code":"OK","grpc.time_ms":"606.893","time":"2023-10-09T15:02:35Z","message":"finished call"}
{"level":"info","requestID":"f89dae6c96742cfdb811f2085a120350","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:35Z","grpc.code":"OK","grpc.time_ms":"40.303","time":"2023-10-09T15:02:35Z","message":"finished call"}
{"level":"info","requestID":"27458f865ad41f48a3c27a0f56b917b9","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:35Z","grpc.code":"OK","grpc.time_ms":"1429.658","time":"2023-10-09T15:02:37Z","message":"finished call"}
{"level":"info","requestID":"1642074db61bd9941a591b152d8ff0a3","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:37Z","grpc.code":"OK","grpc.time_ms":"58.222","time":"2023-10-09T15:02:37Z","message":"finished call"}
{"level":"info","requestID":"83ee338443c01107b52146a71a4c09ac","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:37Z","grpc.code":"OK","grpc.time_ms":"2775.332","time":"2023-10-09T15:02:40Z","message":"finished call"}
{"level":"info","requestID":"8752700f6717c168b7835c1319afd0d7","protocol":"grpc","grpc.component":"server","grpc.service":"authzed.api.v1.PermissionsService","grpc.method":"WriteRelationships","grpc.method_type":"unary","peer.address":"127.0.0.1:38932","grpc.start_time":"2023-10-09T15:02:40Z","grpc.code":"OK","grpc.time_ms":"58.011","time":"2023-10-09T15:02:40Z","message":"finished call"}

I'm wondering if logging every request impacts application performance

Oct 10 '23 06:10 gunpuz

Hi, no updates on this front - each individual would have different log customization needs, so what seems verbose to you could be just fine to others.

Regarding overhead, we've run successfully large-scale load-tests (1M RPS) with info level without a problem.

Oct 10 '23 15:10 vroldanbet