feat: configurable logging

README.md

@@ -264,14 +264,16 @@ export const getServerSideProps: GetServerSideProps = async () => {
 
 **Please note** that server-side database access is not protected by access policies. This is by-design so as to provide a way of bypassing the policies. Please make sure you implement authorization properly.
 
-## What's next?
+## Learning more
 
 ### [Learning the ZModel language](/docs/get-started/learning-the-zmodel-language.md)
 
 ### [Evolving data model with migration](/docs/ref/evolving-data-model-with-migration.md)
 
 ### [Database hosting considerations](/docs/ref/database-hosting-considerations.md)
 
+### [Setup logging](/docs/ref/setup-logging.md)
+
 ## Reach out to us for issues, feedback and ideas!
 
 [Discord](https://discord.gg/dbuC9ZWc) [Twitter](https://twitter.com/zenstackhq)

docs/ref/setup-logging.md

@@ -0,0 +1,75 @@
+# Setup Logging
+
+ZenStack uses the following levels to control server-side logging:
+
+1. error
+
+    Error level logging
+
+1. warn
+
+    Warning level logging
+
+1. info
+
+    Info level logging
+
+1. verbose
+
+    Verbose level logging
+
+1. query
+
+    Detailed database query logging
+
+By default, ZenStack prints `error` and `warn` level of logging with `console.error` and `console.log`, respectively. You can also control the logging behavior by providing a `zenstack.config.json` file at the root of your project.
+
+You can turn log levels on and off in `zenstack.config.json`:
+
+```json
+{
+    "log": ["verbose", "info", "warn"]
+}
+```
+
+You can also configure ZenStack to emit log as event instead of dumping to stdout, like:
+
+```json
+{
+    "log": [
+        {
+            "level": "info",
+            "emit": "event"
+        }
+    ]
+}
+```
+
+To consume the events:
+
+```ts
+import service from '@zenstackhq/runtime';
+
+service.$on('info', (event) => {
+    console.log(event.timestamp, event.message);
+});
+```
+
+You can also mix and match stdout output with event emitting, like:
+
+```json
+{
+    "log": [
+        {
+            "level": "info",
+            "emit": "stdout"
+        },
+        {
+            "level": "info",
+            "emit": "event"
+        }
+    ]
+}
+```
+
+The settings in `zenstack.config.json` controls logging of both ZenStack and the underlying Prisma instance.

package.json

@@ -1,6 +1,6 @@
 {
     "name": "zenstack-monorepo",
-    "version": "0.2.8",
+    "version": "0.2.9",
     "description": "",
     "scripts": {
         "build": "pnpm -r build",

packages/internal/jest.config.ts

@@ -10,6 +10,9 @@ export default {
     // Automatically clear mock calls, instances, contexts and results before every test
     clearMocks: true,
 
+    // Automatically reset mock state before every test
+    resetMocks: true,
+
     // Indicates whether the coverage information should be collected while executing the test
     collectCoverage: true,
 

packages/internal/package.json

@@ -1,6 +1,6 @@
 {
     "name": "@zenstackhq/internal",
-    "version": "0.2.8",
+    "version": "0.2.9",
     "displayName": "ZenStack Internal Library",
     "description": "ZenStack internal runtime library. This package is for supporting runtime functionality of ZenStack and not supposed to be used directly.",
     "repository": {
@@ -25,6 +25,7 @@
     ],
     "dependencies": {
         "bcryptjs": "^2.4.3",
+        "colors": "^1.4.0",
         "cuid": "^2.1.8",
         "deepcopy": "^2.1.0",
         "swr": "^1.3.0"

packages/internal/src/config.ts

@@ -0,0 +1,16 @@
+import { LogLevel } from './types';
+
+/**
+ * Logging config definition
+ */
+export type LogDefinition = {
+    level: LogLevel;
+    emit: 'stdout' | 'event';
+};
+
+/**
+ * Service configuration
+ */
+export interface ServiceConfig {
+    log?: Array<LogLevel | LogDefinition>;
+}

packages/internal/src/handler/data/handler.ts

@@ -49,6 +49,11 @@ export default class DataHandler<DbClient extends DbClientContract>
 
         const context = { user: await this.options.getServerUser(req, res) };
 
+        this.service.verbose(`Data request: ${method} ${path}`);
+        if (req.body) {
+            this.service.verbose(`Request body: ${JSON.stringify(req.body)}`);
+        }
+
         try {
             switch (method) {
                 case 'GET':
@@ -68,12 +73,12 @@ export default class DataHandler<DbClient extends DbClientContract>
                     break;
 
                 default:
-                    console.warn(`Unhandled method: ${method}`);
+                    this.service.warn(`Unhandled method: ${method}`);
                     res.status(200).send({});
                     break;
             }
         } catch (err: unknown) {
-            console.log(`Error handling ${method} ${model}: ${err}`);
+            this.service.error(`${method} ${model}: ${err}`);
 
             if (err instanceof RequestHandlerError) {
                 // in case of errors thrown directly by ZenStack
@@ -85,12 +90,14 @@ export default class DataHandler<DbClient extends DbClientContract>
                             message: err.message,
                         });
                         break;
+
                     case ServerErrorCode.ENTITY_NOT_FOUND:
                         res.status(404).send({
                             code: err.code,
                             message: err.message,
                         });
                         break;
+
                     default:
                         res.status(400).send({
                             code: err.code,
@@ -112,13 +119,21 @@ export default class DataHandler<DbClient extends DbClientContract>
                         message: 'an unhandled Prisma error occurred',
                     });
                 }
+            } else if (this.isPrismaClientValidationError(err)) {
+                // prisma validation error
+                res.status(400).send({
+                    code: ServerErrorCode.INVALID_REQUEST_PARAMS,
+                    message: getServerErrorMessage(
+                        ServerErrorCode.INVALID_REQUEST_PARAMS
+                    ),
+                });
             } else {
                 // generic errors
-                console.error(
+                this.service.error(
                     `An unknown error occurred: ${JSON.stringify(err)}`
                 );
-                if (err instanceof Error) {
-                    console.error(err.stack);
+                if (err instanceof Error && err.stack) {
+                    this.service.error(err.stack);
                 }
                 res.status(500).send({
                     error: ServerErrorCode.UNKNOWN,
@@ -206,7 +221,7 @@ export default class DataHandler<DbClient extends DbClientContract>
                 );
 
                 // conduct the create
-                console.log(
+                this.service.verbose(
                     `Conducting create: ${model}:\n${JSON.stringify(args)}`
                 );
                 const createResult = (await tx[model].create(args)) as {
@@ -229,7 +244,7 @@ export default class DataHandler<DbClient extends DbClientContract>
                         const createdIds = await queryIds(model, tx, {
                             [TRANSACTION_FIELD_NAME]: `${transactionId}:create`,
                         });
-                        console.log(
+                        this.service.verbose(
                             `Validating nestedly created entities: ${model}#[${createdIds.join(
                                 ', '
                             )}]`
@@ -332,7 +347,7 @@ export default class DataHandler<DbClient extends DbClientContract>
                 );
 
                 // conduct the update
-                console.log(
+                this.service.verbose(
                     `Conducting update: ${model}:\n${JSON.stringify(args)}`
                 );
                 await tx[model].update(args);
@@ -343,7 +358,7 @@ export default class DataHandler<DbClient extends DbClientContract>
                         const createdIds = await queryIds(model, tx, {
                             [TRANSACTION_FIELD_NAME]: `${transactionId}:create`,
                         });
-                        console.log(
+                        this.service.verbose(
                             `Validating nestedly created entities: ${model}#[${createdIds.join(
                                 ', '
                             )}]`
@@ -445,7 +460,7 @@ export default class DataHandler<DbClient extends DbClientContract>
                 }
 
                 // conduct the deletion
-                console.log(
+                this.service.verbose(
                     `Conducting delete ${model}:\n${JSON.stringify(args)}`
                 );
                 await tx[model].delete(args);
@@ -463,8 +478,17 @@ export default class DataHandler<DbClient extends DbClientContract>
         }
     }
 
-    private isPrismaClientKnownRequestError(err: any): err is { code: string } {
-        // we can't reference Prisma generated types so need to weakly check error type
-        return !!err.clientVersion && typeof err.code === 'string';
+    private isPrismaClientKnownRequestError(
+        err: any
+    ): err is { code: string; message: string } {
+        return (
+            err.__proto__.constructor.name === 'PrismaClientKnownRequestError'
+        );
+    }
+
+    private isPrismaClientValidationError(
+        err: any
+    ): err is { message: string } {
+        return err.__proto__.constructor.name === 'PrismaClientValidationError';
     }
 }

packages/internal/src/handler/data/policy-utils.ts

@@ -102,7 +102,7 @@ export async function readWithCheck(
     // recursively inject read guard conditions into the query args
     await injectNestedReadConditions(model, args, service, context);
 
-    console.log(
+    service.verbose(
         `Reading with validation for ${model}: ${JSON.stringify(args)}`
     );
     const result = await db[model].findMany(args);
@@ -207,7 +207,7 @@ async function postProcessForRead(
             continue;
         }
 
-        console.log(
+        service.verbose(
             `Validating read of to-one relation: ${fieldInfo.type}#${entityData[field].id}`
         );
 
@@ -378,7 +378,7 @@ export async function checkPolicyForIds(
     context: QueryContext,
     db: Record<string, DbOperations>
 ) {
-    console.log(
+    service.verbose(
         `Checking policy for ${model}#[${ids.join(', ')}] for ${operation}`
     );
 
@@ -427,7 +427,7 @@ async function checkPolicyForSelectionPath(
     // build a Prisma query for the path
     const query = buildChainedSelectQuery(id, selectionPath);
 
-    console.log(
+    service.verbose(
         `Query for selection path: model ${model}, path ${JSON.stringify(
             selectionPath
         )}, query ${JSON.stringify(query)}`
@@ -436,7 +436,7 @@ async function checkPolicyForSelectionPath(
 
     // collect ids at the end of the path
     const ids: string[] = collectTerminalEntityIds(selectionPath, r);
-    console.log(`Collected leaf ids: ${JSON.stringify(ids)}`);
+    service.verbose(`Collected leaf ids: ${JSON.stringify(ids)}`);
 
     if (ids.length === 0) {
         return;

packages/internal/src/index.ts

@@ -1,3 +1,5 @@
 export * from './types';
+export * from './config';
+export * from './service';
 export * from './request-handler';
 export * as request from './request';

packages/internal/src/request-handler.ts

@@ -40,7 +40,8 @@ export function requestHandler<DbClient>(
                 return dataHandler.handle(req, res, rest);
 
             default:
-                res.status(404).json({ error: 'Unknown route: ' + route });
+                service.warn(`Unknown route: ${route}`);
+                res.status(404).json({ error: `Unknown route: ${route}` });
         }
     };
 }

packages/internal/src/request.ts

@@ -113,7 +113,6 @@ export function getMutate(): Mutator {
         const keys = Array.from(cache.keys()).filter(
             (k) => typeof k === 'string' && k.startsWith(key)
         ) as string[];
-        console.log('Mutating keys:', JSON.stringify(keys));
         const mutations = keys.map((key) => mutate(key, data, opts));
         return Promise.all(mutations);
     };