Merge pull request #1859 from gradido/improve-apollo-logging

feat: 🍰 Improve Apollo Logging

.github/workflows/test.yml

@@ -528,7 +528,7 @@ jobs:
           report_name: Coverage Backend
           type: lcov
           result_path: ./backend/coverage/lcov.info
-          min_coverage: 65
+          min_coverage: 64
           token: ${{ github.token }}
 
   ##########################################################################

.gitignore

@@ -1,3 +1,5 @@
+.dbeaver
+.project
 *.log
 /node_modules/*
 messages.pot

admin/.prettierrc.js

@@ -4,5 +4,6 @@ module.exports = {
   singleQuote: true,
   trailingComma: "all",
   tabWidth: 2,
-  bracketSpacing: true
+  bracketSpacing: true,
+  endOfLine: "auto",
 };

backend/.env.dist

@@ -49,4 +49,8 @@ EMAIL_CODE_VALID_TIME=1440
 EMAIL_CODE_REQUEST_TIME=10
 
 # Webhook
-WEBHOOK_ELOPAGE_SECRET=secret
+WEBHOOK_ELOPAGE_SECRET=secret
+
+# SET LOG LEVEL AS NEEDED IN YOUR .ENV
+# POSSIBLE VALUES: all | trace | debug | info | warn | error | fatal
+# LOG_LEVEL=info

backend/.env.template

@@ -47,4 +47,4 @@ EMAIL_CODE_VALID_TIME=$EMAIL_CODE_VALID_TIME
 EMAIL_CODE_REQUEST_TIME=$EMAIL_CODE_REQUEST_TIME
 
 # Webhook
-WEBHOOK_ELOPAGE_SECRET=$WEBHOOK_ELOPAGE_SECRET
+WEBHOOK_ELOPAGE_SECRET=$WEBHOOK_ELOPAGE_SECRET

backend/.prettierrc.js

@@ -5,4 +5,5 @@ module.exports = {
   trailingComma: "all",
   tabWidth: 2,
   bracketSpacing: true,
+  endOfLine: "auto",
 };

backend/log4js-config.json

@@ -0,0 +1,66 @@
+{
+  "appenders": 
+  {
+    "access": 
+    {
+      "type": "dateFile",
+      "filename": "../logs/backend/access.log",
+      "pattern": "%d{ISO8601} %p %c %X{user} %f:%l %m",
+      "keepFileExt" : true,
+      "fileNameSep" : "_" 
+    },
+    "apollo": 
+    {
+      "type": "dateFile",
+      "filename": "../logs/backend/apollo.log",
+      "pattern": "%d{ISO8601} %p %c %X{user} %f:%l %m",
+      "keepFileExt" : true,
+      "fileNameSep" : "_" 
+    },
+    "errorFile": 
+    {
+      "type": "dateFile",
+      "filename": "../logs/backend/errors.log",
+      "pattern": "%d{ISO8601} %p %c %X{user} %f:%l %m",
+      "keepFileExt" : true,
+      "fileNameSep" : "_" 
+    },
+    "errors": 
+    {
+      "type": "logLevelFilter",
+      "level": "error",
+      "appender": "errorFile"
+    },
+    "out": 
+    {
+      "type": "stdout",
+      "layout": 
+      {
+        "type": "pattern", "pattern": "%d{ISO8601} %p %c %X{user} %f:%l %m"
+      }
+
+    }
+  },
+  "categories": 
+  {
+    "default": 
+    {
+      "appenders": 
+      [
+        "out",
+        "apollo",
+        "errors"
+      ],
+      "level": "debug",
+      "enableCallStack": true
+    },
+    "http": 
+    {
+      "appenders": 
+      [
+        "access"
+      ],
+      "level": "info"
+    }
+  }
+}

backend/package.json

@@ -19,7 +19,6 @@
   "dependencies": {
     "@types/jest": "^27.0.2",
     "@types/lodash.clonedeep": "^4.5.6",
-    "apollo-log": "^1.1.0",
     "apollo-server-express": "^2.25.2",
     "apollo-server-testing": "^2.25.2",
     "axios": "^0.21.1",
@@ -33,6 +32,7 @@
     "jest": "^27.2.4",
     "jsonwebtoken": "^8.5.1",
     "lodash.clonedeep": "^4.5.0",
+    "log4js": "^6.4.6",
     "mysql2": "^2.3.0",
     "nodemailer": "^6.6.5",
     "random-bigint": "^0.0.1",

backend/src/apis/HttpRequest.ts

@@ -1,10 +1,14 @@
 import axios from 'axios'
 
+import { backendLogger as logger } from '@/server/logger'
+
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
 export const apiPost = async (url: string, payload: unknown): Promise<any> => {
+  logger.trace('POST: url=' + url + ' payload=' + payload)
   return axios
     .post(url, payload)
     .then((result) => {
+      logger.trace('POST-Response: result=' + result)
       if (result.status !== 200) {
         throw new Error('HTTP Status Error ' + result.status)
       }
@@ -20,9 +24,11 @@ export const apiPost = async (url: string, payload: unknown): Promise<any> => {
 
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
 export const apiGet = async (url: string): Promise<any> => {
+  logger.trace('GET: url=' + url)
   return axios
     .get(url)
     .then((result) => {
+      logger.trace('GET-Response: result=' + result)
       if (result.status !== 200) {
         throw new Error('HTTP Status Error ' + result.status)
       }

backend/src/config/index.ts

@@ -12,6 +12,9 @@ Decimal.set({
 const constants = {
   DB_VERSION: '0036-unique_previous_in_transactions',
   DECAY_START_TIME: new Date('2021-05-13 17:46:31'), // GMT+0
+  LOG4JS_CONFIG: 'log4js-config.json',
+  // default log level on production should be info
+  LOG_LEVEL: process.env.LOG_LEVEL || 'info',
   CONFIG_VERSION: {
     DEFAULT: 'DEFAULT',
     EXPECTED: 'v6.2022-04-21',

backend/src/graphql/resolver/BalanceResolver.ts

@@ -1,3 +1,5 @@
+import { backendLogger as logger } from '@/server/logger'
+
 import { Context, getUser } from '@/server/context'
 import { Resolver, Query, Ctx, Authorized } from 'type-graphql'
 import { Balance } from '@model/Balance'
@@ -18,15 +20,22 @@ export class BalanceResolver {
     const user = getUser(context)
     const now = new Date()
 
+    logger.addContext('user', user.id)
+    logger.info(`balance(userId=${user.id})...`)
+
     const gdtResolver = new GdtResolver()
     const balanceGDT = await gdtResolver.gdtBalance(context)
+    logger.debug(`balanceGDT=${balanceGDT}`)
 
     const lastTransaction = context.lastTransaction
       ? context.lastTransaction
       : await dbTransaction.findOne({ userId: user.id }, { order: { balanceDate: 'DESC' } })
 
+    logger.debug(`lastTransaction=${lastTransaction}`)
+
     // No balance found
     if (!lastTransaction) {
+      logger.info(`no balance found, return Default-Balance!`)
       return new Balance({
         balance: new Decimal(0),
         balanceGDT,
@@ -39,6 +48,8 @@ export class BalanceResolver {
       context.transactionCount || context.transactionCount === 0
         ? context.transactionCount
         : await dbTransaction.count({ where: { userId: user.id } })
+    logger.debug(`transactionCount=${count}`)
+
     const linkCount = await dbTransactionLink.count({
       where: {
         userId: user.id,
@@ -46,6 +57,7 @@ export class BalanceResolver {
         // validUntil: MoreThan(new Date()),
       },
     })
+    logger.debug(`linkCount=${linkCount}`)
 
     // The decay is always calculated on the last booked transaction
     const calculatedDecay = calculateDecay(
@@ -53,6 +65,9 @@ export class BalanceResolver {
       lastTransaction.balanceDate,
       now,
     )
+    logger.info(
+      `calculatedDecay(balance=${lastTransaction.balance}, balanceDate=${lastTransaction.balanceDate})=${calculatedDecay}`,
+    )
 
     // The final balance is reduced by the link amount withheld
     const transactionLinkRepository = getCustomRepository(TransactionLinkRepository)
@@ -60,13 +75,27 @@ export class BalanceResolver {
       ? { sumHoldAvailableAmount: context.sumHoldAvailableAmount }
       : await transactionLinkRepository.summary(user.id, now)
 
-    return new Balance({
+    logger.debug(`context.sumHoldAvailableAmount=${context.sumHoldAvailableAmount}`)
-      balance: calculatedDecay.balance
+    logger.debug(`sumHoldAvailableAmount=${sumHoldAvailableAmount}`)
-        .minus(sumHoldAvailableAmount.toString())
+
-        .toDecimalPlaces(2, Decimal.ROUND_DOWN), // round towards zero
+    const balance = calculatedDecay.balance
+      .minus(sumHoldAvailableAmount.toString())
+      .toDecimalPlaces(2, Decimal.ROUND_DOWN) // round towards zero
+
+    // const newBalance = new Balance({
+    //      balance: calculatedDecay.balance
+    //        .minus(sumHoldAvailableAmount.toString())
+    //        .toDecimalPlaces(2, Decimal.ROUND_DOWN),
+    const newBalance = new Balance({
+      balance,
       balanceGDT,
       count,
       linkCount,
     })
+    logger.info(
+      `new Balance(balance=${balance}, balanceGDT=${balanceGDT}, count=${count}, linkCount=${linkCount}) = ${newBalance}`,
+    )
+
+    return newBalance
   }
 }

backend/src/graphql/resolver/TransactionResolver.ts

@@ -1,6 +1,7 @@
 /* eslint-disable new-cap */
 /* eslint-disable @typescript-eslint/no-non-null-assertion */
 
+import { backendLogger as logger } from '@/server/logger'
 import CONFIG from '@/config'
 
 import { Context, getUser } from '@/server/context'
@@ -44,15 +45,22 @@ export const executeTransaction = async (
   recipient: dbUser,
   transactionLink?: dbTransactionLink | null,
 ): Promise<boolean> => {
+  logger.info(
+    `executeTransaction(amount=${amount}, memo=${memo}, sender=${sender}, recipient=${recipient})...`,
+  )
+
   if (sender.id === recipient.id) {
+    logger.error(`Sender and Recipient are the same.`)
     throw new Error('Sender and Recipient are the same.')
   }
 
   if (memo.length > MEMO_MAX_CHARS) {
+    logger.error(`memo text is too long: memo.length=${memo.length} > (${MEMO_MAX_CHARS}`)
     throw new Error(`memo text is too long (${MEMO_MAX_CHARS} characters maximum)`)
   }
 
   if (memo.length < MEMO_MIN_CHARS) {
+    logger.error(`memo text is too short: memo.length=${memo.length} < (${MEMO_MIN_CHARS}`)
     throw new Error(`memo text is too short (${MEMO_MIN_CHARS} characters minimum)`)
   }
 
@@ -64,13 +72,16 @@ export const executeTransaction = async (
     receivedCallDate,
     transactionLink,
   )
+  logger.debug(`calculated Balance=${sendBalance}`)
   if (!sendBalance) {
+    logger.error(`user hasn't enough GDD or amount is < 0 : balance=${sendBalance}`)
     throw new Error("user hasn't enough GDD or amount is < 0")
   }
 
   const queryRunner = getConnection().createQueryRunner()
   await queryRunner.connect()
   await queryRunner.startTransaction('READ UNCOMMITTED')
+  logger.debug(`open Transaction to write...`)
   try {
     // transaction
     const transactionSend = new dbTransaction()
@@ -87,6 +98,8 @@ export const executeTransaction = async (
     transactionSend.transactionLinkId = transactionLink ? transactionLink.id : null
     await queryRunner.manager.insert(dbTransaction, transactionSend)
 
+    logger.debug(`sendTransaction inserted: ${dbTransaction}`)
+
     const transactionReceive = new dbTransaction()
     transactionReceive.typeId = TransactionTypeId.RECEIVE
     transactionReceive.memo = memo
@@ -102,12 +115,15 @@ export const executeTransaction = async (
     transactionReceive.linkedTransactionId = transactionSend.id
     transactionReceive.transactionLinkId = transactionLink ? transactionLink.id : null
     await queryRunner.manager.insert(dbTransaction, transactionReceive)
+    logger.debug(`receive Transaction inserted: ${dbTransaction}`)
 
     // Save linked transaction id for send
     transactionSend.linkedTransactionId = transactionReceive.id
     await queryRunner.manager.update(dbTransaction, { id: transactionSend.id }, transactionSend)
+    logger.debug(`send Transaction updated: ${transactionSend}`)
 
     if (transactionLink) {
+      logger.info(`transactionLink: ${transactionLink}`)
       transactionLink.redeemedAt = receivedCallDate
       transactionLink.redeemedBy = recipient.id
       await queryRunner.manager.update(
@@ -118,13 +134,15 @@ export const executeTransaction = async (
     }
 
     await queryRunner.commitTransaction()
+    logger.info(`commit Transaction successful...`)
   } catch (e) {
     await queryRunner.rollbackTransaction()
+    logger.error(`Transaction was not successful: ${e}`)
     throw new Error(`Transaction was not successful: ${e}`)
   } finally {
     await queryRunner.release()
   }
-
+  logger.debug(`prepare Email for transaction received...`)
   // send notification email
   // TODO: translate
   await sendTransactionReceivedEmail({
@@ -138,7 +156,7 @@ export const executeTransaction = async (
     memo,
     overviewURL: CONFIG.EMAIL_LINK_OVERVIEW,
   })
-
+  logger.info(`finished executeTransaction successfully`)
   return true
 }
 
@@ -154,16 +172,21 @@ export class TransactionResolver {
     const now = new Date()
     const user = getUser(context)
 
+    logger.addContext('user', user.id)
+    logger.info(`transactionList(user=${user.firstName}.${user.lastName}, ${user.email})`)
+
     // find current balance
     const lastTransaction = await dbTransaction.findOne(
       { userId: user.id },
       { order: { balanceDate: 'DESC' } },
     )
+    logger.debug(`lastTransaction=${lastTransaction}`)
 
     const balanceResolver = new BalanceResolver()
     context.lastTransaction = lastTransaction
 
     if (!lastTransaction) {
+      logger.info('no lastTransaction')
       return new TransactionList(await balanceResolver.balance(context), [])
     }
 
@@ -186,6 +209,8 @@ export class TransactionResolver {
         involvedUserIds.push(transaction.linkedUserId)
       }
     })
+    logger.debug(`involvedUserIds=${involvedUserIds}`)
+
     // We need to show the name for deleted users for old transactions
     const involvedDbUsers = await dbUser
       .createQueryBuilder()
@@ -193,6 +218,7 @@ export class TransactionResolver {
       .where('id IN (:...userIds)', { userIds: involvedUserIds })
       .getMany()
     const involvedUsers = involvedDbUsers.map((u) => new User(u))
+    logger.debug(`involvedUsers=${involvedUsers}`)
 
     const self = new User(user)
     const transactions: Transaction[] = []
@@ -201,10 +227,13 @@ export class TransactionResolver {
     const { sumHoldAvailableAmount, sumAmount, lastDate, firstDate, transactionLinkcount } =
       await transactionLinkRepository.summary(user.id, now)
     context.linkCount = transactionLinkcount
+    logger.debug(`transactionLinkcount=${transactionLinkcount}`)
     context.sumHoldAvailableAmount = sumHoldAvailableAmount
+    logger.debug(`sumHoldAvailableAmount=${sumHoldAvailableAmount}`)
 
     // decay & link transactions
     if (currentPage === 1 && order === Order.DESC) {
+      logger.debug(`currentPage == 1: transactions=${transactions}`)
       // 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(
@@ -216,8 +245,11 @@ export class TransactionResolver {
           sumHoldAvailableAmount,
         ),
       )
+      logger.debug(`transactions=${transactions}`)
+
       // virtual transaction for pending transaction-links sum
       if (sumHoldAvailableAmount.greaterThan(0)) {
+        logger.debug(`sumHoldAvailableAmount > 0: transactions=${transactions}`)
         transactions.push(
           virtualLinkTransaction(
             lastTransaction.balance.minus(sumHoldAvailableAmount.toString()),
@@ -229,6 +261,7 @@ export class TransactionResolver {
             self,
           ),
         )
+        logger.debug(`transactions=${transactions}`)
       }
     }
 
@@ -240,6 +273,7 @@ export class TransactionResolver {
           : involvedUsers.find((u) => u.id === userTransaction.linkedUserId)
       transactions.push(new Transaction(userTransaction, self, linkedUser))
     })
+    logger.debug(`TransactionTypeId.CREATION: transactions=${transactions}`)
 
     // Construct Result
     return new TransactionList(await balanceResolver.balance(context), transactions)
@@ -251,29 +285,38 @@ export class TransactionResolver {
     @Args() { email, amount, memo }: TransactionSendArgs,
     @Ctx() context: Context,
   ): Promise<boolean> {
+    logger.info(`sendCoins(email=${email}, amount=${amount}, memo=${memo})`)
+
     // TODO this is subject to replay attacks
     const senderUser = getUser(context)
     if (senderUser.pubKey.length !== 32) {
+      logger.error(`invalid sender public key:${senderUser.pubKey}`)
       throw new Error('invalid sender public key')
     }
 
     // validate recipient user
     const recipientUser = await dbUser.findOne({ email: email }, { withDeleted: true })
     if (!recipientUser) {
+      logger.error(`recipient not known: email=${email}`)
       throw new Error('recipient not known')
     }
     if (recipientUser.deletedAt) {
+      logger.error(`The recipient account was deleted: recipientUser=${recipientUser}`)
       throw new Error('The recipient account was deleted')
     }
     if (!recipientUser.emailChecked) {
+      logger.error(`The recipient account is not activated: recipientUser=${recipientUser}`)
       throw new Error('The recipient account is not activated')
     }
     if (!isHexPublicKey(recipientUser.pubKey.toString('hex'))) {
+      logger.error(`invalid recipient public key: recipientUser=${recipientUser}`)
       throw new Error('invalid recipient public key')
     }
 
     await executeTransaction(amount, memo, senderUser, recipientUser)
-
+    logger.info(
+      `successful executeTransaction(amount=${amount}, memo=${memo}, senderUser=${senderUser}, recipientUser=${recipientUser})`,
+    )
     return true
   }
 }

backend/src/graphql/resolver/UserResolver.test.ts

@@ -14,6 +14,8 @@ import { sendAccountActivationEmail } from '@/mailer/sendAccountActivationEmail'
 import { sendResetPasswordEmail } from '@/mailer/sendResetPasswordEmail'
 import { printTimeDuration, activationLink } from './UserResolver'
 
+import { logger } from '@test/testSetup'
+
 // import { klicktippSignIn } from '@/apis/KlicktippController'
 
 jest.mock('@/mailer/sendAccountActivationEmail', () => {
@@ -43,7 +45,7 @@ let mutate: any, query: any, con: any
 let testEnv: any
 
 beforeAll(async () => {
-  testEnv = await testEnvironment()
+  testEnv = await testEnvironment(logger)
   mutate = testEnv.mutate
   query = testEnv.query
   con = testEnv.con
@@ -149,12 +151,14 @@ describe('UserResolver', () => {
     })
 
     describe('email already exists', () => {
-      it('throws an error', async () => {
+      it('throws and logs an error', async () => {
-        await expect(mutate({ mutation: createUser, variables })).resolves.toEqual(
+        const mutation = await mutate({ mutation: createUser, variables })
+        expect(mutation).toEqual(
           expect.objectContaining({
             errors: [new GraphQLError('User already exists.')],
           }),
         )
+        expect(logger.error).toBeCalledWith('User already exists with this email=peter@lustig.de')
       })
     })
 

backend/src/graphql/resolver/UserResolver.ts

@@ -1,4 +1,6 @@
 import fs from 'fs'
+import { backendLogger as logger } from '@/server/logger'
+
 import { Context, getUser } from '@/server/context'
 import { Resolver, Query, Args, Arg, Authorized, Ctx, UseMiddleware, Mutation } from 'type-graphql'
 import { getConnection, getCustomRepository } from '@dbTools/typeorm'
@@ -43,6 +45,7 @@ const WORDS = fs
   .toString()
   .split(',')
 const PassphraseGenerate = (): string[] => {
+  logger.trace('PassphraseGenerate...')
   const result = []
   for (let i = 0; i < PHRASE_WORD_COUNT; i++) {
     result.push(WORDS[sodium.randombytes_random() % 2048])
@@ -51,7 +54,9 @@ const PassphraseGenerate = (): string[] => {
 }
 
 const KeyPairEd25519Create = (passphrase: string[]): Buffer[] => {
+  logger.trace('KeyPairEd25519Create...')
   if (!passphrase.length || passphrase.length < PHRASE_WORD_COUNT) {
+    logger.error('passphrase empty or to short')
     throw new Error('passphrase empty or to short')
   }
 
@@ -79,14 +84,19 @@ const KeyPairEd25519Create = (passphrase: string[]): Buffer[] => {
     privKey,
     outputHashBuffer.slice(0, sodium.crypto_sign_SEEDBYTES),
   )
+  logger.debug(`KeyPair creation ready. pubKey=${pubKey}`)
 
   return [pubKey, privKey]
 }
 
 const SecretKeyCryptographyCreateKey = (salt: string, password: string): Buffer[] => {
+  logger.trace('SecretKeyCryptographyCreateKey...')
   const configLoginAppSecret = Buffer.from(CONFIG.LOGIN_APP_SECRET, 'hex')
   const configLoginServerKey = Buffer.from(CONFIG.LOGIN_SERVER_KEY, 'hex')
   if (configLoginServerKey.length !== sodium.crypto_shorthash_KEYBYTES) {
+    logger.error(
+      `ServerKey has an invalid size. The size must be ${sodium.crypto_shorthash_KEYBYTES} bytes.`,
+    )
     throw new Error(
       `ServerKey has an invalid size. The size must be ${sodium.crypto_shorthash_KEYBYTES} bytes.`,
     )
@@ -115,39 +125,50 @@ const SecretKeyCryptographyCreateKey = (salt: string, password: string): Buffer[
   const encryptionKeyHash = Buffer.alloc(sodium.crypto_shorthash_BYTES)
   sodium.crypto_shorthash(encryptionKeyHash, encryptionKey, configLoginServerKey)
 
+  logger.debug(
+    `SecretKeyCryptographyCreateKey...successful: encryptionKeyHash= ${encryptionKeyHash}, encryptionKey= ${encryptionKey}`,
+  )
   return [encryptionKeyHash, encryptionKey]
 }
 
 const getEmailHash = (email: string): Buffer => {
+  logger.trace('getEmailHash...')
   const emailHash = Buffer.alloc(sodium.crypto_generichash_BYTES)
   sodium.crypto_generichash(emailHash, Buffer.from(email))
+  logger.debug(`getEmailHash...successful: ${emailHash}`)
   return emailHash
 }
 
 const SecretKeyCryptographyEncrypt = (message: Buffer, encryptionKey: Buffer): Buffer => {
+  logger.trace('SecretKeyCryptographyEncrypt...')
   const encrypted = Buffer.alloc(message.length + sodium.crypto_secretbox_MACBYTES)
   const nonce = Buffer.alloc(sodium.crypto_secretbox_NONCEBYTES)
   nonce.fill(31) // static nonce
 
   sodium.crypto_secretbox_easy(encrypted, message, nonce, encryptionKey)
+  logger.debug(`SecretKeyCryptographyEncrypt...successful: ${encrypted}`)
   return encrypted
 }
 
 const SecretKeyCryptographyDecrypt = (encryptedMessage: Buffer, encryptionKey: Buffer): Buffer => {
+  logger.trace('SecretKeyCryptographyDecrypt...')
   const message = Buffer.alloc(encryptedMessage.length - sodium.crypto_secretbox_MACBYTES)
   const nonce = Buffer.alloc(sodium.crypto_secretbox_NONCEBYTES)
   nonce.fill(31) // static nonce
 
   sodium.crypto_secretbox_open_easy(message, encryptedMessage, nonce, encryptionKey)
 
+  logger.debug(`SecretKeyCryptographyDecrypt...successful: ${message}`)
   return message
 }
 
 const newEmailOptIn = (userId: number): LoginEmailOptIn => {
+  logger.trace('newEmailOptIn...')
   const emailOptIn = new LoginEmailOptIn()
   emailOptIn.verificationCode = random(64)
   emailOptIn.userId = userId
   emailOptIn.emailOptInTypeId = OptInType.EMAIL_OPT_IN_REGISTER
+  logger.debug(`newEmailOptIn...successful: ${emailOptIn}`)
   return emailOptIn
 }
 
@@ -159,8 +180,14 @@ export const checkOptInCode = async (
   userId: number,
   optInType: OptInType = OptInType.EMAIL_OPT_IN_REGISTER,
 ): Promise<LoginEmailOptIn> => {
+  logger.info(`checkOptInCode... ${optInCode}`)
   if (optInCode) {
     if (!canResendOptIn(optInCode)) {
+      logger.error(
+        `email already sent less than ${printTimeDuration(
+          CONFIG.EMAIL_CODE_REQUEST_TIME,
+        )} minutes ago`,
+      )
       throw new Error(
         `email already sent less than ${printTimeDuration(
           CONFIG.EMAIL_CODE_REQUEST_TIME,
@@ -170,16 +197,20 @@ export const checkOptInCode = async (
     optInCode.updatedAt = new Date()
     optInCode.resendCount++
   } else {
+    logger.trace('create new OptIn for userId=' + userId)
     optInCode = newEmailOptIn(userId)
   }
   optInCode.emailOptInTypeId = optInType
   await LoginEmailOptIn.save(optInCode).catch(() => {
+    logger.error('Unable to save optin code= ' + optInCode)
     throw new Error('Unable to save optin code.')
   })
+  logger.debug(`checkOptInCode...successful: ${optInCode} for userid=${userId}`)
   return optInCode
 }
 
 export const activationLink = (optInCode: LoginEmailOptIn): string => {
+  logger.debug(`activationLink(${LoginEmailOptIn})...`)
   return CONFIG.EMAIL_LINK_SETPASSWORD.replace(/{optin}/g, optInCode.verificationCode.toString())
 }
 
@@ -189,6 +220,7 @@ export class UserResolver {
   @Query(() => User)
   @UseMiddleware(klicktippNewsletterStateMiddleware)
   async verifyLogin(@Ctx() context: Context): Promise<User> {
+    logger.info('verifyLogin...')
     // TODO refactor and do not have duplicate code with login(see below)
     const userEntity = getUser(context)
     const user = new User(userEntity)
@@ -201,10 +233,11 @@ export class UserResolver {
     const coinanimation = await userSettingRepository
       .readBoolean(userEntity.id, Setting.COIN_ANIMATION)
       .catch((error) => {
+        logger.error('error:', error)
         throw new Error(error)
       })
     user.coinanimation = coinanimation
-
+    logger.debug(`verifyLogin... successful: ${user.firstName}.${user.lastName}, ${user.email}`)
     return user
   }
 
@@ -215,34 +248,46 @@ export class UserResolver {
     @Args() { email, password, publisherId }: UnsecureLoginArgs,
     @Ctx() context: Context,
   ): Promise<User> {
+    logger.info(`login with ${email}, ***, ${publisherId} ...`)
     email = email.trim().toLowerCase()
     const dbUser = await DbUser.findOneOrFail({ email }, { withDeleted: true }).catch(() => {
+      logger.error(`User with email=${email} does not exists`)
       throw new Error('No user with this credentials')
     })
     if (dbUser.deletedAt) {
+      logger.error('The User was permanently deleted in database.')
       throw new Error('This user was permanently deleted. Contact support for questions.')
     }
     if (!dbUser.emailChecked) {
+      logger.error('The Users email is not validate yet.')
       throw new Error('User email not validated')
     }
     if (dbUser.password === BigInt(0)) {
+      logger.error('The User has not set a password yet.')
       // TODO we want to catch this on the frontend and ask the user to check his emails or resend code
       throw new Error('User has no password set yet')
     }
     if (!dbUser.pubKey || !dbUser.privKey) {
+      logger.error('The User has no private or publicKey.')
       // TODO we want to catch this on the frontend and ask the user to check his emails or resend code
       throw new Error('User has no private or publicKey')
     }
     const passwordHash = SecretKeyCryptographyCreateKey(email, password) // return short and long hash
     const loginUserPassword = BigInt(dbUser.password.toString())
     if (loginUserPassword !== passwordHash[0].readBigUInt64LE()) {
+      logger.error('The User has no valid credentials.')
       throw new Error('No user with this credentials')
     }
+    // add pubKey in logger-context for layout-pattern X{user} to print it in each logging message
+    logger.addContext('user', dbUser.id)
+    logger.debug('login credentials valid...')
 
     const user = new User(dbUser)
+    logger.debug('user=' + user)
 
     // Elopage Status & Stored PublisherId
     user.hasElopage = await this.hasElopage({ ...context, user: dbUser })
+    logger.info('user.hasElopage=' + user.hasElopage)
     if (!user.hasElopage && publisherId) {
       user.publisherId = publisherId
       dbUser.publisherId = publisherId
@@ -262,7 +307,7 @@ export class UserResolver {
       key: 'token',
       value: encode(dbUser.pubKey),
     })
-
+    logger.info('successful Login:' + user)
     return user
   }
 
@@ -274,6 +319,9 @@ export class UserResolver {
     // The functionality is fully client side - the client just needs to delete his token with the current implementation.
     // we could try to force this by sending `token: null` or `token: ''` with this call. But since it bares no real security
     // we should just return true for now.
+    logger.info('Logout...')
+    // remove user.pubKey from logger-context to ensure a correct filter on log-messages belonging to the same user
+    logger.addContext('user', 'unknown')
     return true
   }
 
@@ -283,6 +331,9 @@ export class UserResolver {
     @Args()
     { email, firstName, lastName, language, publisherId, redeemCode = null }: CreateUserArgs,
   ): Promise<User> {
+    logger.info(
+      `createUser(email=${email}, firstName=${firstName}, lastName=${lastName}, language=${language}, publisherId=${publisherId}, redeemCode =${redeemCode})`,
+    )
     // TODO: wrong default value (should be null), how does graphql work here? Is it an required field?
     // default int publisher_id = 0;
 
@@ -295,7 +346,9 @@ export class UserResolver {
     email = email.trim().toLowerCase()
     // TODO we cannot use repository.count(), since it does not allow to specify if you want to include the soft deletes
     const userFound = await DbUser.findOne({ email }, { withDeleted: true })
+    logger.info(`DbUser.findOne(email=${email}) = ${userFound}`)
     if (userFound) {
+      logger.error('User already exists with this email=' + email)
       // 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.
       throw new Error(`User already exists.`)
     }
@@ -314,8 +367,10 @@ export class UserResolver {
     dbUser.language = language
     dbUser.publisherId = publisherId
     dbUser.passphrase = passphrase.join(' ')
+    logger.debug('new dbUser=' + dbUser)
     if (redeemCode) {
       const transactionLink = await dbTransactionLink.findOne({ code: redeemCode })
+      logger.info('redeemCode found transactionLink=' + transactionLink)
       if (transactionLink) {
         dbUser.referrerId = transactionLink.userId
       }
@@ -332,15 +387,13 @@ export class UserResolver {
     await queryRunner.startTransaction('READ UNCOMMITTED')
     try {
       await queryRunner.manager.save(dbUser).catch((error) => {
-        // eslint-disable-next-line no-console
+        logger.error('Error while saving dbUser', error)
-        console.log('Error while saving dbUser', error)
         throw new Error('error saving user')
       })
 
       const emailOptIn = newEmailOptIn(dbUser.id)
       await queryRunner.manager.save(emailOptIn).catch((error) => {
-        // eslint-disable-next-line no-console
+        logger.error('Error while saving emailOptIn', error)
-        console.log('Error while saving emailOptIn', error)
         throw new Error('error saving email opt in')
       })
 
@@ -357,31 +410,35 @@ export class UserResolver {
         email,
         duration: printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME),
       })
-
+      logger.info(`sendAccountActivationEmail of ${firstName}.${lastName} to ${email}`)
-      /* uncomment this, when you need the activation link on the console
+      /* uncomment this, when you need the activation link on the console */
       // In case EMails are disabled log the activation link for the user
       if (!emailSent) {
-        // eslint-disable-next-line no-console
+        logger.debug(`Account confirmation link: ${activationLink}`)
-        console.log(`Account confirmation link: ${activationLink}`)
       }
-      */
 
       await queryRunner.commitTransaction()
     } catch (e) {
+      logger.error(`error during create user with ${e}`)
       await queryRunner.rollbackTransaction()
       throw e
     } finally {
       await queryRunner.release()
     }
+    logger.info('createUser() successful...')
     return new User(dbUser)
   }
 
   @Authorized([RIGHTS.SEND_RESET_PASSWORD_EMAIL])
   @Mutation(() => Boolean)
   async forgotPassword(@Arg('email') email: string): Promise<boolean> {
+    logger.info(`forgotPassword(${email})...`)
     email = email.trim().toLowerCase()
     const user = await DbUser.findOne({ email })
-    if (!user) return true
+    if (!user) {
+      logger.warn(`no user found with ${email}`)
+      return true
+    }
 
     // can be both types: REGISTER and RESET_PASSWORD
     let optInCode = await LoginEmailOptIn.findOne({
@@ -389,7 +446,7 @@ export class UserResolver {
     })
 
     optInCode = await checkOptInCode(optInCode, user.id, OptInType.EMAIL_OPT_IN_RESET_PASSWORD)
-
+    logger.info(`optInCode for ${email}=${optInCode}`)
     // eslint-disable-next-line @typescript-eslint/no-unused-vars
     const emailSent = await sendResetPasswordEmailMailer({
       link: activationLink(optInCode),
@@ -399,13 +456,12 @@ export class UserResolver {
       duration: printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME),
     })
 
-    /*  uncomment this, when you need the activation link on the console
+    /*  uncomment this, when you need the activation link on the console */
     // In case EMails are disabled log the activation link for the user
     if (!emailSent) {
-      // eslint-disable-next-line no-console
+      logger.debug(`Reset password link: ${activationLink(optInCode)}`)
-      console.log(`Reset password link: ${link}`)
     }
-    */
+    logger.info(`forgotPassword(${email}) successful...`)
 
     return true
   }
@@ -416,6 +472,7 @@ export class UserResolver {
     @Arg('code') code: string,
     @Arg('password') password: string,
   ): Promise<boolean> {
+    logger.info(`setPassword(${code}, ***)...`)
     // Validate Password
     if (!isPassword(password)) {
       throw new Error(
@@ -425,34 +482,44 @@ export class UserResolver {
 
     // Load code
     const optInCode = await LoginEmailOptIn.findOneOrFail({ verificationCode: code }).catch(() => {
+      logger.error('Could not login with emailVerificationCode')
       throw new Error('Could not login with emailVerificationCode')
     })
-
+    logger.debug('optInCode loaded...')
     // Code is only valid for `CONFIG.EMAIL_CODE_VALID_TIME` minutes
     if (!isOptInValid(optInCode)) {
+      logger.error(
+        `email was sent more than ${printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME)} ago`,
+      )
       throw new Error(
         `email was sent more than ${printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME)} ago`,
       )
     }
+    logger.debug('optInCode is valid...')
 
     // load user
     const user = await DbUser.findOneOrFail({ id: optInCode.userId }).catch(() => {
+      logger.error('Could not find corresponding Login User')
       throw new Error('Could not find corresponding Login User')
     })
+    logger.debug('user with optInCode found...')
 
     // Generate Passphrase if needed
     if (!user.passphrase) {
       const passphrase = PassphraseGenerate()
       user.passphrase = passphrase.join(' ')
+      logger.debug('new Passphrase generated...')
     }
 
     const passphrase = user.passphrase.split(' ')
     if (passphrase.length < PHRASE_WORD_COUNT) {
+      logger.error('Could not load a correct passphrase')
       // TODO if this can happen we cannot recover from that
       // this seem to be good on production data, if we dont
       // make a coding mistake we do not have a problem here
       throw new Error('Could not load a correct passphrase')
     }
+    logger.debug('Passphrase is valid...')
 
     // Activate EMail
     user.emailChecked = true
@@ -464,6 +531,7 @@ export class UserResolver {
     user.password = passwordHash[0].readBigUInt64LE() // using the shorthash
     user.pubKey = keyPair[0]
     user.privKey = encryptedPrivkey
+    logger.debug('User credentials updated ...')
 
     const queryRunner = getConnection().createQueryRunner()
     await queryRunner.connect()
@@ -472,12 +540,15 @@ export class UserResolver {
     try {
       // Save user
       await queryRunner.manager.save(user).catch((error) => {
+        logger.error('error saving user: ' + error)
         throw new Error('error saving user: ' + error)
       })
 
       await queryRunner.commitTransaction()
+      logger.info('User data written successfully...')
     } catch (e) {
       await queryRunner.rollbackTransaction()
+      logger.error('Error on writing User data:' + e)
       throw e
     } finally {
       await queryRunner.release()
@@ -488,7 +559,11 @@ export class UserResolver {
     if (optInCode.emailOptInTypeId === OptInType.EMAIL_OPT_IN_REGISTER) {
       try {
         await klicktippSignIn(user.email, user.language, user.firstName, user.lastName)
-      } catch {
+        logger.debug(
+          `klicktippSignIn(${user.email}, ${user.language}, ${user.firstName}, ${user.lastName})`,
+        )
+      } catch (e) {
+        logger.error('Error subscribe to klicktipp:' + e)
         // TODO is this a problem?
         // eslint-disable-next-line no-console
         /*  uncomment this, when you need the activation link on the console
@@ -503,13 +578,19 @@ export class UserResolver {
   @Authorized([RIGHTS.QUERY_OPT_IN])
   @Query(() => Boolean)
   async queryOptIn(@Arg('optIn') optIn: string): Promise<boolean> {
+    logger.info(`queryOptIn(${optIn})...`)
     const optInCode = await LoginEmailOptIn.findOneOrFail({ verificationCode: optIn })
+    logger.debug(`found optInCode=${optInCode}`)
     // Code is only valid for `CONFIG.EMAIL_CODE_VALID_TIME` minutes
     if (!isOptInValid(optInCode)) {
+      logger.error(
+        `email was sent more than ${printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME)} ago`,
+      )
       throw new Error(
         `email was sent more than ${printTimeDuration(CONFIG.EMAIL_CODE_VALID_TIME)} ago`,
       )
     }
+    logger.info(`queryOptIn(${optIn}) successful...`)
     return true
   }
 
@@ -520,6 +601,9 @@ export class UserResolver {
     { firstName, lastName, language, password, passwordNew, coinanimation }: UpdateUserInfosArgs,
     @Ctx() context: Context,
   ): Promise<boolean> {
+    logger.info(
+      `updateUserInfos(${firstName}, ${lastName}, ${language}, ***, ***, ${coinanimation})...`,
+    )
     const userEntity = getUser(context)
 
     if (firstName) {
@@ -532,6 +616,7 @@ export class UserResolver {
 
     if (language) {
       if (!isLanguage(language)) {
+        logger.error(`"${language}" isn't a valid language`)
         throw new Error(`"${language}" isn't a valid language`)
       }
       userEntity.language = language
@@ -540,6 +625,7 @@ export class UserResolver {
     if (password && passwordNew) {
       // Validate Password
       if (!isPassword(passwordNew)) {
+        logger.error('newPassword does not fullfil the rules')
         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!',
         )
@@ -548,13 +634,16 @@ export class UserResolver {
       // TODO: This had some error cases defined - like missing private key. This is no longer checked.
       const oldPasswordHash = SecretKeyCryptographyCreateKey(userEntity.email, password)
       if (BigInt(userEntity.password.toString()) !== oldPasswordHash[0].readBigUInt64LE()) {
+        logger.error(`Old password is invalid`)
         throw new Error(`Old password is invalid`)
       }
 
       const privKey = SecretKeyCryptographyDecrypt(userEntity.privKey, oldPasswordHash[1])
-
+      logger.debug('oldPassword decrypted...')
       const newPasswordHash = SecretKeyCryptographyCreateKey(userEntity.email, passwordNew) // return short and long hash
+      logger.debug('newPasswordHash created...')
       const encryptedPrivkey = SecretKeyCryptographyEncrypt(privKey, newPasswordHash[1])
+      logger.debug('PrivateKey encrypted...')
 
       // Save new password hash and newly encrypted private key
       userEntity.password = newPasswordHash[0].readBigUInt64LE()
@@ -580,25 +669,30 @@ export class UserResolver {
       })
 
       await queryRunner.commitTransaction()
+      logger.debug('writing User data successful...')
     } catch (e) {
       await queryRunner.rollbackTransaction()
+      logger.error(`error on writing updated user data: ${e}`)
       throw e
     } finally {
       await queryRunner.release()
     }
-
+    logger.info('updateUserInfos() successfully finished...')
     return true
   }
 
   @Authorized([RIGHTS.HAS_ELOPAGE])
   @Query(() => Boolean)
   async hasElopage(@Ctx() context: Context): Promise<boolean> {
+    logger.info(`hasElopage()...`)
     const userEntity = context.user
     if (!userEntity) {
+      logger.info('missing context.user for EloPage-check')
       return false
     }
-
+    const elopageBuys = hasElopageBuys(userEntity.email)
-    return hasElopageBuys(userEntity.email)
+    logger.debug(`has ElopageBuys = ${elopageBuys}`)
+    return elopageBuys
   }
 }
 

backend/src/mailer/sendEMail.test.ts

@@ -2,6 +2,8 @@ import { sendEMail } from './sendEMail'
 import { createTransport } from 'nodemailer'
 import CONFIG from '@/config'
 
+import { logger } from '@test/testSetup'
+
 CONFIG.EMAIL = false
 CONFIG.EMAIL_SMTP_URL = 'EMAIL_SMTP_URL'
 CONFIG.EMAIL_SMTP_PORT = '1234'
@@ -26,11 +28,6 @@ jest.mock('nodemailer', () => {
 describe('sendEMail', () => {
   let result: boolean
   describe('config email is false', () => {
-    // eslint-disable-next-line no-console
-    const consoleLog = console.log
-    const consoleLogMock = jest.fn()
-    // eslint-disable-next-line no-console
-    console.log = consoleLogMock
     beforeEach(async () => {
       result = await sendEMail({
         to: 'receiver@mail.org',
@@ -39,13 +36,8 @@ describe('sendEMail', () => {
       })
     })
 
-    afterAll(() => {
+    it('logs warining', () => {
-      // eslint-disable-next-line no-console
+      expect(logger.info).toBeCalledWith('Emails are disabled via config...')
-      console.log = consoleLog
-    })
-
-    it('logs warining to console', () => {
-      expect(consoleLogMock).toBeCalledWith('Emails are disabled via config')
     })
 
     it('returns false', () => {

backend/src/mailer/sendEMail.ts

@@ -1,3 +1,4 @@
+import { backendLogger as logger } from '@/server/logger'
 import { createTransport } from 'nodemailer'
 
 import CONFIG from '@/config'
@@ -7,9 +8,10 @@ export const sendEMail = async (emailDef: {
   subject: string
   text: string
 }): Promise<boolean> => {
+  logger.info(`send Email: to=${emailDef.to}, subject=${emailDef.subject}, text=${emailDef.text}`)
+
   if (!CONFIG.EMAIL) {
-    // eslint-disable-next-line no-console
+    logger.info(`Emails are disabled via config...`)
-    console.log('Emails are disabled via config')
     return false
   }
   const transporter = createTransport({
@@ -27,7 +29,9 @@ export const sendEMail = async (emailDef: {
     from: `Gradido (nicht antworten) <${CONFIG.EMAIL_SENDER}>`,
   })
   if (!info.messageId) {
+    logger.error('error sending notification email, but transaction succeed')
     throw new Error('error sending notification email, but transaction succeed')
   }
+  logger.info('send Email successfully.')
   return true
 }

backend/src/mailer/sendTransactionReceivedEmail.ts

@@ -1,3 +1,4 @@
+import { backendLogger as logger } from '@/server/logger'
 import Decimal from 'decimal.js-light'
 import { sendEMail } from './sendEMail'
 import { transactionReceived } from './text/transactionReceived'
@@ -13,6 +14,12 @@ export const sendTransactionReceivedEmail = (data: {
   memo: string
   overviewURL: string
 }): Promise<boolean> => {
+  logger.info(
+    `sendEmail(): to=${data.recipientFirstName} ${data.recipientLastName}, 
+      <${data.email}>, 
+      subject=${transactionReceived.de.subject}, 
+      text=${transactionReceived.de.text(data)}`,
+  )
   return sendEMail({
     to: `${data.recipientFirstName} ${data.recipientLastName} <${data.email}>`,
     subject: transactionReceived.de.subject,

backend/src/server/createServer.ts

@@ -22,22 +22,32 @@ import schema from '@/graphql/schema'
 import { elopageWebhook } from '@/webhook/elopage'
 import { Connection } from '@dbTools/typeorm'
 
+import { apolloLogger } from './logger'
+import { Logger } from 'log4js'
+
 // TODO implement
 // import queryComplexity, { simpleEstimator, fieldConfigEstimator } from "graphql-query-complexity";
 
 type ServerDef = { apollo: ApolloServer; app: Express; con: Connection }
 
-// eslint-disable-next-line @typescript-eslint/no-explicit-any
+const createServer = async (
-const createServer = async (context: any = serverContext): Promise<ServerDef> => {
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  context: any = serverContext,
+  logger: Logger = apolloLogger,
+): Promise<ServerDef> => {
+  logger.debug('createServer...')
+
   // open mysql connection
   const con = await connection()
   if (!con || !con.isConnected) {
+    logger.fatal(`Couldn't open connection to database!`)
     throw new Error(`Fatal: Couldn't open connection to database`)
   }
 
   // check for correct database version
   const dbVersion = await checkDBVersion(CONFIG.DB_VERSION)
   if (!dbVersion) {
+    logger.fatal('Fatal: Database Version incorrect')
     throw new Error('Fatal: Database Version incorrect')
   }
 
@@ -62,8 +72,10 @@ const createServer = async (context: any = serverContext): Promise<ServerDef> =>
     introspection: CONFIG.GRAPHIQL,
     context,
     plugins,
+    logger,
   })
   apollo.applyMiddleware({ app, path: '/' })
+  logger.debug('createServer...successful')
   return { apollo, app, con }
 }
 

backend/src/server/logger.ts

@@ -0,0 +1,18 @@
+import log4js from 'log4js'
+import CONFIG from '@/config'
+
+import { readFileSync } from 'fs'
+
+const options = JSON.parse(readFileSync(CONFIG.LOG4JS_CONFIG, 'utf-8'))
+
+options.categories.default.level = CONFIG.LOG_LEVEL
+
+log4js.configure(options)
+
+const apolloLogger = log4js.getLogger('apollo')
+const backendLogger = log4js.getLogger('backend')
+
+apolloLogger.addContext('user', 'unknown')
+backendLogger.addContext('user', 'unknown')
+
+export { apolloLogger, backendLogger }

backend/src/server/plugins.ts

@@ -1,8 +1,7 @@
 /* eslint-disable @typescript-eslint/no-explicit-any */
 /* eslint-disable @typescript-eslint/explicit-module-boundary-types */
 
-import { ApolloLogPlugin, LogMutateData } from 'apollo-log'
+import clonedeep from 'lodash.clonedeep'
-import cloneDeep from 'lodash.clonedeep'
 
 const setHeadersPlugin = {
   requestDidStart() {
@@ -22,24 +21,35 @@ const setHeadersPlugin = {
   },
 }
 
-const apolloLogPlugin = ApolloLogPlugin({
+const filterVariables = (variables: any) => {
-  mutate: (data: LogMutateData) => {
+  const vars = clonedeep(variables)
-    // We need to deep clone the object in order to not modify the actual request
+  if (vars.password) vars.password = '***'
-    const dataCopy = cloneDeep(data)
+  if (vars.passwordNew) vars.passwordNew = '***'
+  return vars
+}
 
-    // mask password if part of the query
+const logPlugin = {
-    if (dataCopy.context.request.variables && dataCopy.context.request.variables.password) {
+  requestDidStart(requestContext: any) {
-      dataCopy.context.request.variables.password = '***'
+    const { logger } = requestContext
+    const { query, mutation, variables } = requestContext.request
+    logger.trace(`Request:
+${mutation || query}variables: ${JSON.stringify(filterVariables(variables), null, 2)}`)
+    return {
+      willSendResponse(requestContext: any) {
+        if (requestContext.context.user) logger.trace(`User ID: ${requestContext.context.user.id}`)
+        if (requestContext.response.data)
+          logger.trace(`Response-Data:
+${JSON.stringify(requestContext.response.data, null, 2)}`)
+        if (requestContext.response.errors)
+          logger.trace(`Response-Errors:
+${JSON.stringify(requestContext.response.errors, null, 2)}`)
+        return requestContext
+      },
     }
-
-    // mask token at all times
-    dataCopy.context.context.token = '***'
-
-    return dataCopy
   },
-})
+}
 
 const plugins =
-  process.env.NODE_ENV === 'development' ? [setHeadersPlugin] : [setHeadersPlugin, apolloLogPlugin]
+  process.env.NODE_ENV === 'development' ? [setHeadersPlugin] : [setHeadersPlugin, logPlugin]
 
 export default plugins

backend/src/typeorm/DBVersion.ts

@@ -1,12 +1,12 @@
 import { Migration } from '@entity/Migration'
+import { backendLogger as logger } from '@/server/logger'
 
 const getDBVersion = async (): Promise<string | null> => {
   try {
     const dbVersion = await Migration.findOne({ order: { version: 'DESC' } })
     return dbVersion ? dbVersion.fileName : null
   } catch (error) {
-    // eslint-disable-next-line no-console
+    logger.error(error)
-    console.log(error)
     return null
   }
 }
@@ -14,8 +14,7 @@ const getDBVersion = async (): Promise<string | null> => {
 const checkDBVersion = async (DB_VERSION: string): Promise<boolean> => {
   const dbVersion = await getDBVersion()
   if (!dbVersion || dbVersion.indexOf(DB_VERSION) === -1) {
-    // eslint-disable-next-line no-console
+    logger.error(
-    console.log(
       `Wrong database version detected - the backend requires '${DB_VERSION}' but found '${
         dbVersion || 'None'
       }`,

backend/test/helpers.ts

@@ -25,8 +25,8 @@ export const cleanDB = async () => {
   }
 }
 
-export const testEnvironment = async () => {
+export const testEnvironment = async (logger?: any) => {
-  const server = await createServer(context)
+  const server = await createServer(context, logger)
   const con = server.con
   const testClient = createTestClient(server.apollo)
   const mutate = testClient.mutate

backend/test/testSetup.ts

@@ -1,7 +1,22 @@
-/* eslint-disable no-console */
+import { backendLogger as logger } from '@/server/logger'
 
-// disable console.info for apollo log
-
-// eslint-disable-next-line @typescript-eslint/no-empty-function
-console.info = () => {}
 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(),
+    },
+  }
+})
+
+export { logger }

backend/yarn.lock

@@ -2,7 +2,7 @@
 # yarn lockfile v1
 
 
-"@apollo/protobufjs@1.2.2", "@apollo/protobufjs@^1.0.3":
+"@apollo/protobufjs@1.2.2":
   version "1.2.2"
   resolved "https://registry.yarnpkg.com/@apollo/protobufjs/-/protobufjs-1.2.2.tgz#4bd92cd7701ccaef6d517cdb75af2755f049f87c"
   integrity sha512-vF+zxhPiLtkwxONs6YanSt1EpwpGilThpneExUN5K3tCymuxNnVq2yojTvnpRjv2QfsEIt/n7ozPIIzBLwGIDQ==
@@ -1265,24 +1265,6 @@ apollo-link@^1.2.14:
     tslib "^1.9.3"
     zen-observable-ts "^0.8.21"
 
-apollo-log@^1.1.0:
-  version "1.1.0"
-  resolved "https://registry.yarnpkg.com/apollo-log/-/apollo-log-1.1.0.tgz#e21287c917cf735b77adc06f07034f965e9b24de"
-  integrity sha512-TciLu+85LSqk7t7ZGKrYN5jFiCcRMLujBjrLiOQGHGgVVkvmKlwK0oELSS9kiHQIhTq23p8qVVWb08spLpQ7Jw==
-  dependencies:
-    apollo-server-plugin-base "^0.10.4"
-    chalk "^4.1.0"
-    fast-safe-stringify "^2.0.7"
-    loglevelnext "^4.0.1"
-    nanoid "^3.1.20"
-
-apollo-reporting-protobuf@^0.6.2:
-  version "0.6.2"
-  resolved "https://registry.yarnpkg.com/apollo-reporting-protobuf/-/apollo-reporting-protobuf-0.6.2.tgz#5572866be9b77f133916532b10e15fbaa4158304"
-  integrity sha512-WJTJxLM+MRHNUxt1RTl4zD0HrLdH44F2mDzMweBj1yHL0kSt8I1WwoiF/wiGVSpnG48LZrBegCaOJeuVbJTbtw==
-  dependencies:
-    "@apollo/protobufjs" "^1.0.3"
-
 apollo-reporting-protobuf@^0.8.0:
   version "0.8.0"
   resolved "https://registry.yarnpkg.com/apollo-reporting-protobuf/-/apollo-reporting-protobuf-0.8.0.tgz#ae9d967934d3d8ed816fc85a0d8068ef45c371b9"
@@ -1290,13 +1272,6 @@ apollo-reporting-protobuf@^0.8.0:
   dependencies:
     "@apollo/protobufjs" "1.2.2"
 
-apollo-server-caching@^0.5.3:
-  version "0.5.3"
-  resolved "https://registry.yarnpkg.com/apollo-server-caching/-/apollo-server-caching-0.5.3.tgz#cf42a77ad09a46290a246810075eaa029b5305e1"
-  integrity sha512-iMi3087iphDAI0U2iSBE9qtx9kQoMMEWr6w+LwXruBD95ek9DWyj7OeC2U/ngLjRsXM43DoBDXlu7R+uMjahrQ==
-  dependencies:
-    lru-cache "^6.0.0"
-
 apollo-server-caching@^0.7.0:
   version "0.7.0"
   resolved "https://registry.yarnpkg.com/apollo-server-caching/-/apollo-server-caching-0.7.0.tgz#e6d1e68e3bb571cba63a61f60b434fb771c6ff39"
@@ -1335,7 +1310,7 @@ apollo-server-core@^2.25.2:
     subscriptions-transport-ws "^0.9.19"
     uuid "^8.0.0"
 
-apollo-server-env@^3.0.0, apollo-server-env@^3.1.0:
+apollo-server-env@^3.1.0:
   version "3.1.0"
   resolved "https://registry.yarnpkg.com/apollo-server-env/-/apollo-server-env-3.1.0.tgz#0733c2ef50aea596cc90cf40a53f6ea2ad402cd0"
   integrity sha512-iGdZgEOAuVop3vb0F2J3+kaBVi4caMoxefHosxmgzAbbSpvWehB8Y1QiSyyMeouYC38XNVk5wnZl+jdGSsWsIQ==
@@ -1371,13 +1346,6 @@ apollo-server-express@^2.25.2:
     subscriptions-transport-ws "^0.9.19"
     type-is "^1.6.16"
 
-apollo-server-plugin-base@^0.10.4:
-  version "0.10.4"
-  resolved "https://registry.yarnpkg.com/apollo-server-plugin-base/-/apollo-server-plugin-base-0.10.4.tgz#fbf73f64f95537ca9f9639dd7c535eb5eeb95dcd"
-  integrity sha512-HRhbyHgHFTLP0ImubQObYhSgpmVH4Rk1BinnceZmwudIVLKrqayIVOELdyext/QnSmmzg5W7vF3NLGBcVGMqDg==
-  dependencies:
-    apollo-server-types "^0.6.3"
-
 apollo-server-plugin-base@^0.13.0:
   version "0.13.0"
   resolved "https://registry.yarnpkg.com/apollo-server-plugin-base/-/apollo-server-plugin-base-0.13.0.tgz#3f85751a420d3c4625355b6cb3fbdd2acbe71f13"
@@ -1392,15 +1360,6 @@ apollo-server-testing@^2.25.2:
   dependencies:
     apollo-server-core "^2.25.2"
 
-apollo-server-types@^0.6.3:
-  version "0.6.3"
-  resolved "https://registry.yarnpkg.com/apollo-server-types/-/apollo-server-types-0.6.3.tgz#f7aa25ff7157863264d01a77d7934aa6e13399e8"
-  integrity sha512-aVR7SlSGGY41E1f11YYz5bvwA89uGmkVUtzMiklDhZ7IgRJhysT5Dflt5IuwDxp+NdQkIhVCErUXakopocFLAg==
-  dependencies:
-    apollo-reporting-protobuf "^0.6.2"
-    apollo-server-caching "^0.5.3"
-    apollo-server-env "^3.0.0"
-
 apollo-server-types@^0.9.0:
   version "0.9.0"
   resolved "https://registry.yarnpkg.com/apollo-server-types/-/apollo-server-types-0.9.0.tgz#ccf550b33b07c48c72f104fbe2876232b404848b"
@@ -1952,6 +1911,11 @@ data-urls@^2.0.0:
     whatwg-mimetype "^2.3.0"
     whatwg-url "^8.0.0"
 
+date-format@^4.0.9:
+  version "4.0.9"
+  resolved "https://registry.yarnpkg.com/date-format/-/date-format-4.0.9.tgz#4788015ac56dedebe83b03bc361f00c1ddcf1923"
+  integrity sha512-+8J+BOUpSrlKLQLeF8xJJVTxS8QfRSuJgwxSVvslzgO3E6khbI0F5mMEPf5mTYhCCm4h99knYP6H3W9n3BQFrg==
+
 debug@2.6.9, debug@^2.2.0, debug@^2.6.9:
   version "2.6.9"
   resolved "https://registry.yarnpkg.com/debug/-/debug-2.6.9.tgz#5d128515df134ff327e90a4c93f4e077a536341f"
@@ -1973,6 +1937,13 @@ debug@^3.2.6, debug@^3.2.7:
   dependencies:
     ms "^2.1.1"
 
+debug@^4.3.4:
+  version "4.3.4"
+  resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.4.tgz#1319f6579357f2338d3337d2cdd4914bb5dcc865"
+  integrity sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ==
+  dependencies:
+    ms "2.1.2"
+
 decimal.js-light@^2.5.1:
   version "2.5.1"
   resolved "https://registry.yarnpkg.com/decimal.js-light/-/decimal.js-light-2.5.1.tgz#134fd32508f19e208f4fb2f8dac0d2626a867934"
@@ -2558,11 +2529,6 @@ fast-levenshtein@^2.0.6, fast-levenshtein@~2.0.6:
   resolved "https://registry.yarnpkg.com/fast-levenshtein/-/fast-levenshtein-2.0.6.tgz#3d8a5c66883a16a30ca8643e851f19baa7797917"
   integrity sha1-PYpcZog6FqMMqGQ+hR8Zuqd5eRc=
 
-fast-safe-stringify@^2.0.7:
-  version "2.1.1"
-  resolved "https://registry.yarnpkg.com/fast-safe-stringify/-/fast-safe-stringify-2.1.1.tgz#c406a83b6e70d9e35ce3b30a81141df30aeba884"
-  integrity sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==
-
 fastq@^1.6.0:
   version "1.13.0"
   resolved "https://registry.yarnpkg.com/fastq/-/fastq-1.13.0.tgz#616760f88a7526bdfc596b7cab8c18938c36b98c"
@@ -2632,6 +2598,11 @@ flatted@^3.1.0:
   resolved "https://registry.yarnpkg.com/flatted/-/flatted-3.2.2.tgz#64bfed5cb68fe3ca78b3eb214ad97b63bedce561"
   integrity sha512-JaTY/wtrcSyvXJl4IMFHPKyFur1sE9AUqc0QnhOaJ0CxHtAoIV8pYDzeEfAaNEtGkOfq4gr3LBFmdXW5mOQFnA==
 
+flatted@^3.2.5:
+  version "3.2.5"
+  resolved "https://registry.yarnpkg.com/flatted/-/flatted-3.2.5.tgz#76c8584f4fc843db64702a6bd04ab7a8bd666da3"
+  integrity sha512-WIWGi2L3DyTUvUrwRKgGi9TwxQMUEqPOPQBVi71R96jZXJdFskXEmf54BoZaS1kknGODoIGASGEzBUYdyMCBJg==
+
 follow-redirects@^1.14.0:
   version "1.14.4"
   resolved "https://registry.yarnpkg.com/follow-redirects/-/follow-redirects-1.14.4.tgz#838fdf48a8bbdd79e52ee51fb1c94e3ed98b9379"
@@ -2668,6 +2639,15 @@ fs-capacitor@^2.0.4:
   resolved "https://registry.yarnpkg.com/fs-capacitor/-/fs-capacitor-2.0.4.tgz#5a22e72d40ae5078b4fe64fe4d08c0d3fc88ad3c"
   integrity sha512-8S4f4WsCryNw2mJJchi46YgB6CR5Ze+4L1h8ewl9tEpL4SJ3ZO+c/bS4BWhB8bK+O3TMqhuZarTitd0S0eh2pA==
 
+fs-extra@^10.1.0:
+  version "10.1.0"
+  resolved "https://registry.yarnpkg.com/fs-extra/-/fs-extra-10.1.0.tgz#02873cfbc4084dde127eaa5f9905eef2325d1abf"
+  integrity sha512-oRXApq54ETRj4eMiFzGnHWGy+zo5raudjuxN0b8H7s/RU2oW0Wvsx9O0ACRN/kRq9E8Vu/ReskGB5o3ji+FzHQ==
+  dependencies:
+    graceful-fs "^4.2.0"
+    jsonfile "^6.0.1"
+    universalify "^2.0.0"
+
 fs.realpath@^1.0.0:
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/fs.realpath/-/fs.realpath-1.0.0.tgz#1504ad2523158caa40db4a2787cb01411994ea4f"
@@ -2818,6 +2798,11 @@ graceful-fs@^4.1.2, graceful-fs@^4.2.4:
   resolved "https://registry.yarnpkg.com/graceful-fs/-/graceful-fs-4.2.8.tgz#e412b8d33f5e006593cbd3cee6df9f2cebbe802a"
   integrity sha512-qkIilPUYcNhJpd33n0GBXTB1MMPp14TxEsEs0pTrsSVucApsYzW5V+Q8Qxhik6KU3evy+qkAAowTByymK0avdg==
 
+graceful-fs@^4.1.6, graceful-fs@^4.2.0:
+  version "4.2.10"
+  resolved "https://registry.yarnpkg.com/graceful-fs/-/graceful-fs-4.2.10.tgz#147d3a006da4ca3ce14728c7aefc287c367d7a6c"
+  integrity sha512-9ByhssR2fPVsNZj478qUUbKfmL0+t5BDVyjShtyZZLiK7ZDAArFFfopyOTj0M05wE2tJPisA4iTnnXl2YoPvOA==
+
 graphql-extensions@^0.15.0:
   version "0.15.0"
   resolved "https://registry.yarnpkg.com/graphql-extensions/-/graphql-extensions-0.15.0.tgz#3f291f9274876b0c289fa4061909a12678bd9817"
@@ -3810,6 +3795,15 @@ json5@^1.0.1:
   dependencies:
     minimist "^1.2.0"
 
+jsonfile@^6.0.1:
+  version "6.1.0"
+  resolved "https://registry.yarnpkg.com/jsonfile/-/jsonfile-6.1.0.tgz#bc55b2634793c679ec6403094eb13698a6ec0aae"
+  integrity sha512-5dgndWOriYSm5cnYaJNhalLNDKOqFwyDB/rr1E9ZsGciGvKPs8R2xYGCacuf3z6K1YKDz182fd+fY3cn3pMqXQ==
+  dependencies:
+    universalify "^2.0.0"
+  optionalDependencies:
+    graceful-fs "^4.1.6"
+
 jsonwebtoken@^8.5.1:
   version "8.5.1"
   resolved "https://registry.yarnpkg.com/jsonwebtoken/-/jsonwebtoken-8.5.1.tgz#00e71e0b8df54c2121a1f26137df2280673bcc0d"
@@ -3978,16 +3972,22 @@ lodash@4.x, lodash@^4.7.0:
   resolved "https://registry.yarnpkg.com/lodash/-/lodash-4.17.21.tgz#679591c564c3bffaae8454cf0b3df370c3d6911c"
   integrity sha512-v2kDEe57lecTulaDIuNTPy3Ry4gLGJ6Z1O3vE1krgXZNrsQ+LFTGHVxVjcXPs17LhbZVGedAJv8XZ1tvj5FvSg==
 
+log4js@^6.4.6:
+  version "6.4.6"
+  resolved "https://registry.yarnpkg.com/log4js/-/log4js-6.4.6.tgz#1878aa3f09973298ecb441345fe9dd714e355c15"
+  integrity sha512-1XMtRBZszmVZqPAOOWczH+Q94AI42mtNWjvjA5RduKTSWjEc56uOBbyM1CJnfN4Ym0wSd8cQ43zOojlSHgRDAw==
+  dependencies:
+    date-format "^4.0.9"
+    debug "^4.3.4"
+    flatted "^3.2.5"
+    rfdc "^1.3.0"
+    streamroller "^3.0.8"
+
 loglevel@^1.6.7:
   version "1.7.1"
   resolved "https://registry.yarnpkg.com/loglevel/-/loglevel-1.7.1.tgz#005fde2f5e6e47068f935ff28573e125ef72f197"
   integrity sha512-Hesni4s5UkWkwCGJMQGAh71PaLUmKFM60dHvq0zi/vDhhrzuk+4GgNbTXJ12YYQJn6ZKBDNIjYcuQGKudvqrIw==
 
-loglevelnext@^4.0.1:
-  version "4.0.1"
-  resolved "https://registry.yarnpkg.com/loglevelnext/-/loglevelnext-4.0.1.tgz#4406c6348c243a35272ac75d7d8e4e60ecbcd011"
-  integrity sha512-/tlMUn5wqgzg9msy0PiWc+8fpVXEuYPq49c2RGyw2NAh0hSrgq6j/Z3YPnwWsILMoFJ+ZT6ePHnWUonkjDnq2Q==
-
 long@^4.0.0:
   version "4.0.0"
   resolved "https://registry.yarnpkg.com/long/-/long-4.0.0.tgz#9a7b71cfb7d361a194ea555241c92f7468d5bf28"
@@ -4150,11 +4150,6 @@ named-placeholders@^1.1.2:
   dependencies:
     lru-cache "^4.1.3"
 
-nanoid@^3.1.20:
-  version "3.1.32"
-  resolved "https://registry.yarnpkg.com/nanoid/-/nanoid-3.1.32.tgz#8f96069e6239cc0a9ae8c0d3b41a3b4933a88c0a"
-  integrity sha512-F8mf7R3iT9bvThBoW4tGXhXFHCctyCiUUPrWF8WaTqa3h96d9QybkSeba43XVOOE3oiLfkVDe4bT8MeGmkrTxw==
-
 natural-compare@^1.4.0:
   version "1.4.0"
   resolved "https://registry.yarnpkg.com/natural-compare/-/natural-compare-1.4.0.tgz#4abebfeed7541f2c27acfb29bdbbd15c8d5ba4f7"
@@ -4746,6 +4741,11 @@ reusify@^1.0.4:
   resolved "https://registry.yarnpkg.com/reusify/-/reusify-1.0.4.tgz#90da382b1e126efc02146e90845a88db12925d76"
   integrity sha512-U9nH88a3fc/ekCF1l0/UP1IosiuIjyTh7hBvXVMHYgVcfGvt897Xguj2UOLDeI5BG2m7/uwyaLVT6fbtCwTyzw==
 
+rfdc@^1.3.0:
+  version "1.3.0"
+  resolved "https://registry.yarnpkg.com/rfdc/-/rfdc-1.3.0.tgz#d0b7c441ab2720d05dc4cf26e01c89631d9da08b"
+  integrity sha512-V2hovdzFbOi77/WajaSMXk2OLm+xNIeQdMMuB7icj7bk6zi2F8GGAxigcnDFpJHbNyNcgyJDiP+8nOrY5cZGrA==
+
 rimraf@^3.0.0, rimraf@^3.0.2:
   version "3.0.2"
   resolved "https://registry.yarnpkg.com/rimraf/-/rimraf-3.0.2.tgz#f1a5402ba6220ad52cc1282bac1ae3aa49fd061a"
@@ -4981,6 +4981,15 @@ stack-utils@^2.0.3:
   resolved "https://registry.yarnpkg.com/statuses/-/statuses-1.5.0.tgz#161c7dac177659fd9811f43771fa99381478628c"
   integrity sha1-Fhx9rBd2Wf2YEfQ3cfqZOBR4Yow=
 
+streamroller@^3.0.8:
+  version "3.0.8"
+  resolved "https://registry.yarnpkg.com/streamroller/-/streamroller-3.0.8.tgz#84b190e4080ee311ca1ebe0444e30ac8eedd028d"
+  integrity sha512-VI+ni3czbFZrd1MrlybxykWZ8sMDCMtTU7YJyhgb9M5X6d1DDxLdJr+gSnmRpXPMnIWxWKMaAE8K0WumBp3lDg==
+  dependencies:
+    date-format "^4.0.9"
+    debug "^4.3.4"
+    fs-extra "^10.1.0"
+
 streamsearch@0.1.2:
   version "0.1.2"
   resolved "https://registry.yarnpkg.com/streamsearch/-/streamsearch-0.1.2.tgz#808b9d0e56fc273d809ba57338e929919a1a9f1a"
@@ -5363,6 +5372,11 @@ universalify@^0.1.2:
   resolved "https://registry.yarnpkg.com/universalify/-/universalify-0.1.2.tgz#b646f69be3942dabcecc9d6639c80dc105efaa66"
   integrity sha512-rBJeI5CXAlmy1pV+617WB9J63U6XcazHHF2f2dbJix4XzpUF0RS3Zbj0FGIOCAva5P/d/GBOYaACQ1w+0azUkg==
 
+universalify@^2.0.0:
+  version "2.0.0"
+  resolved "https://registry.yarnpkg.com/universalify/-/universalify-2.0.0.tgz#75a4984efedc4b08975c5aeb73f530d02df25717"
+  integrity sha512-hAZsKq7Yy11Zu1DE0OzWjw7nnLZmJZYTDZZyEFHZdUhV8FkH5MCfoU1XMaxXovpyW5nq5scPqq0ZDP9Zyl04oQ==
+
 unpipe@1.0.0, unpipe@~1.0.0:
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/unpipe/-/unpipe-1.0.0.tgz#b2bf4ee8514aae6165b4817829d21b2ef49904ec"

database/.prettierrc.js

@@ -5,4 +5,5 @@ module.exports = {
   trailingComma: "all",
   tabWidth: 2,
   bracketSpacing: true,
+  endOfLine: "auto",
 };

frontend/.prettierrc.js

@@ -4,5 +4,6 @@ module.exports = {
   singleQuote: true,
   trailingComma: "all",
   tabWidth: 2,
-  bracketSpacing: true
+  bracketSpacing: true,
+  endOfLine: "auto",
 };