WEBDIENSTE/huly-platform
1
0
Fork 0
mirror of https://github.com/hcengineering/platform.git synced 2026-09-21 17:17:54 +02:00
Code Issues Packages Projects Releases Wiki Activity

UBERF-6374: Improve server logging and improve startup performance (#5210)

Browse Source
This commit is contained in:
Andrey Sobolev
2024-04-06 15:14:06 +07:00
committed by GitHub
parent ceac67f3a3
commit 034700a65b
39 changed files with 631 additions and 405 deletions
Download Patch File Download Diff File Expand all files Collapse all files
server/ws/src/__tests__/server.test.ts
-3
View File
@@ -42,12 +42,9 @@ import {
import { type SessionContext } from '@hcengineering/server-core'
import { ClientSession } from '../client'
import { startHttpServer } from '../server_http'
import { disableLogging } from '../types'
import { genMinModel } from './minmodel'
describe('server', () => {
disableLogging()
async function getModelDb (): Promise<ModelDb> {
const txes = genMinModel()
const hierarchy = new Hierarchy()
server/ws/src/client.ts
+2 -1
View File
@@ -48,6 +48,7 @@ import { type BroadcastCall, type Session, type SessionRequest, type StatisticsE
* @public
*/
export class ClientSession implements Session {
createTime = Date.now()
requests = new Map<string, SessionRequest>()
binaryResponseMode: boolean = false
useCompression: boolean = true
@@ -81,7 +82,7 @@ export class ClientSession implements Session {
}
async loadModel (ctx: MeasureContext, lastModelTx: Timestamp, hash?: string): Promise<Tx[] | LoadModelResponse> {
return await this._pipeline.storage.loadModel(lastModelTx, hash)
return await ctx.with('load-model', {}, async () => await this._pipeline.storage.loadModel(lastModelTx, hash))
}
async getAccount (ctx: MeasureContext): Promise<Account> {
server/ws/src/server.ts
+107 -60
View File
@@ -145,7 +145,7 @@ class TSessionManager implements SessionManager {
const now = Date.now()
const diff = now - s[1].session.lastRequest
if (diff > 60000 && this.ticks % 10 === 0) {
console.log('session hang, closing...', h[0], s[1].session.getUser())
void this.ctx.error('session hang, closing...', { sessionId: h[0], user: s[1].session.getUser() })
void this.close(s[1].socket, h[1].workspaceId, 1001, 'CLIENT_HANGOUT')
continue
}
@@ -160,7 +160,11 @@ class TSessionManager implements SessionManager {
for (const r of s[1].session.requests.values()) {
if (now - r.start > 30000) {
console.log(h[0], 'request hang found, 30sec', h[0], s[1].session.getUser(), r.params)
void this.ctx.info('request hang found, 30sec', {
sessionId: h[0],
user: s[1].session.getUser(),
...r.params
})
}
}
}
@@ -212,8 +216,9 @@ class TSessionManager implements SessionManager {
return await baseCtx.with('📲 add-session', {}, async (ctx) => {
const wsString = toWorkspaceString(token.workspace, '@')
let workspaceInfo =
let workspaceInfo = await ctx.with('check-token', {}, async (ctx) =>
accountsUrl !== '' ? await this.getWorkspaceInfo(accountsUrl, rawToken) : this.wsFromToken(token)
)
if (workspaceInfo === undefined && token.extra?.admin !== 'true') {
// No access to workspace for token.
return { error: new Error(`No access to workspace for token ${token.email} ${token.workspace.name}`) }
@@ -222,6 +227,10 @@ class TSessionManager implements SessionManager {
}
let workspace = this.workspaces.get(wsString)
if (workspace?.closeTimeout !== undefined) {
await ctx.info('Cancel workspace warm close', { wsString })
clearTimeout(workspace?.closeTimeout)
}
await workspace?.closing
workspace = this.workspaces.get(wsString)
if (sessionId !== undefined && workspace?.sessions?.has(sessionId) === true) {
@@ -278,7 +287,9 @@ class TSessionManager implements SessionManager {
this.sessions.set(ws.id, { session, socket: ws })
// We need to delete previous session with Id if found.
workspace.sessions.set(session.sessionId, { session, socket: ws })
await ctx.with('set-status', {}, () => this.setStatus(ctx, session, true))
// We do not need to wait for set-status, just return session to client
void ctx.with('set-status', {}, (ctx) => this.setStatus(ctx, session, true))
if (this.timeMinutes > 0) {
void ws.send(
@@ -316,7 +327,7 @@ class TSessionManager implements SessionManager {
workspaceName: string
): Promise<Pipeline> {
if (LOGGING_ENABLED) {
console.log(workspaceName, 'reloading workspace', JSON.stringify(token))
await ctx.info('reloading workspace', { workspaceName, token: JSON.stringify(token) })
}
// If upgrade client is used.
// Drop all existing clients
@@ -351,12 +362,16 @@ class TSessionManager implements SessionManager {
for (const session of sessions.splice(0, 1)) {
if (targets !== undefined && !targets.includes(session.session.getUser())) continue
for (const _tx of tx) {
void session.socket.send(
ctx,
{ result: _tx },
session.session.binaryResponseMode,
session.session.useCompression
)
try {
void session.socket.send(
ctx,
{ result: _tx },
session.session.binaryResponseMode,
session.session.useCompression
)
} catch (err: any) {
void ctx.error('error during send', { error: err })
}
}
}
if (sessions.length > 0) {
@@ -377,11 +392,12 @@ class TSessionManager implements SessionManager {
): Workspace {
const upgrade = token.extra?.model === 'upgrade'
const context = ctx.newChild('🧲 session', {})
const pipelineCtx = context.newChild('🧲 pipeline-factory', {})
const workspace: Workspace = {
context,
id: generateId(),
pipeline: pipelineFactory(
context,
pipelineCtx,
{ ...token.workspace, workspaceUrl, workspaceName },
upgrade,
(tx, targets) => {
@@ -393,8 +409,6 @@ class TSessionManager implements SessionManager {
workspaceId: token.workspace,
workspaceName
}
if (LOGGING_ENABLED) console.time(workspaceName)
if (LOGGING_ENABLED) console.timeLog(workspaceName, 'Creating Workspace:', workspace.id)
this.workspaces.set(toWorkspaceString(token.workspace), workspace)
return workspace
}
@@ -429,11 +443,12 @@ class TSessionManager implements SessionManager {
}
async close (ws: ConnectionSocket, workspaceId: WorkspaceId, code: number, reason: string): Promise<void> {
// if (LOGGING_ENABLED) console.log(workspaceId.name, `closing websocket, code: ${code}, reason: ${reason}`)
const wsid = toWorkspaceString(workspaceId)
const workspace = this.workspaces.get(wsid)
if (workspace === undefined) {
if (LOGGING_ENABLED) console.error(new Error('internal: cannot find sessions'))
if (LOGGING_ENABLED) {
await this.ctx.error('internal: cannot find sessions', { id: ws.id, workspace: workspaceId.name, code, reason })
}
return
}
const sessionRef = this.sessions.get(ws.id)
@@ -458,7 +473,9 @@ class TSessionManager implements SessionManager {
if (!workspace.upgrade) {
// Wait some time for new client to appear before closing workspace.
if (workspace.sessions.size === 0) {
setTimeout(() => {
clearTimeout(workspace.closeTimeout)
void this.ctx.info('schedule warm closing', { workspace: workspace.workspaceName, wsid })
workspace.closeTimeout = setTimeout(() => {
void this.performWorkspaceCloseCheck(workspace, workspaceId, wsid)
}, this.timeouts.shutdownWarmTimeout)
}
@@ -469,7 +486,15 @@ class TSessionManager implements SessionManager {
}
async closeAll (wsId: string, workspace: Workspace, code: number, reason: 'upgrade' | 'shutdown'): Promise<void> {
if (LOGGING_ENABLED) console.timeLog(wsId, `closing workspace ${workspace.id}, code: ${code}, reason: ${reason}`)
if (LOGGING_ENABLED) {
await this.ctx.info('closing workspace', {
workspace: workspace.id,
wsName: workspace.workspaceName,
code,
reason,
wsId
})
}
const sessions = Array.from(workspace.sessions)
workspace.sessions = new Map()
@@ -484,21 +509,30 @@ class TSessionManager implements SessionManager {
await this.setStatus(workspace.context, s, false)
}
if (LOGGING_ENABLED) console.timeLog(wsId, workspace.id, 'Clients disconnected. Closing Workspace...')
if (LOGGING_ENABLED) {
await this.ctx.info('Clients disconnected. Closing Workspace...', {
wsId,
workspace: workspace.id,
wsName: workspace.workspaceName
})
}
await Promise.all(sessions.map((s) => closeS(s[1].session, s[1].socket)))
const closePipeline = async (): Promise<void> => {
try {
if (LOGGING_ENABLED) console.timeLog(wsId, 'closing pipeline')
await (await workspace.pipeline).close()
if (LOGGING_ENABLED) console.timeLog(wsId, 'closing pipeline done')
await this.ctx.with('close-pipeline', {}, async () => {
await (await workspace.pipeline).close()
})
} catch (err: any) {
console.error(err)
await this.ctx.error('close-pipeline-error', { error: err })
}
}
await Promise.race([closePipeline(), timeoutPromise(15000)])
if (LOGGING_ENABLED) console.timeLog(wsId, 'Workspace closed...')
console.timeEnd(wsId)
await this.ctx.with('closing', {}, async () => {
await Promise.race([closePipeline(), timeoutPromise(15000)])
})
if (LOGGING_ENABLED) {
await this.ctx.info('Workspace closed...', { workspace: workspace.id, wsId, wsName: workspace.workspaceName })
}
}
private async sendUpgrade (ctx: MeasureContext, webSocket: ConnectionSocket, binary: boolean): Promise<void> {
@@ -530,31 +564,36 @@ class TSessionManager implements SessionManager {
): Promise<void> {
if (workspace.sessions.size === 0) {
const wsUID = workspace.id
const logParams = { wsid, workspace: workspace.id, wsName: workspaceId.name }
if (LOGGING_ENABLED) {
console.log(workspaceId.name, 'no sessions for workspace', wsid, wsUID)
await this.ctx.info('no sessions for workspace', logParams)
}
const waitAndClose = async (workspace: Workspace): Promise<void> => {
try {
const pl = await workspace.pipeline
await Promise.race([pl, timeoutPromise(60000)])
await Promise.race([pl.close(), timeoutPromise(60000)])
if (workspace.closing === undefined) {
const waitAndClose = async (workspace: Workspace): Promise<void> => {
try {
if (workspace.sessions.size === 0) {
const pl = await workspace.pipeline
await Promise.race([pl, timeoutPromise(60000)])
await Promise.race([pl.close(), timeoutPromise(60000)])
if (this.workspaces.get(wsid)?.id === wsUID) {
if (this.workspaces.get(wsid)?.id === wsUID) {
this.workspaces.delete(wsid)
}
workspace.context.end()
if (LOGGING_ENABLED) {
await this.ctx.info('Closed workspace', logParams)
}
}
} catch (err: any) {
this.workspaces.delete(wsid)
}
workspace.context.end()
if (LOGGING_ENABLED) {
console.timeLog(workspaceId.name, 'Closed workspace', wsUID)
}
} catch (err: any) {
this.workspaces.delete(wsid)
if (LOGGING_ENABLED) {
console.error(workspaceId.name, err)
if (LOGGING_ENABLED) {
await this.ctx.error('failed', { ...logParams, error: err })
}
}
}
workspace.closing = waitAndClose(workspace)
}
workspace.closing = waitAndClose(workspace)
await workspace.closing
}
}
@@ -562,13 +601,22 @@ class TSessionManager implements SessionManager {
broadcast (from: Session | null, workspaceId: WorkspaceId, resp: Response<any>, target?: string[]): void {
const workspace = this.workspaces.get(toWorkspaceString(workspaceId))
if (workspace === undefined) {
console.error(new Error('internal: cannot find sessions'))
void this.ctx.error('internal: cannot find sessions', {
workspaceId: workspaceId.name,
target,
userId: from?.getUser() ?? '$unknown'
})
return
}
if (workspace?.upgrade ?? false) {
return
}
if (LOGGING_ENABLED) console.log(workspaceId.name, `server broadcasting to ${workspace.sessions.size} clients...`)
if (LOGGING_ENABLED) {
void this.ctx.info('server broadcasting to clients...', {
workspace: workspaceId.name,
count: workspace.sessions.size
})
}
const sessions = [...workspace.sessions.values()]
const ctx = this.ctx.newChild('📭 broadcast', {})
@@ -627,19 +675,14 @@ class TSessionManager implements SessionManager {
service.useBroadcast = hello.broadcast ?? false
if (LOGGING_ENABLED) {
console.timeLog(
workspace,
'hello happen',
service.getUser(),
'binary:',
service.binaryResponseMode,
'compression:',
service.useCompression,
'workspace users:',
this.workspaces.get(workspace)?.sessions?.size,
'total users:',
this.sessions.size
)
await ctx.info('hello happen', {
user: service.getUser(),
binary: service.binaryResponseMode,
compression: service.useCompression,
timeToHello: Date.now() - service.createTime,
workspaceUsers: this.workspaces.get(workspace)?.sessions?.size,
totalUsers: this.sessions.size
})
}
const helloResponse: HelloResponse = {
id: -1,
@@ -684,7 +727,9 @@ class TSessionManager implements SessionManager {
service.useCompression
)
} catch (err: any) {
if (LOGGING_ENABLED) console.error(err)
if (LOGGING_ENABLED) {
await this.ctx.error('error handle request', { error: err, request })
}
const resp: Response<any> = {
id: request.id,
error: unknownError(err),
@@ -726,7 +771,9 @@ class TSessionManager implements SessionManager {
service.useCompression
)
} catch (err: any) {
if (LOGGING_ENABLED) console.error(err)
if (LOGGING_ENABLED) {
await ctx.error('error handle measure', { error: err, request })
}
const resp: Response<any> = {
id: request.id,
error: unknownError(err),
server/ws/src/server_http.ts
+28 -13
View File
@@ -47,7 +47,9 @@ export function startHttpServer (
enableCompression: boolean,
accountsUrl: string
): () => Promise<void> {
if (LOGGING_ENABLED) console.log(`starting server on port ${port} ...`)
if (LOGGING_ENABLED) {
void ctx.info('starting server on', { port, productId, enableCompression, accountsUrl })
}
const app = express()
app.use(cors())
@@ -209,21 +211,27 @@ export function startHttpServer (
)
if ('upgrade' in session || 'error' in session) {
if ('error' in session) {
console.error(session.error)
void ctx.error('error', { error: session.error })
}
cs.close()
return
}
// eslint-disable-next-line @typescript-eslint/no-misused-promises
ws.on('message', (msg: RawData) => {
let buff: any | undefined
if (msg instanceof Buffer) {
buff = msg?.toString()
} else if (Array.isArray(msg)) {
buff = Buffer.concat(msg).toString()
}
if (buff !== undefined) {
void handleRequest(session.context, session.session, cs, buff, session.workspaceName)
try {
let buff: any | undefined
if (msg instanceof Buffer) {
buff = msg?.toString()
} else if (Array.isArray(msg)) {
buff = Buffer.concat(msg).toString()
}
if (buff !== undefined) {
void handleRequest(session.context, session.session, cs, buff, session.workspaceName)
}
} catch (err: any) {
if (LOGGING_ENABLED) {
void ctx.error('message error', err)
}
}
})
// eslint-disable-next-line @typescript-eslint/no-misused-promises
@@ -251,12 +259,17 @@ export function startHttpServer (
const sessionId = url.searchParams.get('sessionId')
if (payload.workspace.productId !== productId) {
if (LOGGING_ENABLED) {
void ctx.error('invalid product', { required: payload.workspace.productId, productId })
}
throw new Error('Invalid workspace product')
}
wss.handleUpgrade(request, socket, head, (ws) => wss.emit('connection', ws, request, payload, token, sessionId))
} catch (err) {
if (LOGGING_ENABLED) console.error('invalid token', err)
} catch (err: any) {
if (LOGGING_ENABLED) {
void ctx.error('invalid token', err)
}
wss.handleUpgrade(request, socket, head, (ws) => {
const resp: Response<any> = {
id: -1,
@@ -274,7 +287,9 @@ export function startHttpServer (
}
})
httpServer.on('error', (err) => {
if (LOGGING_ENABLED) console.error('server error', err)
if (LOGGING_ENABLED) {
void ctx.error('server error', err)
}
})
httpServer.listen(port)
server/ws/src/types.ts
+3
View File
@@ -35,6 +35,7 @@ export interface StatisticsElement {
* @public
*/
export interface Session {
createTime: number
getUser: () => string
pipeline: () => Pipeline
ping: () => Promise<string>
@@ -117,7 +118,9 @@ export interface Workspace {
pipeline: Promise<Pipeline>
sessions: Map<string, { session: Session, socket: ConnectionSocket }>
upgrade: boolean
closing?: Promise<void>
closeTimeout?: any
workspaceId: WorkspaceId
workspaceName: string