From fd8810d27fac0993ca18d32c4188be11681689c1 Mon Sep 17 00:00:00 2001 From: prostgles Date: Wed, 15 May 2024 11:44:12 +0300 Subject: [PATCH] improve logging --- lib/AuthHandler.ts | 12 ++ lib/DboBuilder/DboBuilderTypes.ts | 3 +- lib/DboBuilder/ViewHandler/ViewHandler.ts | 9 +- lib/Logging.ts | 44 ++++--- lib/Prostgles.ts | 141 +++++++++++++--------- lib/PubSubManager/PubSubManager.ts | 3 + lib/PubSubManager/addSync.ts | 24 ++-- lib/SyncReplication.ts | 62 ++++++---- package-lock.json | 18 +-- package.json | 4 +- tests/server/package-lock.json | 6 +- 11 files changed, 192 insertions(+), 134 deletions(-) diff --git a/lib/AuthHandler.ts b/lib/AuthHandler.ts index 61643317..c23795d8 100644 --- a/lib/AuthHandler.ts +++ b/lib/AuthHandler.ts @@ -578,6 +578,18 @@ export default class AuthHandler { } } + /** + * Used for logging + */ + getSIDNoError = (localParams: LocalParams | undefined): string | undefined => { + if(!localParams) return undefined; + try { + return this.getSID(localParams); + } catch (err) { + return undefined; + } + } + async getClientInfo(localParams: Pick): Promise { if (!this.opts) return {}; diff --git a/lib/DboBuilder/DboBuilderTypes.ts b/lib/DboBuilder/DboBuilderTypes.ts index 8c70d062..74d15ddb 100644 --- a/lib/DboBuilder/DboBuilderTypes.ts +++ b/lib/DboBuilder/DboBuilderTypes.ts @@ -209,7 +209,8 @@ export type LocalParams = { t: pgPromise.ITask<{}>; } - // localTX?: pgPromise.ITask<{}>; + /** Used to exclude certain logs */ + noLog?: boolean; returnQuery?: boolean | "noRLS" | "where-condition"; returnNewQuery?: boolean; diff --git a/lib/DboBuilder/ViewHandler/ViewHandler.ts b/lib/DboBuilder/ViewHandler/ViewHandler.ts index 16a00d09..557fd7fe 100644 --- a/lib/DboBuilder/ViewHandler/ViewHandler.ts +++ b/lib/DboBuilder/ViewHandler/ViewHandler.ts @@ -86,7 +86,14 @@ export class ViewHandler { } _log = ({ command, data, localParams, duration, error }: Pick & { duration: number; error?: any; }) => { - return this.dboBuilder.prostgles.opts.onLog?.({ type: "table", tableName: this.name, command, data, localParams, duration, error }); + if(localParams?.noLog){ + if(localParams?.socket || localParams.httpReq) { + throw new Error("noLog option is not allowed from a remote client"); + } + return; + } + const sid = this.dboBuilder.prostgles.authHandler?.getSIDNoError(localParams); + return this.dboBuilder.prostgles.opts.onLog?.({ type: "table", sid, socketId: localParams?.socket?.id, tableName: this.name, command, data, localParams, duration, error }); } getRowHashSelect(allowedFields: FieldFilter, alias?: string, tableAlias?: string): string { diff --git a/lib/Logging.ts b/lib/Logging.ts index 2c6b495a..40f9a0c4 100644 --- a/lib/Logging.ts +++ b/lib/Logging.ts @@ -3,7 +3,7 @@ import { LocalParams } from "./DboBuilder/DboBuilder"; import { TableHandler } from "./DboBuilder/TableHandler/TableHandler"; type ClientInfo = { - socketId: string; + socketId: string | undefined; sid: string | undefined; } @@ -13,32 +13,21 @@ export namespace EventTypes { error?: any; } - export type Table = { + export type Table = ClientInfo & DebugInfo & { type: "table"; tableName: string; command: keyof TableHandler; data: AnyObject; localParams: LocalParams | undefined; - duration: number; - error?: any; }; - export type Sync = { + type SyncOneClient = ClientInfo & DebugInfo & { type: "sync"; tableName: string; localParams?: LocalParams; connectedSocketIds: string[]; - duration?: number; - error?: any; } & ( { - command: "notifListener"; - op_name: string | undefined; - condition_ids_str: string | undefined; - tableTriggers: string[] | undefined; - tableSyncs: string; - state: "ok" | "error" | "no-triggers" | "invalid_condition_ids"; - } | { command: "syncData"; source: "client" | "trigger"; connectedSocketIds: string[]; @@ -65,16 +54,36 @@ export namespace EventTypes { connectedSocketIds: string[]; } ); + export type SyncMultiClient = { + type: "sync"; + tableName: string; + localParams?: LocalParams; + connectedSocketIds: string[]; + } & ( + { + command: "notifListener"; + op_name: string | undefined; + condition_ids_str: string | undefined; + tableTriggers: string[] | undefined; + tableSyncs: string; + state: "ok" | "error" | "no-triggers" | "invalid_condition_ids"; + } + ); + + export type Sync = SyncOneClient | SyncMultiClient; - export type Connection = ClientInfo & { + export type Connection = (ClientInfo & { type: "connect" | "disconnect"; socketId: string; connectedSocketIds: string[]; - }; + }) | (ClientInfo & DebugInfo & { + type: "connect.getClientSchema"; + }); - export type Method = { + export type Method = ClientInfo & DebugInfo & { type: "method"; args: any[]; + localParams: LocalParams; }; export type Debug = DebugInfo & { @@ -102,6 +111,7 @@ export type EventInfo = | EventTypes.Table | EventTypes.Method | EventTypes.Sync + | EventTypes.SyncMultiClient | EventTypes.Connection | EventTypes.Debug; diff --git a/lib/Prostgles.ts b/lib/Prostgles.ts index f1670d32..8f33f258 100644 --- a/lib/Prostgles.ts +++ b/lib/Prostgles.ts @@ -384,9 +384,9 @@ export class Prostgles { type: "debug", command: "refreshDBO.start", duration: -1, - data: { work_mem: await this.db?.oneOrNone(`show work_mem;`) } + data: { } }); - const now = Date.now(); + const start = Date.now(); if (this._dboBuilder) { await this._dboBuilder.build(); } else { @@ -394,7 +394,7 @@ export class Prostgles { } if (!this.dboBuilder) throw "this.dboBuilder"; this.dbo = this.dboBuilder.dbo; - await this.opts.onLog?.({ type: "debug", command: "refreshDBO.end", duration: Date.now() - now }) + await this.opts.onLog?.({ type: "debug", command: "refreshDBO.end", duration: Date.now() - start }) return this.dbo; } @@ -429,7 +429,7 @@ export class Prostgles { } }); await this.opts.onLog?.({ type: "debug", command: "initTableConfig", ...res }); - if(res.error !== undefined) throw res.error; + if(res.hasError) throw res.error; return res.data; } @@ -619,70 +619,91 @@ export class Prostgles { } getClientSchema = async (clientReq: Pick) => { - const clientInfo = clientReq.socket? { type: "socket" as const, socket: clientReq.socket } : clientReq.httpReq? { type: "http" as const, httpReq: clientReq.httpReq } : undefined; - if(!clientInfo) throw "Invalid client"; - if(!this.authHandler) throw "this.authHandler missing"; - const userData = await this.authHandler.getClientInfo(clientInfo); - const { publishParser } = this; - let fullSchema: { - schema: TableSchemaForClient; - tables: DBSchemaTable[]; - } | undefined; - let publishValidationError; - try { - if (!publishParser) throw "publishParser undefined"; - fullSchema = await publishParser.getSchemaFromPublish({ ...clientInfo, userData }); - } catch (e) { - publishValidationError = "Server Error: PUBLISH VALIDATION ERROR"; - console.error(`\nProstgles PUBLISH VALIDATION ERROR (after socket connected):\n ->`, e); - } - let rawSQL = false; - if (this.opts.publishRawSQL && typeof this.opts.publishRawSQL === "function") { - const { allowed } = await clientCanRunSqlRequest.bind(this)(clientInfo); - rawSQL = allowed; - } + const result = await tryCatch(async () => { - const { schema, tables } = fullSchema ?? { schema: {}, tables: [] }; - const joinTables2: string[][] = []; - if (this.opts.joins) { - const _joinTables2 = this.dboBuilder.getAllJoinPaths() - .filter(jp => - ![jp.t1, jp.t2].find(t => !schema[t] || !schema[t]?.findOne) - ).map(jp => [jp.t1, jp.t2].sort()); - _joinTables2.map(jt => { - if (!joinTables2.find(_jt => _jt.join() === jt.join())) { - joinTables2.push(jt); - } - }); - } + const clientInfo = clientReq.socket? { type: "socket" as const, socket: clientReq.socket } : clientReq.httpReq? { type: "http" as const, httpReq: clientReq.httpReq } : undefined; + if(!clientInfo) throw "Invalid client"; + if(!this.authHandler) throw "this.authHandler missing"; + const userData = await this.authHandler.getClientInfo(clientInfo); - const methods = await publishParser?.getAllowedMethods(clientInfo, userData); + const { publishParser } = this; + let fullSchema: { + schema: TableSchemaForClient; + tables: DBSchemaTable[]; + } | undefined; + let publishValidationError; - const methodSchema: ClientSchema["methods"] = !methods? [] : getKeys(methods).map(methodName => { - const method = methods[methodName]; + try { + if (!publishParser) throw "publishParser undefined"; + fullSchema = await publishParser.getSchemaFromPublish({ ...clientInfo, userData }); + } catch (e) { + publishValidationError = e; + console.error(`\nProstgles Publish validation failed (after socket connected):\n ->`, e); + } + let rawSQL = false; + if (this.opts.publishRawSQL && typeof this.opts.publishRawSQL === "function") { + const { allowed } = await clientCanRunSqlRequest.bind(this)(clientInfo); + rawSQL = allowed; + } - if(isObject(method) && "run" in method){ - return { - name: methodName, - ...omitKeys(method, ["run"]), + const { schema, tables } = fullSchema ?? { schema: {}, tables: [] }; + const joinTables2: string[][] = []; + if (this.opts.joins) { + const _joinTables2 = this.dboBuilder.getAllJoinPaths() + .filter(jp => + ![jp.t1, jp.t2].find(t => !schema[t] || !schema[t]?.findOne) + ).map(jp => [jp.t1, jp.t2].sort()); + _joinTables2.map(jt => { + if (!joinTables2.find(_jt => _jt.join() === jt.join())) { + joinTables2.push(jt); + } + }); + } + + const methods = await publishParser?.getAllowedMethods(clientInfo, userData); + + const methodSchema: ClientSchema["methods"] = !methods? [] : getKeys(methods).map(methodName => { + const method = methods[methodName]; + + if(isObject(method) && "run" in method){ + return { + name: methodName, + ...omitKeys(method, ["run"]), + } } + return methodName; + }); + + const { auth } = clientReq.socket? await this.authHandler.makeSocketAuth(clientReq.socket) : { auth: {} }; + + const clientSchema: ClientSchema = { + schema, + methods: methodSchema, + tableSchema: tables, + rawSQL, + joinTables: joinTables2, + auth, + version, + err: publishValidationError? "Server Error: User publish validation failed." : undefined + }; + + return { + publishValidationError, + clientSchema, + userData } - return methodName; }); - - const { auth } = clientReq.socket? await this.authHandler.makeSocketAuth(clientReq.socket) : { auth: {} }; - const clientSchema: ClientSchema = { - schema, - methods: methodSchema, - tableSchema: tables, - rawSQL, - joinTables: joinTables2, - auth, - version, - err: publishValidationError - } - return clientSchema; + const sid = result.userData?.sid ?? this.authHandler?.getSIDNoError(clientReq); + await this.opts.onLog?.({ + type: "connect.getClientSchema", + duration: result.duration, + sid, + socketId: clientReq.socket?.id, + error: result.error || result.publishValidationError, + }); + if(result.hasError) throw result.error; + return result.clientSchema; } pushSocketSchema = async (socket: PRGLIOSocket) => { diff --git a/lib/PubSubManager/PubSubManager.ts b/lib/PubSubManager/PubSubManager.ts index 0070efe5..e75d7195 100644 --- a/lib/PubSubManager/PubSubManager.ts +++ b/lib/PubSubManager/PubSubManager.ts @@ -43,6 +43,7 @@ export type BasicCallback = (err?: any, res?: any) => void export type SyncParams = { socket_id: string; + sid: string | undefined; channel_name: string; table_name: string; table_rules?: TableRule; @@ -375,6 +376,7 @@ export class PubSubManager { command: "upsertSocket.disconnect", tableName: "", duration: 0, + sid: this.dboBuilder.prostgles.authHandler?.getSIDNoError({ socket }), socketId: socket.id, connectedSocketIds: this.connectedSocketIds, remainingSubs: JSON.stringify(this.subs.map(s => ({ tableName: s.table_info.name, triggers: s.triggers }))), @@ -498,6 +500,7 @@ export class PubSubManager { socketId: socket?.id, state: !addedTrigger.tbl? "fail" : "ok", error: addedTrigger.error, + sid: this.dboBuilder.prostgles.authHandler?.getSIDNoError({ socket }), tableName: addedTrigger.tbl ?? params.table_name, connectedSocketIds: this.dboBuilder.prostgles.connectedSockets.map(s => s.id), localParams: { socket } diff --git a/lib/PubSubManager/addSync.ts b/lib/PubSubManager/addSync.ts index 75b8c0ff..8f161283 100644 --- a/lib/PubSubManager/addSync.ts +++ b/lib/PubSubManager/addSync.ts @@ -1,6 +1,5 @@ import { find, tryCatch } from "prostgles-types/dist/util"; -import { BasicCallback, parseCondition, PubSubManager } from "./PubSubManager"; -import { AddSyncParams, DEFAULT_SYNC_BATCH_SIZE } from "./PubSubManager"; +import { AddSyncParams, BasicCallback, DEFAULT_SYNC_BATCH_SIZE, PubSubManager, parseCondition } from "./PubSubManager"; /** * Returns a sync channel @@ -8,6 +7,7 @@ import { AddSyncParams, DEFAULT_SYNC_BATCH_SIZE } from "./PubSubManager"; */ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { + const sid = this.dboBuilder.prostgles.authHandler?.getSIDNoError({ socket: syncParams.socket }); const res = await tryCatch(async () => { const { @@ -18,7 +18,6 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { const conditionParsed = parseCondition(condition); if (!socket || !table_info) throw "socket or table_info missing"; - const { name: table_name } = table_info; const channel_name = `${this.socketChannelPreffix}.${table_name}.${JSON.stringify(filter)}.sync`; @@ -33,12 +32,12 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { filter, condition: conditionParsed, synced_field, + sid, id_fields, allow_delete, table_rules, throttle: Math.max(throttle || 0, table_rules?.sync?.throttle || 0), batch_size: table_rules?.sync?.batch_size || DEFAULT_SYNC_BATCH_SIZE, - // last_throttled: 0, socket_id: socket.id, is_sync: true, last_synced: 0, @@ -65,7 +64,9 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { socketId: socket.id, tableName: table_name, condition, - connectedSocketIds: this.connectedSocketIds, + sid, + connectedSocketIds: this.connectedSocketIds, + duration: -1, }); socket.removeAllListeners(channel_name); socket.removeAllListeners(unsyncChn); @@ -100,23 +101,14 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { 4. Upsert data.data | deleted on(data.data | data.deleted) */ - // if(data.data){ - // console.error("THIS SHOUKD NEVER FIRE !! NEW DATA FROM SYNC"); - // this.upsertClientData(newSync, data.data); - // } else if (data.onSyncRequest) { - // console.log("syncData from socket") this.syncData(newSync, data.onSyncRequest, "client"); - // console.log("onSyncRequest ", socket._user) } else { console.error("Unexpected sync request data from client: ", data) } }); - // socket.emit(channel_name, { onSyncRequest: true }, (response) => { - // console.log(response) - // }); } else { console.warn("UNCLOSED DUPLICATE SYNC FOUND", existing.channel_name); } @@ -124,9 +116,6 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { return newSync; }; - - // const { min_id, max_id, count, max_synced } = params; - upsertSync(); await this.addTrigger({ table_name, condition: conditionParsed }, undefined, socket); @@ -143,6 +132,7 @@ export async function addSync(this: PubSubManager, syncParams: AddSyncParams) { connectedSocketIds: this.connectedSocketIds, duration: res.duration, error: res.error, + sid, }); if(res.error !== undefined) throw res.error; diff --git a/lib/SyncReplication.ts b/lib/SyncReplication.ts index 61cea8c3..d627db44 100644 --- a/lib/SyncReplication.ts +++ b/lib/SyncReplication.ts @@ -50,11 +50,14 @@ export async function syncData (this: PubSubManager, sync: SyncParams, clientDat type: "sync", command: "syncData", tableName: sync.table_name, + sid: sync.sid, source, ...pickKeys(sync, ["socket_id", "condition", "last_synced", "is_syncing"]), lr: JSON.stringify(sync.lr), connectedSocketIds: this.dboBuilder.prostgles.connectedSockets.map(s => s.id), - localParams: undefined + localParams: undefined, + duration: -1, + socketId: sync.socket_id }); const { @@ -193,16 +196,8 @@ export async function syncData (this: PubSubManager, sync: SyncParams, clientDat */ upsertData = async (data: AnyObject[]) => { - await this._log({ - type: "sync", - command: "upsertData", - tableName: sync.table_name, - rows: data.length, - socketId: socket_id, - connectedSocketIds: this.dboBuilder.prostgles.connectedSockets.map(s => s.id) - }); - - return this.dboBuilder.getTX(async (dbTX) => { + const start = Date.now(); + const result = await this.dboBuilder.getTX(async (dbTX) => { const tbl = dbTX[table_name] as TableHandler; const existingData = await tbl.find( { $or: data.map(d => pickKeys(d, id_fields)) }, @@ -247,26 +242,32 @@ export async function syncData (this: PubSubManager, sync: SyncParams, clientDat log(`upsertData: inserted( ${inserts.length} ) updated( ${updates.length} ) total( ${data.length} ) \n last insert ${JSON.stringify(inserts.at(-1))} \n last update ${JSON.stringify(updates.at(-1))}`); return { inserted: inserts.length, updated: updates.length, total: data.length }; }) - .catch(err => { - console.trace("Something went wrong with syncing to server: \n ->", err, data.length, id_fields); - return Promise.reject("Something went wrong with syncing to server: ") - }); - }, + .catch(err => { + console.trace("Something went wrong with syncing to server: \n ->", err, data.length, id_fields); + return Promise.reject("Something went wrong with syncing to server: ") + }); - /** - * Pushes the given data to client - * @param isSynced = true if - */ - pushData = async (data?: AnyObject[], isSynced = false, err: any = null) => { await this._log({ type: "sync", - command: "pushData", + command: "upsertData", tableName: sync.table_name, - rows: data?.length ?? 0, + rows: data.length, socketId: socket_id, + sid: sync.sid, + duration: Date.now() - start, connectedSocketIds: this.dboBuilder.prostgles.connectedSockets.map(s => s.id) }); - return new Promise((resolve, reject) => { + + return result; + }, + + /** + * Pushes the given data to client + * @param isSynced = true if + */ + pushData = async (data?: AnyObject[], isSynced = false, err: any = null) => { + const start = Date.now(); + const result = await new Promise((resolve, reject) => { socket.emit(channel_name, { data, isSynced }, (resp?: { ok: boolean }) => { if (resp && resp.ok) { @@ -278,6 +279,19 @@ export async function syncData (this: PubSubManager, sync: SyncParams, clientDat } }); }); + + await this._log({ + type: "sync", + command: "pushData", + tableName: sync.table_name, + rows: data?.length ?? 0, + socketId: socket_id, + duration: Date.now() - start, + sid: sync.sid, + connectedSocketIds: this.dboBuilder.prostgles.connectedSockets.map(s => s.id) + }); + + return result; }, /** diff --git a/package-lock.json b/package-lock.json index 1835baf3..77b25c42 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "prostgles-server", - "version": "4.2.59", + "version": "4.2.60", "lockfileVersion": 2, "requires": true, "packages": { "": { "name": "prostgles-server", - "version": "4.2.59", + "version": "4.2.60", "license": "MIT", "dependencies": { "bluebird": "^3.7.2", @@ -17,7 +17,7 @@ "pg-cursor": "^2.10.5", "pg-promise": "^11.6.0", "prostgles-client": "^4.0.53", - "prostgles-types": "^4.0.85" + "prostgles-types": "^4.0.86" }, "devDependencies": { "@types/bluebird": "^3.5.36", @@ -2193,9 +2193,9 @@ } }, "node_modules/prostgles-types": { - "version": "4.0.85", - "resolved": "https://registry.npmjs.org/prostgles-types/-/prostgles-types-4.0.85.tgz", - "integrity": "sha512-rMG5Wq6w7tyS14gpZ/aBliwgA4MEpZQUAkBjtgq9IVSBPJlCBBYOftC5YHzEXA1btKQr5UDIF32q5FYLgKPTTw==", + "version": "4.0.86", + "resolved": "https://registry.npmjs.org/prostgles-types/-/prostgles-types-4.0.86.tgz", + "integrity": "sha512-xLxeT/4eue/U0eIF3Rzv43pdyEsPovU6vRxKYj1V3Y+UjHOf118gXeGvGmcsa/W3eLXlb6SSy/ailWslnr0zRA==", "dependencies": { "json-schema": "^0.4.0" } @@ -4376,9 +4376,9 @@ } }, "prostgles-types": { - "version": "4.0.85", - "resolved": "https://registry.npmjs.org/prostgles-types/-/prostgles-types-4.0.85.tgz", - "integrity": "sha512-rMG5Wq6w7tyS14gpZ/aBliwgA4MEpZQUAkBjtgq9IVSBPJlCBBYOftC5YHzEXA1btKQr5UDIF32q5FYLgKPTTw==", + "version": "4.0.86", + "resolved": "https://registry.npmjs.org/prostgles-types/-/prostgles-types-4.0.86.tgz", + "integrity": "sha512-xLxeT/4eue/U0eIF3Rzv43pdyEsPovU6vRxKYj1V3Y+UjHOf118gXeGvGmcsa/W3eLXlb6SSy/ailWslnr0zRA==", "requires": { "json-schema": "^0.4.0" } diff --git a/package.json b/package.json index 4fb5e0b8..abd0a3ac 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "prostgles-server", - "version": "4.2.59", + "version": "4.2.60", "description": "", "main": "dist/index.js", "types": "dist/index.d.ts", @@ -43,7 +43,7 @@ "pg-cursor": "^2.10.5", "pg-promise": "^11.6.0", "prostgles-client": "^4.0.53", - "prostgles-types": "^4.0.85" + "prostgles-types": "^4.0.86" }, "devDependencies": { "@types/bluebird": "^3.5.36", diff --git a/tests/server/package-lock.json b/tests/server/package-lock.json index 5b1fa9c7..4f148a01 100644 --- a/tests/server/package-lock.json +++ b/tests/server/package-lock.json @@ -21,7 +21,7 @@ }, "../..": { "name": "prostgles-server", - "version": "4.2.59", + "version": "4.2.60", "license": "MIT", "dependencies": { "bluebird": "^3.7.2", @@ -32,7 +32,7 @@ "pg-cursor": "^2.10.5", "pg-promise": "^11.6.0", "prostgles-client": "^4.0.53", - "prostgles-types": "^4.0.85" + "prostgles-types": "^4.0.86" }, "devDependencies": { "@types/bluebird": "^3.5.36", @@ -1548,7 +1548,7 @@ "pg-cursor": "^2.10.5", "pg-promise": "^11.6.0", "prostgles-client": "^4.0.53", - "prostgles-types": "^4.0.85", + "prostgles-types": "^4.0.86", "typescript": "^5.3.3" } },