update logging, reduce logging redundant informations

This commit is contained in:
einhornimmond 2025-10-14 14:32:01 +02:00
parent 1c347b7ff7
commit 2a7e97319b
7 changed files with 126 additions and 144 deletions

View File

@ -1,5 +1,5 @@
import { EncryptedTransferArgs } from '../model/EncryptedTransferArgs'
import { JwtPayloadType } from 'shared'
import { Ed25519PublicKey, JwtPayloadType } from 'shared'
import { Community as DbCommunity } from 'database'
import { getLogger } from 'log4js'
import { CommunityLoggingView, getHomeCommunity } from 'database'
@ -12,16 +12,17 @@ export const interpretEncryptedTransferArgs = async (args: EncryptedTransferArgs
const methodLogger = createLogger('interpretEncryptedTransferArgs')
methodLogger.addContext('handshakeID', args.handshakeID)
methodLogger.debug('interpretEncryptedTransferArgs()... args:', args)
const argsPublicKey = new Ed25519PublicKey(args.publicKey)
// first find with args.publicKey the community 'requestingCom', which starts the request
// TODO: maybe use community from caller instead of loading it separately
const requestingCom = await DbCommunity.findOneBy({ publicKey: Buffer.from(args.publicKey, 'hex') })
const requestingCom = await DbCommunity.findOneBy({ publicKey: argsPublicKey.asBuffer() })
if (!requestingCom) {
const errmsg = `unknown requesting community with publicKey ${args.publicKey}`
const errmsg = `unknown requesting community with publicKey ${argsPublicKey.asHex()}`
methodLogger.error(errmsg)
throw new Error(errmsg)
}
if (!requestingCom.publicJwtKey) {
const errmsg = `missing publicJwtKey of requesting community with publicKey ${args.publicKey}`
const errmsg = `missing publicJwtKey of requesting community with publicKey ${argsPublicKey.asHex()}`
methodLogger.error(errmsg)
throw new Error(errmsg)
}
@ -31,7 +32,7 @@ export const interpretEncryptedTransferArgs = async (args: EncryptedTransferArgs
const homeCom = await getHomeCommunity()
const jwtPayload = await verifyAndDecrypt(args.handshakeID, args.jwt, homeCom!.privateJwtKey!, requestingCom.publicJwtKey) as JwtPayloadType
if (!jwtPayload) {
const errmsg = `invalid payload of community with publicKey ${args.publicKey}`
const errmsg = `invalid payload of community with publicKey ${argsPublicKey.asHex()}`
methodLogger.error(errmsg)
throw new Error(errmsg)
}

View File

@ -1,13 +0,0 @@
import { Community as DbCommunity, FederatedCommunity as DbFederatedCommunity } from 'database'
export class CommunityLogic {
public constructor(private self: DbCommunity) {}
public getFederatedCommunityWithApiOrFail(apiVersion: string): DbFederatedCommunity {
const fedCom = this.self.federatedCommunities?.find((fedCom) => fedCom.apiVersion === apiVersion)
if (!fedCom) {
throw new Error(`Missing federated community with api version ${apiVersion}`)
}
return fedCom
}
}

View File

@ -0,0 +1,12 @@
import { Community as DbCommunity, FederatedCommunity as DbFederatedCommunity } from 'database'
export function getFederatedCommunityWithApiOrFail(
community: DbCommunity,
apiVersion: string
): DbFederatedCommunity {
const fedCom = community.federatedCommunities?.find((fedCom) => fedCom.apiVersion === apiVersion)
if (!fedCom) {
throw new Error(`Missing federated community with api version ${apiVersion}`)
}
return fedCom
}

View File

@ -1,2 +1,2 @@
export { CommunityHandshakeStateLogic } from './CommunityHandshakeState.logic'
export { CommunityLogic } from './Community.logic'
export * from './CommunityHandshakeState.logic'
export * from './community.logic'

View File

@ -10,7 +10,6 @@ import {
FederatedCommunityLoggingView,
getHomeCommunity,
findPendingCommunityHandshakeOrFailByOneTimeCode,
Community as DbCommunity,
getCommunityByPublicKeyOrFail,
} from 'database'
import { getLogger } from 'log4js'
@ -27,11 +26,12 @@ import {
import { Arg, Mutation, Resolver } from 'type-graphql'
import { startAuthentication, startOpenConnectionCallback } from '../util/authenticateCommunity'
const createLogger = (method: string ) => getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.graphql.api.1_0.resolver.AuthenticationResolver.${method}`)
// TODO: think about the case, when we have a higher api version, which still use this resolver
const apiVersion = '1_0'
const createLogger = (method: string ) => getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.graphql.api.${apiVersion}.resolver.AuthenticationResolver.${method}`)
@Resolver()
export class AuthenticationResolver {
@Mutation(() => Boolean)
async openConnection(
@Arg('data')
@ -39,39 +39,37 @@ export class AuthenticationResolver {
): Promise<boolean> {
const methodLogger = createLogger('openConnection')
methodLogger.addContext('handshakeID', args.handshakeID)
methodLogger.debug(`openConnection() via apiVersion=1_0:`, args)
const argsPublicKey = new Ed25519PublicKey(args.publicKey)
methodLogger.debug(`start via apiVersion=${apiVersion}, public key: ${argsPublicKey.asHex()}`)
try {
const openConnectionJwtPayload = await interpretEncryptedTransferArgs(args) as OpenConnectionJwtPayloadType
methodLogger.debug('openConnectionJwtPayload', openConnectionJwtPayload)
methodLogger.debug(`openConnectionJwtPayload url: ${openConnectionJwtPayload.url}`)
if (!openConnectionJwtPayload) {
throw new Error(`invalid OpenConnection payload of requesting community with publicKey ${argsPublicKey.asHex()}`)
}
if (openConnectionJwtPayload.tokentype !== OpenConnectionJwtPayloadType.OPEN_CONNECTION_TYPE) {
throw new Error(`invalid tokentype of community with publicKey ${argsPublicKey.asHex()}`)
throw new Error(`invalid tokentype: ${openConnectionJwtPayload.tokentype} of community with publicKey ${argsPublicKey.asHex()}`)
}
if (!openConnectionJwtPayload.url) {
throw new Error(`invalid url of community with publicKey ${argsPublicKey.asHex()}`)
}
methodLogger.debug(`before DbFedCommunity.findOneByOrFail()...`, { publicKey: argsPublicKey.asHex() })
// methodLogger.debug(`before DbFedCommunity.findOneByOrFail()...`, { publicKey: argsPublicKey.asHex() })
const fedComA = await DbFedCommunity.findOneByOrFail({ publicKey: argsPublicKey.asBuffer() })
methodLogger.debug(`after DbFedCommunity.findOneByOrFail()...`, new FederatedCommunityLoggingView(fedComA))
// methodLogger.debug(`after DbFedCommunity.findOneByOrFail()...`, new FederatedCommunityLoggingView(fedComA))
if (!openConnectionJwtPayload.url.startsWith(fedComA.endPoint)) {
throw new Error(`invalid url of community with publicKey ${argsPublicKey.asHex()}`)
}
if (fedComA.apiVersion !== apiVersion) {
throw new Error(`invalid apiVersion: ${fedComA.apiVersion} of community with publicKey ${argsPublicKey.asHex()}`)
}
// no await to respond immediately and invoke callback-request asynchronously
void startOpenConnectionCallback(args.handshakeID, argsPublicKey, CONFIG.FEDERATION_API)
// important: startOpenConnectionCallback must catch all exceptions them self, or server will crash!
void startOpenConnectionCallback(args.handshakeID, argsPublicKey, fedComA)
methodLogger.debug('openConnection() successfully initiated callback and returns true immediately...')
return true
} catch (err) {
let errorText = ''
if (err instanceof Error) {
errorText = err.message
} else {
errorText = String(err)
}
methodLogger.error('invalid jwt token:', errorText)
methodLogger.error('invalid jwt token:', err)
// no infos to the caller
return true
}
@ -84,7 +82,7 @@ export class AuthenticationResolver {
): Promise<boolean> {
const methodLogger = createLogger('openConnectionCallback')
methodLogger.addContext('handshakeID', args.handshakeID)
methodLogger.debug(`openConnectionCallback() via apiVersion=1_0 ...`, args)
methodLogger.debug(`start via apiVersion=${apiVersion}, public key: ${args.publicKey}`)
try {
// decrypt args.url with homeCom.privateJwtKey and verify signing with callbackFedCom.publicKey
const openConnectionCallbackJwtPayload = await interpretEncryptedTransferArgs(args) as OpenConnectionCallbackJwtPayloadType
@ -92,27 +90,20 @@ export class AuthenticationResolver {
throw new Error(`invalid OpenConnectionCallback payload of requesting community with publicKey ${args.publicKey}`)
}
const { endPoint, apiVersion } = splitUrlInEndPointAndApiVersion(openConnectionCallbackJwtPayload.url)
methodLogger.debug(`search fedComB per:`, endPoint, apiVersion)
// methodLogger.debug(`search fedComB per:`, endPoint, apiVersion)
const fedComB = await DbFedCommunity.findOneBy({ endPoint, apiVersion })
if (!fedComB) {
throw new Error(`unknown callback community with url ${openConnectionCallbackJwtPayload.url}`)
throw new Error(`unknown callback community for ${endPoint}${apiVersion}`)
}
methodLogger.debug(
`found fedComB and start authentication:`,
new FederatedCommunityLoggingView(fedComB),
`found fedComB and start authentication: ${fedComB.endPoint}${fedComB.apiVersion}`,
)
// no await to respond immediately and invoke authenticate-request asynchronously
void startAuthentication(args.handshakeID, openConnectionCallbackJwtPayload.oneTimeCode, fedComB)
methodLogger.debug('openConnectionCallback() successfully initiated authentication and returns true immediately...')
// methodLogger.debug('openConnectionCallback() successfully initiated authentication and returns true immediately...')
return true
} catch (err) {
let errorText = ''
if (err instanceof Error) {
errorText = err.message
} else {
errorText = String(err)
}
methodLogger.error('invalid jwt token:', errorText)
methodLogger.error('invalid jwt token:', err)
// no infos to the caller
return true
}
@ -125,13 +116,14 @@ export class AuthenticationResolver {
): Promise<string | null> {
const methodLogger = createLogger('authenticate')
methodLogger.addContext('handshakeID', args.handshakeID)
methodLogger.debug(`authenticate() via apiVersion=1_0 ...`, args)
methodLogger.debug(`start via apiVersion=${apiVersion}, public key: ${args.publicKey}`)
let state: DbCommunityHandshakeState | null = null
const argsPublicKey = new Ed25519PublicKey(args.publicKey)
try {
const authArgs = await interpretEncryptedTransferArgs(args) as AuthenticationJwtPayloadType
methodLogger.debug(`interpreted authentication payload...authArgs:`, authArgs)
// methodLogger.debug(`interpreted authentication payload...authArgs:`, authArgs)
if (!authArgs) {
methodLogger.debug(`interpretEncryptedTransferArgs was called with`, args)
throw new Error(`invalid authentication payload of requesting community with publicKey ${argsPublicKey.asHex()}`)
}
const validOneTimeCode = uint32Schema.safeParse(Number(authArgs.oneTimeCode))
@ -152,13 +144,13 @@ export class AuthenticationResolver {
state.status = CommunityHandshakeStateType.SUCCESS
await state.save()
methodLogger.debug(`search community per oneTimeCode:`, authArgs.oneTimeCode)
// methodLogger.debug(`search community per oneTimeCode:`, authArgs.oneTimeCode)
const authCom = await getCommunityByPublicKeyOrFail(argsPublicKey)
if (authCom) {
methodLogger.debug('found authCom:', new CommunityLoggingView(authCom))
methodLogger.debug(`found authCom ${authCom.name}`)
const authComPublicKey = new Ed25519PublicKey(authCom.publicKey)
methodLogger.debug('authCom.publicKey', authComPublicKey.asHex())
methodLogger.debug('args.publicKey', argsPublicKey.asHex())
// methodLogger.debug('authCom.publicKey', authComPublicKey.asHex())
// methodLogger.debug('args.publicKey', argsPublicKey.asHex())
if (!authComPublicKey.isSame(argsPublicKey)) {
throw new Error(
`corrupt authentication call detected, oneTimeCode: ${authArgs.oneTimeCode} doesn't belong to caller: ${argsPublicKey.asHex()}`
@ -173,30 +165,29 @@ export class AuthenticationResolver {
authCom.communityUuid = communityUuid.data
authCom.authenticatedAt = new Date()
await authCom.save()
methodLogger.debug('update authCom.uuid successfully')
methodLogger.debug(`update authCom.uuid successfully with ${authCom.communityUuid} at ${authCom.authenticatedAt}`)
const homeComB = await getHomeCommunity()
if (homeComB?.communityUuid) {
const responseArgs = new AuthenticationResponseJwtPayloadType(args.handshakeID,homeComB.communityUuid)
const responseJwt = await encryptAndSign(responseArgs, homeComB.privateJwtKey!, authCom.publicJwtKey!)
return responseJwt
}
} else {
throw new Error(`community with publicKey ${argsPublicKey.asHex()} not found`)
}
return null
} catch (err) {
let errorString = ''
if (err instanceof Error) {
errorString = err.message
} else {
errorString = String(err)
}
if (state) {
methodLogger.info(`state: ${new CommunityHandshakeStateLoggingView(state)}`)
state.status = CommunityHandshakeStateType.FAILED
state.lastError = errorString
await state.save()
try {
state.status = CommunityHandshakeStateType.FAILED
state.lastError = String(err)
await state.save()
} catch (err) {
methodLogger.error(`failed to save state`, new CommunityHandshakeStateLoggingView(state), err)
}
}
methodLogger.error(`failed: ${errorString}`)
methodLogger.error(`failed`, err)
// no infos to the caller
return null
}

View File

@ -1,4 +1,4 @@
import { CommunityHandshakeStateLogic, CommunityLogic, EncryptedTransferArgs, ensureUrlEndsWithSlash } from 'core'
import { CommunityHandshakeStateLogic, EncryptedTransferArgs, ensureUrlEndsWithSlash } from 'core'
import {
CommunityHandshakeStateLoggingView,
CommunityLoggingView,
@ -6,6 +6,7 @@ import {
FederatedCommunity as DbFedCommunity,
FederatedCommunityLoggingView,
findPendingCommunityHandshake,
getCommunityByPublicKeyOrFail,
getCommunityWithFederatedCommunityWithApiOrFail,
getHomeCommunity,
getHomeCommunityWithFederatedCommunityOrFail,
@ -27,67 +28,55 @@ import {
verifyAndDecrypt
} from 'shared'
import { CommunityHandshakeState as DbCommunityHandshakeState, CommunityHandshakeStateType } from 'database'
import { getFederatedCommunityWithApiOrFail } from 'core'
const createLogger = (method: string ) => getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.graphql.api.1_0.util.authenticateCommunity.${method}`)
async function errorState(
error: string,
methodLogger: Logger,
state: DbCommunityHandshakeState,
): Promise<DbCommunityHandshakeState> {
methodLogger.error(error)
state.status = CommunityHandshakeStateType.FAILED
state.lastError = error
return state.save()
}
export async function startOpenConnectionCallback(
handshakeID: string,
publicKey: Ed25519PublicKey,
api: string,
fedComA: DbFedCommunity,
): Promise<void> {
const methodLogger = createLogger('startOpenConnectionCallback')
methodLogger.addContext('handshakeID', handshakeID)
methodLogger.debug(`Authentication: startOpenConnectionCallback() with:`, {
publicKey: publicKey.asHex(),
})
const pendingState = await findPendingCommunityHandshake(publicKey, api)
if (pendingState) {
const stateLogic = new CommunityHandshakeStateLogic(pendingState)
// retry on timeout or failure
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(pendingState))
return
}
}
const state = new DbCommunityHandshakeState()
methodLogger.debug(`start`)
const api = fedComA.apiVersion
let state: DbCommunityHandshakeState | null = null
try {
const pendingState = await findPendingCommunityHandshake(publicKey, api)
if (pendingState) {
const stateLogic = new CommunityHandshakeStateLogic(pendingState)
// retry on timeout or failure
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(pendingState))
return
}
}
// load comA and comB parallel
// load with joined federated community of given api version
const [homeComB, comA] = await Promise.all([
getHomeCommunityWithFederatedCommunityOrFail(api),
getCommunityWithFederatedCommunityWithApiOrFail(publicKey, api),
getCommunityByPublicKeyOrFail(publicKey),
])
// load helpers
const homeComBLogic = new CommunityLogic(homeComB)
const comALogic = new CommunityLogic(comA)
// get federated communities with correct api version
const homeFedComB = homeComBLogic.getFederatedCommunityWithApiOrFail(api)
const fedComA = comALogic.getFederatedCommunityWithApiOrFail(api)
// simply check and extract federated community from community of given api version or throw error if not found
const homeFedComB = getFederatedCommunityWithApiOrFail(homeComB, api)
// TODO: make sure it is unique
const oneTimeCode = randombytes_random()
const oneTimeCodeString = oneTimeCode.toString()
// Create new community handshake state
state = new DbCommunityHandshakeState()
state.publicKey = publicKey.asBuffer()
state.apiVersion = api
state.status = CommunityHandshakeStateType.START_OPEN_CONNECTION_CALLBACK
state.handshakeId = parseInt(handshakeID)
state.oneTimeCode = oneTimeCode
await state.save()
methodLogger.debug(
`Authentication: store oneTimeCode in CommunityHandshakeState:`,
new CommunityHandshakeStateLoggingView(state),
)
state = await state.save()
methodLogger.debug('[START_OPEN_CONNECTION_CALLBACK] community handshake state created')
const client = AuthenticationClientFactory.getInstance(fedComA)
@ -95,29 +84,37 @@ export async function startOpenConnectionCallback(
const url = ensureUrlEndsWithSlash(homeFedComB.endPoint) + homeFedComB.apiVersion
const callbackArgs = new OpenConnectionCallbackJwtPayloadType(handshakeID, oneTimeCodeString, url)
methodLogger.debug(`Authentication: start openConnectionCallback with args:`, callbackArgs)
// methodLogger.debug(`Authentication: start openConnectionCallback with args:`, callbackArgs)
// encrypt callbackArgs with requestedCom.publicJwtKey and sign it with homeCom.privateJwtKey
const jwt = await encryptAndSign(callbackArgs, homeComB.privateJwtKey!, comA.publicJwtKey!)
const args = new EncryptedTransferArgs()
args.publicKey = new Ed25519PublicKey(homeComB.publicKey).asHex()
args.jwt = jwt
args.handshakeID = handshakeID
methodLogger.debug(`invoke openConnectionCallback(), oneTimeCode: ${oneTimeCodeString}`)
const result = await client.openConnectionCallback(args)
if (result) {
methodLogger.debug(`startOpenConnectionCallback() successful: ${jwt}`)
methodLogger.debug(`startOpenConnectionCallback() successful`)
} else {
methodLogger.debug(`jwt: ${jwt}`)
await errorState('startOpenConnectionCallback() failed', methodLogger, state)
const errorString = 'startOpenConnectionCallback() failed'
methodLogger.error(errorString)
state.status = CommunityHandshakeStateType.FAILED
state.lastError = errorString
state = await state.save()
}
}
} catch (err) {
let errorString: string = ''
if (err instanceof Error) {
errorString = err.message
} else {
errorString = String(err)
methodLogger.error('error in startOpenConnectionCallback', err)
if (state) {
try {
state.status = CommunityHandshakeStateType.FAILED
state.lastError = String(err)
state = await state.save()
} catch(e) {
methodLogger.error('error on saving CommunityHandshakeState', e)
}
}
await errorState(`error in startOpenConnectionCallback: ${errorString}`, methodLogger, state)
}
}
@ -128,13 +125,10 @@ export async function startAuthentication(
): Promise<void> {
const methodLogger = createLogger('startAuthentication')
methodLogger.addContext('handshakeID', handshakeID)
methodLogger.debug(`startAuthentication()...`, {
oneTimeCode,
fedComB: new FederatedCommunityLoggingView(fedComB),
})
methodLogger.debug(`startAuthentication()... oneTimeCode: ${oneTimeCode}`)
let state: DbCommunityHandshakeState | null = null
const fedComBPublicKey = new Ed25519PublicKey(fedComB.publicKey)
try {
const fedComBPublicKey = new Ed25519PublicKey(fedComB.publicKey)
const homeComA = await getHomeCommunity()
const comB = await DbCommunity.findOneByOrFail({
foreign: true,
@ -168,29 +162,33 @@ export async function startAuthentication(
args.publicKey = new Ed25519PublicKey(homeComA!.publicKey).asHex()
args.jwt = jwt
args.handshakeID = handshakeID
methodLogger.debug(`invoke authenticate() with:`, args)
methodLogger.debug(`invoke authenticate(), publicKey: ${args.publicKey}`)
const responseJwt = await client.authenticate(args)
methodLogger.debug(`response of authenticate():`, responseJwt)
// methodLogger.debug(`response of authenticate():`, responseJwt)
if (responseJwt !== null) {
const payload = await verifyAndDecrypt(handshakeID, responseJwt, homeComA!.privateJwtKey!, comB.publicJwtKey!) as AuthenticationResponseJwtPayloadType
methodLogger.debug(
/*methodLogger.debug(
`received payload from authenticate ComB:`,
payload,
new FederatedCommunityLoggingView(fedComB),
)
)*/
if (payload.tokentype !== AuthenticationResponseJwtPayloadType.AUTHENTICATION_RESPONSE_TYPE) {
throw new Error(`Invalid tokentype in authenticate-response of community with publicKey ${fedComBPublicKey.asHex()}`)
}
if (!uuidv4Schema.safeParse(payload.uuid).success) {
const parsedUuidv4 = uuidv4Schema.safeParse(payload.uuid)
if (!parsedUuidv4.success) {
throw new Error(`Invalid uuid in authenticate-response of community with publicKey ${fedComBPublicKey.asHex()}`)
}
comB.communityUuid = payload.uuid
methodLogger.debug('received uuid from authenticate ComB:', parsedUuidv4.data)
comB.communityUuid = parsedUuidv4.data
comB.authenticatedAt = new Date()
await DbCommunity.save(comB)
state.status = CommunityHandshakeStateType.SUCCESS
await state.save()
methodLogger.debug('Community Authentication successful:', new CommunityLoggingView(comB))
const endTime = new Date()
const duration = endTime.getTime() - state.createdAt.getTime()
methodLogger.debug(`Community Authentication successful in ${duration} ms`)
} else {
state.status = CommunityHandshakeStateType.FAILED
state.lastError = 'Community Authentication failed, empty response'
@ -199,17 +197,16 @@ export async function startAuthentication(
}
}
} catch (err) {
let errorString: string = ''
if (err instanceof Error) {
errorString = err.message
} else {
errorString = String(err)
}
methodLogger.error('error in startAuthentication:', err)
if (state) {
state.status = CommunityHandshakeStateType.FAILED
state.lastError = errorString
await state.save()
try {
state.status = CommunityHandshakeStateType.FAILED
state.lastError = String(err)
await state.save()
} catch(e) {
methodLogger.error('error on saving CommunityHandshakeState', e)
}
}
methodLogger.error('error in startAuthentication:', errorString)
}
}

View File

@ -18,19 +18,13 @@ export class BinaryData {
} else if (Buffer.isBuffer(input)) {
this.buf = input
this.hex = input.toString('hex')
} else if (input === undefined) {
} else {
this.buf = Buffer.from('')
this.hex = ''
} else {
throw new Error(`Either valid hex string or Buffer expected: ${input}`)
}
}
asBuffer(): Buffer {
if (!this.buf || !Buffer.isBuffer(this.buf)) {
logging.warn('BinaryData.buf is invalid, try to create fresh buffer from hex')
this.buf = Buffer.from(this.hex, 'hex')
}
return this.buf
}