more logging optimizations

This commit is contained in:
einhornimmond 2025-10-14 14:50:05 +02:00
parent 2a7e97319b
commit b78a627844
4 changed files with 31 additions and 34 deletions

View File

@ -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<void> {
): Promise<StartCommunityAuthenticationResult> {
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
}

View File

@ -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<v
// delete all foreign federated community entries to avoid increasing validation efforts and log-files
await DbFederatedCommunity.delete({ foreign: true })
// clean community_uuid and authenticated_at fields for community with one-time-code in community_uuid field
const notReachableCommunities = await getNotReachableCommunities()
for (const community of notReachableCommunities) {
if (uint32Schema.safeParse(Number(community.communityUuid)).success) {
community.communityUuid = null
community.authenticatedAt = null
await DbCommunity.save(community)
}
}
// TODO: replace the timer-loop by an event-based communication to verify announced foreign communities
// better to use setTimeout twice than setInterval once -> see https://javascript.info/settimeout-setinterval
setTimeout(async function run() {
@ -56,11 +46,11 @@ export async function validateCommunities(): Promise<void> {
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<void> {
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)
}

View File

@ -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)

View File

@ -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`)