From 39a2f152602d6aa33904b53da08453dcc90db476 Mon Sep 17 00:00:00 2001 From: waiting <1661926154@qq.com> Date: Thu, 21 Nov 2024 21:22:32 +0800 Subject: [PATCH] refactor(mwcp): trace --- .../src/lib/caller.service.ts | 4 +- .../src/lib/db-event.ts | 152 ++++++++++-------- .../src/lib/db-hook/db-hook.builder.ts | 33 ++-- .../src/lib/db-hook/db-hook.trx.helper.ts | 18 ++- .../src/lib/db-hook/db-hook.trx.ts | 78 +++++---- .../src/lib/db-source-manager.ts | 79 ++++++++- .../src/lib/propagation/trx-status.helper.ts | 2 +- .../src/lib/trx-status.service.ts | 20 ++- .../test/30.transactional-simple.test.ts | 88 ++++++++-- .../test/config.unittest.ts | 1 + .../30/30c.transactional-simple.controller.ts | 7 + .../30/30r.transactional-simple.repo.ts | 7 + 12 files changed, 351 insertions(+), 138 deletions(-) diff --git a/packages/midway-component-kmore/src/lib/caller.service.ts b/packages/midway-component-kmore/src/lib/caller.service.ts index 9db3235e..91eca844 100644 --- a/packages/midway-component-kmore/src/lib/caller.service.ts +++ b/packages/midway-component-kmore/src/lib/caller.service.ts @@ -46,8 +46,8 @@ export class CallerService { // #region Call stack - retrieveCallerInfo(distance = 0): CallerInfo { - const callerInfo = getCallerStack(distance + 1, false) + retrieveCallerInfo(distance = 0, retrievePosition = false): CallerInfo { + const callerInfo = getCallerStack(distance + 1, retrievePosition) return callerInfo } diff --git a/packages/midway-component-kmore/src/lib/db-event.ts b/packages/midway-component-kmore/src/lib/db-event.ts index 75838732..4e0d7391 100644 --- a/packages/midway-component-kmore/src/lib/db-event.ts +++ b/packages/midway-component-kmore/src/lib/db-event.ts @@ -8,6 +8,8 @@ import { Singleton, } from '@midwayjs/core' import { + type Span, + type TraceService, AttrNames, Attributes, DecoratorTraceData, @@ -16,6 +18,7 @@ import { Trace, TraceLog, TraceScopeType, + getSpan, } from '@mwcp/otel' import { Application, Context, MConfig, getWebContext } from '@mwcp/share' import { humanMemoryUsage } from '@waiting/shared-core' @@ -38,7 +41,7 @@ export class DbEvent { @Inject() readonly baseDir: string @Inject() readonly trxStatusSvc: TrxStatusService - + @Inject() readonly traceService: TraceService getDbConfigByDbId(dbId: SourceName): DbConfig | undefined { assert(dbId) @@ -62,6 +65,7 @@ export class DbEvent { } } + // #region onStart @Trace({ @@ -77,39 +81,43 @@ export class DbEvent { const name = `Kmore ${kmore.dbId} ${method}` return name }, - scope([options]) { + before([options], decoratorContext) { + if (! eventNeedTrace(KmoreAttrNames.BuilderCompile, options.dbConfig)) { return } + const traceContext = decoratorContext.traceContext ?? this.traceService.getActiveContext() const { kmore, event } = options const { kmoreQueryId, queryBuilder } = event + const traceScope = this.retrieveTraceScope(kmore, kmoreQueryId, queryBuilder) - return traceScope - }, - before: ([options], decoratorContext) => { - if (! eventNeedTrace(KmoreAttrNames.BuilderCompile, options.dbConfig)) { return } - const { event } = options - const { queryBuilder } = event + if (! this.trxStatusSvc.getTraceContextByScope(traceScope)) { + this.trxStatusSvc.setTraceContextByScope(traceScope, traceContext) + } + this.trxStatusSvc.setTraceContextByScope(kmoreQueryId, traceContext) + const { pagingType } = queryBuilder - const { traceSpan } = decoratorContext + const traceSpan = getSpan(traceContext) const ret: DecoratorTraceData = {} if (pagingType && traceSpan) { - const { traceService, traceScope, traceContext } = decoratorContext if (pagingType === 'counter') { + assert(queryBuilder.pagingGroupKey, 'queryBuilder.pagingGroupKey is empty') + if (! this.trxStatusSvc.getTraceContextByScope(queryBuilder.pagingGroupKey)) { + this.trxStatusSvc.setTraceContextByScope(queryBuilder.pagingGroupKey, traceContext) + } + // @ts-expect-error name const spanName = traceSpan.name as string const spanName2 = `${spanName} AutoPaging` if (! spanName.endsWith('AutoPaging')) { traceSpan.updateName(spanName2) } - const opts: StartScopeActiveSpanOptions = { name: 'Kmore Counter', scope: traceScope, traceContext, } - assert(traceService, 'traceService is empty') - const { span, traceContext: traceCtx2 } = traceService.startScopeActiveSpan(opts) - void span - ret.traceContext = traceCtx2 + const { traceContext: traceCtx2 } = this.traceService.startScopeSpan(opts) + this.trxStatusSvc.setTraceContextByScope(kmoreQueryId, traceCtx2) + ret.traceContext = traceCtx2 // necessary } else { const spanName2 = 'Kmore Pager' @@ -133,7 +141,6 @@ export class DbEvent { // value: true, // }) // } - const cb = dbConfig.eventCallbacks?.start return cb?.(event, kmore) } @@ -141,19 +148,8 @@ export class DbEvent { // #region onResp @TraceLog({ - scope([options]) { - const { kmore, event } = options - // const traceScope = this.getTrxTraceScopeByQueryId(kmore, event.kmoreQueryId) - // if (traceScope) { - // return traceScope - // } - // const traceScope2 = event.queryBuilder.kmoreQueryId - const traceScope = this.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) - return traceScope - }, - before: ([options]) => { + before([options]) { if (! eventNeedTrace(KmoreAttrNames.QueryResponse, options.dbConfig)) { return } - const { respRaw } = options.event const attrs: Attributes = {} @@ -171,28 +167,55 @@ export class DbEvent { return { attrs, events } }, - after([options], _result, decoratorContext) { + after([options]) { if (! eventNeedTrace(KmoreAttrNames.QueryResponse, options.dbConfig)) { return } - const { traceService, traceScope, traceSpan } = decoratorContext - assert(traceService, 'traceService is empty') - assert(traceScope, 'onResp.after() traceScope is empty') - assert(traceSpan, 'traceSpan is empty') - const ret: DecoratorTraceData = {} - const { pagingType } = options.event.queryBuilder - if (pagingType && pagingType !== 'counter') { - ret.endParentSpan = true - } - const scopeRootSpan = traceService.getActiveSpanOnlyScope(traceScope) - // const foo = traceService.retrieveParentTraceInfoBySpan(traceSpan, traceScope) - // void foo + const { kmore, event } = options + const { kmoreQueryId } = event + const traceScope = this.retrieveTraceScope(kmore, kmoreQueryId, event.queryBuilder) + + switch (pagingType) { + case 'counter': { + this.trxStatusSvc.removeTraceContextByScope(kmoreQueryId) + ret.endSpanAfterTraceLog = true + break + } - if (scopeRootSpan && scopeRootSpan === traceSpan) { - ret.endSpanAfterTraceLog = true + case 'pager': { + const spans: Span[] = [] + const scopeCtx = this.trxStatusSvc.getTraceContextByScope(traceScope) + if (scopeCtx) { + const span = getSpan(scopeCtx) + if (span?.isRecording()) { + spans.push(span) + } + } + const activeCtx = this.trxStatusSvc.getTraceContextByScope(event.kmoreQueryId) + if (activeCtx) { + const span = getSpan(activeCtx) + if (span?.isRecording()) { + spans.push(span) + } + } + + this.trxStatusSvc.removeTraceContextByScope(kmoreQueryId) + const { pagingGroupKey } = event.queryBuilder + if (pagingGroupKey) { + this.trxStatusSvc.removeTraceContextByScope(pagingGroupKey) + } + this.trxStatusSvc.removeTraceContextByScope(traceScope) + ret.endSpanAfterTraceLog = spans + break + } + + default: { + ret.endSpanAfterTraceLog = true + } } + return ret }, }) @@ -209,17 +232,10 @@ export class DbEvent { // #region onQuery @TraceLog({ - scope([options]) { - const { kmore, event } = options - const traceScope = this.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) - return traceScope - }, before([options], decoratorContext) { if (! eventNeedTrace(KmoreAttrNames.QueryQuerying, options.dbConfig)) { return } - - const { traceService, traceScope, traceSpan } = decoratorContext + const { traceService, traceSpan } = decoratorContext assert(traceService, 'traceService is empty') - assert(traceScope, 'onQuery.after() traceScope is empty') assert(traceSpan, 'traceSpan is empty') const { config: knexConfig } = options.dbConfig @@ -262,13 +278,13 @@ export class DbEvent { // #region onError @TraceLog({ - scope([options]) { - const { kmore, event } = options - const traceScope = this.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) - return traceScope - }, before([options]) { if (! eventNeedTrace(KmoreAttrNames.QueryError, options.dbConfig)) { return } + // if (! decoratorContext.traceScope) { + // const { kmore } = options + // const { kmoreQueryId, queryBuilder } = options.event + // decoratorContext.traceScope = this.retrieveTraceScope(kmore, kmoreQueryId, queryBuilder) + // } const { dbId, kUid, queryUid, trxId, exData, exError, @@ -296,13 +312,15 @@ export class DbEvent { const { traceService, traceScope, traceSpan } = decoratorContext assert(traceService, 'traceService is empty') - assert(traceScope, 'onResp.after() traceScope is empty') + // assert(traceScope, 'onResp.after() traceScope is empty') assert(traceSpan, 'traceSpan is empty') - const scopeRootSpan = traceService.getActiveSpanOnlyScope(traceScope) - if (scopeRootSpan && scopeRootSpan === traceSpan) { - const spanStatusOptions = { code: SpanStatusCode.ERROR } - return { endSpanAfterTraceLog: true, spanStatusOptions } + if (traceScope) { + const scopeRootSpan = traceService.getRootSpan(traceScope) + if (scopeRootSpan && scopeRootSpan === traceSpan) { + const spanStatusOptions = { code: SpanStatusCode.ERROR } + return { endSpanAfterTraceLog: true, spanStatusOptions } + } } return null @@ -318,12 +336,7 @@ export class DbEvent { } - protected getTrxTraceScopeByQueryId(db: Kmore, queryId: symbol): TraceScopeType | undefined { - const trx = db.getTrxByQueryId(queryId) - return trx?.kmoreTrxId - } - - protected retrieveTraceScope(kmore: Kmore, kmoreQueryId: symbol, builder: KmoreQueryBuilder): TraceScopeType { + retrieveTraceScope(kmore: Kmore, kmoreQueryId: symbol, builder: KmoreQueryBuilder): TraceScopeType { const { pagingGroupKey, pagingType } = builder const traceScope = this.getTrxTraceScopeByQueryId(kmore, kmoreQueryId) @@ -339,6 +352,11 @@ export class DbEvent { return traceScope ?? kmoreQueryId } + protected getTrxTraceScopeByQueryId(db: Kmore, queryId: symbol): TraceScopeType | undefined { + const trx = db.getTrxByQueryId(queryId) + return trx?.kmoreTrxId + } + } // #region types diff --git a/packages/midway-component-kmore/src/lib/db-hook/db-hook.builder.ts b/packages/midway-component-kmore/src/lib/db-hook/db-hook.builder.ts index f10f6a2a..cdf8531b 100644 --- a/packages/midway-component-kmore/src/lib/db-hook/db-hook.builder.ts +++ b/packages/midway-component-kmore/src/lib/db-hook/db-hook.builder.ts @@ -65,9 +65,9 @@ export class DbHookBuilder { } /* Call stack in bindBuilderPropagationData(): - 1 - TrxStatusService.bindBuilderPropagationData(trx - status.service.ts: 389) - 2 - DbSourceManager.builderPrePropagating(db - source - manager.ts: 377) - 3 - DbSourceManager.builderPreProcessor(db - source - manager.ts: 378) + 1 - TrxStatusService.bindBuilderPropagationData(trx-status.service.ts: 389) + 2 - DbSourceManager.builderPrePropagating(db- source-manager.ts: 377) + 3 - DbSourceManager.builderPreProcessor(db-source-manager.ts: 378) 4 - (builder.index.js: 67) 5 - extRefTableFnProperty(builder.index.js: 64) 6 - tb_user(builder.index.js: 28) @@ -84,7 +84,20 @@ export class DbHookBuilder { 7 - TrxRepo._update (101/101r.middle-trx-auto-action.repo.ts:46) <-- call from here 6+1 8 - TrxRepo.commit (101/101r.middle-trx-auto-action.repo.ts:33) */ - this.trxStatusSvc.bindBuilderPropagationData(kmore.dbId, builder, 6) + /* + 1 - TrxStatusService.bindBuilderPropagationData(src\lib\trx-status.service.ts: 342) + 2 - DbHookBuilder.builderPrePropagating(src\lib\db-hook\db-hook.builder.ts: 87) + 3 - DbHookBuilder.builderPreHooks(src\lib\db-hook\db-hook.builder.ts: 44) + 4 - (kmore\dist\lib\builder\builder.index.js: 57) + 5 - createQueryBuilder(kmore\dist\lib\builder\builder.index.js: 55) + 6 - tb_user(kmore\dist\lib\builder\builder.index.js: 25) + 7 - TransactionalSimpleRepo.getUserOne(test\fixtures\base-app\src\transactional\30\30r.transactional - simple.repo.ts: 51) + 8 - Clz.(kmore\node_modules\@midwayjs\core\dist\service\aspectService.js: 92) + 9 - process.processTicksAndRejections( /internal/process / task_queues: 105) + 10 - await(未知源: 0) + 11 - user(test\fixtures\base - app\src\transactional\30\30r.transactional - simple.repo.ts: 33) + */ + this.trxStatusSvc.bindBuilderPropagationData(kmore.dbId, builder, 5) } protected async builderPostPropagating(options: BuilderHookOptions): Promise { @@ -126,20 +139,12 @@ export class DbHookBuilder { // #region builderTransactingPostHook @TraceLog({ - scope([options]) { - const { kmore, builder } = options - const traceScope = this.getTrxTraceScopeByQueryId(kmore, builder.kmoreQueryId) - if (traceScope) { - return traceScope - } - const traceScope2 = builder.kmoreQueryId - return traceScope2 - }, - after([options]) { // options.dbConfig not exists at before() + after([options]) { // options.dbConfig not exist at before() const dbConfig = this.getDbConfigByDbId(options.kmore.dbId) if (dbConfig && ! eventNeedTrace(KmoreAttrNames.BuilderTransacting, dbConfig)) { return } const { builder } = options + // @ts-expect-error builder._method // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment let method: string = builder._method ?? 'unknown' diff --git a/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.helper.ts b/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.helper.ts index 8fd289a2..fb18032a 100644 --- a/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.helper.ts +++ b/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.helper.ts @@ -51,8 +51,13 @@ export function processTrxCommitAndRollback( const { traceScope } = decoratorContext if (traceScope) { - const scopeRootSpan2 = traceService.getActiveSpanOnlyScope(traceScope) - if (scopeRootSpan2 && scopeRootSpan2 === traceSpan) { + const scopeRootSpan2 = traceService.getRootSpan(traceScope) + if (scopeRootSpan2) { + if (scopeRootSpan2 === traceSpan) { + ret.endSpanAfterTraceLog = true + } + } + else { ret.endSpanAfterTraceLog = true } return ret @@ -60,8 +65,13 @@ export function processTrxCommitAndRollback( const { scope } = trx assert(scope, `${hook}.${stage}-${op.toUpperCase()} trx.scope is empty`) - const scopeRootSpan = traceService.getActiveSpanOnlyScope(scope) - if (scopeRootSpan && scopeRootSpan === traceSpan) { + const scopeRootSpan = traceService.getRootSpan(scope) + if (scopeRootSpan) { + if (scopeRootSpan === traceSpan) { + ret.endSpanAfterTraceLog = true + } + } + else { ret.endSpanAfterTraceLog = true } diff --git a/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.ts b/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.ts index 56c35585..d1535354 100644 --- a/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.ts +++ b/packages/midway-component-kmore/src/lib/db-hook/db-hook.trx.ts @@ -1,4 +1,3 @@ - import assert from 'node:assert' import { relative } from 'node:path' @@ -15,9 +14,11 @@ import { Trace, TraceLog, TraceScopeType, + TraceService, } from '@mwcp/otel' import { Application, Context, MConfig, getWebContext } from '@mwcp/share' import { + type HookReturn, type KmoreTransaction, type TransactionHookOptions, type TransactionPreHookOptions, @@ -43,7 +44,7 @@ export class DbHookTrx { @Inject() readonly baseDir: string @Inject() readonly trxStatusSvc: TrxStatusService - + @Inject() readonly traceService: TraceService getDbConfigByDbId(dbId: SourceName): DbConfig | undefined { assert(dbId) @@ -64,24 +65,36 @@ export class DbHookTrx { @Trace({ autoEndSpan: false, // end span in DbHook.afterCommitHook/afterRollbackHook - spanName: ([options]) => { + spanName([options]) { + const { kmore, config } = options + if (! config.kmoreTrxId) { + const entryKey = config.trxPropagateOptions?.entryKey ?? '' + const kmoreTrxId = genKmoreTrxId(`trx-${kmore.dbId}-`, entryKey) + config.kmoreTrxId = kmoreTrxId + } + const dbSourceName = options.kmore.dbId return `Kmore ${dbSourceName} transaction` }, - scope: ([options]: [TransactionPreHookOptions]) => { - const { kmore, config } = options - if (config.kmoreTrxId) { - return config.kmoreTrxId - } - const entryKey = config.trxPropagateOptions?.entryKey ?? '' - const kmoreTrxId = genKmoreTrxId(`trx-${kmore.dbId}-`, entryKey) - config.kmoreTrxId = kmoreTrxId - return kmoreTrxId + before([options], decoratorContext) { + options.traceContext = decoratorContext.traceContext ?? this.traceService.getActiveContext() // necessary for update trace context correctly + return null }, - after([options]: [TransactionPreHookOptions]) { + after([options]: [TransactionPreHookOptions], _res, decoratorContext) { const { kmore, config } = options + + if (! config.kmoreTrxId) { + const entryKey = config.trxPropagateOptions?.entryKey ?? '' + const kmoreTrxId = genKmoreTrxId(`trx-${kmore.dbId}-`, entryKey) + config.kmoreTrxId = kmoreTrxId + } + const { kmoreTrxId } = config - assert(kmoreTrxId, 'transactionPreHook() kmoreTrxId is empty') + assert(config.kmoreTrxId, 'transactionPreHook() after: kmoreTrxId is empty') + + const activeTraceCtx = decoratorContext.traceContext ?? this.traceService.getActiveContext() + assert(activeTraceCtx, 'transactionPostHook() before: activeTraceCtx is empty') + this.trxStatusSvc.setTraceContextByScope(kmoreTrxId, activeTraceCtx) if (! config.scope) { config.scope = this.getWebContext() ?? this.app @@ -96,18 +109,17 @@ export class DbHookTrx { return { attrs, events } }, }) - async transactionPreHook(this: DbHookTrx, options: TransactionPreHookOptions): Promise { - void options + async transactionPreHook(this: DbHookTrx, options: TransactionPreHookOptions): Promise { + const { traceContext } = options + if (traceContext) { + return { traceContext } // necessary for update trace context correctly + } + return } // #region transactionPostHook @TraceLog({ - scope: ([options]: [TransactionPreHookOptions]) => { - const { kmoreTrxId } = options.config - assert(kmoreTrxId, 'transactionPostHook() kmoreTrxId is empty') - return kmoreTrxId - }, before([options]) { const { kmore, config, trx } = options const { kmoreTrxId } = config @@ -145,10 +157,10 @@ export class DbHookTrx { // #region beforeCommit @TraceLog({ - scope([options]) { - return this.getTraceScopeByTrx(options.trx) - }, after([options]) { + const activeTraceCtx = this.traceService.getActiveContext() + void activeTraceCtx + const { kmore, trx } = options const events = genCommonAttr(KmoreAttrNames.TrxCommitStart, { dbId: kmore.dbId, @@ -164,10 +176,10 @@ export class DbHookTrx { // #region afterCommit @TraceLog({ - scope([options]) { - return this.getTraceScopeByTrx(options.trx) - }, before([options], decoratorContext) { + if (! decoratorContext.traceScope) { + decoratorContext.traceScope = this.getTraceScopeByTrx(options.trx) + } const data: ProcessTrxCommitAndRollbackData = { eventName: KmoreAttrNames.TrxCommitEnd, hook: 'afterCommitHook', @@ -184,10 +196,7 @@ export class DbHookTrx { // #region beforeRollback @TraceLog({ - scope([options]) { - return this.getTraceScopeByTrx(options.trx) - }, - after: ([options]) => { + after([options]) { const { kmore, trx } = options const events = genCommonAttr(KmoreAttrNames.TrxRollbackStart, { dbId: kmore.dbId, @@ -203,10 +212,10 @@ export class DbHookTrx { // #region afterRollback @TraceLog({ - scope([options]) { - return this.getTraceScopeByTrx(options.trx) - }, before([options], decoratorContext) { + if (! decoratorContext.traceScope) { + decoratorContext.traceScope = this.getTraceScopeByTrx(options.trx) + } const data: ProcessTrxCommitAndRollbackData = { eventName: KmoreAttrNames.TrxRollbackEnd, hook: 'afterRollbackHook', @@ -219,5 +228,6 @@ export class DbHookTrx { async afterRollbackHook(this: DbHookTrx, options: TransactionHookOptions): Promise { void options } + } diff --git a/packages/midway-component-kmore/src/lib/db-source-manager.ts b/packages/midway-component-kmore/src/lib/db-source-manager.ts index 6b68f876..ac5a0eca 100644 --- a/packages/midway-component-kmore/src/lib/db-source-manager.ts +++ b/packages/midway-component-kmore/src/lib/db-source-manager.ts @@ -1,3 +1,4 @@ +/* eslint-disable max-lines-per-function */ import assert from 'node:assert' import { @@ -11,8 +12,10 @@ import { Singleton, } from '@midwayjs/core' import { ILogger } from '@midwayjs/logger' -import { Attributes, SpanKind, Trace, TraceInit } from '@mwcp/otel' +import { type TraceContext, Attributes, SpanKind, Trace, TraceInit } from '@mwcp/otel' import { Application, Context, MConfig, getWebContext } from '@mwcp/share' +// eslint-disable-next-line import/no-extraneous-dependencies +import { context } from '@opentelemetry/api' import { type EventCallbacks, type Kmore, @@ -194,15 +197,89 @@ export class DbManager { + if (kmore.enableTrace) { + let activeTraceCtx: TraceContext | undefined + + const traceScope = this.dbEvent.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) + const activeRoot = this.trxStatusSvc.getTraceContextByScope(traceScope) + if (activeRoot) { + activeTraceCtx = activeRoot + } + else { + const trx = kmore.getTrxByQueryId(event.kmoreQueryId) + activeTraceCtx = trx ? kmore.trx2TraceContextMap.get(trx) : void 0 + } + if (! activeTraceCtx) { + activeTraceCtx = context.active() + } + + context.with(activeTraceCtx, () => { + this.dbEvent.onStart({ dataSourceName, dbConfig: config, event, kmore }) + }) + return + } this.dbEvent.onStart({ dataSourceName, dbConfig: config, event, kmore }) }, query: (event: KmoreEvent, kmore: Kmore) => { + if (kmore.enableTrace) { + let activeTraceCtx = this.trxStatusSvc.getTraceContextByScope(event.kmoreQueryId) + if (! activeTraceCtx) { + const traceScope = this.dbEvent.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) + const active = this.trxStatusSvc.getTraceContextByScope(traceScope) + if (active) { + activeTraceCtx = active + } + else { + const trx = kmore.getTrxByQueryId(event.kmoreQueryId) + activeTraceCtx = trx ? kmore.trx2TraceContextMap.get(trx) : void 0 + } + } + context.with(activeTraceCtx ?? context.active(), () => { + this.dbEvent.onQuery({ dataSourceName, dbConfig: config, event, kmore }) + }) + return + } this.dbEvent.onQuery({ dataSourceName, dbConfig: config, event, kmore }) }, queryResponse: (event: KmoreEvent, kmore: Kmore) => { + if (kmore.enableTrace) { + let activeTraceCtx = this.trxStatusSvc.getTraceContextByScope(event.kmoreQueryId) + if (! activeTraceCtx) { + const traceScope = this.dbEvent.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) + const active = this.trxStatusSvc.getTraceContextByScope(traceScope) + if (active) { + activeTraceCtx = active + } + else { + const trx = kmore.getTrxByQueryId(event.kmoreQueryId) + activeTraceCtx = trx ? kmore.trx2TraceContextMap.get(trx) : void 0 + } + } + context.with(activeTraceCtx ?? context.active(), () => { + this.dbEvent.onResp({ dataSourceName, dbConfig: config, event, kmore }) + }) + return + } this.dbEvent.onResp({ dataSourceName, dbConfig: config, event, kmore }) }, queryError: (event: KmoreEvent, kmore: Kmore) => { + if (kmore.enableTrace) { + let activeTraceCtx = this.trxStatusSvc.getTraceContextByScope(event.kmoreQueryId) + if (! activeTraceCtx) { + const traceScope = this.dbEvent.retrieveTraceScope(kmore, event.kmoreQueryId, event.queryBuilder) + const active = this.trxStatusSvc.getTraceContextByScope(traceScope) + if (active) { + activeTraceCtx = active + } + else { + const trx = kmore.getTrxByQueryId(event.kmoreQueryId) + activeTraceCtx = trx ? kmore.trx2TraceContextMap.get(trx) : void 0 + } + } + return context.with(activeTraceCtx ?? context.active(), () => { + return this.dbEvent.onError({ dataSourceName, dbConfig: config, event, kmore }) + }) + } return this.dbEvent.onError({ dataSourceName, dbConfig: config, event, kmore }) }, } diff --git a/packages/midway-component-kmore/src/lib/propagation/trx-status.helper.ts b/packages/midway-component-kmore/src/lib/propagation/trx-status.helper.ts index 9e6462e9..810a68e0 100644 --- a/packages/midway-component-kmore/src/lib/propagation/trx-status.helper.ts +++ b/packages/midway-component-kmore/src/lib/propagation/trx-status.helper.ts @@ -78,7 +78,7 @@ export function trxTrace(options: TrxTraceOptions): void { traceSvc.addEvent(span, attrs) } else { - traceSvc.setAttributesLater(span, attrs) + traceSvc.otel.setAttributesLater(span, attrs) } } diff --git a/packages/midway-component-kmore/src/lib/trx-status.service.ts b/packages/midway-component-kmore/src/lib/trx-status.service.ts index 603e8c24..0aa91114 100644 --- a/packages/midway-component-kmore/src/lib/trx-status.service.ts +++ b/packages/midway-component-kmore/src/lib/trx-status.service.ts @@ -1,7 +1,7 @@ import assert from 'node:assert' import { ApplicationContext, IMidwayContainer, Inject, Singleton } from '@midwayjs/core' -import { AttrNames, Attributes, TraceService } from '@mwcp/otel' +import { type TraceContext, AttrNames, Attributes, TraceService } from '@mwcp/otel' import type { ScopeType } from '@mwcp/share' import { CallerInfo, genISO8601String } from '@waiting/shared-core' import { @@ -46,6 +46,8 @@ export class TrxStatusService { @Inject() protected readonly traceSvc: TraceService @Inject() protected readonly callerSvc: CallerService + readonly scope2TraceContextMap = new WeakMap() + protected readonly dbInstanceList = new Map() protected readonly callerKeyPropagationMapIndex: CallerKeyPropagationMapIndex = new Map() protected readonly entryCallerKeyTrxMapIndex: EntryCallerKeyTrxMapIndex = new Map() @@ -338,6 +340,7 @@ export class TrxStatusService { try { callerInfo = this.callerSvc.retrieveCallerInfo(distance + 1) if (! callerInfo.className || ! callerInfo.funcName) { + console.warn('Warn [@mwcp/kmore] retrieveCallerInfo() failed' + JSON.stringify(callerInfo)) return } } @@ -667,5 +670,20 @@ export class TrxStatusService { } } + getTraceContextByScope(scope: ScopeType): TraceContext | undefined { + const traceContextArr = this.scope2TraceContextMap.get(scope) + return traceContextArr + } + + /** + * @param scope kmoreTrxId or kmoreQueryId + */ + setTraceContextByScope(scope: ScopeType, traceContext: TraceContext): void { + this.scope2TraceContextMap.set(scope, traceContext) + } + + removeTraceContextByScope(scope: ScopeType): void { + this.scope2TraceContextMap.delete(scope) + } } diff --git a/packages/midway-component-kmore/test/30.transactional-simple.test.ts b/packages/midway-component-kmore/test/30.transactional-simple.test.ts index e016971e..83dc401b 100644 --- a/packages/midway-component-kmore/test/30.transactional-simple.test.ts +++ b/packages/midway-component-kmore/test/30.transactional-simple.test.ts @@ -34,22 +34,20 @@ describe(fileShortPath(import.meta.url), () => { assert(traceId.length === 32) console.log({ traceId }) - const [info] = await retrieveTraceInfoFromRemote(traceId, 5) + const [info] = await retrieveTraceInfoFromRemote(traceId, 4) assert(info) // info.spans.forEach((span, idx) => { console.info(idx, { span }) }) - const [rootSpan, span1, span2, span3, span4] = sortSpans(info.spans) + const [rootSpan, span1, span2, span3] = sortSpans(info.spans) assert(rootSpan) assert(span1) assert(span2) assert(span3) - assert(span4) assertJaegerParentSpanArray([ { parentSpan: rootSpan, childSpan: span1 }, { parentSpan: rootSpan, childSpan: span2 }, { parentSpan: span2, childSpan: span3 }, - { parentSpan: span2, childSpan: span4 }, ]) try { @@ -110,7 +108,6 @@ describe(fileShortPath(import.meta.url), () => { { event: 'trx.create.start' }, { event: 'trx.create.end' }, { event: KmoreAttrNames.BuilderTransacting, method: 'select', table: 'tb_user' }, - { event: KmoreAttrNames.BuilderTransacting, method: 'select', table: 'tb_user' }, { event: 'trx.commit.start', dbId: 'master' }, { event: 'trx.commit.end', dbId: 'master' }, ], @@ -142,8 +139,72 @@ describe(fileShortPath(import.meta.url), () => { ], } assertsSpan(span3, opt3) + }) + + it(`${apiRoute.simple} again`, async () => { + const { httpRequest } = testConfig + const path = `${prefix}/${apiRoute.simple}` + + const resp = await httpRequest.get(path) + assert(resp.ok, resp.text) + + const traceId = resp.text + assert(traceId.length === 32) + console.log({ traceId }) + + const [info] = await retrieveTraceInfoFromRemote(traceId, 3) + assert(info) + // info.spans.forEach((span, idx) => { console.info(idx, { span }) }) + + const [rootSpan, span1, span2] = sortSpans(info.spans) + assert(rootSpan) + assert(span1) + assert(span2) + + assertJaegerParentSpanArray([ + { parentSpan: rootSpan, childSpan: span1 }, + { parentSpan: span1, childSpan: span2 }, + ]) + + assertRootSpan({ + path, + span: rootSpan, + traceId, + tags: { + [SEMATTRS_HTTP_TARGET]: path, + [SEMATTRS_HTTP_ROUTE]: path, + }, + mergeDefaultLogs: false, + }) + + const opt1: AssertsOptions = { + traceId, + operationName: 'Kmore master transaction', + tags: { + 'caller.class': 'DbHookTrx', + 'caller.method': 'transactionPreHook', + 'span.kind': 'client', + dbId: 'master', + op: 'commit', + 'otel.status_code': 'OK', + 'trx.propagation.class': 'TransactionalSimpleRepo', + 'trx.propagation.func': 'getUserOne', + // 'trx.propagation.path': 'src/transactional/30/30r.transactional-simple.repo.ts', + 'trx.propagation.read.rowlock.level': 'FOR_SHARE', + 'trx.propagation.type': 'REQUIRED', + 'trx.propagation.write.rowlock.level': 'FOR_UPDATE', + }, + logs: [ + { event: 'trx.create.start' }, + { event: 'trx.create.end' }, + { event: KmoreAttrNames.BuilderTransacting, method: 'select', table: 'tb_user' }, + { event: 'trx.commit.start', dbId: 'master' }, + { event: 'trx.commit.end', dbId: 'master' }, + ], + } + assertsSpan(span1, opt1) - const opt4: AssertsOptions = { + const opt2: AssertsOptions = { traceId, operationName: 'Kmore master select', tags: { @@ -152,28 +213,27 @@ describe(fileShortPath(import.meta.url), () => { 'span.kind': 'client', 'db.name': 'db_ci_test', 'db.operation': 'SELECT', - 'db.statement': 'select * from "tb_user" for share', + 'db.statement': 'select * from "tb_user" where "uid" = ? for share', 'db.system': 'pg', 'db.user': 'postgres', dbId: 'master', // 'net.peer.name': 'localhost', 'net.peer.port': 5432, 'otel.status_code': 'OK', - 'row.count': 3, + 'row.count': 1, }, logs: [ { event: 'builder.compile' }, - { event: 'query.querying', bindings: '' }, - { event: 'query.response', 'row.count': 3 }, + { event: 'query.querying', bindings: JSON.stringify([1], null, 2) }, + { event: 'query.response', 'row.count': 1 }, ], } - assertsSpan(span4, opt4) - + assertsSpan(span2, opt2) }) - it(`${apiRoute.simple} again`, async () => { + it(`${apiRoute.hello} `, async () => { const { httpRequest } = testConfig - const path = `${prefix}/${apiRoute.simple}` + const path = `${prefix}/${apiRoute.hello}` const resp = await httpRequest.get(path) assert(resp.ok, resp.text) diff --git a/packages/midway-component-kmore/test/config.unittest.ts b/packages/midway-component-kmore/test/config.unittest.ts index 6d131761..7c8b0a38 100644 --- a/packages/midway-component-kmore/test/config.unittest.ts +++ b/packages/midway-component-kmore/test/config.unittest.ts @@ -65,6 +65,7 @@ export const master: DbConfig = { dict: dbDict, eventCallbacks: eventCbs, traceInitConnection: true, + enableTrace: true, } export const kmoreConfig: Config<'master'> = { enableDefaultRoute: true, diff --git a/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30c.transactional-simple.controller.ts b/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30c.transactional-simple.controller.ts index 85e6ee99..02f206af 100644 --- a/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30c.transactional-simple.controller.ts +++ b/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30c.transactional-simple.controller.ts @@ -16,6 +16,13 @@ export class TransactionalSimpleController { @Get(`/${apiRoute.simple}`) async simple(): Promise { + const traceId = this.traceSvc.getTraceId() + await this.repo.user() + return traceId + } + + @Get(`/${apiRoute.hello}`) + async hello(): Promise { const traceId = this.traceSvc.getTraceId() await this.repo.userAll() return traceId diff --git a/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30r.transactional-simple.repo.ts b/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30r.transactional-simple.repo.ts index 7af90441..f4bd4f52 100644 --- a/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30r.transactional-simple.repo.ts +++ b/packages/midway-component-kmore/test/fixtures/base-app/src/transactional/30/30r.transactional-simple.repo.ts @@ -28,6 +28,13 @@ export class TransactionalSimpleRepo { this.tb_user = db.camelTables.tb_user } + @Transactional() + async user(): Promise { + const [users, trx] = await this.getUserOne() + assert(users && users.length === 1) + assert(trx, 'trx should be defined') + } + @Transactional() async userAll(): Promise { const [users, trx] = await this.getUserOne()