diff --git a/backend/Dockerfile b/backend/Dockerfile index 4c1ceb36e..4ab2f1883 100644 --- a/backend/Dockerfile +++ b/backend/Dockerfile @@ -113,8 +113,6 @@ COPY --chown=app:app --from=build ${DOCKER_WORKDIR}/backend/build/worker.js ./wo # add node_modules from production_node_modules COPY --chown=app:app --from=production-node-modules ${DOCKER_WORKDIR}/node_modules ./node_modules -# Copy log4js-config.json to provide log configuration -COPY --chown=app:app --from=build ${DOCKER_WORKDIR}/backend/log4js-config.json ./log4js-config.json # Copy locales COPY --chown=app:app --from=build ${DOCKER_WORKDIR}/backend/locales ./locales diff --git a/backend/esbuild.config.ts b/backend/esbuild.config.ts index 87efef48e..9cdd51cc1 100644 --- a/backend/esbuild.config.ts +++ b/backend/esbuild.config.ts @@ -13,4 +13,5 @@ build({ external: ['sodium-native', 'email-templates'], plugins: [esbuildDecorators()], minify: true, + sourcemap: true, }) diff --git a/backend/jest.config.js b/backend/jest.config.js index 87f32599d..ddf94f977 100644 --- a/backend/jest.config.js +++ b/backend/jest.config.js @@ -2,7 +2,7 @@ module.exports = { verbose: true, preset: 'ts-jest', - collectCoverage: true, + collectCoverage: false, collectCoverageFrom: ['src/**/*.ts', '!**/node_modules/**', '!src/seeds/**', '!build/**'], coverageThreshold: { global: { diff --git a/backend/log4js-config.json b/backend/log4js-config.json deleted file mode 100644 index 0807e6a12..000000000 --- a/backend/log4js-config.json +++ /dev/null @@ -1,173 +0,0 @@ -{ - "appenders": - { - "access": - { - "type": "dateFile", - "filename": "../logs/backend/access.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "apollo": - { - "type": "dateFile", - "filename": "../logs/backend/apollo.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "backend": - { - "type": "dateFile", - "filename": "../logs/backend/backend.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "klicktipp": - { - "type": "dateFile", - "filename": "../logs/backend/klicktipp.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "gms": - { - "type": "dateFile", - "filename": "../logs/backend/gms.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "errorFile": - { - "type": "dateFile", - "filename": "../logs/backend/errors.log", - "pattern": "yyyy-MM-dd", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m %s" - }, - "compress": true, - "keepFileExt" : true, - "fileNameSep" : "_", - "numBackups" : 30 - }, - "errors": - { - "type": "logLevelFilter", - "level": "error", - "appender": "errorFile" - }, - "out": - { - "type": "stdout", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - } - }, - "apolloOut": - { - "type": "stdout", - "layout": - { - "type": "pattern", "pattern": "%d{ISO8601} %p %c [%X{user}] [%f : %l] - %m" - } - } - }, - "categories": - { - "default": - { - "appenders": - [ - "out", - "errors" - ], - "level": "debug", - "enableCallStack": true - }, - "apollo": - { - "appenders": - [ - "apollo", - "apolloOut", - "errors" - ], - "level": "debug", - "enableCallStack": true - }, - "backend": - { - "appenders": - [ - "backend", - "errors" - ], - "level": "debug", - "enableCallStack": true - }, - "klicktipp": - { - "appenders": - [ - "klicktipp", - "errors" - ], - "level": "debug", - "enableCallStack": true - }, - "gms": - { - "appenders": - [ - "gms", - "errors" - ], - "level": "debug", - "enableCallStack": true - }, - "http": - { - "appenders": - [ - "access" - ], - "level": "info" - } - } -} diff --git a/backend/package.json b/backend/package.json index 1ab660238..8673ff42d 100644 --- a/backend/package.json +++ b/backend/package.json @@ -9,9 +9,9 @@ "main": "src/index.ts", "scripts": { "build": "ts-node ./esbuild.config.ts && mkdirp build/templates/ && ncp src/emails/templates build/templates && mkdirp locales/ && ncp src/locales locales", - "clean": "tsc --build --clean", "dev": "cross-env TZ=UTC nodemon -w src --ext ts,pug,json,css -r tsconfig-paths/register src/index.ts", "test": "cross-env TZ=UTC NODE_ENV=development DB_DATABASE=gradido_test_backend jest --runInBand --forceExit --detectOpenHandles", + "test:coverage": "cross-env TZ=UTC NODE_ENV=development DB_DATABASE=gradido_test_backend jest --coverage --runInBand --forceExit --detectOpenHandles", "seed": "cross-env TZ=UTC NODE_ENV=development ts-node -r tsconfig-paths/register src/seeds/index.ts", "klicktipp": "cross-env TZ=UTC NODE_ENV=development ts-node -r tsconfig-paths/register src/util/executeKlicktipp.ts", "gmsusers": "cross-env TZ=UTC NODE_ENV=development ts-node -r tsconfig-paths/register src/apis/gms/ExportUsers.ts", @@ -21,7 +21,7 @@ "lint:fix:unsafe": "biome check --fix --unsafe", "locales": "scripts/sort.sh", "locales:fix": "scripts/sort.sh --fix", - "start": "cross-env TZ=UTC NODE_ENV=production node build/index.js", + "start": "cross-env TZ=UTC node build/index.js", "typecheck": "tsc --noEmit" }, "nodemonConfig": { @@ -47,6 +47,7 @@ "@types/node": "^17.0.21", "@types/nodemailer": "^6.4.4", "@types/sodium-native": "^2.3.5", + "@types/source-map-support": "^0.5.10", "@types/uuid": "^8.3.4", "apollo-server-express": "^2.25.2", "apollo-server-testing": "^2.25.2", @@ -85,6 +86,7 @@ "random-bigint": "^0.0.1", "reflect-metadata": "^0.1.13", "regenerator-runtime": "^0.14.1", + "source-map-support": "^0.5.21", "ts-jest": "27.0.5", "ts-node": "^10.9.2", "tsconfig-paths": "^4.1.1", diff --git a/backend/src/apis/HttpRequest.ts b/backend/src/apis/HttpRequest.ts index ef6f540b7..0b63c4af9 100644 --- a/backend/src/apis/HttpRequest.ts +++ b/backend/src/apis/HttpRequest.ts @@ -1,7 +1,10 @@ import axios from 'axios' +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_APIS_CATEGORY_NAME}.HttpRequest`) import { httpAgent, httpsAgent } from './ConnectionAgents' diff --git a/backend/src/apis/KlicktippController.ts b/backend/src/apis/KlicktippController.ts index cb665ea7f..5fe55fb2e 100644 --- a/backend/src/apis/KlicktippController.ts +++ b/backend/src/apis/KlicktippController.ts @@ -1,9 +1,10 @@ +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis' import { CONFIG } from '@/config' -import { backendLogger as logger } from '@/server/logger' - import KlicktippConnector from 'klicktipp-api' +import { getLogger } from 'log4js' const klicktippConnector = new KlicktippConnector() +const logger = getLogger(`${LOG4JS_APIS_CATEGORY_NAME}.KlicktippController`) export const subscribe = async ( email: string, diff --git a/backend/src/apis/dltConnector/DltConnectorClient.test.ts b/backend/src/apis/dltConnector/DltConnectorClient.test.ts index 0367c6350..00b15348d 100644 --- a/backend/src/apis/dltConnector/DltConnectorClient.test.ts +++ b/backend/src/apis/dltConnector/DltConnectorClient.test.ts @@ -6,7 +6,6 @@ import { cleanDB, testEnvironment } from '@test/helpers' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { DltConnectorClient } from './DltConnectorClient' @@ -76,7 +75,7 @@ describe.skip('transmitTransaction, without db connection', () => { describe('transmitTransaction', () => { beforeAll(async () => { - testEnv = await testEnvironment(logger) + testEnv = await testEnvironment() con = testEnv.con await cleanDB() }) diff --git a/backend/src/apis/dltConnector/DltConnectorClient.ts b/backend/src/apis/dltConnector/DltConnectorClient.ts index 2bebc84c0..8eb8de3fb 100644 --- a/backend/src/apis/dltConnector/DltConnectorClient.ts +++ b/backend/src/apis/dltConnector/DltConnectorClient.ts @@ -1,14 +1,17 @@ import { Transaction as DbTransaction } from 'database' import { GraphQLClient, gql } from 'graphql-request' +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis/index' import { CONFIG } from '@/config' import { TransactionTypeId } from '@/graphql/enum/TransactionTypeId' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' import { TransactionResult } from './model/TransactionResult' import { UserIdentifier } from './model/UserIdentifier' +const logger = getLogger(`${LOG4JS_APIS_CATEGORY_NAME}.dltConnector`) + const sendTransaction = gql` mutation ($input: TransactionInput!) { sendTransaction(data: $input) { diff --git a/backend/src/apis/gms/ExportUsers.ts b/backend/src/apis/gms/ExportUsers.ts index 981f9c90e..fb7cc81dc 100644 --- a/backend/src/apis/gms/ExportUsers.ts +++ b/backend/src/apis/gms/ExportUsers.ts @@ -1,14 +1,18 @@ import { User as DbUser } from 'database' // import { createTestClient } from 'apollo-server-testing' +import { LOG4JS_GMS_CATEGORY_NAME } from '@/apis/gms/index' // import { createGmsUser } from '@/apis/gms/GmsClient' // import { GmsUser } from '@/apis/gms/model/GmsUser' import { CONFIG } from '@/config' import { getHomeCommunity } from '@/graphql/resolver/util/communities' import { sendUserToGms } from '@/graphql/resolver/util/sendUserToGms' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { initLogging } from '@/server/logger' import { AppDatabase } from 'database' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_GMS_CATEGORY_NAME}.ExportUsers`) CONFIG.EMAIL = false // use force to copy over all user even if gmsRegistered is set to true @@ -70,7 +74,7 @@ async function main() { } main().catch((e) => { - // biome-ignore lint/suspicious/noConsole: logger isn't used here - console.error(e) + initLogging() + logger.error(e) process.exit(1) }) diff --git a/backend/src/apis/gms/GmsClient.ts b/backend/src/apis/gms/GmsClient.ts index 537fe36f2..0dd5eccc5 100644 --- a/backend/src/apis/gms/GmsClient.ts +++ b/backend/src/apis/gms/GmsClient.ts @@ -1,13 +1,16 @@ import axios from 'axios' import { httpAgent, httpsAgent } from '@/apis/ConnectionAgents' +import { LOG4JS_GMS_CATEGORY_NAME } from '@/apis/gms/index' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { getLogger } from 'log4js' import { GmsUser } from './model/GmsUser' +const logger = getLogger(`${LOG4JS_GMS_CATEGORY_NAME}.GmsClient`) + /* export async function communityList(): Promise { const baseUrl = ensureUrlEndsWithSlash(CONFIG.GMS_URL) diff --git a/backend/src/apis/gms/index.ts b/backend/src/apis/gms/index.ts new file mode 100644 index 000000000..620aaca4b --- /dev/null +++ b/backend/src/apis/gms/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis' + +export const LOG4JS_GMS_CATEGORY_NAME = `${LOG4JS_APIS_CATEGORY_NAME}.gms` diff --git a/backend/src/apis/humhub/ExportUsers.ts b/backend/src/apis/humhub/ExportUsers.ts index dc1f4fb5d..c0746ceb4 100644 --- a/backend/src/apis/humhub/ExportUsers.ts +++ b/backend/src/apis/humhub/ExportUsers.ts @@ -1,9 +1,9 @@ import { AppDatabase, User } from 'database' import { IsNull, Not } from 'typeorm' -import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' - +import { LOG4JS_HUMHUB_CATEGORY_NAME } from '@/apis/humhub/index' +import { initLogging } from '@/server/logger' +import { getLogger } from 'log4js' import { HumHubClient } from './HumHubClient' import { GetUser } from './model/GetUser' import { UsersResponse } from './model/UsersResponse' @@ -11,6 +11,7 @@ import { ExecutedHumhubAction, syncUser } from './syncUser' const USER_BULK_SIZE = 20 const HUMHUB_BULK_SIZE = 50 +const logger = getLogger(`${LOG4JS_HUMHUB_CATEGORY_NAME}.ExportUsers`) function getUsersPage(page: number, limit: number): Promise<[User[], number]> { return User.findAndCount({ @@ -34,7 +35,7 @@ async function loadUsersFromHumHub(client: HumHubClient): Promise { - // biome-ignore lint/suspicious/noConsole: logger isn't used here - console.error(e) + initLogging() + logger.error(e) process.exit(1) }) diff --git a/backend/src/apis/humhub/HumHubClient.ts b/backend/src/apis/humhub/HumHubClient.ts index daa19b5b8..ff4529234 100644 --- a/backend/src/apis/humhub/HumHubClient.ts +++ b/backend/src/apis/humhub/HumHubClient.ts @@ -4,8 +4,9 @@ import { IRequestOptions, IRestResponse, RestClient } from 'typed-rest-client' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_HUMHUB_CATEGORY_NAME } from '@/apis/humhub/index' +import { getLogger } from 'log4js' import { PostUserLoggingView } from './logging/PostUserLogging.view' import { GetUser } from './model/GetUser' import { PostUser } from './model/PostUser' @@ -13,6 +14,8 @@ import { Space } from './model/Space' import { SpacesResponse } from './model/SpacesResponse' import { UsersResponse } from './model/UsersResponse' +const logger = getLogger(`${LOG4JS_HUMHUB_CATEGORY_NAME}.HumHubClient`) + /** * HumHubClient as singleton class */ diff --git a/backend/src/apis/humhub/index.ts b/backend/src/apis/humhub/index.ts new file mode 100644 index 000000000..dda319145 --- /dev/null +++ b/backend/src/apis/humhub/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis' + +export const LOG4JS_HUMHUB_CATEGORY_NAME = `${LOG4JS_APIS_CATEGORY_NAME}.humhub` diff --git a/backend/src/apis/humhub/syncUser.ts b/backend/src/apis/humhub/syncUser.ts index 1e62871be..257f16683 100644 --- a/backend/src/apis/humhub/syncUser.ts +++ b/backend/src/apis/humhub/syncUser.ts @@ -1,13 +1,16 @@ import { User } from 'database' +import { LOG4JS_HUMHUB_CATEGORY_NAME } from '@/apis/humhub/index' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' import { HumHubClient } from './HumHubClient' import { isHumhubUserIdenticalToDbUser } from './compareHumhubUserDbUser' import { GetUser } from './model/GetUser' import { PostUser } from './model/PostUser' +const logger = getLogger(`${LOG4JS_HUMHUB_CATEGORY_NAME}.syncUser`) + export enum ExecutedHumhubAction { UPDATE, CREATE, diff --git a/backend/src/apis/index.ts b/backend/src/apis/index.ts new file mode 100644 index 000000000..c4e45826d --- /dev/null +++ b/backend/src/apis/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' + +export const LOG4JS_APIS_CATEGORY_NAME = `${LOG4JS_BASE_CATEGORY_NAME}.apis` diff --git a/backend/src/apis/openai/OpenaiClient.ts b/backend/src/apis/openai/OpenaiClient.ts index b2a859581..dd447c7ad 100644 --- a/backend/src/apis/openai/OpenaiClient.ts +++ b/backend/src/apis/openai/OpenaiClient.ts @@ -4,10 +4,14 @@ import { Message } from 'openai/resources/beta/threads/messages' import { httpsAgent } from '@/apis/ConnectionAgents' import { CONFIG } from '@/config' -import { backendLogger as logger } from '@/server/logger' import { Message as MessageModel } from './model/Message' +import { LOG4JS_APIS_CATEGORY_NAME } from '@/apis' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_APIS_CATEGORY_NAME}.openai.OpenaiClient`) + /** * The `OpenaiClient` class is a singleton that provides an interface to interact with the OpenAI API. * It ensures that only one instance of the client is created and used throughout the application. diff --git a/backend/src/auth/jwt/JWT.ts b/backend/src/auth/jwt/JWT.ts index 6f6581773..07384c03b 100644 --- a/backend/src/auth/jwt/JWT.ts +++ b/backend/src/auth/jwt/JWT.ts @@ -1,12 +1,14 @@ -import { createPrivateKey, sign } from 'node:crypto' - -import { JWTPayload, SignJWT, decodeJwt, jwtVerify } from 'jose' +import { SignJWT, decodeJwt, jwtVerify } from 'jose' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { JwtPayloadType } from './payloadtypes/JwtPayloadType' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.auth.jwt.JWT`) + export const verify = async (token: string, signkey: string): Promise => { if (!token) { throw new LogError('401 Unauthorized') diff --git a/backend/src/config/const.ts b/backend/src/config/const.ts new file mode 100644 index 000000000..68bd124a8 --- /dev/null +++ b/backend/src/config/const.ts @@ -0,0 +1 @@ +export const LOG4JS_BASE_CATEGORY_NAME = 'backend' diff --git a/backend/src/config/index.test.ts b/backend/src/config/index.test.ts deleted file mode 100644 index 24908513a..000000000 --- a/backend/src/config/index.test.ts +++ /dev/null @@ -1,9 +0,0 @@ -import { CONFIG } from './index' - -describe('config/index', () => { - describe('decay start block', () => { - it('has the correct date set', () => { - expect(CONFIG.DECAY_START_TIME).toEqual(new Date('2021-05-13 17:46:31-0000')) - }) - }) -}) diff --git a/backend/src/config/index.ts b/backend/src/config/index.ts index f29f5ed4b..9d61c2da4 100644 --- a/backend/src/config/index.ts +++ b/backend/src/config/index.ts @@ -1,21 +1,18 @@ // ATTENTION: DO NOT PUT ANY SECRETS IN HERE (or the .env) -import { validate } from 'config-schema' -import { Decimal } from 'decimal.js-light' +import { LogLevel, validate } from 'config-schema' import dotenv from 'dotenv' import { schema } from './schema' dotenv.config() -Decimal.set({ - precision: 25, - rounding: Decimal.ROUND_HALF_UP, -}) - -const constants = { - DECAY_START_TIME: new Date('2021-05-13 17:46:31-0000'), // GMT+0 - LOG4JS_CONFIG: 'log4js-config.json', +const logging = { + LOG4JS_CONFIG: process.env.LOG4JS_CONFIG ?? 'log4js-config.json', + // default log level on production should be info + // log level for default log4js-config.json, don't change existing log4js-config.json + LOG_LEVEL: (process.env.LOG_LEVEL ?? 'info') as LogLevel, + LOG_FILES_BASE_PATH: process.env.LOG_FILES_BASE_PATH ?? '../logs/backend', } const server = { @@ -27,8 +24,6 @@ const server = { GDT_ACTIVE: process.env.GDT_ACTIVE === 'true' || false, GDT_API_URL: process.env.GDT_API_URL ?? 'https://gdt.gradido.net', PRODUCTION: process.env.NODE_ENV === 'production' || false, - // default log level on production should be info - LOG_LEVEL: process.env.LOG_LEVEL ?? 'info', } const klicktipp = { @@ -143,7 +138,7 @@ const openai = { } export const CONFIG = { - ...constants, + ...logging, ...server, ...klicktipp, ...dltConnector, diff --git a/backend/src/config/schema.ts b/backend/src/config/schema.ts index f805d02a7..2fb576bdd 100644 --- a/backend/src/config/schema.ts +++ b/backend/src/config/schema.ts @@ -13,6 +13,7 @@ import { LOG4JS_CONFIG, LOGIN_APP_SECRET, LOGIN_SERVER_KEY, + LOG_FILES_BASE_PATH, LOG_LEVEL, NODE_ENV, OPENAI_ACTIVE, @@ -32,6 +33,7 @@ export const schema = Joi.object({ GRAPHIQL, HUMHUB_ACTIVE, HUMHUB_API_URL, + LOG_FILES_BASE_PATH, LOG4JS_CONFIG, LOGIN_APP_SECRET, LOGIN_SERVER_KEY, diff --git a/backend/src/emails/index.ts b/backend/src/emails/index.ts new file mode 100644 index 000000000..d529ac28d --- /dev/null +++ b/backend/src/emails/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' + +export const LOG4JS_EMAILS_CATEGORY_NAME = `${LOG4JS_BASE_CATEGORY_NAME}.emails` diff --git a/backend/src/emails/sendEmailTranslated.test.ts b/backend/src/emails/sendEmailTranslated.test.ts index 917d80ea6..b4da5fbfb 100644 --- a/backend/src/emails/sendEmailTranslated.test.ts +++ b/backend/src/emails/sendEmailTranslated.test.ts @@ -1,11 +1,15 @@ import { createTransport } from 'nodemailer' -import { i18n, logger } from '@test/testSetup' +import { i18n } from '@test/testSetup' import { CONFIG } from '@/config' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_EMAILS_CATEGORY_NAME } from '.' import { sendEmailTranslated } from './sendEmailTranslated' +const logger = getLogger(`${LOG4JS_EMAILS_CATEGORY_NAME}.sendEmailTranslated`) + const testMailServerHost = 'localhost' const testMailServerPort = 1025 diff --git a/backend/src/emails/sendEmailTranslated.ts b/backend/src/emails/sendEmailTranslated.ts index ae52b3975..30050abf3 100644 --- a/backend/src/emails/sendEmailTranslated.ts +++ b/backend/src/emails/sendEmailTranslated.ts @@ -5,7 +5,10 @@ import i18n from 'i18n' import { createTransport } from 'nodemailer' import { CONFIG } from '@/config' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_EMAILS_CATEGORY_NAME } from '@/emails' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_EMAILS_CATEGORY_NAME}.sendEmailTranslated`) export const sendEmailTranslated = async ({ receiver, @@ -31,8 +34,8 @@ export const sendEmailTranslated = async ({ i18n.setLocale('en') // for logging logger.info( - `send Email: language=${locals.locale as string} to=${receiver.to}` + - (receiver.cc ? `, cc=${receiver.cc}` : '') + + `send Email: language=${locals.locale as string} to=${receiver.to.substring(0, 3)}...` + + (receiver.cc ? `, cc=${receiver.cc.substring(0, 3)}...` : '') + `, subject=${i18n.__('emails.' + template + '.subject')}`, ) diff --git a/backend/src/emails/sendEmailVariants.test.ts b/backend/src/emails/sendEmailVariants.test.ts index 2c2885ebf..b264ddbf5 100644 --- a/backend/src/emails/sendEmailVariants.test.ts +++ b/backend/src/emails/sendEmailVariants.test.ts @@ -3,7 +3,11 @@ import { Decimal } from 'decimal.js-light' import { DataSource } from 'typeorm' import { testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_EMAILS_CATEGORY_NAME } from '.' + +const logger = getLogger(`${LOG4JS_EMAILS_CATEGORY_NAME}.sendEmailTranslated`) import { CONFIG } from '@/config' diff --git a/backend/src/federation/authenticateCommunities.ts b/backend/src/federation/authenticateCommunities.ts index c4263445b..2a1c6f51d 100644 --- a/backend/src/federation/authenticateCommunities.ts +++ b/backend/src/federation/authenticateCommunities.ts @@ -4,12 +4,15 @@ import { validate as validateUUID, version as versionUUID } from 'uuid' import { CONFIG } from '@/config' import { AuthenticationClient as V1_0_AuthenticationClient } from '@/federation/client/1_0/AuthenticationClient' -import { backendLogger as logger } from '@/server/logger' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { LOG4JS_FEDERATION_CATEGORY_NAME } from '@/federation' +import { getLogger } from 'log4js' import { OpenConnectionArgs } from './client/1_0/model/OpenConnectionArgs' import { AuthenticationClientFactory } from './client/AuthenticationClientFactory' +const logger = getLogger(`${LOG4JS_FEDERATION_CATEGORY_NAME}.authenticateCommunities`) + export async function startCommunityAuthentication( foreignFedCom: DbFederatedCommunity, ): Promise { diff --git a/backend/src/federation/client/1_0/AuthenticationClient.ts b/backend/src/federation/client/1_0/AuthenticationClient.ts index 264afe3a0..38996433f 100644 --- a/backend/src/federation/client/1_0/AuthenticationClient.ts +++ b/backend/src/federation/client/1_0/AuthenticationClient.ts @@ -1,12 +1,15 @@ import { FederatedCommunity as DbFederatedCommunity } from 'database' import { GraphQLClient } from 'graphql-request' -import { backendLogger as logger } from '@/server/logger' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME } from '@/federation/client/1_0' +import { getLogger } from 'log4js' import { OpenConnectionArgs } from './model/OpenConnectionArgs' import { openConnection } from './query/openConnection' +const logger = getLogger(`${LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME}.AuthenticationClient`) + export class AuthenticationClient { dbCom: DbFederatedCommunity endpoint: string @@ -25,25 +28,19 @@ export class AuthenticationClient { } async openConnection(args: OpenConnectionArgs): Promise { - logger.debug(`Authentication: openConnection at ${this.endpoint} for args:`, args) + logger.debug(`openConnection at ${this.endpoint} for args:`, args) try { const { data } = await this.client.rawRequest<{ openConnection: boolean }>(openConnection, { args, }) if (!data?.openConnection) { - logger.warn( - 'Authentication: openConnection without response data from endpoint', - this.endpoint, - ) + logger.warn('openConnection without response data from endpoint', this.endpoint) return false } - logger.debug( - 'Authentication: openConnection successfully started with endpoint', - this.endpoint, - ) + logger.debug('openConnection successfully started with endpoint', this.endpoint) return true } catch (err) { - logger.error('Authentication: error on openConnection: ', err) + logger.error('error on openConnection: ', err) } } } diff --git a/backend/src/federation/client/1_0/FederationClient.ts b/backend/src/federation/client/1_0/FederationClient.ts index b83da8a8b..b548a97e1 100644 --- a/backend/src/federation/client/1_0/FederationClient.ts +++ b/backend/src/federation/client/1_0/FederationClient.ts @@ -1,15 +1,18 @@ import { FederatedCommunity as DbFederatedCommunity } from 'database' import { GraphQLClient } from 'graphql-request' +import { LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME } from '@/federation/client/1_0' import { getPublicCommunityInfo } from '@/federation/client/1_0/query/getPublicCommunityInfo' import { getPublicKey } from '@/federation/client/1_0/query/getPublicKey' -import { backendLogger as logger } from '@/server/logger' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { getLogger } from 'log4js' import { PublicCommunityInfoLoggingView } from './logging/PublicCommunityInfoLogging.view' import { GetPublicKeyResult } from './model/GetPublicKeyResult' import { PublicCommunityInfo } from './model/PublicCommunityInfo' +const logger = getLogger(`${LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME}.FederationClient`) + export class FederationClient { dbCom: DbFederatedCommunity endpoint: string @@ -32,25 +35,25 @@ export class FederationClient { } getPublicKey = async (): Promise => { - logger.debug('Federation: getPublicKey from endpoint', this.endpoint) + logger.debug('getPublicKey from endpoint', this.endpoint) try { const { data } = await this.client.rawRequest<{ getPublicKey: GetPublicKeyResult }>( getPublicKey, {}, ) if (!data?.getPublicKey?.publicKey) { - logger.warn('Federation: getPublicKey without response data from endpoint', this.endpoint) + logger.warn('getPublicKey without response data from endpoint', this.endpoint) return } logger.debug( - 'Federation: getPublicKey successful from endpoint', + 'getPublicKey successful from endpoint', this.endpoint, data.getPublicKey.publicKey, ) return data.getPublicKey.publicKey } catch (err) { const errorString = JSON.stringify(err) - logger.warn('Federation: getPublicKey failed for endpoint', { + logger.warn('getPublicKey failed for endpoint', { endpoint: this.endpoint, err: errorString.length <= 200 ? errorString : errorString.substring(0, 200) + '...', }) @@ -58,20 +61,17 @@ export class FederationClient { } getPublicCommunityInfo = async (): Promise => { - logger.debug(`Federation: getPublicCommunityInfo with endpoint='${this.endpoint}'...`) + logger.debug(`getPublicCommunityInfo with endpoint='${this.endpoint}'...`) try { const { data } = await this.client.rawRequest<{ getPublicCommunityInfo: PublicCommunityInfo }>(getPublicCommunityInfo, {}) if (!data?.getPublicCommunityInfo?.name) { - logger.warn( - 'Federation: getPublicCommunityInfo without response data from endpoint', - this.endpoint, - ) + logger.warn('getPublicCommunityInfo without response data from endpoint', this.endpoint) return } - logger.debug(`Federation: getPublicCommunityInfo successful from endpoint=${this.endpoint}`) + logger.debug(`getPublicCommunityInfo successful from endpoint=${this.endpoint}`) logger.debug( `publicCommunityInfo:`, new PublicCommunityInfoLoggingView(data.getPublicCommunityInfo), @@ -80,7 +80,7 @@ export class FederationClient { } catch (err) { logger.warn(' err', err) const errorString = JSON.stringify(err) - logger.warn('Federation: getPublicCommunityInfo failed for endpoint', { + logger.warn('getPublicCommunityInfo failed for endpoint', { endpoint: this.endpoint, err: errorString.length <= 200 ? errorString : errorString.substring(0, 200) + '...', }) diff --git a/backend/src/federation/client/1_0/SendCoinsClient.ts b/backend/src/federation/client/1_0/SendCoinsClient.ts index 91e7b827c..cc0c74846 100644 --- a/backend/src/federation/client/1_0/SendCoinsClient.ts +++ b/backend/src/federation/client/1_0/SendCoinsClient.ts @@ -2,9 +2,10 @@ import { FederatedCommunity as DbFederatedCommunity } from 'database' import { GraphQLClient } from 'graphql-request' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { getLogger } from 'log4js' +import { LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME } from '.' import { SendCoinsArgsLoggingView } from './logging/SendCoinsArgsLogging.view' import { SendCoinsResultLoggingView } from './logging/SendCoinsResultLogging.view' import { SendCoinsArgs } from './model/SendCoinsArgs' @@ -14,6 +15,8 @@ import { revertSettledSendCoins as revertSettledSendCoinsQuery } from './query/r import { settleSendCoins as settleSendCoinsQuery } from './query/settleSendCoins' import { voteForSendCoins as voteForSendCoinsQuery } from './query/voteForSendCoins' +const logger = getLogger(`${LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME}.SendCoinsClient`) + export class SendCoinsClient { dbCom: DbFederatedCommunity endpoint: string @@ -32,123 +35,87 @@ export class SendCoinsClient { } async voteForSendCoins(args: SendCoinsArgs): Promise { - logger.debug('X-Com: voteForSendCoins against endpoint=', this.endpoint) + logger.debug('voteForSendCoins against endpoint=', this.endpoint) try { - logger.debug( - `X-Com: SendCoinsClient: voteForSendCoins with args=`, - new SendCoinsArgsLoggingView(args), - ) + logger.debug(`voteForSendCoins with args=`, new SendCoinsArgsLoggingView(args)) const { data } = await this.client.rawRequest<{ voteForSendCoins: SendCoinsResult }>( voteForSendCoinsQuery, { args }, ) const result = data.voteForSendCoins if (!data?.voteForSendCoins?.vote) { - logger.debug( - 'X-Com: voteForSendCoins failed with: ', - new SendCoinsResultLoggingView(result), - ) + logger.debug('voteForSendCoins failed with: ', new SendCoinsResultLoggingView(result)) return new SendCoinsResult() } logger.debug( - 'X-Com: voteForSendCoins successful with result=', + 'voteForSendCoins successful with result=', new SendCoinsResultLoggingView(result), ) return result } catch (err) { - throw new LogError(`X-Com: voteForSendCoins failed for endpoint=${this.endpoint}:`, err) + throw new LogError(`voteForSendCoins failed for endpoint=${this.endpoint}:`, err) } } async revertSendCoins(args: SendCoinsArgs): Promise { - logger.debug('X-Com: revertSendCoins against endpoint=', this.endpoint) + logger.debug('revertSendCoins against endpoint=', this.endpoint) try { - logger.debug( - `X-Com: SendCoinsClient: revertSendCoins with args=`, - new SendCoinsArgsLoggingView(args), - ) + logger.debug(`revertSendCoins with args=`, new SendCoinsArgsLoggingView(args)) const { data } = await this.client.rawRequest<{ revertSendCoins: boolean }>( revertSendCoinsQuery, { args }, ) - logger.debug(`X-Com: SendCoinsClient: after revertSendCoins: data=`, data) + logger.debug(`after revertSendCoins: data=`, data) if (!data?.revertSendCoins) { - logger.warn('X-Com: revertSendCoins without response data from endpoint', this.endpoint) + logger.warn('revertSendCoins without response data from endpoint', this.endpoint) return false } - logger.debug( - `X-Com: SendCoinsClient: revertSendCoins successful from endpoint=${this.endpoint}`, - ) + logger.debug(`revertSendCoins successful from endpoint=${this.endpoint}`) return true } catch (err) { - logger.error( - `X-Com: SendCoinsClient: revertSendCoins failed for endpoint=${this.endpoint}`, - err, - ) + logger.error(`revertSendCoins failed for endpoint=${this.endpoint}`, err) return false } } async settleSendCoins(args: SendCoinsArgs): Promise { - logger.debug(`X-Com: settleSendCoins against endpoint='${this.endpoint}'...`) + logger.debug(`settleSendCoins against endpoint='${this.endpoint}'...`) try { - logger.debug( - `X-Com: SendCoinsClient: settleSendCoins with args=`, - new SendCoinsArgsLoggingView(args), - ) + logger.debug(`settleSendCoins with args=`, new SendCoinsArgsLoggingView(args)) const { data } = await this.client.rawRequest<{ settleSendCoins: boolean }>( settleSendCoinsQuery, { args }, ) - logger.debug(`X-Com: SendCoinsClient: after settleSendCoins: data=`, data) + logger.debug(`after settleSendCoins: data=`, data) if (!data?.settleSendCoins) { - logger.warn( - 'X-Com: SendCoinsClient: settleSendCoins without response data from endpoint', - this.endpoint, - ) + logger.warn('settleSendCoins without response data from endpoint', this.endpoint) return false } - logger.debug( - `X-Com: SendCoinsClient: settleSendCoins successful from endpoint=${this.endpoint}`, - ) + logger.debug(`settleSendCoins successful from endpoint=${this.endpoint}`) return true } catch (err) { - throw new LogError( - `X-Com: SendCoinsClient: settleSendCoins failed for endpoint=${this.endpoint}`, - err, - ) + throw new LogError(`settleSendCoins failed for endpoint=${this.endpoint}`, err) } } async revertSettledSendCoins(args: SendCoinsArgs): Promise { - logger.debug(`X-Com: revertSettledSendCoins against endpoint='${this.endpoint}'...`) + logger.debug(`revertSettledSendCoins against endpoint='${this.endpoint}'...`) try { - logger.debug( - `X-Com: SendCoinsClient: revertSettledSendCoins with args=`, - new SendCoinsArgsLoggingView(args), - ) + logger.debug(`revertSettledSendCoins with args=`, new SendCoinsArgsLoggingView(args)) const { data } = await this.client.rawRequest<{ revertSettledSendCoins: boolean }>( revertSettledSendCoinsQuery, { args }, ) - logger.debug(`X-Com: SendCoinsClient: after revertSettledSendCoins: data=`, data) + logger.debug(`after revertSettledSendCoins: data=`, data) if (!data?.revertSettledSendCoins) { - logger.warn( - 'X-Com: SendCoinsClient: revertSettledSendCoins without response data from endpoint', - this.endpoint, - ) + logger.warn('revertSettledSendCoins without response data from endpoint', this.endpoint) return false } - logger.debug( - `X-Com: SendCoinsClient: revertSettledSendCoins successful from endpoint=${this.endpoint}`, - ) + logger.debug(`revertSettledSendCoins successful from endpoint=${this.endpoint}`) return true } catch (err) { - throw new LogError( - `X-Com: SendCoinsClient: revertSettledSendCoins failed for endpoint=${this.endpoint}`, - err, - ) + throw new LogError(`revertSettledSendCoins failed for endpoint=${this.endpoint}`, err) } } } diff --git a/backend/src/federation/client/1_0/index.ts b/backend/src/federation/client/1_0/index.ts new file mode 100644 index 000000000..c21700126 --- /dev/null +++ b/backend/src/federation/client/1_0/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_FEDERATION_CATEGORY_NAME } from '@/federation' + +export const LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME = `${LOG4JS_FEDERATION_CATEGORY_NAME}.client.1_0` diff --git a/backend/src/federation/index.ts b/backend/src/federation/index.ts new file mode 100644 index 000000000..c1684852b --- /dev/null +++ b/backend/src/federation/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' + +export const LOG4JS_FEDERATION_CATEGORY_NAME = `${LOG4JS_BASE_CATEGORY_NAME}.federation` diff --git a/backend/src/federation/validateCommunities.test.ts b/backend/src/federation/validateCommunities.test.ts index 731ca72a1..bfb43fd35 100644 --- a/backend/src/federation/validateCommunities.test.ts +++ b/backend/src/federation/validateCommunities.test.ts @@ -4,11 +4,16 @@ import { GraphQLClient } from 'graphql-request' import { Response } from 'graphql-request/dist/types' import { DataSource } from 'typeorm' +import { LOG4JS_FEDERATION_CATEGORY_NAME } from '@/federation' +import { LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME } from '@/federation/client/1_0' import { cleanDB, testEnvironment } from '@test/helpers' -import { logger } from '@test/testSetup' +import { clearLogs, getLogger, printLogs } from 'config-schema/test/testSetup' import { validateCommunities } from './validateCommunities' +const logger = getLogger(`${LOG4JS_FEDERATION_CATEGORY_NAME}.validateCommunities`) +const federationClientLogger = getLogger(`${LOG4JS_FEDERATION_CLIENT1_0_CATEGORY_NAME}.FederationClient`) + let con: DataSource let testEnv: { mutate: ApolloServerTestClient['mutate'] @@ -49,7 +54,7 @@ describe('validate Communities', () => { }) it('logs zero communities found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 0 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 0 dbCommunities`) }) describe('with one Community of api 1_0 but missing pubKey response', () => { @@ -79,13 +84,12 @@ describe('validate Communities', () => { }) it('logs one community found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 1 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 1 dbCommunities`) }) it('logs requestGetPublicKey missing response data ', () => { - expect(logger.warn).toBeCalledWith( - 'Federation: getPublicKey without response data from endpoint', - 'http//localhost:5001/api/1_0/', - ) + expect(federationClientLogger.warn).toBeCalledWith( + 'getPublicKey without response data from endpoint', 'http//localhost:5001/api/1_0/' + ) }) }) @@ -153,17 +157,14 @@ describe('validate Communities', () => { }) it('logs one community found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 1 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 1 dbCommunities`) }) it('logs requestGetPublicKey for community api 1_0 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', - 'http//localhost:5001/api/1_0/', - ) + expect(federationClientLogger.debug).toBeCalledWith('getPublicKey from endpoint', 'http//localhost:5001/api/1_0/') }) it('logs not matching publicKeys', () => { expect(logger.debug).toBeCalledWith( - 'Federation: received not matching publicKey:', + 'received not matching publicKey:', 'somePubKey', expect.stringMatching('11111111111111111111111111111111'), ) @@ -203,18 +204,18 @@ describe('validate Communities', () => { }) it('logs one community found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 1 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 1 dbCommunities`) }) it('logs requestGetPublicKey for community api 1_0 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', + expect(federationClientLogger.debug).toBeCalledWith( + 'getPublicKey from endpoint', 'http//localhost:5001/api/1_0/', ) }) it('logs community pubKey verified', () => { - expect(logger.debug).toHaveBeenNthCalledWith( - 5, - 'Federation: getPublicKey successful from endpoint', + expect(federationClientLogger.debug).toHaveBeenNthCalledWith( + 2, + 'getPublicKey successful from endpoint', 'http//localhost:5001/api/1_0/', '11111111111111111111111111111111', ) @@ -269,19 +270,16 @@ describe('validate Communities', () => { await validateCommunities() }) it('logs two communities found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 2 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 2 dbCommunities`) }) it('logs requestGetPublicKey for community api 1_0 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', + expect(federationClientLogger.debug).toBeCalledWith( + 'getPublicKey from endpoint', 'http//localhost:5001/api/1_0/', ) }) it('logs requestGetPublicKey for community api 1_1 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', - 'http//localhost:5001/api/1_1/', - ) + expect(federationClientLogger.debug).toBeCalledWith('getPublicKey from endpoint', 'http//localhost:5001/api/1_1/') }) }) describe('with three Communities of api 1_0, 1_1 and 2_0', () => { @@ -321,26 +319,19 @@ describe('validate Communities', () => { await validateCommunities() }) it('logs three community found', () => { - expect(logger.debug).toBeCalledWith(`Federation: found 3 dbCommunities`) + expect(logger.debug).toBeCalledWith(`found 3 dbCommunities`) }) it('logs requestGetPublicKey for community api 1_0 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', + expect(federationClientLogger.debug).toBeCalledWith( + 'getPublicKey from endpoint', 'http//localhost:5001/api/1_0/', ) }) it('logs requestGetPublicKey for community api 1_1 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: getPublicKey from endpoint', - 'http//localhost:5001/api/1_1/', - ) + expect(federationClientLogger.debug).toBeCalledWith('getPublicKey from endpoint', 'http//localhost:5001/api/1_1/') }) it('logs unsupported api for community with api 2_0 ', () => { - expect(logger.debug).toBeCalledWith( - 'Federation: dbCom with unsupported apiVersion', - dbCom.endPoint, - '2_0', - ) + expect(logger.debug).toBeCalledWith('dbCom with unsupported apiVersion', dbCom.endPoint, '2_0') }) }) }) diff --git a/backend/src/federation/validateCommunities.ts b/backend/src/federation/validateCommunities.ts index 2a1bc630e..dc4747352 100644 --- a/backend/src/federation/validateCommunities.ts +++ b/backend/src/federation/validateCommunities.ts @@ -5,23 +5,23 @@ import { } from 'database' import { IsNull } from 'typeorm' +import { LOG4JS_FEDERATION_CATEGORY_NAME } from '@/federation' import { FederationClient as V1_0_FederationClient } from '@/federation/client/1_0/FederationClient' import { PublicCommunityInfo } from '@/federation/client/1_0/model/PublicCommunityInfo' import { FederationClientFactory } from '@/federation/client/FederationClientFactory' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' - +import { getLogger } from 'log4js' import { startCommunityAuthentication } from './authenticateCommunities' import { PublicCommunityInfoLoggingView } from './client/1_0/logging/PublicCommunityInfoLogging.view' import { ApiVersionType } from './enum/apiVersionType' +const logger = getLogger(`${LOG4JS_FEDERATION_CATEGORY_NAME}.validateCommunities`) + export async function startValidateCommunities(timerInterval: number): Promise { if (Number.isNaN(timerInterval) || timerInterval <= 0) { throw new LogError('FEDERATION_VALIDATE_COMMUNITY_TIMER is not a positive number') } - logger.info( - `Federation: startValidateCommunities loop with an interval of ${timerInterval} ms...`, - ) + logger.info(`startValidateCommunities loop with an interval of ${timerInterval} ms...`) // delete all foreign federated community entries to avoid increasing validation efforts and log-files await DbFederatedCommunity.delete({ foreign: true }) @@ -40,17 +40,13 @@ export async function validateCommunities(): Promise { .orWhere('verified_at < last_announced_at') .getMany() - logger.debug(`Federation: found ${dbFederatedCommunities.length} dbCommunities`) + logger.debug(`found ${dbFederatedCommunities.length} dbCommunities`) for (const dbCom of dbFederatedCommunities) { - logger.debug('Federation: dbCom', new FederatedCommunityLoggingView(dbCom)) + logger.debug('dbCom', new FederatedCommunityLoggingView(dbCom)) const apiValueStrings: string[] = Object.values(ApiVersionType) logger.debug(`suppported ApiVersions=`, apiValueStrings) if (!apiValueStrings.includes(dbCom.apiVersion)) { - logger.debug( - 'Federation: dbCom with unsupported apiVersion', - dbCom.endPoint, - dbCom.apiVersion, - ) + logger.debug('dbCom with unsupported apiVersion', dbCom.endPoint, dbCom.apiVersion) continue } try { @@ -60,21 +56,17 @@ export async function validateCommunities(): Promise { const pubKey = await client.getPublicKey() if (pubKey && pubKey === dbCom.publicKey.toString('hex')) { await DbFederatedCommunity.update({ id: dbCom.id }, { verifiedAt: new Date() }) - logger.debug(`Federation: verified community with:`, dbCom.endPoint) + logger.debug(`verified community with:`, dbCom.endPoint) const pubComInfo = await client.getPublicCommunityInfo() if (pubComInfo) { await writeForeignCommunity(dbCom, pubComInfo) await startCommunityAuthentication(dbCom) - logger.debug(`Federation: write publicInfo of community: name=${pubComInfo.name}`) + logger.debug(`write publicInfo of community: name=${pubComInfo.name}`) } else { - logger.debug('Federation: missing result of getPublicCommunityInfo') + logger.debug('missing result of getPublicCommunityInfo') } } else { - logger.debug( - 'Federation: received not matching publicKey:', - pubKey, - dbCom.publicKey.toString('hex'), - ) + logger.debug('received not matching publicKey:', pubKey, dbCom.publicKey.toString('hex')) } } } catch (err) { diff --git a/backend/src/graphql/resolver/BalanceResolver.ts b/backend/src/graphql/resolver/BalanceResolver.ts index 2ea34cc5a..f3c7d4709 100644 --- a/backend/src/graphql/resolver/BalanceResolver.ts +++ b/backend/src/graphql/resolver/BalanceResolver.ts @@ -9,9 +9,10 @@ import { RIGHTS } from '@/auth/RIGHTS' import { BalanceLoggingView } from '@/logging/BalanceLogging.view' import { DecayLoggingView } from '@/logging/DecayLogging.view' import { Context, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' import { calculateDecay } from '@/util/decay' +import { getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { GdtResolver } from './GdtResolver' import { getLastTransaction } from './util/getLastTransaction' import { transactionLinkSummary } from './util/transactionLinkSummary' @@ -23,9 +24,10 @@ export class BalanceResolver { async balance(@Ctx() context: Context): Promise { const user = getUser(context) const now = new Date() + const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.BalanceResolver`) logger.addContext('user', user.id) - logger.info(`balance(userId=${user.id})...`) + logger.info(`balance...`) let balanceGDT if (!context.balanceGDT) { diff --git a/backend/src/graphql/resolver/CommunityResolver.test.ts b/backend/src/graphql/resolver/CommunityResolver.test.ts index f636bf53d..428915765 100644 --- a/backend/src/graphql/resolver/CommunityResolver.test.ts +++ b/backend/src/graphql/resolver/CommunityResolver.test.ts @@ -5,7 +5,7 @@ import { DataSource } from 'typeorm' import { v4 as uuidv4 } from 'uuid' import { cleanDB, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' import { userFactory } from '@/seeds/factory/user' import { login, updateHomeCommunityQuery } from '@/seeds/graphql/mutations' @@ -18,10 +18,14 @@ import { } from '@/seeds/graphql/queries' import { peterLustig } from '@/seeds/users/peter-lustig' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { getCommunityByUuid } from './util/communities' jest.mock('@/password/EncryptorUtils') +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.CommunityResolver`) + // to do: We need a setup for the tests that closes the connection let mutate: ApolloServerTestClient['mutate'] let query: ApolloServerTestClient['query'] diff --git a/backend/src/graphql/resolver/ContributionLinkResolver.test.ts b/backend/src/graphql/resolver/ContributionLinkResolver.test.ts index 9c9bdfa55..bf8c37126 100644 --- a/backend/src/graphql/resolver/ContributionLinkResolver.test.ts +++ b/backend/src/graphql/resolver/ContributionLinkResolver.test.ts @@ -5,7 +5,6 @@ import { GraphQLError } from 'graphql' import { DataSource } from 'typeorm' import { cleanDB, resetToken, testEnvironment } from '@test/helpers' -import { logger } from '@test/testSetup' import { EventType } from '@/event/Events' import { userFactory } from '@/seeds/factory/user' @@ -18,9 +17,15 @@ import { import { listContributionLinks } from '@/seeds/graphql/queries' import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' import { peterLustig } from '@/seeds/users/peter-lustig' +import { clearLogs, getLogger, printLogs } from 'config-schema/test/testSetup' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' jest.mock('@/password/EncryptorUtils') +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.ContributionLinkResolver`) +const logErrorLogger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + let mutate: ApolloServerTestClient['mutate'] let query: ApolloServerTestClient['query'] let con: DataSource @@ -286,7 +291,7 @@ describe('Contribution Links', () => { }) it('logs the error "A Start-Date must be set"', () => { - expect(logger.error).toBeCalledWith('A Start-Date must be set') + expect(logErrorLogger.error).toBeCalledWith('A Start-Date must be set') }) it('returns an error if missing endDate', async () => { @@ -307,7 +312,7 @@ describe('Contribution Links', () => { }) it('logs the error "An End-Date must be set"', () => { - expect(logger.error).toBeCalledWith('An End-Date must be set') + expect(logErrorLogger.error).toBeCalledWith('An End-Date must be set') }) it('returns an error if endDate is before startDate', async () => { @@ -331,7 +336,7 @@ describe('Contribution Links', () => { }) it('logs the error "The value of validFrom must before or equals the validTo"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( `The value of validFrom must before or equals the validTo`, ) }) @@ -531,7 +536,7 @@ describe('Contribution Links', () => { }) it('logs the error "Contribution Link not found"', () => { - expect(logger.error).toBeCalledWith('Contribution Link not found', -1) + expect(logErrorLogger.error).toBeCalledWith('Contribution Link not found', -1) }) describe('valid id', () => { @@ -613,7 +618,7 @@ describe('Contribution Links', () => { }) it('logs the error "Contribution Link not found"', () => { - expect(logger.error).toBeCalledWith('Contribution Link not found', -1) + expect(logErrorLogger.error).toBeCalledWith('Contribution Link not found', -1) }) }) diff --git a/backend/src/graphql/resolver/ContributionMessageResolver.test.ts b/backend/src/graphql/resolver/ContributionMessageResolver.test.ts index 00b7032dc..16ad4dbb2 100644 --- a/backend/src/graphql/resolver/ContributionMessageResolver.test.ts +++ b/backend/src/graphql/resolver/ContributionMessageResolver.test.ts @@ -5,7 +5,7 @@ import { DataSource } from 'typeorm' import { ContributionStatus } from '@enum/ContributionStatus' import { cleanDB, resetToken, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' import { sendAddedContributionMessageEmail } from '@/emails/sendEmailVariants' import { EventType } from '@/event/Events' @@ -20,6 +20,14 @@ import { adminListContributionMessages, listContributionMessages } from '@/seeds import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' import { bobBaumeister } from '@/seeds/users/bob-baumeister' import { peterLustig } from '@/seeds/users/peter-lustig' +import { clearLogs, getLogger, printLogs } from 'config-schema/test/testSetup' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { LOG4JS_INTERACTION_CATEGORY_NAME } from '@/interactions' + +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.ContributionMessageResolver`) +const logErrorLogger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) +const interactionLogger = getLogger(`${LOG4JS_INTERACTION_CATEGORY_NAME}.updateUnconfirmedContribution`) jest.mock('@/password/EncryptorUtils') jest.mock('@/emails/sendEmailVariants', () => { @@ -121,7 +129,7 @@ describe('ContributionMessageResolver', () => { }) it('logs the error "ContributionMessage was not sent successfully: Error: Contribution not found"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'ContributionMessage was not sent successfully: Error: Contribution not found', new Error('Contribution not found'), ) @@ -148,11 +156,7 @@ describe('ContributionMessageResolver', () => { message: 'Test', }, }) - expect(logger.debug).toBeCalledTimes(5) - expect(logger.debug).toHaveBeenNthCalledWith( - 5, - 'use UnconfirmedContributionUserAddMessageRole', - ) + expect(interactionLogger.debug).toBeCalledWith('use UnconfirmedContributionUserAddMessageRole') expect(mutationResult).toEqual( expect.objectContaining({ data: { @@ -325,7 +329,7 @@ describe('ContributionMessageResolver', () => { }) it('logs the error "ContributionMessage was not sent successfully: Error: Contribution not found"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'ContributionMessage was not sent successfully: Error: Contribution not found', new Error('Contribution not found'), ) @@ -346,11 +350,7 @@ describe('ContributionMessageResolver', () => { }, }) - expect(logger.debug).toBeCalledTimes(5) - expect(logger.debug).toHaveBeenNthCalledWith( - 5, - 'use UnconfirmedContributionAdminAddMessageRole', - ) + expect(interactionLogger.debug).toBeCalledWith('use UnconfirmedContributionAdminAddMessageRole') expect(mutationResult).toEqual( expect.objectContaining({ @@ -380,12 +380,7 @@ describe('ContributionMessageResolver', () => { message: 'Test', }, }) - - expect(logger.debug).toBeCalledTimes(5) - expect(logger.debug).toHaveBeenNthCalledWith( - 5, - 'use UnconfirmedContributionAdminAddMessageRole', - ) + expect(interactionLogger.debug).toBeCalledWith('use UnconfirmedContributionAdminAddMessageRole') expect(mutationResult).toEqual( expect.objectContaining({ @@ -399,13 +394,12 @@ describe('ContributionMessageResolver', () => { }) it('logs the error "ContributionMessage was not sent successfully: Error: missing right ADMIN_CREATE_CONTRIBUTION_MESSAGE for user"', () => { - expect(logger.debug).toBeCalledTimes(5) - expect(logger.error).toHaveBeenNthCalledWith( + expect(logErrorLogger.error).toHaveBeenNthCalledWith( 1, 'missing right ADMIN_CREATE_CONTRIBUTION_MESSAGE for user', expect.any(Number), ) - expect(logger.error).toHaveBeenNthCalledWith( + expect(logErrorLogger.error).toHaveBeenNthCalledWith( 2, 'ContributionMessage was not sent successfully: Error: missing right ADMIN_CREATE_CONTRIBUTION_MESSAGE for user', new Error('missing right ADMIN_CREATE_CONTRIBUTION_MESSAGE for user'), diff --git a/backend/src/graphql/resolver/ContributionMessageResolver.ts b/backend/src/graphql/resolver/ContributionMessageResolver.ts index c1d25bd19..4444a0ef0 100644 --- a/backend/src/graphql/resolver/ContributionMessageResolver.ts +++ b/backend/src/graphql/resolver/ContributionMessageResolver.ts @@ -22,11 +22,12 @@ import { import { UpdateUnconfirmedContributionContext } from '@/interactions/updateUnconfirmedContribution/UpdateUnconfirmedContribution.context' import { LogError } from '@/server/LogError' import { Context, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' - +import { getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { findContributionMessages } from './util/findContributionMessages' const db = AppDatabase.getInstance() +const createLogger = () => getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.ContributionMessageResolver`) @Resolver() export class ContributionMessageResolver { @@ -125,7 +126,9 @@ export class ContributionMessageResolver { @Args() contributionMessageArgs: ContributionMessageArgs, @Ctx() context: Context, ): Promise { + const logger = createLogger() const { contributionId, messageType } = contributionMessageArgs + logger.addContext('contribution', contributionMessageArgs.contributionId) const updateUnconfirmedContributionContext = new UpdateUnconfirmedContributionContext( contributionId, contributionMessageArgs, diff --git a/backend/src/graphql/resolver/ContributionResolver.test.ts b/backend/src/graphql/resolver/ContributionResolver.test.ts index 02ec62748..77e879f8d 100644 --- a/backend/src/graphql/resolver/ContributionResolver.test.ts +++ b/backend/src/graphql/resolver/ContributionResolver.test.ts @@ -14,7 +14,7 @@ import { resetToken, testEnvironment, } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' import { sendContributionConfirmedEmail, @@ -50,10 +50,15 @@ import { peterLustig } from '@/seeds/users/peter-lustig' import { raeuberHotzenplotz } from '@/seeds/users/raeuber-hotzenplotz' import { stephenHawking } from '@/seeds/users/stephen-hawking' import { getFirstDayOfPreviousNMonth } from '@/util/utilities' +import { getLogger, clearLogs, printLogs } from 'config-schema/test/testSetup' +import { getLogger as originalGetLogger } from 'log4js' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' jest.mock('@/emails/sendEmailVariants') jest.mock('@/password/EncryptorUtils') +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError` ) + let mutate: ApolloServerTestClient['mutate'] let query: ApolloServerTestClient['query'] let con: DataSource @@ -72,7 +77,7 @@ let contributionToDelete: any let bibiCreatedContribution: Contribution beforeAll(async () => { - testEnv = await testEnvironment(logger, localization) + testEnv = await testEnvironment(originalGetLogger('apollo'), localization) mutate = testEnv.mutate query = testEnv.query con = testEnv.con diff --git a/backend/src/graphql/resolver/ContributionResolver.ts b/backend/src/graphql/resolver/ContributionResolver.ts index 32bb0ff82..328a70dc7 100644 --- a/backend/src/graphql/resolver/ContributionResolver.ts +++ b/backend/src/graphql/resolver/ContributionResolver.ts @@ -7,7 +7,7 @@ import { import { Decimal } from 'decimal.js-light' import { GraphQLResolveInfo } from 'graphql' import { Arg, Args, Authorized, Ctx, Info, Int, Mutation, Query, Resolver } from 'type-graphql' -import { EntityManager, IsNull, getConnection } from 'typeorm' +import { EntityManager, IsNull } from 'typeorm' import { AdminCreateContributionArgs } from '@arg/AdminCreateContributionArgs' import { AdminUpdateContributionArgs } from '@arg/AdminUpdateContributionArgs' @@ -43,13 +43,14 @@ import { import { UpdateUnconfirmedContributionContext } from '@/interactions/updateUnconfirmedContribution/UpdateUnconfirmedContribution.context' import { LogError } from '@/server/LogError' import { Context, getClientTimezoneOffset, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' import { TRANSACTIONS_LOCK } from '@/util/TRANSACTIONS_LOCK' import { calculateDecay } from '@/util/decay' import { fullName } from '@/util/utilities' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '@/graphql/resolver' +import { ContributionMessageType } from '@enum/ContributionMessageType' import { AppDatabase } from 'database' -import { ContributionMessageType } from '../enum/ContributionMessageType' +import { getLogger } from 'log4js' import { loadAllContributions, loadUserContributions } from './util/contributions' import { getOpenCreations, getUserCreation, validateContribution } from './util/creations' import { extractGraphQLFields } from './util/extractGraphQLFields' @@ -58,6 +59,7 @@ import { getLastTransaction } from './util/getLastTransaction' import { sendTransactionsToDltConnector } from './util/sendTransactionsToDltConnector' const db = AppDatabase.getInstance() +const createLogger = () => getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.ContributionResolver`) @Resolver(() => Contribution) export class ContributionResolver { @@ -81,6 +83,8 @@ export class ContributionResolver { const user = getUser(context) const creations = await getUserCreation(user.id, clientTimezoneOffset) + const logger = createLogger() + logger.addContext('user', user.id) logger.trace('creations', creations) const contributionDateObj = new Date(contributionDate) validateContribution(creations, amount, contributionDateObj, clientTimezoneOffset) @@ -211,6 +215,8 @@ export class ContributionResolver { @Args() { email, amount, memo, creationDate }: AdminCreateContributionArgs, @Ctx() context: Context, ): Promise { + const logger = createLogger() + logger.addContext('admin', context.user?.id) logger.info( `adminCreateContribution(email=${email}, amount=${amount.toString()}, memo=${memo}, creationDate=${creationDate})`, ) @@ -262,6 +268,8 @@ export class ContributionResolver { @Args() adminUpdateContributionArgs: AdminUpdateContributionArgs, @Ctx() context: Context, ): Promise { + const logger = createLogger() + logger.addContext('contribution', adminUpdateContributionArgs.id) const updateUnconfirmedContributionContext = new UpdateUnconfirmedContributionContext( adminUpdateContributionArgs.id, adminUpdateContributionArgs, @@ -273,7 +281,6 @@ export class ContributionResolver { await transactionalEntityManager.save(contribution) // TODO: move into specialized view or formatting for logging class logger.debug('saved changed contribution', { - id: contribution.id, amount: contribution.amount.toString(), memo: contribution.memo, contributionDate: contribution.contributionDate.toString(), @@ -284,7 +291,6 @@ export class ContributionResolver { await transactionalEntityManager.save(contributionMessage) // TODO: move into specialized view or formatting for logging class logger.debug('save new contributionMessage', { - contributionId: contributionMessage.contributionId, type: contributionMessage.type, message: contributionMessage.message, isModerator: contributionMessage.isModerator, @@ -416,6 +422,9 @@ export class ContributionResolver { @Arg('id', () => Int) id: number, @Ctx() context: Context, ): Promise { + const logger = createLogger() + logger.addContext('contribution', id) + // acquire lock const releaseLock = await TRANSACTIONS_LOCK.acquire() try { diff --git a/backend/src/graphql/resolver/EmailOptinCodes.test.ts b/backend/src/graphql/resolver/EmailOptinCodes.test.ts index 37bf6cc8b..b916d23b6 100644 --- a/backend/src/graphql/resolver/EmailOptinCodes.test.ts +++ b/backend/src/graphql/resolver/EmailOptinCodes.test.ts @@ -101,6 +101,7 @@ describe('EmailOptinCodes', () => { describe('forgotPassword', () => { it('throws an error', async () => { + await mutate({ mutation: forgotPassword, variables: { email: 'peter@lustig.de' } }) await expect( mutate({ mutation: forgotPassword, variables: { email: 'peter@lustig.de' } }), ).resolves.toMatchObject({ diff --git a/backend/src/graphql/resolver/GdtResolver.ts b/backend/src/graphql/resolver/GdtResolver.ts index 933fdb397..9d7451ed8 100644 --- a/backend/src/graphql/resolver/GdtResolver.ts +++ b/backend/src/graphql/resolver/GdtResolver.ts @@ -10,8 +10,10 @@ import { RIGHTS } from '@/auth/RIGHTS' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' import { Context, getUser } from '@/server/context' +import { getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' -import { backendLogger as logger } from '@/server/logger' +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.GdtResolver`) @Resolver() export class GdtResolver { diff --git a/backend/src/graphql/resolver/KlicktippResolver.test.ts b/backend/src/graphql/resolver/KlicktippResolver.test.ts index 6e6cdefca..10ef6a760 100644 --- a/backend/src/graphql/resolver/KlicktippResolver.test.ts +++ b/backend/src/graphql/resolver/KlicktippResolver.test.ts @@ -2,15 +2,19 @@ import { Event as DbEvent, UserContact } from 'database' import { GraphQLError } from 'graphql' import { cleanDB, resetToken, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' +import { getLogger } from 'config-schema/test/testSetup' import { EventType } from '@/event/Events' import { userFactory } from '@/seeds/factory/user' import { login, subscribeNewsletter, unsubscribeNewsletter } from '@/seeds/graphql/mutations' import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' jest.mock('@/password/EncryptorUtils') +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.KlicktippResolver`) + let testEnv: any let mutate: any let con: any diff --git a/backend/src/graphql/resolver/ProjectBrandingResolver.ts b/backend/src/graphql/resolver/ProjectBrandingResolver.ts index 3742ac2c4..a7ef1c8b8 100644 --- a/backend/src/graphql/resolver/ProjectBrandingResolver.ts +++ b/backend/src/graphql/resolver/ProjectBrandingResolver.ts @@ -9,7 +9,10 @@ import { SpaceList } from '@model/SpaceList' import { HumHubClient } from '@/apis/humhub/HumHubClient' import { RIGHTS } from '@/auth/RIGHTS' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' + +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.ProjectBrandingResolver`) @Resolver(() => ProjectBranding) export class ProjectBrandingResolver { diff --git a/backend/src/graphql/resolver/TransactionLinkResolver.test.ts b/backend/src/graphql/resolver/TransactionLinkResolver.test.ts index 92c147389..f0107dcdd 100644 --- a/backend/src/graphql/resolver/TransactionLinkResolver.test.ts +++ b/backend/src/graphql/resolver/TransactionLinkResolver.test.ts @@ -12,7 +12,6 @@ import { DataSource } from 'typeorm' import { UnconfirmedContribution } from '@model/UnconfirmedContribution' import { cleanDB, resetEntity, resetToken, testEnvironment } from '@test/helpers' -import { logger } from '@test/testSetup' import { EventType } from '@/event/Events' import { creations } from '@/seeds/creation/index' @@ -35,8 +34,14 @@ import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' import { peterLustig } from '@/seeds/users/peter-lustig' import { TRANSACTIONS_LOCK } from '@/util/TRANSACTIONS_LOCK' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { transactionLinkCode } from './TransactionLinkResolver' +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.TransactionLinkResolver`) +const logErrorLogger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + jest.mock('@/password/EncryptorUtils') // mock semaphore to allow use fake timers @@ -221,7 +226,7 @@ describe('TransactionLinkResolver', () => { }) }) it('logs the error "User has not enough GDD"', () => { - expect(logger.error).toBeCalledWith('User has not enough GDD', expect.any(Number)) + expect(logErrorLogger.error).toBeCalledWith('User has not enough GDD', expect.any(Number)) }) }) }) @@ -273,11 +278,11 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "No contribution link found to given code"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'No contribution link found to given code', 'CL-123456', ) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('No contribution link found to given code'), ) @@ -317,8 +322,8 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Contribution link is not valid yet"', () => { - expect(logger.error).toBeCalledWith('Contribution link is not valid yet', validFrom) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith('Contribution link is not valid yet', validFrom) + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('Contribution link is not valid yet'), ) @@ -356,8 +361,8 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Contribution link has unknown cycle"', () => { - expect(logger.error).toBeCalledWith('Contribution link has unknown cycle', 'INVALID') - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith('Contribution link has unknown cycle', 'INVALID') + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('Contribution link has unknown cycle'), ) @@ -395,8 +400,8 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Contribution link is no longer valid"', () => { - expect(logger.error).toBeCalledWith('Contribution link is no longer valid', validTo) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith('Contribution link is no longer valid', validTo) + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('Contribution link is no longer valid'), ) @@ -491,7 +496,7 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Creation from contribution link was not successful"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error( 'The amount to be created exceeds the amount still available for this month', @@ -566,7 +571,7 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Creation from contribution link was not successful"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('Contribution link already redeemed today'), ) @@ -618,7 +623,7 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Creation from contribution link was not successful"', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Creation from contribution link was not successful', new Error('Contribution link already redeemed today'), ) @@ -652,7 +657,7 @@ describe('TransactionLinkResolver', () => { ).resolves.toMatchObject({ errors: [new GraphQLError('Transaction link not found')], }) - expect(logger.error).toBeCalledWith('Transaction link not found', 'not-valid') + expect(logErrorLogger.error).toBeCalledWith('Transaction link not found', 'not-valid') }) }) @@ -723,7 +728,7 @@ describe('TransactionLinkResolver', () => { ).resolves.toMatchObject({ errors: [new GraphQLError('Cannot redeem own transaction link')], }) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Cannot redeem own transaction link', expect.any(Number), ) @@ -927,7 +932,7 @@ describe('TransactionLinkResolver', () => { }) it('logs the error "Could not find requested User"', () => { - expect(logger.error).toBeCalledWith('Could not find requested User', -1) + expect(logErrorLogger.error).toBeCalledWith('Could not find requested User', -1) }) }) diff --git a/backend/src/graphql/resolver/TransactionLinkResolver.ts b/backend/src/graphql/resolver/TransactionLinkResolver.ts index 01be0fef1..34c073e45 100644 --- a/backend/src/graphql/resolver/TransactionLinkResolver.ts +++ b/backend/src/graphql/resolver/TransactionLinkResolver.ts @@ -24,7 +24,6 @@ import { } from 'database' import { Decimal } from 'decimal.js-light' import { Arg, Args, Authorized, Ctx, Int, Mutation, Query, Resolver } from 'type-graphql' -import { getConnection } from 'typeorm' import { RIGHTS } from '@/auth/RIGHTS' import { decode, encode, verify } from '@/auth/jwt/JWT' @@ -37,7 +36,6 @@ import { } from '@/event/Events' import { LogError } from '@/server/LogError' import { Context, getClientTimezoneOffset, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' import { TRANSACTIONS_LOCK } from '@/util/TRANSACTIONS_LOCK' import { TRANSACTION_LINK_LOCK } from '@/util/TRANSACTION_LINK_LOCK' import { calculateDecay } from '@/util/decay' @@ -45,6 +43,8 @@ import { fullName } from '@/util/utilities' import { calculateBalance } from '@/util/validate' import { DisburseJwtPayloadType } from '@/auth/jwt/payloadtypes/DisburseJwtPayloadType' +import { Logger, getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { executeTransaction } from './TransactionResolver' import { getAuthenticatedCommunities, @@ -56,6 +56,8 @@ import { getLastTransaction } from './util/getLastTransaction' import { sendTransactionsToDltConnector } from './util/sendTransactionsToDltConnector' import { transactionLinkList } from './util/transactionLinkList' +const createLogger = () => getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.TransactionLinkResolver`) + // TODO: do not export, test it inside the resolver export const transactionLinkCode = (date: Date): string => { const time = date.getTime().toString(16) @@ -149,7 +151,9 @@ export class TransactionLinkResolver { @Authorized([RIGHTS.QUERY_TRANSACTION_LINK]) @Query(() => QueryLinkResult) async queryTransactionLink(@Arg('code') code: string): Promise { - logger.debug('TransactionLinkResolver.queryTransactionLink... code=', code) + const logger = createLogger() + logger.addContext('code', code.substring(0, 6)) + logger.debug('TransactionLinkResolver.queryTransactionLink...') if (code.match(/^CL-/)) { const contributionLink = await DbContributionLink.findOneOrFail({ where: { code: code.replace('CL-', '') }, @@ -185,7 +189,7 @@ export class TransactionLinkResolver { return new TransactionLink(dbTransactionLink, new User(user), redeemedBy, communities) } else { // redeem jwt-token - return await this.queryRedeemJwtLink(code) + return await this.queryRedeemJwtLink(code, logger) } } } @@ -196,6 +200,8 @@ export class TransactionLinkResolver { @Arg('code', () => String) code: string, @Ctx() context: Context, ): Promise { + const logger = createLogger() + logger.addContext('code', code.substring(0, 6)) const clientTimezoneOffset = getClientTimezoneOffset(context) // const homeCom = await DbCommunity.findOneOrFail({ where: { foreign: false } }) const user = getUser(context) @@ -380,6 +386,7 @@ export class TransactionLinkResolver { transactionLink.memo, linkedUser, user, + logger, transactionLink, ) await EVENT_TRANSACTION_LINK_REDEEM( @@ -409,6 +416,8 @@ export class TransactionLinkResolver { @Arg('alias', { nullable: true }) alias?: string, @Arg('validUntil', { nullable: true }) validUntil?: string, ): Promise { + const logger = createLogger() + logger.addContext('code', code.substring(0, 6)) logger.debug('TransactionLinkResolver.queryRedeemJwt... args=', { gradidoId, senderCommunityUuid, @@ -457,6 +466,8 @@ export class TransactionLinkResolver { @Arg('validUntil', { nullable: true }) validUntil?: string, @Arg('recipientAlias', { nullable: true }) recipientAlias?: string, ): Promise { + const logger = createLogger() + logger.addContext('code', code.substring(0, 6)) logger.debug('TransactionLinkResolver.disburseTransactionLink... args=', { senderGradidoId, senderCommunityUuid, @@ -528,7 +539,7 @@ export class TransactionLinkResolver { return transactionLinkList(paginated, filters, user) } - async queryRedeemJwtLink(code: string): Promise { + async queryRedeemJwtLink(code: string, logger: Logger): Promise { logger.debug('TransactionLinkResolver.queryRedeemJwtLink... redeem jwt-token found') // decode token first to get the senderCommunityUuid as input for verify token const decodedPayload = decode(code) @@ -653,6 +664,8 @@ export class TransactionLinkResolver { validUntil: string, recipientAlias: string, ): Promise { + const logger = createLogger() + logger.addContext('code', code.substring(0, 6)) logger.debug('TransactionLinkResolver.createDisburseJwt... args=', { senderCommunityUuid, senderGradidoId, diff --git a/backend/src/graphql/resolver/TransactionResolver.test.ts b/backend/src/graphql/resolver/TransactionResolver.test.ts index d164cd5a8..dd0983efc 100644 --- a/backend/src/graphql/resolver/TransactionResolver.test.ts +++ b/backend/src/graphql/resolver/TransactionResolver.test.ts @@ -8,11 +8,10 @@ import { User, } from 'database' import { GraphQLError } from 'graphql' -import { Connection, In } from 'typeorm' +import { DataSource, In } from 'typeorm' import { v4 as uuidv4 } from 'uuid' import { cleanDB, testEnvironment } from '@test/helpers' -import { logger } from '@test/testSetup' import { CONFIG } from '@/config' import { EventType } from '@/event/Events' @@ -32,16 +31,20 @@ import { bobBaumeister } from '@/seeds/users/bob-baumeister' import { garrickOllivander } from '@/seeds/users/garrick-ollivander' import { peterLustig } from '@/seeds/users/peter-lustig' import { stephenHawking } from '@/seeds/users/stephen-hawking' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' jest.mock('@/password/EncryptorUtils') +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + let mutate: ApolloServerTestClient['mutate'] let query: ApolloServerTestClient['query'] -let con: Connection +let con: DataSource let testEnv: { mutate: ApolloServerTestClient['mutate'] query: ApolloServerTestClient['query'] - con: Connection + con: DataSource } beforeAll(async () => { @@ -477,8 +480,6 @@ describe('send coins', () => { }) it('has wait till sendTransactionsToDltConnector created all dlt-transactions', () => { - expect(logger.info).toBeCalledWith('sendTransactionsToDltConnector...') - expect(dltTransactions).toEqual( expect.arrayContaining([ expect.objectContaining({ diff --git a/backend/src/graphql/resolver/TransactionResolver.ts b/backend/src/graphql/resolver/TransactionResolver.ts index b842a2d34..511c7167d 100644 --- a/backend/src/graphql/resolver/TransactionResolver.ts +++ b/backend/src/graphql/resolver/TransactionResolver.ts @@ -29,13 +29,14 @@ import { EVENT_TRANSACTION_RECEIVE, EVENT_TRANSACTION_SEND } from '@/event/Event import { SendCoinsResult } from '@/federation/client/1_0/model/SendCoinsResult' import { LogError } from '@/server/LogError' import { Context, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' import { TRANSACTIONS_LOCK } from '@/util/TRANSACTIONS_LOCK' import { communityUser } from '@/util/communityUser' import { fullName } from '@/util/utilities' import { calculateBalance } from '@/util/validate' import { virtualDecayTransaction, virtualLinkTransaction } from '@/util/virtualTransactions' +import { Logger, getLogger } from 'log4js' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { BalanceResolver } from './BalanceResolver' import { GdtResolver } from './GdtResolver' import { getCommunityByIdentifier, getCommunityName, isHomeCommunity } from './util/communities' @@ -51,16 +52,19 @@ import { storeForeignUser } from './util/storeForeignUser' import { transactionLinkSummary } from './util/transactionLinkSummary' const db = AppDatabase.getInstance() +const createLogger = () => getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.TransactionResolver`) export const executeTransaction = async ( amount: Decimal, memo: string, sender: dbUser, recipient: dbUser, + logger: Logger, transactionLink?: dbTransactionLink | null, ): Promise => { // acquire lock const releaseLock = await TRANSACTIONS_LOCK.acquire() + try { logger.info('executeTransaction', amount, memo, sender, recipient) @@ -228,9 +232,9 @@ export class TransactionResolver { ): Promise { const now = new Date() const user = getUser(context) - + const logger = createLogger() logger.addContext('user', user.id) - logger.info(`transactionList(user=${user.firstName}.${user.lastName}, ${user.emailId})`) + logger.info(`transactionList`) let balanceGDTPromise: Promise = Promise.resolve(null) if (CONFIG.GDT_ACTIVE) { @@ -240,7 +244,7 @@ export class TransactionResolver { // find current balance const lastTransaction = await getLastTransaction(user.id) - logger.debug(`lastTransaction=${lastTransaction}`) + logger.debug(`lastTransaction=${lastTransaction?.id}`) const balanceResolver = new BalanceResolver() context.lastTransaction = lastTransaction @@ -288,10 +292,10 @@ export class TransactionResolver { }, ], }) - logger.debug('found dbRemoteUser:', dbRemoteUser) + logger.debug(`found dbRemoteUser: ${dbRemoteUser?.id}`) const remoteUser = new User(dbRemoteUser) if (dbRemoteUser === null) { - logger.debug('no dbRemoteUser found, init from tx:', transaction) + logger.debug(`no dbRemoteUser found, init from tx: ${transaction.id}`) if (transaction.linkedUserCommunityUuid !== null) { remoteUser.communityUuid = transaction.linkedUserCommunityUuid } @@ -312,7 +316,10 @@ export class TransactionResolver { } } logger.debug(`involvedUserIds=`, involvedUserIds) - logger.debug(`involvedRemoteUsers=`, involvedRemoteUsers) + logger.debug( + `involvedRemoteUsers=`, + involvedRemoteUsers.map((u) => u.id), + ) // We need to show the name for deleted users for old transactions const involvedDbUsers = await dbUser.find({ @@ -321,7 +328,10 @@ export class TransactionResolver { relations: ['emailContact'], }) const involvedUsers = involvedDbUsers.map((u) => new User(u)) - logger.debug(`involvedUsers=`, involvedUsers) + logger.debug( + `involvedUsers=`, + involvedUsers.map((u) => u.id), + ) const self = new User(user) const transactions: Transaction[] = [] @@ -332,11 +342,11 @@ export class TransactionResolver { context.linkCount = transactionLinkcount logger.debug(`transactionLinkcount=${transactionLinkcount}`) context.sumHoldAvailableAmount = sumHoldAvailableAmount - logger.debug(`sumHoldAvailableAmount=${sumHoldAvailableAmount}`) + logger.debug(`sumHoldAvailableAmount=${sumHoldAvailableAmount.toString()}`) // decay & link transactions if (currentPage === 1 && order === Order.DESC) { - logger.debug(`currentPage == 1: transactions=${transactions}`) + logger.debug(`currentPage == 1: transactions=${transactions.map((t) => t.id)}`) // The virtual decay is always on the booked amount, not including the generated, not yet booked links, // since the decay is substantially different when the amount is less transactions.push( @@ -348,7 +358,7 @@ export class TransactionResolver { sumHoldAvailableAmount, ), ) - logger.debug(`transactions=${transactions}`) + logger.debug(`transactions=${transactions.map((t) => t.id)}`) // virtual transaction for pending transaction-links sum if (sumHoldAvailableAmount.isZero()) { @@ -373,7 +383,7 @@ export class TransactionResolver { ) } } else if (sumHoldAvailableAmount.greaterThan(0)) { - logger.debug(`sumHoldAvailableAmount > 0: transactions=${transactions}`) + logger.debug(`sumHoldAvailableAmount > 0: transactions=${transactions.map((t) => t.id)}`) transactions.push( virtualLinkTransaction( lastTransaction.balance.minus(sumHoldAvailableAmount.toString()), @@ -386,7 +396,7 @@ export class TransactionResolver { (userTransactions.length && userTransactions[0].balance) || new Decimal(0), ), ) - logger.debug(`transactions=`, transactions) + logger.debug(`transactions=${transactions.map((t) => t.id)}`) } } @@ -401,19 +411,22 @@ export class TransactionResolver { let linkedUser: User | undefined if ((userTransaction.typeId as TransactionTypeId) === TransactionTypeId.CREATION) { linkedUser = communityUser - logger.debug('CREATION-linkedUser=', linkedUser) + logger.debug(`CREATION-linkedUser=${linkedUser.id}`) } else if (userTransaction.linkedUserId) { linkedUser = involvedUsers.find((u) => u.id === userTransaction.linkedUserId) - logger.debug('local linkedUser=', linkedUser) + logger.debug(`local linkedUser=${linkedUser?.id}`) } else if (userTransaction.linkedUserCommunityUuid) { linkedUser = involvedRemoteUsers.find( (u) => u.gradidoID === userTransaction.linkedUserGradidoID, ) - logger.debug('remote linkedUser=', linkedUser) + logger.debug(`remote linkedUser=${linkedUser?.id}`) } transactions.push(new Transaction(userTransaction, self, linkedUser)) }) - logger.debug(`TransactionTypeId.CREATION: transactions=`, transactions) + logger.debug( + `TransactionTypeId.CREATION: transactions=`, + transactions.map((t) => t.id), + ) transactions.forEach((transaction: Transaction) => { if (transaction.typeId !== TransactionTypeId.DECAY) { @@ -439,6 +452,9 @@ export class TransactionResolver { { recipientCommunityIdentifier, recipientIdentifier, amount, memo }: TransactionSendArgs, @Ctx() context: Context, ): Promise { + const logger = createLogger() + logger.addContext('from', context.user?.id) + logger.addContext('amount', amount.toString()) logger.debug( `sendCoins(recipientCommunityIdentifier=${recipientCommunityIdentifier}, recipientIdentifier=${recipientIdentifier}, amount=${amount}, memo=${memo})`, ) @@ -454,28 +470,28 @@ export class TransactionResolver { if (!recipientUser) { throw new LogError('The recipient user was not found', recipientUser) } + logger.addContext('to', recipientUser?.id) if (recipientUser.foreign) { throw new LogError('Found foreign recipient user for a local transaction:', recipientUser) } - await executeTransaction(amount, memo, senderUser, recipientUser) - logger.info('successful executeTransaction', amount, memo, senderUser, recipientUser) + await executeTransaction(amount, memo, senderUser, recipientUser, logger) + logger.info('successful executeTransaction') } else { // processing a x-community sendCoins - logger.debug('X-Com: processing a x-community transaction...') + logger.info('X-Com: processing a x-community transaction...') if (!CONFIG.FEDERATION_XCOM_SENDCOINS_ENABLED) { throw new LogError('X-Community sendCoins disabled per configuration!') } const recipCom = await getCommunityByIdentifier(recipientCommunityIdentifier) - logger.debug('recipient commuity: ', recipCom) + logger.debug('recipient community: ', recipCom?.id) if (recipCom === null) { throw new LogError( - 'no recipient commuity found for identifier:', - recipientCommunityIdentifier, + `no recipient community found for identifier: ${recipientCommunityIdentifier}`, ) } if (recipCom !== null && recipCom.authenticatedAt === null) { - throw new LogError('recipient commuity is connected, but still not authenticated yet!') + throw new LogError('recipient community is connected, but still not authenticated yet!') } let pendingResult: SendCoinsResult let committingResult: SendCoinsResult diff --git a/backend/src/graphql/resolver/UserResolver.test.ts b/backend/src/graphql/resolver/UserResolver.test.ts index e6c38c442..0edcf30cf 100644 --- a/backend/src/graphql/resolver/UserResolver.test.ts +++ b/backend/src/graphql/resolver/UserResolver.test.ts @@ -20,7 +20,7 @@ import { UserContactType } from '@enum/UserContactType' import { ContributionLink } from '@model/ContributionLink' import { Location } from '@model/Location' import { cleanDB, headerPushMock, resetToken, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' import { subscribe } from '@/apis/KlicktippController' import { CONFIG } from '@/config' @@ -67,7 +67,10 @@ import { stephenHawking } from '@/seeds/users/stephen-hawking' import { printTimeDuration } from '@/util/time' import { objectValuesToArray } from '@/util/utilities' +import { clearLogs, getLogger, printLogs } from 'config-schema/test/testSetup' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '.' import { Location2Point } from './util/Location2Point' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' jest.mock('@/apis/humhub/HumHubClient') jest.mock('@/password/EncryptorUtils') @@ -93,6 +96,9 @@ jest.mock('@/apis/KlicktippController', () => { } }) +const logger = getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.UserResolver`) +const logErrorLogger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + CONFIG.EMAIL_CODE_REQUEST_TIME = 10 let admin: User @@ -275,7 +281,8 @@ describe('UserResolver', () => { }) it('logs an info', () => { - expect(logger.info).toBeCalledWith('User already exists with this email=peter@lustig.de') + expect(logger.info).toBeCalledWith('User already exists') + expect(logger.addContext).toBeCalledWith('user', user[0].id) }) it('sends an account multi registration email', () => { @@ -642,7 +649,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Please enter a valid password with at least 8 characters, upper and lower case letters, at least one number and one special character!', ) }) @@ -672,7 +679,7 @@ describe('UserResolver', () => { }) it('logs the error found', () => { - expect(logger.error).toBeCalledWith('Could not login with emailVerificationCode') + expect(logger.warn).toBeCalledWith('invalid emailVerificationCode=not valid') }) }) }) @@ -693,7 +700,8 @@ describe('UserResolver', () => { describe('no users in database', () => { it('throws an error', async () => { jest.clearAllMocks() - expect(await mutate({ mutation: login, variables })).toEqual( + const result = await mutate({ mutation: login, variables }) + expect(result).toEqual( expect.objectContaining({ errors: [new GraphQLError('No user with this credentials')], }), @@ -701,7 +709,7 @@ describe('UserResolver', () => { }) it('logs the error found', () => { - expect(logger.error).toBeCalledWith('No user with this credentials', variables.email) + expect(logger.warn).toBeCalledWith(`findUserByEmail failed, user with email=${variables.email} not found`) }) }) @@ -782,8 +790,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('No user with this credentials', variables.email) + it('logs warning before error is thrown', () => { + expect(logger.warn).toBeCalledWith('login failed, wrong password') }) }) @@ -813,14 +821,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( - 'This user was permanently deleted. Contact support for questions', - expect.objectContaining({ - firstName: stephenHawking.firstName, - lastName: stephenHawking.lastName, - }), - ) + it('logs warning before error is thrown', () => { + expect(logger.warn).toBeCalledWith('login failed, user was deleted') }) }) @@ -848,14 +850,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( - 'The Users email is not validate yet', - expect.objectContaining({ - firstName: garrickOllivander.firstName, - lastName: garrickOllivander.lastName, - }), - ) + it('logs warning before error is thrown', () => { + expect(logger.warn).toBeCalledWith('login failed, user email not checked') }) }) @@ -881,14 +877,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( - 'The User has not set a password yet', - expect.objectContaining({ - firstName: bibiBloxberg.firstName, - lastName: bibiBloxberg.lastName, - }), - ) + it('logs warning before error is thrown', () => { + expect(logger.warn).toBeCalledWith('login failed, user has not set a password yet') }) }) }) @@ -1114,7 +1104,7 @@ describe('UserResolver', () => { }) describe('request reset password again', () => { - it('thows an error', async () => { + it('throws an error', async () => { CONFIG.EMAIL_CODE_REQUEST_TIME = emailCodeRequestTime await expect(mutate({ mutation: forgotPassword, variables })).resolves.toEqual( expect.objectContaining({ @@ -1123,8 +1113,8 @@ describe('UserResolver', () => { ) }) - it('logs the error found', () => { - expect(logger.error).toBeCalledWith(`Email already sent less than 10 minutes ago`) + it('logs warning before throwing error', () => { + expect(logger.warn).toBeCalledWith('email already sent 0 minutes ago, min wait time: 10 minutes') }) }) }) @@ -1374,13 +1364,13 @@ describe('UserResolver', () => { }), ).resolves.toEqual( expect.objectContaining({ - errors: [new GraphQLError('Given language is not a valid language')], + errors: [new GraphQLError('Given language is not a valid language or not supported')], }), ) }) it('logs the error found', () => { - expect(logger.error).toBeCalledWith('Given language is not a valid language', 'not-valid') + expect(logger.warn).toBeCalledWith('try to set unsupported language', 'not-valid') }) }) @@ -1403,8 +1393,8 @@ describe('UserResolver', () => { ) }) - it('logs the error found', () => { - expect(logger.error).toBeCalledWith(`Old password is invalid`) + it('logs if logger is in debug mode', () => { + expect(logger.debug).toBeCalledWith(`old password is invalid`) }) }) @@ -1430,10 +1420,8 @@ describe('UserResolver', () => { ) }) - it('logs the error found', () => { - expect(logger.error).toBeCalledWith( - 'Please enter a valid password with at least 8 characters, upper and lower case letters, at least one number and one special character!', - ) + it('logs warning', () => { + expect(logger.warn).toBeCalledWith('try to set invalid password') }) }) @@ -1490,10 +1478,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( - 'Please enter a valid password with at least 8 characters, upper and lower case letters, at least one number and one special character!', - ) + it('log warning', () => { + expect(logger.warn).toBeCalledWith('login failed, wrong password') }) }) }) @@ -1776,7 +1762,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) + expect(logErrorLogger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) }) }) @@ -1892,7 +1878,7 @@ describe('UserResolver', () => { ) }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Administrator can not change his own role') + expect(logErrorLogger.error).toBeCalledWith('Administrator can not change his own role') }) }) @@ -1937,7 +1923,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('User already has role=', RoleNames.ADMIN) + expect(logErrorLogger.error).toBeCalledWith('User already has role=', RoleNames.ADMIN) }) }) @@ -1961,7 +1947,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('User already has role=', RoleNames.MODERATOR) + expect(logErrorLogger.error).toBeCalledWith('User already has role=', RoleNames.MODERATOR) }) }) @@ -1982,7 +1968,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('User is already an usual user') + expect(logErrorLogger.error).toBeCalledWith('User is already an usual user') }) }) }) @@ -2055,7 +2041,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) + expect(logErrorLogger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) }) }) @@ -2072,7 +2058,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Moderator can not delete his own account') + expect(logErrorLogger.error).toBeCalledWith('Moderator can not delete his own account') }) }) @@ -2125,7 +2111,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Could not find user with given ID', user.id) + expect(logErrorLogger.error).toBeCalledWith('Could not find user with given ID', user.id) }) }) }) @@ -2201,7 +2187,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('No user with this credentials', 'invalid') + expect(logger.warn).toBeCalledWith('findUserByEmail failed, user with email=invalid not found') }) }) @@ -2218,11 +2204,8 @@ describe('UserResolver', () => { ) }) - it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith( - 'User with given email contact is deleted', - 'stephen@hawking.uk', - ) + it('log warning', () => { + expect(logger.warn).toBeCalledWith('call for activation of deleted user') }) }) @@ -2348,7 +2331,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) + expect(logErrorLogger.error).toBeCalledWith('Could not find user with given ID', admin.id + 1) }) }) @@ -2369,7 +2352,7 @@ describe('UserResolver', () => { }) it('logs the error thrown', () => { - expect(logger.error).toBeCalledWith('User is not deleted') + expect(logErrorLogger.error).toBeCalledWith('User is not deleted') }) describe('undelete deleted user', () => { @@ -2682,7 +2665,7 @@ describe('UserResolver', () => { errors: [new GraphQLError('401 Unauthorized')], }), ) - expect(logger.error).toBeCalledWith('401 Unauthorized') + expect(logErrorLogger.error).toBeCalledWith('401 Unauthorized') }) }) @@ -2720,7 +2703,7 @@ describe('UserResolver', () => { errors: [new GraphQLError('Unknown identifier type')], }), ) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'Unknown identifier type', 'identifier_is_no_valid_alias!', ) @@ -2742,7 +2725,7 @@ describe('UserResolver', () => { errors: [new GraphQLError('No user found to given identifier(s)')], }), ) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'No user found to given identifier(s)', uuid, homeCom1.communityUuid, @@ -2765,7 +2748,7 @@ describe('UserResolver', () => { errors: [new GraphQLError('No user with this credentials')], }), ) - expect(logger.error).toBeCalledWith( + expect(logErrorLogger.error).toBeCalledWith( 'No user with this credentials', 'bibi@bloxberg.de', foreignCom1.communityUuid, diff --git a/backend/src/graphql/resolver/UserResolver.ts b/backend/src/graphql/resolver/UserResolver.ts index ee83937f0..861ee3622 100644 --- a/backend/src/graphql/resolver/UserResolver.ts +++ b/backend/src/graphql/resolver/UserResolver.ts @@ -23,7 +23,7 @@ import { Root, } from 'type-graphql' import { IRestResponse } from 'typed-rest-client' -import { In, Point } from 'typeorm' +import { EntityNotFoundError, In, Point } from 'typeorm' import { v4 as uuidv4 } from 'uuid' import { UserArgs } from '@arg//UserArgs' @@ -80,15 +80,16 @@ import { isValidPassword } from '@/password/EncryptorUtils' import { encryptPassword, verifyPassword } from '@/password/PasswordEncryptor' import { LogError } from '@/server/LogError' import { Context, getClientTimezoneOffset, getUser } from '@/server/context' -import { backendLogger as logger } from '@/server/logger' import { communityDbUser } from '@/util/communityUser' import { hasElopageBuys } from '@/util/hasElopageBuys' -import { getTimeDurationObject, printTimeDuration } from '@/util/time' +import { durationInMinutesFromDates, getTimeDurationObject, printTimeDuration } from '@/util/time' import { delay } from '@/util/utilities' import random from 'random-bigint' import { randombytes_random } from 'sodium-native' +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '@/graphql/resolver' +import { Logger, getLogger } from 'log4js' import { FULL_CREATION_AVAILABLE } from './const/const' import { Location2Point, Point2Location } from './util/Location2Point' import { authenticateGmsUserPlayground } from './util/authenticateGmsUserPlayground' @@ -107,11 +108,12 @@ import { validateAlias } from './util/validateAlias' const LANGUAGES = ['de', 'en', 'es', 'fr', 'nl'] const DEFAULT_LANGUAGE = 'de' const db = AppDatabase.getInstance() +const createLogger = () => getLogger(`${LOG4JS_RESOLVER_CATEGORY_NAME}.UserResolver`) const isLanguage = (language: string): boolean => { return LANGUAGES.includes(language) } -const newEmailContact = (email: string, userId: number): DbUserContact => { +const newEmailContact = (email: string, userId: number, logger: Logger): DbUserContact => { logger.trace(`newEmailContact...`) const emailContact = new DbUserContact() emailContact.email = email @@ -124,12 +126,12 @@ const newEmailContact = (email: string, userId: number): DbUserContact => { return emailContact } -export const activationLink = (verificationCode: string): string => { +export const activationLink = (verificationCode: string, logger: Logger): string => { logger.debug(`activationLink(${verificationCode})...`) return CONFIG.EMAIL_LINK_SETPASSWORD + verificationCode.toString() } -const newGradidoID = async (): Promise => { +const newGradidoID = async (logger: Logger): Promise => { let gradidoId: string let countIds: number do { @@ -147,14 +149,16 @@ export class UserResolver { @Authorized([RIGHTS.VERIFY_LOGIN]) @Query(() => User) async verifyLogin(@Ctx() context: Context): Promise { + const logger = createLogger() logger.info('verifyLogin...') // TODO refactor and do not have duplicate code with login(see below) const userEntity = getUser(context) + logger.addContext('user', userEntity.id) const user = new User(userEntity) // Elopage Status & Stored PublisherId user.hasElopage = await this.hasElopage(context) - logger.debug(`verifyLogin... successful: ${user.firstName}.${user.lastName}`) + logger.debug(`verifyLogin... successful`) user.klickTipp = await getKlicktippState(userEntity.emailContact.email) return user } @@ -165,31 +169,39 @@ export class UserResolver { @Args() { email, password, publisherId, project }: UnsecureLoginArgs, @Ctx() context: Context, ): Promise { - logger.info(`login with ${email}, ***, ${publisherId}, project=${project} ...`) + const logger = createLogger() + logger.info(`login with ${email.substring(0, 3)}..., project=${project} ...`) email = email.trim().toLowerCase() let dbUser: DbUser try { dbUser = await findUserByEmail(email) + // add pubKey in logger-context for layout-pattern X{user} to print it in each logging message + logger.addContext('user', dbUser.id) + logger.trace('user before login', new UserLoggingView(dbUser)) } catch (e) { // simulate delay which occur on password encryption 650 ms +- 50 rnd await delay(650 + Math.floor(Math.random() * 101) - 50) throw e } - + // TODO: discuss need we logging all this cases? if (dbUser.deletedAt) { - throw new LogError('This user was permanently deleted. Contact support for questions', dbUser) + logger.warn('login failed, user was deleted') + throw new Error('This user was permanently deleted. Contact support for questions') } if (!dbUser.emailContact.emailChecked) { - throw new LogError('The Users email is not validate yet', dbUser) + logger.warn('login failed, user email not checked') + throw new Error('The Users email is not validate yet') } // TODO: at least in test this does not work since `dbUser.password = 0` and `BigInto(0) = 0n` if (dbUser.password === BigInt(0)) { // TODO we want to catch this on the frontend and ask the user to check his emails or resend code - throw new LogError('The User has not set a password yet', dbUser) + logger.warn('login failed, user has not set a password yet') + throw new Error('The User has not set a password yet') } if (!(await verifyPassword(dbUser, password))) { - throw new LogError('No user with this credentials', dbUser) + logger.warn('login failed, wrong password') + throw new Error('No user with this credentials') } // request to humhub and klicktipp run in parallel @@ -217,17 +229,14 @@ export class UserResolver { dbUser.password = await encryptPassword(dbUser, password) await dbUser.save() } - // add pubKey in logger-context for layout-pattern X{user} to print it in each logging message - logger.addContext('user', dbUser.id) logger.debug('validation of login credentials successful...') const user = new User(dbUser) - logger.debug(`user= ${JSON.stringify(user, null, 2)}`) i18n.setLocale(user.language) // Elopage Status & Stored PublisherId user.hasElopage = await this.hasElopage({ ...context, user: dbUser }) - logger.info('user.hasElopage', user.hasElopage) + logger.debug('user.hasElopage', user.hasElopage) if (!user.hasElopage && publisherId) { user.publisherId = publisherId dbUser.publisherId = publisherId @@ -241,7 +250,7 @@ export class UserResolver { await EVENT_USER_LOGIN(dbUser) const projectBranding = await projectBrandingPromise - logger.debug('project branding: ', projectBranding) + logger.debug('project branding: ', projectBranding?.id) // load humhub state if (humhubUserPromise) { try { @@ -260,7 +269,8 @@ export class UserResolver { } } user.klickTipp = await klicktippStatePromise - logger.info(`successful Login: ${JSON.stringify(user, null, 2)}`) + logger.info('successful Login') + logger.trace('user after login', new UserLoggingView(dbUser)) return user } @@ -268,8 +278,6 @@ export class UserResolver { @Mutation(() => Boolean) async logout(@Ctx() context: Context): Promise { await EVENT_USER_LOGOUT(getUser(context)) - // remove user from logger context - logger.addContext('user', 'unknown') return true } @@ -288,10 +296,24 @@ export class UserResolver { project = null, }: CreateUserArgs, ): Promise { - logger.addContext('user', 'unknown') - logger.info( - `createUser(email=${email}, firstName=${firstName}, lastName=${lastName}, language=${language}, publisherId=${publisherId}, redeemCode=${redeemCode}, project=${project})`, - ) + const logger = createLogger() + const shortEmail = email.substring(0, 3) + logger.addContext('email', shortEmail) + + const shortRedeemCode = redeemCode?.substring(0, 6) + const infos = [] + infos.push(`language=${language}`) + if (publisherId) { + infos.push(`publisherId=${publisherId}`) + } + if (redeemCode) { + infos.push(`redeemCode=${shortRedeemCode}`) + } + if (project) { + infos.push(`project=${project}`) + } + logger.info(`createUser(${infos.join(', ')})`) + // TODO: wrong default value (should be null), how does graphql work here? Is it an required field? // default int publisher_id = 0; @@ -305,15 +327,16 @@ export class UserResolver { email = email.trim().toLowerCase() if (await checkEmailExists(email)) { const foundUser = await findUserByEmail(email) - logger.info('DbUser.findOne', email, foundUser) + logger.info('DbUser.findOne', foundUser.id) if (foundUser) { + logger.addContext('user', foundUser.id) + logger.removeContext('email') // ATTENTION: this logger-message will be exactly expected during tests, next line - logger.info(`User already exists with this email=${email}`) + logger.info(`User already exists`) logger.info( - `Specified username when trying to register multiple times with this email: firstName=${firstName}, lastName=${lastName}`, + `Specified username when trying to register multiple times with this email: firstName=${firstName.substring(0, 4)}, lastName=${lastName.substring(0, 4)}`, ) - // TODO: this is unsecure, but the current implementation of the login server. This way it can be queried if the user with given EMail is existent. const user = new User(communityDbUser) user.id = randombytes_random() % (2048 * 16) // TODO: for a better faking derive id from email so that it will be always the same id when the same email comes in? @@ -325,7 +348,7 @@ export class UserResolver { if (alias && (await validateAlias(alias))) { user.alias = alias } - logger.debug('partly faked user', user) + logger.debug('partly faked user', { id: user.id, gradidoID: user.gradidoID }) await sendAccountMultiRegistrationEmail({ firstName: foundUser.firstName, // this is the real name of the email owner, but just "firstName" would be the name of the new registrant which shall not be passed to the outside @@ -335,9 +358,6 @@ export class UserResolver { }) await EVENT_EMAIL_ACCOUNT_MULTIREGISTRATION(foundUser) - logger.info( - `sendAccountMultiRegistrationEmail by ${firstName} ${lastName} to ${foundUser.firstName} ${foundUser.lastName} <${email}>`, - ) /* uncomment this, when you need the activation link on the console */ // In case EMails are disabled log the activation link for the user logger.info('createUser() faked and send multi registration mail...') @@ -352,7 +372,7 @@ export class UserResolver { select: { logoUrl: true, spaceId: true }, }) } - const gradidoID = await newGradidoID() + const gradidoID = await newGradidoID(logger) const eventRegisterRedeem = Event( EventType.USER_REGISTER_REDEEM, @@ -375,21 +395,21 @@ export class UserResolver { } dbUser.publisherId = publisherId ?? 0 dbUser.passwordEncryptionType = PasswordEncryptionType.NO_PASSWORD - logger.debug('new dbUser', dbUser) + logger.debug('new dbUser', new UserLoggingView(dbUser)) if (redeemCode) { if (redeemCode.match(/^CL-/)) { const contributionLink = await DbContributionLink.findOne({ where: { code: redeemCode.replace('CL-', '') }, }) - logger.info('redeemCode found contributionLink', contributionLink) if (contributionLink) { + logger.info('redeemCode found contributionLink', contributionLink.id) dbUser.contributionLinkId = contributionLink.id eventRegisterRedeem.involvedContributionLink = contributionLink } } else { const transactionLink = await DbTransactionLink.findOne({ where: { code: redeemCode } }) - logger.info('redeemCode found transactionLink', transactionLink) if (transactionLink) { + logger.info('redeemCode found transactionLink', transactionLink.id) dbUser.referrerId = transactionLink.userId eventRegisterRedeem.involvedTransactionLink = transactionLink } @@ -404,7 +424,7 @@ export class UserResolver { dbUser = await queryRunner.manager.save(dbUser).catch((error) => { throw new LogError('Error while saving dbUser', error) }) - let emailContact = newEmailContact(email, dbUser.id) + let emailContact = newEmailContact(email, dbUser.id, logger) emailContact = await queryRunner.manager.save(emailContact).catch((error) => { throw new LogError('Error while saving user email contact', error) }) @@ -431,7 +451,7 @@ export class UserResolver { timeDurationObject: getTimeDurationObject(CONFIG.EMAIL_CODE_VALID_TIME), logoUrl: projectBranding?.logoUrl, }) - logger.info(`sendAccountActivationEmail of ${firstName}.${lastName} to ${email}`) + logger.info('sendAccountActivationEmail') await EVENT_EMAIL_CONFIRMATION(dbUser) @@ -485,18 +505,28 @@ export class UserResolver { @Authorized([RIGHTS.SEND_RESET_PASSWORD_EMAIL]) @Mutation(() => Boolean) async forgotPassword(@Arg('email') email: string): Promise { - logger.addContext('user', 'unknown') - logger.info(`forgotPassword(${email})...`) + const logger = createLogger() + const shortEmail = email.substring(0, 3) + logger.addContext('email', shortEmail) + logger.info('forgotPassword...') email = email.trim().toLowerCase() - const user = await findUserByEmail(email).catch((error) => { - logger.warn(`fail on find UserContact per ${email} because: ${error}`) - }) + let user: DbUser + try { + user = await findUserByEmail(email) + logger.removeContext('email') + logger.addContext('user', user.id) + } catch (_e) { + logger.warn(`fail on find UserContact`) + return true + } - if (!user || user.deletedAt) { - logger.warn(`no user found with ${email}`) + if (user.deletedAt) { + logger.warn(`user was deleted`) return true } if (!canEmailResend(user.emailContact.updatedAt || user.emailContact.createdAt)) { + const diff = durationInMinutesFromDates(user.emailContact.updatedAt || user.emailContact.createdAt, new Date()) + logger.warn(`email already sent ${printTimeDuration(diff)} ago, min wait time: ${printTimeDuration(CONFIG.EMAIL_CODE_REQUEST_TIME)}`) throw new LogError( `Email already sent less than ${printTimeDuration(CONFIG.EMAIL_CODE_REQUEST_TIME)} ago`, ) @@ -507,21 +537,19 @@ export class UserResolver { user.emailContact.emailVerificationCode = random(64).toString() user.emailContact.emailOptInTypeId = OptInType.EMAIL_OPT_IN_RESET_PASSWORD await user.emailContact.save().catch(() => { - throw new LogError('Unable to save email verification code', user.emailContact) + throw new LogError('Unable to save email verification code', user.emailContact.id) }) - logger.info('optInCode for', email, user.emailContact) - await sendResetPasswordEmail({ firstName: user.firstName, lastName: user.lastName, email, language: user.language, - resetLink: activationLink(user.emailContact.emailVerificationCode), + resetLink: activationLink(user.emailContact.emailVerificationCode, logger), timeDurationObject: getTimeDurationObject(CONFIG.EMAIL_CODE_VALID_TIME), }) - logger.info(`forgotPassword(${email}) successful...`) + logger.info(`forgotPassword successful...`) await EVENT_EMAIL_FORGOT_PASSWORD(user) return true @@ -533,7 +561,8 @@ export class UserResolver { @Arg('code') code: string, @Arg('password') password: string, ): Promise { - logger.info(`setPassword(${code}, ***)...`) + const logger = createLogger() + logger.info(`setPassword...`) // Validate Password if (!isValidPassword(password)) { throw new LogError( @@ -545,8 +574,11 @@ export class UserResolver { where: { emailVerificationCode: code }, relations: ['user'], }).catch(() => { - throw new LogError('Could not login with emailVerificationCode') + // code wasn't in db, so we can write it into log without hesitation + logger.warn(`invalid emailVerificationCode=${code}`) + throw new Error('Could not login with emailVerificationCode') }) + logger.addContext('user', userContact.user.id) logger.debug('userContact loaded...') // Code is only valid for `CONFIG.EMAIL_CODE_VALID_TIME` minutes if (!isEmailVerificationCodeValid(userContact.updatedAt || userContact.createdAt)) { @@ -596,9 +628,7 @@ export class UserResolver { if ((userContact.emailOptInTypeId as OptInType) === OptInType.EMAIL_OPT_IN_REGISTER) { try { await subscribe(userContact.email, user.language, user.firstName, user.lastName) - logger.debug( - `subscribe(${userContact.email}, ${user.language}, ${user.firstName}, ${user.lastName})`, - ) + logger.debug('Success subscribe to klicktipp') } catch (e) { logger.error('Error subscribing to klicktipp', e) } @@ -611,18 +641,21 @@ export class UserResolver { @Authorized([RIGHTS.QUERY_OPT_IN]) @Query(() => Boolean) async queryOptIn(@Arg('optIn') optIn: string): Promise { - logger.info(`queryOptIn(${optIn})...`) + const logger = createLogger() + logger.addContext('optIn', optIn.substring(0, 4)) + logger.info(`queryOptIn...`) const userContact = await DbUserContact.findOneOrFail({ where: { emailVerificationCode: optIn }, }) - logger.debug('found optInCode', userContact) + logger.addContext('user', userContact.userId) + logger.debug('found optInCode', userContact.id) // Code is only valid for `CONFIG.EMAIL_CODE_VALID_TIME` minutes if (!isEmailVerificationCodeValid(userContact.updatedAt || userContact.createdAt)) { throw new LogError( `Email was sent more than ${printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME)} ago`, ) } - logger.info(`queryOptIn(${optIn}) successful...`) + logger.info(`queryOptIn successful...`) return true } @@ -659,10 +692,27 @@ export class UserResolver { gmsLocation, gmsPublishLocation, } = updateUserInfosArgs - logger.info( - `updateUserInfos(${firstName}, ${lastName}, ${alias}, ${language}, ***, ***, ${hideAmountGDD}, ${hideAmountGDT}, ${gmsAllowed}, ${gmsPublishName}, ${gmsLocation}, ${gmsPublishLocation})...`, - ) const user = getUser(context) + const logger = createLogger() + logger.addContext('user', user.id) + // log only if a value is set + logger.info(`updateUserInfos...`, { + firstName: firstName !== undefined, + lastName: lastName !== undefined, + alias: alias !== undefined, + language: language !== undefined, + password: password !== undefined, + passwordNew: passwordNew !== undefined, + hideAmountGDD: hideAmountGDD !== undefined, + hideAmountGDT: hideAmountGDT !== undefined, + humhubAllowed: humhubAllowed !== undefined, + gmsAllowed: gmsAllowed !== undefined, + gmsPublishName: gmsPublishName !== undefined, + humhubPublishName: humhubPublishName !== undefined, + gmsLocation: gmsLocation !== undefined, + gmsPublishLocation: gmsPublishLocation !== undefined, + }) + const updateUserInGMS = compareGmsRelevantUserSettings(user, updateUserInfosArgs) const publishNameLogic = new PublishNameLogic(user) const oldHumhubUsername = publishNameLogic.getUserIdentifier( @@ -685,7 +735,8 @@ export class UserResolver { if (language) { if (!isLanguage(language)) { - throw new LogError('Given language is not a valid language', language) + logger.warn('try to set unsupported language', language) + throw new LogError('Given language is not a valid language or not supported') } user.language = language i18n.setLocale(language) @@ -694,12 +745,15 @@ export class UserResolver { if (password && passwordNew) { // Validate Password if (!isValidPassword(passwordNew)) { - throw new LogError( + // TODO: log which rule(s) wasn't met + logger.warn('try to set invalid password') + throw new Error( 'Please enter a valid password with at least 8 characters, upper and lower case letters, at least one number and one special character!', ) } - + if (!(await verifyPassword(user, password))) { + logger.debug('old password is invalid') throw new LogError(`Old password is invalid`) } @@ -763,7 +817,7 @@ export class UserResolver { logger.debug(`changed user-settings relevant for gms-user update...`) const homeCom = await getHomeCommunity() if (homeCom.gmsApiKey !== null) { - logger.debug(`send User to Gms...`, user) + logger.debug(`send User to Gms...`) await sendUserToGms(user, homeCom) logger.debug(`sendUserToGms successfully.`) } @@ -785,18 +839,22 @@ export class UserResolver { @Authorized([RIGHTS.HAS_ELOPAGE]) @Query(() => Boolean) async hasElopage(@Ctx() context: Context): Promise { - logger.info(`hasElopage()...`) - const userEntity = getUser(context) - const elopageBuys = hasElopageBuys(userEntity.emailContact.email) - logger.debug('has ElopageBuys', elopageBuys) + const dbUser = getUser(context) + const logger = createLogger() + logger.addContext('user', dbUser.id) + const elopageBuys = await hasElopageBuys(dbUser.emailContact.email) + logger.info(`has Elopage (ablify): ${elopageBuys}`) return elopageBuys } @Authorized([RIGHTS.GMS_USER_PLAYGROUND]) @Query(() => GmsUserAuthenticationResult) async authenticateGmsUserSearch(@Ctx() context: Context): Promise { - logger.info(`authenticateGmsUserSearch()...`) const dbUser = getUser(context) + const logger = createLogger() + logger.addContext('user', dbUser.id) + logger.info(`authenticateGmsUserSearch()...`) + let result = new GmsUserAuthenticationResult() if (context.token) { const homeCom = await getHomeCommunity() @@ -815,8 +873,11 @@ export class UserResolver { @Authorized([RIGHTS.GMS_USER_PLAYGROUND]) @Query(() => UserLocationResult) async userLocation(@Ctx() context: Context): Promise { - logger.info(`userLocation()...`) const dbUser = getUser(context) + const logger = createLogger() + logger.addContext('user', dbUser.id) + logger.info(`userLocation()...`) + const result = new UserLocationResult() if (context.token) { const homeCom = await getHomeCommunity() @@ -835,8 +896,11 @@ export class UserResolver { @Ctx() context: Context, @Arg('project', () => String, { nullable: true }) project?: string | null, ): Promise { - logger.info(`authenticateHumhubAutoLogin()...`) const dbUser = getUser(context) + const logger = createLogger() + logger.addContext('user', dbUser.id) + logger.info(`authenticateHumhubAutoLogin()...`) + const humhubClient = HumHubClient.getInstance() if (!humhubClient) { throw new LogError('cannot create humhub client') @@ -1029,13 +1093,15 @@ export class UserResolver { @Arg('email') email: string, @Ctx() context: Context, ): Promise { + const logger = createLogger() email = email.trim().toLowerCase() - // const user = await dbUser.findOne({ id: emailContact.userId }) - const user = await findUserByEmail(email) + const user = await findUserByEmail(email) + logger.addContext('user', user.id) + logger.info('sendActivationEmail...') if (user.deletedAt || user.emailContact.deletedAt) { - throw new LogError('User with given email contact is deleted', email) - } - + logger.warn('call for activation of deleted user') + throw new Error('User with given email contact is deleted') + } user.emailContact.emailResendCount++ await user.emailContact.save() @@ -1044,7 +1110,7 @@ export class UserResolver { lastName: user.lastName, email, language: user.language, - activationLink: activationLink(user.emailContact.emailVerificationCode), + activationLink: activationLink(user.emailContact.emailVerificationCode, logger), timeDurationObject: getTimeDurationObject(CONFIG.EMAIL_CODE_VALID_TIME), }) @@ -1090,16 +1156,25 @@ export class UserResolver { } export async function findUserByEmail(email: string): Promise { - const dbUser = await DbUser.findOneOrFail({ - where: { - emailContact: { email }, - }, - withDeleted: true, - relations: { userRoles: true, emailContact: true }, - }).catch(() => { - throw new LogError('No user with this credentials', email) - }) - return dbUser + try { + const dbUser = await DbUser.findOneOrFail({ + where: { + emailContact: { email }, + }, + withDeleted: true, + relations: { userRoles: true, emailContact: true }, + }) + return dbUser + } catch(e) { + const logger = createLogger() + if (e instanceof EntityNotFoundError) { + // TODO: discuss if it is ok to print email in log for this case + logger.warn(`findUserByEmail failed, user with email=${email} not found`) + } else { + logger.error(`findUserByEmail failed, unknown error: ${e}`) + } + throw new Error('No user with this credentials') + } } async function checkEmailExists(email: string): Promise { diff --git a/backend/src/graphql/resolver/index.ts b/backend/src/graphql/resolver/index.ts new file mode 100644 index 000000000..0ee59f7f6 --- /dev/null +++ b/backend/src/graphql/resolver/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' + +export const LOG4JS_RESOLVER_CATEGORY_NAME = `${LOG4JS_BASE_CATEGORY_NAME}.graphql.resolver` diff --git a/backend/src/graphql/resolver/util/authenticateGmsUserPlayground.ts b/backend/src/graphql/resolver/util/authenticateGmsUserPlayground.ts index 5d7b9f723..01d423993 100644 --- a/backend/src/graphql/resolver/util/authenticateGmsUserPlayground.ts +++ b/backend/src/graphql/resolver/util/authenticateGmsUserPlayground.ts @@ -3,8 +3,13 @@ import { User as DbUser } from 'database' import { verifyAuthToken } from '@/apis/gms/GmsClient' import { CONFIG } from '@/config' import { GmsUserAuthenticationResult } from '@/graphql/model/GmsUserAuthenticationResult' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { ensureUrlEndsWithSlash } from '@/util/utilities' +import { getLogger } from 'log4js' + +const logger = getLogger( + `${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.authenticateGmsUserPlayground`, +) export async function authenticateGmsUserPlayground( _apiKey: string, diff --git a/backend/src/graphql/resolver/util/compareGmsRelevantUserSettings.ts b/backend/src/graphql/resolver/util/compareGmsRelevantUserSettings.ts index cc53ff5a1..80a1e608a 100644 --- a/backend/src/graphql/resolver/util/compareGmsRelevantUserSettings.ts +++ b/backend/src/graphql/resolver/util/compareGmsRelevantUserSettings.ts @@ -5,10 +5,15 @@ import { UpdateUserInfosArgs } from '@/graphql/arg/UpdateUserInfosArgs' import { GmsPublishLocationType } from '@/graphql/enum/GmsPublishLocationType' import { PublishNameType } from '@/graphql/enum/PublishNameType' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '.' import { Point2Location } from './Location2Point' +const logger = getLogger( + `${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.compareGmsRelevantUserSettings`, +) + export function compareGmsRelevantUserSettings( orgUser: DbUser, updateUserInfosArgs: UpdateUserInfosArgs, diff --git a/backend/src/graphql/resolver/util/creations.ts b/backend/src/graphql/resolver/util/creations.ts index 9dadaa8e3..02439e10a 100644 --- a/backend/src/graphql/resolver/util/creations.ts +++ b/backend/src/graphql/resolver/util/creations.ts @@ -4,12 +4,14 @@ import { Decimal } from 'decimal.js-light' import { OpenCreation } from '@model/OpenCreation' import { FULL_CREATION_AVAILABLE, MAX_CREATION_AMOUNT } from '@/graphql/resolver/const/const' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { getFirstDayOfPreviousNMonth } from '@/util/utilities' import { AppDatabase } from 'database' +import { getLogger } from 'log4js' const db = AppDatabase.getInstance() +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.creations`) interface CreationMap { id: number diff --git a/backend/src/graphql/resolver/util/getKlicktippState.ts b/backend/src/graphql/resolver/util/getKlicktippState.ts index e006ff20a..719286223 100644 --- a/backend/src/graphql/resolver/util/getKlicktippState.ts +++ b/backend/src/graphql/resolver/util/getKlicktippState.ts @@ -1,7 +1,10 @@ import { KlickTipp } from '@model/KlickTipp' import { getKlickTippUser } from '@/apis/KlicktippController' -import { klickTippLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.getKlicktippState`) export const getKlicktippState = async (email: string): Promise => { try { @@ -10,7 +13,7 @@ export const getKlicktippState = async (email: string): Promise => { return new KlickTipp(klickTippUser.status === 'Subscribed') } } catch (err) { - logger.error('There is no klicktipp user for email', email, err) + logger.error('There is no klicktipp user for email', email.substring(0, 3), '...', err) } return new KlickTipp(false) } diff --git a/backend/src/graphql/resolver/util/index.ts b/backend/src/graphql/resolver/util/index.ts new file mode 100644 index 000000000..bf0fba6d1 --- /dev/null +++ b/backend/src/graphql/resolver/util/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_RESOLVER_CATEGORY_NAME } from '@/graphql/resolver' + +export const LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME = `${LOG4JS_RESOLVER_CATEGORY_NAME}.util` diff --git a/backend/src/graphql/resolver/util/processXComSendCoins.ts b/backend/src/graphql/resolver/util/processXComSendCoins.ts index 67b6d71bd..7115d3d1f 100644 --- a/backend/src/graphql/resolver/util/processXComSendCoins.ts +++ b/backend/src/graphql/resolver/util/processXComSendCoins.ts @@ -14,13 +14,16 @@ import { SendCoinsResult } from '@/federation/client/1_0/model/SendCoinsResult' import { SendCoinsClientFactory } from '@/federation/client/SendCoinsClientFactory' import { PendingTransactionState } from '@/graphql/enum/PendingTransactionState' import { TransactionTypeId } from '@/graphql/enum/TransactionTypeId' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { calculateSenderBalance } from '@/util/calculateSenderBalance' import { fullName } from '@/util/utilities' +import { getLogger } from 'log4js' import { settlePendingSenderTransaction } from './settlePendingSenderTransaction' +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.processXComSendCoins`) + export async function processXComPendingSendCoins( receiverCom: DbCommunity, senderCom: DbCommunity, @@ -63,7 +66,7 @@ export async function processXComPendingSendCoins( if (!senderBalance) { throw new LogError('User has not enough GDD or amount is < 0', senderBalance) } - logger.debug(`X-Com: calculated senderBalance = `, senderBalance) + logger.debug(`calculated senderBalance = `, senderBalance) const receiverFCom = await DbFederatedCommunity.findOneOrFail({ where: { @@ -88,11 +91,11 @@ export async function processXComPendingSendCoins( args.senderUserUuid = sender.gradidoID args.senderUserName = fullName(sender.firstName, sender.lastName) args.senderAlias = sender.alias - logger.debug(`X-Com: ready for voteForSendCoins with args=`, args) + logger.debug(`ready for voteForSendCoins with args=`, args) voteResult = await client.voteForSendCoins(args) - logger.debug(`X-Com: returned from voteForSendCoins:`, voteResult) + logger.debug(`returned from voteForSendCoins:`, voteResult) if (voteResult.vote) { - logger.debug(`X-Com: prepare pendingTransaction for sender...`) + logger.debug(`prepare pendingTransaction for sender...`) // writing the pending transaction on receiver-side was successfull, so now write the sender side try { const pendingTx = DbPendingTransaction.create() @@ -120,20 +123,20 @@ export async function processXComPendingSendCoins( pendingTx.userId = sender.id pendingTx.userGradidoID = sender.gradidoID pendingTx.userName = fullName(sender.firstName, sender.lastName) - logger.debug(`X-Com: initialized sender pendingTX=`, pendingTx) + logger.debug(`initialized sender pendingTX=`, pendingTx) await DbPendingTransaction.insert(pendingTx) - logger.debug(`X-Com: sender pendingTx successfully inserted...`) + logger.debug(`sender pendingTx successfully inserted...`) } catch (err) { logger.error(`Error in writing sender pending transaction: `, err) // revert the existing pending transaction on receiver side let revertCount = 0 - logger.debug(`X-Com: first try to revertSendCoins of receiver`) + logger.debug(`first try to revertSendCoins of receiver`) do { if (await client.revertSendCoins(args)) { logger.debug(`revertSendCoins()-1_0... successfull after revertCount=`, revertCount) // treat revertingSendCoins as an error of the whole sendCoins-process - throw new LogError('Error in writing sender pending transaction: `, err') + throw new LogError('Error in writing sender pending transaction: ', err) } } while (CONFIG.FEDERATION_XCOM_MAXREPEAT_REVERTSENDCOINS > revertCount++) throw new LogError( @@ -143,10 +146,7 @@ export async function processXComPendingSendCoins( } logger.debug(`voteForSendCoins()-1_0... successfull`) } else { - logger.error( - `X-Com: break with error on writing pendingTransaction for recipient...`, - voteResult, - ) + logger.error(`break with error on writing pendingTransaction for recipient...`, voteResult) } return voteResult } @@ -168,7 +168,7 @@ export async function processXComCommittingSendCoins( const sendCoinsResult = new SendCoinsResult() try { logger.debug( - `XCom: processXComCommittingSendCoins...`, + `processXComCommittingSendCoins...`, receiverCom, senderCom, creationDate, @@ -191,7 +191,7 @@ export async function processXComCommittingSendCoins( memo, }) if (pendingTx) { - logger.debug(`X-Com: find pending Tx for settlement:`, pendingTx) + logger.debug('find pending Tx for settlement:', pendingTx) const receiverFCom = await DbFederatedCommunity.findOneOrFail({ where: { publicKey: receiverCom.publicKey, @@ -218,9 +218,9 @@ export async function processXComCommittingSendCoins( args.senderUserName = pendingTx.userName } args.senderAlias = sender.alias - logger.debug(`X-Com: ready for settleSendCoins with args=`, args) + logger.debug('ready for settleSendCoins with args=', args) const acknowledge = await client.settleSendCoins(args) - logger.debug(`X-Com: returnd from settleSendCoins:`, acknowledge) + logger.debug('returnd from settleSendCoins:', acknowledge) if (acknowledge) { // settle the pending transaction on receiver-side was successfull, so now settle the sender side try { @@ -244,22 +244,22 @@ export async function processXComCommittingSendCoins( sendCoinsResult.recipAlias = recipient.recipAlias } } catch (err) { - logger.error(`Error in writing sender pending transaction: `, err) + logger.error('Error in writing sender pending transaction: ', err) // revert the existing pending transaction on receiver side let revertCount = 0 - logger.debug(`X-Com: first try to revertSetteledSendCoins of receiver`) + logger.debug('first try to revertSetteledSendCoins of receiver') do { if (await client.revertSettledSendCoins(args)) { logger.debug( - `revertSettledSendCoins()-1_0... successfull after revertCount=`, + 'revertSettledSendCoins()-1_0... successfull after revertCount=', revertCount, ) // treat revertingSettledSendCoins as an error of the whole sendCoins-process - throw new LogError('Error in settle sender pending transaction: `, err') + throw new LogError('Error in settle sender pending transaction: ', err) } } while (CONFIG.FEDERATION_XCOM_MAXREPEAT_REVERTSENDCOINS > revertCount++) throw new LogError( - `Error in reverting receiver pending transaction even after revertCount=`, + 'Error in reverting receiver pending transaction even after revertCount=', revertCount, ) } @@ -267,7 +267,7 @@ export async function processXComCommittingSendCoins( } } } catch (err) { - logger.error(`Error:`, err) + logger.error('Error: ', err) sendCoinsResult.vote = false } return sendCoinsResult diff --git a/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.test.ts b/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.test.ts index 72a458642..4dd1672af 100644 --- a/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.test.ts +++ b/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.test.ts @@ -9,7 +9,7 @@ import { DataSource } from 'typeorm' import { v4 as uuidv4 } from 'uuid' import { cleanDB, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' import { CONFIG } from '@/config' import { TransactionTypeId } from '@/graphql/enum/TransactionTypeId' @@ -20,11 +20,17 @@ import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' import { bobBaumeister } from '@/seeds/users/bob-baumeister' import { peterLustig } from '@/seeds/users/peter-lustig' import { raeuberHotzenplotz } from '@/seeds/users/raeuber-hotzenplotz' +import { getLogger } from 'config-schema/test/testSetup' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '.' import { sendTransactionsToDltConnector } from './sendTransactionsToDltConnector' jest.mock('@/password/EncryptorUtils') +const logger = getLogger( + `${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.sendTransactionsToDltConnector`, +) + /* // Mock the GraphQLClient jest.mock('graphql-request', () => { @@ -417,7 +423,7 @@ describe('create and send Transactions to DltConnector', () => { ]), ) - expect(logger.info).nthCalledWith(3, 'sending to DltConnector currently not configured...') + expect(logger.info).nthCalledWith(2, 'sending to DltConnector currently not configured...') }) }) diff --git a/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.ts b/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.ts index 010188dca..98e53456e 100644 --- a/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.ts +++ b/backend/src/graphql/resolver/util/sendTransactionsToDltConnector.ts @@ -3,8 +3,13 @@ import { IsNull } from 'typeorm' import { DltConnectorClient } from '@dltConnector/DltConnectorClient' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { Monitor, MonitorNames } from '@/util/Monitor' +import { getLogger } from 'log4js' + +const logger = getLogger( + `${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.sendTransactionsToDltConnector`, +) export async function sendTransactionsToDltConnector(): Promise { logger.info('sendTransactionsToDltConnector...') @@ -35,7 +40,7 @@ export async function sendTransactionsToDltConnector(): Promise { if (result) { dltTx.messageId = 'sended' await DltTransaction.save(dltTx) - logger.info('store messageId=%s in dltTx=%d', dltTx.messageId, dltTx.id) + logger.info(`store messageId=${dltTx.messageId} in dltTx=${dltTx.id}`) } } catch (e) { logger.error( diff --git a/backend/src/graphql/resolver/util/sendUserToGms.ts b/backend/src/graphql/resolver/util/sendUserToGms.ts index 26ac070d5..835d36343 100644 --- a/backend/src/graphql/resolver/util/sendUserToGms.ts +++ b/backend/src/graphql/resolver/util/sendUserToGms.ts @@ -3,8 +3,11 @@ import { Community as DbCommunity, User as DbUser } from 'database' import { createGmsUser, updateGmsUser } from '@/apis/gms/GmsClient' import { GmsUser } from '@/apis/gms/model/GmsUser' import { CONFIG } from '@/config' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.sendUserToGms`) export async function sendUserToGms( user: DbUser, diff --git a/backend/src/graphql/resolver/util/settlePendingSenderTransaction.ts b/backend/src/graphql/resolver/util/settlePendingSenderTransaction.ts index 82c95ba2e..81f1d5042 100644 --- a/backend/src/graphql/resolver/util/settlePendingSenderTransaction.ts +++ b/backend/src/graphql/resolver/util/settlePendingSenderTransaction.ts @@ -8,14 +8,17 @@ import { import { Decimal } from 'decimal.js-light' import { PendingTransactionState } from '@/graphql/enum/PendingTransactionState' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { TRANSACTIONS_LOCK } from '@/util/TRANSACTIONS_LOCK' import { calculateSenderBalance } from '@/util/calculateSenderBalance' - +import { getLogger } from 'log4js' import { getLastTransaction } from './getLastTransaction' const db = AppDatabase.getInstance() +const logger = getLogger( + `${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.settlePendingSenderTransaction`, +) export async function settlePendingSenderTransaction( homeCom: DbCommunity, @@ -31,7 +34,7 @@ export async function settlePendingSenderTransaction( logger.debug(`start Transaction for write-access...`) try { - logger.info('X-Com: settlePendingSenderTransaction:', homeCom, senderUser, pendingTx) + logger.info('settlePendingSenderTransaction:', homeCom, senderUser, pendingTx) // ensure that no other pendingTx with the same sender or recipient exists const openSenderPendingTx = await DbPendingTransaction.count({ diff --git a/backend/src/graphql/resolver/util/storeForeignUser.ts b/backend/src/graphql/resolver/util/storeForeignUser.ts index 929aa9cca..bd0eeb68f 100644 --- a/backend/src/graphql/resolver/util/storeForeignUser.ts +++ b/backend/src/graphql/resolver/util/storeForeignUser.ts @@ -1,7 +1,10 @@ import { Community as DbCommunity, User as DbUser } from 'database' import { SendCoinsResult } from '@/federation/client/1_0/model/SendCoinsResult' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.storeForeignUser`) export async function storeForeignUser( recipCom: DbCommunity, @@ -18,7 +21,7 @@ export async function storeForeignUser( }) if (!user) { logger.debug( - 'X-Com: no foreignUser found for:', + 'no foreignUser found for:', recipCom.communityUuid, committingResult.recipGradidoID, ) @@ -36,7 +39,7 @@ export async function storeForeignUser( } foreignUser.gradidoID = committingResult.recipGradidoID foreignUser = await DbUser.save(foreignUser) - logger.debug('X-Com: new foreignUser inserted:', foreignUser) + logger.debug('new foreignUser inserted:', foreignUser) return true } else if ( @@ -45,7 +48,7 @@ export async function storeForeignUser( user.alias !== committingResult.recipAlias ) { logger.warn( - 'X-Com: foreignUser still exists, but with different name or alias:', + 'foreignUser still exists, but with different name or alias:', user, committingResult, ) @@ -62,11 +65,11 @@ export async function storeForeignUser( logger.debug('update recipient successful.', user) return true } else { - logger.debug('X-Com: foreignUser still exists...:', user) + logger.debug('foreignUser still exists...:', user) return true } } catch (err) { - logger.error('X-Com: error in storeForeignUser;', err) + logger.error('error in storeForeignUser;', err) return false } } diff --git a/backend/src/graphql/resolver/util/syncHumhub.test.ts b/backend/src/graphql/resolver/util/syncHumhub.test.ts index 594f5fdfd..2eba3be40 100644 --- a/backend/src/graphql/resolver/util/syncHumhub.test.ts +++ b/backend/src/graphql/resolver/util/syncHumhub.test.ts @@ -4,8 +4,9 @@ import { HumHubClient } from '@/apis/humhub/HumHubClient' import { GetUser } from '@/apis/humhub/model/GetUser' import { UpdateUserInfosArgs } from '@/graphql/arg/UpdateUserInfosArgs' import { PublishNameType } from '@/graphql/enum/PublishNameType' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' +import { getLogger } from 'config-schema/test/testSetup' import { syncHumhub } from './syncHumhub' jest.mock('@/apis/humhub/HumHubClient') @@ -19,6 +20,8 @@ mockUser.humhubPublishName = PublishNameType.PUBLISH_NAME_FULL const mockUpdateUserInfosArg = new UpdateUserInfosArgs() const mockHumHubUser = new GetUser(mockUser, 1) +const logger = getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.syncHumhub`) + describe('syncHumhub', () => { beforeEach(() => { jest.spyOn(logger, 'debug').mockImplementation() @@ -33,8 +36,7 @@ describe('syncHumhub', () => { it('Should not sync if no relevant changes', async () => { await syncHumhub(mockUpdateUserInfosArg, new User(), 'username') expect(HumHubClient.getInstance).not.toBeCalled() - // language logging from some other place - expect(logger.debug).toBeCalledTimes(5) + expect(logger.debug).toBeCalledTimes(1) expect(logger.info).toBeCalledTimes(0) }) @@ -42,7 +44,7 @@ describe('syncHumhub', () => { mockUpdateUserInfosArg.firstName = 'New' // Relevant changes mockUser.firstName = 'New' await syncHumhub(mockUpdateUserInfosArg, mockUser, 'username') - expect(logger.debug).toHaveBeenCalledTimes(8) // Four language logging calls, two debug calls in function, one for not syncing + expect(logger.debug).toHaveBeenCalledTimes(4) // Four language logging calls, two debug calls in function, one for not syncing expect(logger.info).toHaveBeenLastCalledWith('finished sync user with humhub', { localId: mockUser.id, externId: mockHumHubUser.id, diff --git a/backend/src/graphql/resolver/util/syncHumhub.ts b/backend/src/graphql/resolver/util/syncHumhub.ts index b483af1ce..c866daf5a 100644 --- a/backend/src/graphql/resolver/util/syncHumhub.ts +++ b/backend/src/graphql/resolver/util/syncHumhub.ts @@ -7,7 +7,10 @@ import { ExecutedHumhubAction, syncUser } from '@/apis/humhub/syncUser' import { PublishNameLogic } from '@/data/PublishName.logic' import { UpdateUserInfosArgs } from '@/graphql/arg/UpdateUserInfosArgs' import { PublishNameType } from '@/graphql/enum/PublishNameType' -import { backendLogger as logger } from '@/server/logger' +import { LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME } from '@/graphql/resolver/util' +import { getLogger } from 'log4js' + +const createLogger = () => getLogger(`${LOG4JS_GRAPHQL_RESOLVER_UTIL_CATEGORY_NAME}.syncHumhub`) /** * Syncs the user with humhub @@ -21,6 +24,8 @@ export async function syncHumhub( oldHumhubUsername: string, spaceId?: number | null, ): Promise { + const logger = createLogger() + logger.addContext('user', user.id) // check for humhub relevant changes if ( updateUserInfosArg && diff --git a/backend/src/graphql/resolver/util/validateAlias.test.ts b/backend/src/graphql/resolver/util/validateAlias.test.ts index c57a6332f..f10f54886 100644 --- a/backend/src/graphql/resolver/util/validateAlias.test.ts +++ b/backend/src/graphql/resolver/util/validateAlias.test.ts @@ -2,14 +2,18 @@ import { ApolloServerTestClient } from 'apollo-server-testing' import { User } from 'database' import { DataSource } from 'typeorm' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { cleanDB, testEnvironment } from '@test/helpers' -import { i18n as localization, logger } from '@test/testSetup' +import { i18n as localization } from '@test/testSetup' +import { getLogger } from 'config-schema/test/testSetup' import { userFactory } from '@/seeds/factory/user' import { bibiBloxberg } from '@/seeds/users/bibi-bloxberg' import { validateAlias } from './validateAlias' +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + let con: DataSource let testEnv: { mutate: ApolloServerTestClient['mutate'] @@ -18,7 +22,7 @@ let testEnv: { } beforeAll(async () => { - testEnv = await testEnvironment(logger, localization) + testEnv = await testEnvironment(getLogger('apollo'), localization) con = testEnv.con await cleanDB() }) diff --git a/backend/src/index.ts b/backend/src/index.ts index 01f7f47a3..6197f39df 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -1,10 +1,14 @@ import 'reflect-metadata' +import 'source-map-support/register' +import { getLogger } from 'log4js' import { CONFIG } from './config' import { startValidateCommunities } from './federation/validateCommunities' import { createServer } from './server/createServer' +import { initLogging } from './server/logger' async function main() { - const { app } = await createServer() + initLogging() + const { app } = await createServer(getLogger('apollo')) app.listen(CONFIG.PORT, () => { // biome-ignore lint/suspicious/noConsole: no need for logging the start message diff --git a/backend/src/interactions/index.ts b/backend/src/interactions/index.ts new file mode 100644 index 000000000..3aad98ba5 --- /dev/null +++ b/backend/src/interactions/index.ts @@ -0,0 +1,3 @@ +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' + +export const LOG4JS_INTERACTION_CATEGORY_NAME = `${LOG4JS_BASE_CATEGORY_NAME}.interaction` diff --git a/backend/src/interactions/updateUnconfirmedContribution/AbstractUnconfirmedContribution.role.ts b/backend/src/interactions/updateUnconfirmedContribution/AbstractUnconfirmedContribution.role.ts index 36369987b..b713aeefd 100644 --- a/backend/src/interactions/updateUnconfirmedContribution/AbstractUnconfirmedContribution.role.ts +++ b/backend/src/interactions/updateUnconfirmedContribution/AbstractUnconfirmedContribution.role.ts @@ -5,13 +5,16 @@ import { Role } from '@/auth/Role' import { ContributionLogic } from '@/data/Contribution.logic' import { ContributionMessageBuilder } from '@/data/ContributionMessage.builder' import { ContributionStatus } from '@/graphql/enum/ContributionStatus' +import { LOG4JS_INTERACTION_CATEGORY_NAME } from '@/interactions' import { LogError } from '@/server/LogError' import { Context, getClientTimezoneOffset } from '@/server/context' +import { Logger, getLogger } from 'log4js' export abstract class AbstractUnconfirmedContributionRole { private availableCreationSums?: Decimal[] protected changed = true private currentStep = 0 + protected logger: Logger public constructor( protected self: Contribution, @@ -21,6 +24,8 @@ export abstract class AbstractUnconfirmedContributionRole { if (self.confirmedAt || self.deniedAt) { throw new LogError("this contribution isn't unconfirmed!") } + this.logger = getLogger(`${LOG4JS_INTERACTION_CATEGORY_NAME}.updateUnconfirmedContribution`) + this.logger.addContext('contribution', this.self.id) } public isChanged(): boolean { diff --git a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdmin.role.ts b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdmin.role.ts index a216a8919..f160966d3 100644 --- a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdmin.role.ts +++ b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdmin.role.ts @@ -6,8 +6,6 @@ import { ContributionMessageBuilder } from '@/data/ContributionMessage.builder' import { AdminUpdateContributionArgs } from '@/graphql/arg/AdminUpdateContributionArgs' import { ContributionStatus } from '@/graphql/enum/ContributionStatus' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' - import { AbstractUnconfirmedContributionRole } from './AbstractUnconfirmedContribution.role' /** @@ -25,7 +23,7 @@ export class UnconfirmedContributionAdminRole extends AbstractUnconfirmedContrib updateData.amount ?? contribution.amount, updateData.creationDate ? new Date(updateData.creationDate) : contribution.contributionDate, ) - logger.debug('use UnconfirmedContributionAdminRole') + this.logger.debug('use UnconfirmedContributionAdminRole') } /** diff --git a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdminAddMessage.role.ts b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdminAddMessage.role.ts index 42bb75e00..dcc10091f 100644 --- a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdminAddMessage.role.ts +++ b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionAdminAddMessage.role.ts @@ -7,7 +7,6 @@ import { ContributionMessageArgs } from '@/graphql/arg/ContributionMessageArgs' import { ContributionMessageType } from '@/graphql/enum/ContributionMessageType' import { ContributionStatus } from '@/graphql/enum/ContributionStatus' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { AbstractUnconfirmedContributionRole } from './AbstractUnconfirmedContribution.role' @@ -21,7 +20,7 @@ export class UnconfirmedContributionAdminAddMessageRole extends AbstractUnconfir private updateData: ContributionMessageArgs, ) { super(contribution, contribution.amount, contribution.contributionDate) - logger.debug('use UnconfirmedContributionAdminAddMessageRole') + this.logger.debug('use UnconfirmedContributionAdminAddMessageRole') } protected update(): void { diff --git a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUser.role.ts b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUser.role.ts index dedc7a1d1..6955cbfa7 100644 --- a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUser.role.ts +++ b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUser.role.ts @@ -4,7 +4,6 @@ import { ContributionMessageBuilder } from '@/data/ContributionMessage.builder' import { ContributionArgs } from '@/graphql/arg/ContributionArgs' import { ContributionStatus } from '@/graphql/enum/ContributionStatus' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { AbstractUnconfirmedContributionRole } from './AbstractUnconfirmedContribution.role' @@ -18,7 +17,7 @@ export class UnconfirmedContributionUserRole extends AbstractUnconfirmedContribu private updateData: ContributionArgs, ) { super(contribution, updateData.amount, new Date(updateData.contributionDate)) - logger.debug('use UnconfirmedContributionUserRole') + this.logger.debug('use UnconfirmedContributionUserRole') } protected update(): void { diff --git a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUserAddMessage.role.ts b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUserAddMessage.role.ts index 77d89ac2b..0440762f3 100644 --- a/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUserAddMessage.role.ts +++ b/backend/src/interactions/updateUnconfirmedContribution/UnconfirmedContributionUserAddMessage.role.ts @@ -5,7 +5,6 @@ import { ContributionMessageArgs } from '@/graphql/arg/ContributionMessageArgs' import { ContributionMessageType } from '@/graphql/enum/ContributionMessageType' import { ContributionStatus } from '@/graphql/enum/ContributionStatus' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { AbstractUnconfirmedContributionRole } from './AbstractUnconfirmedContribution.role' @@ -19,7 +18,7 @@ export class UnconfirmedContributionUserAddMessageRole extends AbstractUnconfirm private updateData: ContributionMessageArgs, ) { super(contribution, contribution.amount, contribution.contributionDate) - logger.debug('use UnconfirmedContributionUserAddMessageRole') + this.logger.debug('use UnconfirmedContributionUserAddMessageRole') } protected update(): void { diff --git a/backend/src/password/EncryptorUtils.ts b/backend/src/password/EncryptorUtils.ts index 7da8bc9c1..20ff202b7 100644 --- a/backend/src/password/EncryptorUtils.ts +++ b/backend/src/password/EncryptorUtils.ts @@ -8,7 +8,6 @@ import { PasswordEncryptionType } from '@enum/PasswordEncryptionType' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' import { crypto_shorthash_KEYBYTES } from 'sodium-native' @@ -40,7 +39,6 @@ export const SecretKeyCryptographyCreateKey = async ( password: string, ): Promise => { try { - logger.trace('call worker for: SecretKeyCryptographyCreateKey') if (configLoginServerKey.length !== crypto_shorthash_KEYBYTES) { throw new LogError( 'ServerKey has an invalid size', diff --git a/backend/src/password/PasswordEncryptor.ts b/backend/src/password/PasswordEncryptor.ts index 1131b97ef..9efe4e60e 100644 --- a/backend/src/password/PasswordEncryptor.ts +++ b/backend/src/password/PasswordEncryptor.ts @@ -1,6 +1,5 @@ import { User } from 'database' -// import { logger } from '@test/testSetup' getting error "jest is not defined" import { SecretKeyCryptographyCreateKey, getUserCryptographicSalt } from './EncryptorUtils' export const encryptPassword = async (dbUser: User, password: string): Promise => { diff --git a/backend/src/password/__mocks__/EncryptorUtils.ts b/backend/src/password/__mocks__/EncryptorUtils.ts index 5575f72f7..1bac06239 100644 --- a/backend/src/password/__mocks__/EncryptorUtils.ts +++ b/backend/src/password/__mocks__/EncryptorUtils.ts @@ -4,8 +4,9 @@ import { PasswordEncryptionType } from '@enum/PasswordEncryptionType' import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { crypto_box_SEEDBYTES, crypto_hash_sha512_BYTES, @@ -22,6 +23,8 @@ import { crypto_shorthash_KEYBYTES, } from 'sodium-native' +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.password.EncryptorUtils`) + const SecretKeyCryptographyCreateKeyMock = ( salt: string, password: string, diff --git a/backend/src/seeds/index.ts b/backend/src/seeds/index.ts index 8036d49e5..d99e33872 100644 --- a/backend/src/seeds/index.ts +++ b/backend/src/seeds/index.ts @@ -4,8 +4,9 @@ import { datatype, internet, name } from 'faker' import { CONFIG } from '@/config' import { createServer } from '@/server/createServer' -import { backendLogger as logger } from '@/server/logger' +import { initLogging } from '@/server/logger' +import { getLogger } from 'log4js' import { writeHomeCommunityEntry } from './community' import { contributionLinks } from './contributionLink/index' import { creations } from './creation/index' @@ -17,6 +18,7 @@ import { transactionLinks } from './transactionLink/index' import { users } from './users/index' CONFIG.EMAIL = false +const logger = getLogger('seed') const context = { token: '', @@ -48,7 +50,7 @@ const resetEntity = async (entity: any) => { } const run = async () => { - const server = await createServer(context) + const server = await createServer(getLogger('apollo'), context) const seedClient = createTestClient(server.apollo) const { con } = server await cleanDB() @@ -97,6 +99,7 @@ const run = async () => { } run().catch((err) => { + initLogging() // biome-ignore lint/suspicious/noConsole: no logger present console.error('error on seeding', err) }) diff --git a/backend/src/server/LogError.test.ts b/backend/src/server/LogError.test.ts index 431b60e6e..3b98aea89 100644 --- a/backend/src/server/LogError.test.ts +++ b/backend/src/server/LogError.test.ts @@ -1,7 +1,10 @@ -import { logger } from '@test/testSetup' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { getLogger } from 'config-schema/test/testSetup' import { LogError } from './LogError' +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + describe('LogError', () => { it('logs an Error when created', () => { new LogError('new LogError') diff --git a/backend/src/server/LogError.ts b/backend/src/server/LogError.ts index 346923019..c455eaa15 100644 --- a/backend/src/server/LogError.ts +++ b/backend/src/server/LogError.ts @@ -1,5 +1,21 @@ -import { backendLogger as logger } from './logger' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' +import { getLogger } from 'log4js' +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.LogError`) + +/** + * A custom Error that logs itself immediately upon instantiation. + * + * TODO: Anti-pattern warning: + * Logging inside the constructor introduces side effects during object creation, + * which breaks separation of concerns and can lead to duplicate or unwanted logs. + * It is generally better to log errors where they are caught, not where they are thrown. + * + * @class LogError + * @extends {Error} + * @param {string} msg - The error message. + * @param {...any} details - Additional details passed to the logger. + */ export class LogError extends Error { constructor(msg: string, ...details: any[]) { super(msg) diff --git a/backend/src/server/createServer.ts b/backend/src/server/createServer.ts index 40d0144fa..60f6fc31e 100644 --- a/backend/src/server/createServer.ts +++ b/backend/src/server/createServer.ts @@ -6,14 +6,14 @@ import { ApolloServer } from 'apollo-server-express' import express, { Express, json, urlencoded } from 'express' import { slowDown } from 'express-slow-down' import helmet from 'helmet' -import { Logger } from 'log4js' +import { Logger, getLogger } from 'log4js' import { DataSource } from 'typeorm' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { AppDatabase } from 'database' import { context as serverContext } from './context' import { cors } from './cors' import { i18n } from './localization' -import { apolloLogger } from './logger' import { plugins } from './plugins' // TODO implement // import queryComplexity, { simpleEstimator, fieldConfigEstimator } from "graphql-query-complexity"; @@ -25,11 +25,11 @@ interface ServerDef { } export const createServer = async ( + apolloLogger: Logger, context: any = serverContext, - logger: Logger = apolloLogger, localization: i18n.I18n = i18n, ): Promise => { - logger.addContext('user', 'unknown') + const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.createServer`) logger.debug('createServer...') // open mariadb connection, retry connecting with mariadb @@ -91,7 +91,7 @@ export const createServer = async ( introspection: CONFIG.GRAPHIQL, context, plugins, - logger, + logger: apolloLogger, }) apollo.applyMiddleware({ app, path: '/' }) logger.info( diff --git a/backend/src/server/localization.ts b/backend/src/server/localization.ts index 8e533576a..1e587104a 100644 --- a/backend/src/server/localization.ts +++ b/backend/src/server/localization.ts @@ -1,7 +1,9 @@ import path from 'node:path' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import i18n from 'i18n' +import { getLogger } from 'log4js' -import { backendLogger } from './logger' +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.server.localization`) i18n.configure({ locales: ['en', 'de'], @@ -11,9 +13,9 @@ i18n.configure({ // autoReload: true, // if this is activated the seeding hangs at the very end updateFiles: false, objectNotation: true, - logDebugFn: (msg) => backendLogger.debug(msg), - logWarnFn: (msg) => backendLogger.info(msg), - logErrorFn: (msg) => backendLogger.error(msg), + logDebugFn: (msg) => logger.debug(msg), + logWarnFn: (msg) => logger.info(msg), + logErrorFn: (msg) => logger.error(msg), // this api is needed for email-template pug files api: { __: 't', // now req.__ becomes req.t diff --git a/backend/src/server/logger.ts b/backend/src/server/logger.ts index 24ae79c67..be9cababe 100644 --- a/backend/src/server/logger.ts +++ b/backend/src/server/logger.ts @@ -1,21 +1,17 @@ -import { readFileSync } from 'fs' - -import { configure, getLogger } from 'log4js' - import { CONFIG } from '@/config' +import { defaultCategory, initLogger } from 'config-schema' -const options = JSON.parse(readFileSync(CONFIG.LOG4JS_CONFIG, 'utf-8')) - -options.categories.backend.level = CONFIG.LOG_LEVEL -options.categories.apollo.level = CONFIG.LOG_LEVEL - -configure(options) - -const apolloLogger = getLogger('apollo') -const backendLogger = getLogger('backend') -const klickTippLogger = getLogger('klicktipp') -const gmsLogger = getLogger('gms') - -backendLogger.addContext('user', 'unknown') - -export { apolloLogger, backendLogger, klickTippLogger, gmsLogger } +export function initLogging() { + // init logger + initLogger( + [ + defaultCategory('backend', CONFIG.LOG_LEVEL), + defaultCategory('apollo', CONFIG.LOG_LEVEL), + defaultCategory('klicktipp', CONFIG.LOG_LEVEL), + defaultCategory('gms', CONFIG.LOG_LEVEL), + defaultCategory('seed', CONFIG.LOG_LEVEL), + ], + CONFIG.LOG_FILES_BASE_PATH, + CONFIG.LOG4JS_CONFIG, + ) +} diff --git a/backend/src/util/Monitor.ts b/backend/src/util/Monitor.ts index f592a343d..31d6d8938 100644 --- a/backend/src/util/Monitor.ts +++ b/backend/src/util/Monitor.ts @@ -1,7 +1,8 @@ import { registerEnumType } from 'type-graphql' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { LogError } from '@/server/LogError' -import { backendLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' export enum MonitorNames { SEND_DLT_TRANSACTIONS = 1, @@ -15,6 +16,7 @@ registerEnumType(MonitorNames, { /* @typescript-eslint/no-extraneous-class */ export class Monitor { private static locks = new Map() + private static logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.util.Monitor`) private constructor() {} @@ -25,15 +27,15 @@ export class Monitor { public static isLocked(key: MonitorNames): boolean | undefined { if (this.locks.has(key)) { - logger.debug(`Monitor isLocked key=${key} = `, this.locks.get(key)) + this.logger.debug(`Monitor isLocked key=${key} = `, this.locks.get(key)) return this.locks.get(key) } - logger.debug(`Monitor isLocked key=${key} not exists`) + this.logger.debug(`Monitor isLocked key=${key} not exists`) return false } public static lockIt(key: MonitorNames): void { - logger.debug(`Monitor lockIt key=`, key) + this.logger.debug(`Monitor lockIt key=`, key) if (this.locks.has(key)) { throw new LogError('still existing Monitor with key=', key) } @@ -41,7 +43,7 @@ export class Monitor { } public static releaseIt(key: MonitorNames): void { - logger.debug(`Monitor releaseIt key=`, key) + this.logger.debug(`Monitor releaseIt key=`, key) if (this.locks.has(key)) { this.locks.delete(key) } diff --git a/backend/src/util/decay.ts b/backend/src/util/decay.ts index 1d1775cc9..96c7ddb4b 100644 --- a/backend/src/util/decay.ts +++ b/backend/src/util/decay.ts @@ -2,8 +2,13 @@ import { Decimal } from 'decimal.js-light' import { Decay } from '@model/Decay' -import { CONFIG } from '@/config' import { LogError } from '@/server/LogError' +import { DECAY_START_TIME } from 'config-schema' + +Decimal.set({ + precision: 25, + rounding: Decimal.ROUND_HALF_UP, +}) // TODO: externalize all those definitions and functions into an external decay library @@ -18,7 +23,7 @@ function calculateDecay( amount: Decimal, from: Date, to: Date, - startBlock: Date = CONFIG.DECAY_START_TIME, + startBlock: Date = DECAY_START_TIME, ): Decay { const fromMs = from.getTime() const toMs = to.getTime() diff --git a/backend/src/util/time.ts b/backend/src/util/time.ts index 0acaf2501..ccbb91c07 100644 --- a/backend/src/util/time.ts +++ b/backend/src/util/time.ts @@ -1,3 +1,6 @@ +/** + * @param {number} time - in minutes + */ export const getTimeDurationObject = ( time: number, ): { @@ -13,11 +16,27 @@ export const getTimeDurationObject = ( return { minutes: time } } +/** + * @param startDate + * @param endDate + * @returns duration in minutes + */ +export const durationInMinutesFromDates = (startDate: Date, endDate: Date): number => { + const diff = endDate.getTime() - startDate.getTime() + return Math.floor(diff / (1000 * 60)) +} + +/** + * @param duration in minutes + */ export const printTimeDuration = (duration: number): string => { const time = getTimeDurationObject(duration) const result = time.minutes > 0 ? `${time.minutes} minutes` : '' if (time.hours) { return `${time.hours} hours` + (result !== '' ? ` and ${result}` : '') } + if (result === '') { + return '0 minutes' + } return result } diff --git a/backend/src/webhook/elopage.ts b/backend/src/webhook/elopage.ts index b027633a6..64113062f 100644 --- a/backend/src/webhook/elopage.ts +++ b/backend/src/webhook/elopage.ts @@ -25,10 +25,13 @@ I assume that the webhook arrives via POST and transmits a string as shown above */ -import { backendLogger as logger } from '@/server/logger' import { LoginElopageBuys, UserContact as dbUserContact } from 'database' +import { LOG4JS_BASE_CATEGORY_NAME } from '@/config/const' import { UserResolver } from '@/graphql/resolver/UserResolver' +import { getLogger } from 'log4js' + +const logger = getLogger(`${LOG4JS_BASE_CATEGORY_NAME}.webhook.elopage`) export const elopageWebhook = async (req: any, res: any): Promise => { logger.info('Elopage Hook received') diff --git a/backend/src/webhook/gms.ts b/backend/src/webhook/gms.ts index 915552390..06f48024d 100644 --- a/backend/src/webhook/gms.ts +++ b/backend/src/webhook/gms.ts @@ -1,7 +1,9 @@ import { User as DbUser } from 'database' import { decode } from '@/auth/JWT' -import { gmsLogger as logger } from '@/server/logger' +import { getLogger } from 'log4js' + +const logger = getLogger('gms.GmsWebhook') export const gmsWebhook = async (req: any, res: any): Promise => { logger.info('GMS Hook received') diff --git a/backend/test/helpers.ts b/backend/test/helpers.ts index 6d567f029..a966eccf6 100644 --- a/backend/test/helpers.ts +++ b/backend/test/helpers.ts @@ -3,7 +3,9 @@ import { entities } from 'database' import { createServer } from '@/server/createServer' -import { i18n, logger } from './testSetup' +import { i18n } from './testSetup' + +import { getLogger } from 'log4js' export const headerPushMock = jest.fn((t) => { context.token = t.value @@ -25,8 +27,8 @@ export const cleanDB = async () => { } } -export const testEnvironment = async (testLogger = logger, testI18n = i18n) => { - const server = await createServer(context, testLogger, testI18n) +export const testEnvironment = async (testLogger = getLogger('apollo'), testI18n = i18n) => { + const server = await createServer( testLogger, context, testI18n) const con = server.con const testClient = createTestClient(server.apollo) const mutate = testClient.mutate diff --git a/backend/test/testSetup.ts b/backend/test/testSetup.ts index 02c325794..c010ff705 100644 --- a/backend/test/testSetup.ts +++ b/backend/test/testSetup.ts @@ -1,7 +1,7 @@ import 'openai/shims/node' import { CONFIG } from '@/config' import { i18n } from '@/server/localization' -import { backendLogger as logger } from '@/server/logger' +import { getLogger, printLogs, clearLogs } from 'config-schema/test/testSetup' CONFIG.EMAIL = true CONFIG.EMAIL_TEST_MODUS = false @@ -10,23 +10,6 @@ CONFIG.GMS_ACTIVE = false jest.setTimeout(1000000) -jest.mock('@/server/logger', () => { - const originalModule = jest.requireActual('@/server/logger') - return { - __esModule: true, - ...originalModule, - backendLogger: { - addContext: jest.fn(), - trace: jest.fn(), - debug: jest.fn(), - warn: jest.fn(), - info: jest.fn(), - error: jest.fn(), - fatal: jest.fn(), - }, - } -}) - jest.mock('@/server/localization', () => { const originalModule = jest.requireActual('@/server/localization') return { @@ -41,4 +24,4 @@ jest.mock('@/server/localization', () => { } }) -export { logger, i18n } +export { i18n, getLogger, printLogs, clearLogs as cleanLogs } diff --git a/backend/tsconfig.json b/backend/tsconfig.json index 79bdd2cf3..2152f4b79 100644 --- a/backend/tsconfig.json +++ b/backend/tsconfig.json @@ -12,7 +12,7 @@ // "jsx": "preserve", /* Specify JSX code generation: 'preserve', 'react-native', 'react', 'react-jsx' or 'react-jsxdev'. */ // "declaration": true, /* Generates corresponding '.d.ts' file. */ // "declarationMap": true, /* Generates a sourcemap for each corresponding '.d.ts' file. */ - // "sourceMap": true, /* Generates corresponding '.map' file. */ + "sourceMap": true, /* Generates corresponding '.map' file. */ // "outFile": "./", /* Concatenate and emit output to single file. */ "outDir": "./build", /* Redirect output structure to the directory. */ // "rootDir" : ".", diff --git a/backend/turbo.json b/backend/turbo.json index e4dfea9a8..fa9af6ce2 100644 --- a/backend/turbo.json +++ b/backend/turbo.json @@ -24,6 +24,9 @@ }, "start": { "dependsOn": ["database#up", "build"] + }, + "start:bundle": { + "dependsOn": ["build:bundle"] } } } \ No newline at end of file