From b78a627844624eea90dd2f453f88e032eb740c39 Mon Sep 17 00:00:00 2001 From: einhornimmond Date: Tue, 14 Oct 2025 14:50:05 +0200 Subject: [PATCH] more logging optimizations --- .../src/federation/authenticateCommunities.ts | 42 ++++++++++--------- backend/src/federation/validateCommunities.ts | 21 +++------- .../1_0/resolver/AuthenticationResolver.ts | 1 + .../api/1_0/util/authenticateCommunity.ts | 1 + 4 files changed, 31 insertions(+), 34 deletions(-) diff --git a/backend/src/federation/authenticateCommunities.ts b/backend/src/federation/authenticateCommunities.ts index 9226d652c..5c314ab93 100644 --- a/backend/src/federation/authenticateCommunities.ts +++ b/backend/src/federation/authenticateCommunities.ts @@ -7,12 +7,12 @@ import { findPendingCommunityHandshake, getHomeCommunityWithFederatedCommunityOrFail, CommunityHandshakeStateType, - getCommunityByPublicKeyOrFail + getCommunityByPublicKeyOrFail, } from 'database' import { randombytes_random } from 'sodium-native' import { AuthenticationClient as V1_0_AuthenticationClient } from '@/federation/client/1_0/AuthenticationClient' -import { ensureUrlEndsWithSlash } from 'core' +import { ensureUrlEndsWithSlash, getFederatedCommunityWithApiOrFail } from 'core' import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { communityAuthenticatedSchema, encryptAndSign, OpenConnectionJwtPayloadType } from 'shared' @@ -20,27 +20,29 @@ import { getLogger } from 'log4js' import { AuthenticationClientFactory } from './client/AuthenticationClientFactory' import { EncryptedTransferArgs } from 'core' import { CommunityHandshakeStateLogic } from 'core' -import { CommunityLogic } from 'core' import { Ed25519PublicKey } from 'shared' const createLogger = (functionName: string) => getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.federation.authenticateCommunities.${functionName}`) +export enum StartCommunityAuthenticationResult { + ALREADY_AUTHENTICATED = 'already authenticated', + ALREADY_IN_PROGRESS = 'already in progress', + SUCCESSFULLY_STARTED = 'successfully started', +} + export async function startCommunityAuthentication( fedComB: DbFederatedCommunity, -): Promise { +): Promise { const methodLogger = createLogger('startCommunityAuthentication') const handshakeID = randombytes_random().toString() methodLogger.addContext('handshakeID', handshakeID) - methodLogger.debug(`startCommunityAuthentication()...`, { - fedComB: new FederatedCommunityLoggingView(fedComB), - }) + methodLogger.debug(`start with public key ${fedComB.publicKey}`) const homeComA = await getHomeCommunityWithFederatedCommunityOrFail(fedComB.apiVersion) - methodLogger.debug('homeComA', new CommunityLoggingView(homeComA)) - const homeComALogic = new CommunityLogic(homeComA) - const homeFedComA = homeComALogic.getFederatedCommunityWithApiOrFail(fedComB.apiVersion) + // methodLogger.debug('homeComA', new CommunityLoggingView(homeComA)) + const homeFedComA = getFederatedCommunityWithApiOrFail(homeComA, fedComB.apiVersion) const fedComBPublicKey = new Ed25519PublicKey(fedComB.publicKey) const comB = await getCommunityByPublicKeyOrFail(fedComBPublicKey) - methodLogger.debug('started with comB:', new CommunityLoggingView(comB)) + // methodLogger.debug('started with comB:', new CommunityLoggingView(comB)) // check if communityUuid is not a valid v4Uuid // communityAuthenticatedSchema.safeParse return true @@ -48,11 +50,11 @@ export async function startCommunityAuthentication( // - if authenticatedAt is a valid date if (communityAuthenticatedSchema.safeParse(comB).success) { methodLogger.debug(`comB.communityUuid is already a valid v4Uuid ${ comB.communityUuid || 'null' } and was authenticated at ${ comB.authenticatedAt || 'null'}`) - return + return StartCommunityAuthenticationResult.ALREADY_AUTHENTICATED } - methodLogger.debug('comB.uuid is null or is a not valid v4Uuid...', + /*methodLogger.debug('comB.uuid is null or is a not valid v4Uuid...', comB.communityUuid || 'null', comB.authenticatedAt || 'null' - ) + )*/ // check if a authentication is already in progress const existingState = await findPendingCommunityHandshake(fedComBPublicKey, fedComB.apiVersion) @@ -62,7 +64,7 @@ export async function startCommunityAuthentication( if (!(await stateLogic.isTimeoutUpdate())) { // authentication with community and api version is still in progress and it is not timeout yet methodLogger.debug('existingState, so we exit here', new CommunityHandshakeStateLoggingView(existingState)) - return + return StartCommunityAuthenticationResult.ALREADY_IN_PROGRESS } } @@ -78,24 +80,25 @@ export async function startCommunityAuthentication( state.status = CommunityHandshakeStateType.START_COMMUNITY_AUTHENTICATION state.handshakeId = parseInt(handshakeID) await state.save() + methodLogger.debug('[START_COMMUNITY_AUTHENTICATION] community handshake state created') //create JWT with url in payload encrypted by foreignCom.publicJwtKey and signed with homeCom.privateJwtKey const payload = new OpenConnectionJwtPayloadType(handshakeID, ensureUrlEndsWithSlash(homeFedComA.endPoint).concat(homeFedComA.apiVersion), ) - methodLogger.debug('payload', payload) + // methodLogger.debug('payload', payload) const jws = await encryptAndSign(payload, homeComA!.privateJwtKey!, comB.publicJwtKey!) - methodLogger.debug('jws', jws) + // methodLogger.debug('jws', jws) // prepare the args for the client invocation const args = new EncryptedTransferArgs() const homeComAPublicKey = new Ed25519PublicKey(homeComA!.publicKey) args.publicKey = homeComAPublicKey.asHex() args.jwt = jws args.handshakeID = handshakeID - methodLogger.debug('before client.openConnection() args:', args) + // methodLogger.debug('before client.openConnection() args:', args) const result = await client.openConnection(args) if (result) { - methodLogger.info(`successful initiated at community:`, fedComB.endPoint) + methodLogger.debug(`successful initiated at community:`, fedComB.endPoint) } else { const errorMsg = `can't initiate at community: ${fedComB.endPoint}` methodLogger.error(errorMsg) @@ -104,4 +107,5 @@ export async function startCommunityAuthentication( } await state.save() } + return StartCommunityAuthenticationResult.SUCCESSFULLY_STARTED } diff --git a/backend/src/federation/validateCommunities.ts b/backend/src/federation/validateCommunities.ts index 8d8972ed5..bb5905aa3 100644 --- a/backend/src/federation/validateCommunities.ts +++ b/backend/src/federation/validateCommunities.ts @@ -12,7 +12,7 @@ import { FederationClient as V1_0_FederationClient } from '@/federation/client/1 import { PublicCommunityInfo } from '@/federation/client/1_0/model/PublicCommunityInfo' import { FederationClientFactory } from '@/federation/client/FederationClientFactory' import { LogError } from '@/server/LogError' -import { buffer32Schema, createKeyPair, Ed25519PublicKey, hex64Schema, uint32Schema } from 'shared' +import { createKeyPair, Ed25519PublicKey, uint32Schema } from 'shared' import { getLogger } from 'log4js' import { startCommunityAuthentication } from './authenticateCommunities' import { PublicCommunityInfoLoggingView } from './client/1_0/logging/PublicCommunityInfoLogging.view' @@ -28,16 +28,6 @@ export async function startValidateCommunities(timerInterval: number): Promise see https://javascript.info/settimeout-setinterval setTimeout(async function run() { @@ -56,11 +46,11 @@ export async function validateCommunities(): Promise { logger.debug(`found ${dbFederatedCommunities.length} dbCommunities`) for (const dbFedComB of dbFederatedCommunities) { - logger.debug('dbFedComB', new FederatedCommunityLoggingView(dbFedComB)) + logger.debug(`verify federation community: ${dbFedComB.endPoint}${dbFedComB.apiVersion}`) const apiValueStrings: string[] = Object.values(ApiVersionType) - logger.debug(`suppported ApiVersions=`, apiValueStrings) if (!apiValueStrings.includes(dbFedComB.apiVersion)) { logger.debug('dbFedComB with unsupported apiVersion', dbFedComB.endPoint, dbFedComB.apiVersion) + logger.debug(`supported ApiVersions=`, apiValueStrings) continue } try { @@ -73,13 +63,14 @@ export async function validateCommunities(): Promise { const fedComBPublicKey = new Ed25519PublicKey(dbFedComB.publicKey) if (clientPublicKey.isSame(fedComBPublicKey)) { await DbFederatedCommunity.update({ id: dbFedComB.id }, { verifiedAt: new Date() }) - logger.debug(`verified dbFedComB with:`, dbFedComB.endPoint) + // logger.debug(`verified dbFedComB with:`, dbFedComB.endPoint) const pubComInfo = await client.getPublicCommunityInfo() if (pubComInfo) { await writeForeignCommunity(dbFedComB, pubComInfo) logger.debug(`wrote response of getPublicCommunityInfo in dbFedComB ${dbFedComB.endPoint}`) try { - await startCommunityAuthentication(dbFedComB) + const result = await startCommunityAuthentication(dbFedComB) + logger.info(`${dbFedComB.endPoint}${dbFedComB.apiVersion} verified, authentication state: ${result}`) } catch (err) { logger.warn(`Warning: Authentication of community ${dbFedComB.endPoint} still ongoing:`, err) } diff --git a/federation/src/graphql/api/1_0/resolver/AuthenticationResolver.ts b/federation/src/graphql/api/1_0/resolver/AuthenticationResolver.ts index 9a8008a3c..7a709d3f7 100644 --- a/federation/src/graphql/api/1_0/resolver/AuthenticationResolver.ts +++ b/federation/src/graphql/api/1_0/resolver/AuthenticationResolver.ts @@ -143,6 +143,7 @@ export class AuthenticationResolver { } state.status = CommunityHandshakeStateType.SUCCESS await state.save() + methodLogger.debug('[SUCCESS] community handshake state updated') // methodLogger.debug(`search community per oneTimeCode:`, authArgs.oneTimeCode) const authCom = await getCommunityByPublicKeyOrFail(argsPublicKey) diff --git a/federation/src/graphql/api/1_0/util/authenticateCommunity.ts b/federation/src/graphql/api/1_0/util/authenticateCommunity.ts index efff863fa..b6766f73a 100644 --- a/federation/src/graphql/api/1_0/util/authenticateCommunity.ts +++ b/federation/src/graphql/api/1_0/util/authenticateCommunity.ts @@ -186,6 +186,7 @@ export async function startAuthentication( await DbCommunity.save(comB) state.status = CommunityHandshakeStateType.SUCCESS await state.save() + methodLogger.debug('[SUCCESS] community handshake state updated') const endTime = new Date() const duration = endTime.getTime() - state.createdAt.getTime() methodLogger.debug(`Community Authentication successful in ${duration} ms`)