Skip to content

Commit 935fd6e

Browse files
mirgeemirgee
authored
Merge pull request #146 from AbsaOSS/logging/improvements
Improve logging, various enhancements
2 parents cc557db + c076be9 commit 935fd6e

File tree

15 files changed

+171
-116
lines changed

15 files changed

+171
-116
lines changed

‎vcxagency-client/src/encryption/a2a.js‎

Lines changed: 8 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -19,36 +19,21 @@
1919
const { unpack } = require('easy-indysdk')
2020

2121
async function parseAnoncrypted (walletHandle, buffer) {
22-
const agencyMode = '2.0'
23-
if (agencyMode === '1.0') {
24-
throw Error('Not implemented')
25-
} else {
26-
const { message } = await unpack(walletHandle, buffer)
27-
return JSON.parse(message)
28-
}
22+
const { message } = await unpack(walletHandle, buffer)
23+
return JSON.parse(message)
2924
}
3025

3126
async function parseAuthcrypted (walletHandle, buffer) {
32-
const agencyMode = '2.0'
33-
if (agencyMode === '1.0') {
34-
throw Error('Not implemented')
35-
} else {
36-
const { message, sender_verkey: senderVerkey } = await unpack(walletHandle, buffer)
37-
if (!senderVerkey) {
38-
throw Error('Authcrypted message was expected but sender_verkey is unknown after unpack.')
39-
}
40-
return { message: JSON.parse(message), senderVerkey }
27+
const { message, sender_verkey: senderVerkey } = await unpack(walletHandle, buffer)
28+
if (!senderVerkey) {
29+
throw Error('Authcrypted message was expected but sender_verkey is unknown after unpack.')
4130
}
31+
return { message: JSON.parse(message), senderVerkey }
4232
}
4333

4434
async function tryParseAuthcrypted (walletHandle, buffer) {
45-
const agencyMode = '2.0'
46-
if (agencyMode === '1.0') {
47-
throw Error('Not implemented')
48-
} else {
49-
const { message, sender_verkey: senderVerkey } = await unpack(walletHandle, buffer)
50-
return { message: JSON.parse(message), senderVerkey }
51-
}
35+
const { message, sender_verkey: senderVerkey } = await unpack(walletHandle, buffer)
36+
return { message: JSON.parse(message), senderVerkey }
5237
}
5338

5439
module.exports = {

‎vcxagency-client/test/e2e/ea/longpoll-disabled.spec.js‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -80,6 +80,6 @@ describe('longpoll', () => {
8080
thrown = err
8181
}
8282
expect(thrown.response.status).toBe(409)
83-
expect(thrown.response.data.error.message).toBe('Feature is not enabled.')
83+
expect(thrown.response.data.errorTraceId).toBeDefined()
8484
})
8585
})

‎vcxagency-node/src/api/api-messaging.js‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -21,10 +21,13 @@ const { asyncHandler } = require('./middleware')
2121
module.exports = function (expressRouter, forwardAgent) {
2222
expressRouter.post('/',
2323
asyncHandler(async function (req, res) {
24-
let resStatus = 200
2524
const responseData = await forwardAgent.handleIncomingMessage(req.body)
26-
if (responseData.errorMsg) resStatus = 500
25+
const { errorTraceId } = responseData
26+
if (errorTraceId) {
27+
res.set('content-type', 'application/json')
28+
return res.status(500).send({ errorTraceId })
29+
}
2730
res.set('content-type', 'application/ssi-agent-wire')
28-
res.status(resStatus).send(responseData)
31+
res.status(200).send(responseData)
2932
}))
3033
}

‎vcxagency-node/src/api/middleware.js‎

Lines changed: 7 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ module.exports.finalExpressHandlers = function finalExpressHandlers (app) {
2828
res.status(404).send({ message: `Your request: '${req.originalUrl}' didn't reach any handler.` })
2929
})
3030

31-
app.use(function (err, req, res, next) {
31+
app.use(function (err, req, res) {
3232
if (err instanceof ValidationError) {
3333
return res.status(err.statusCode).json(err)
3434
}
@@ -42,27 +42,21 @@ module.exports.asyncHandler = function asyncHandler (fn) {
4242
const result = Promise
4343
.resolve(fn(req, res, next))
4444
.catch(function (err) {
45-
const traceId = httpContext.get('reqId')
46-
const responsePayload = { 'trace-id': traceId }
45+
const errorTraceId = httpContext.get('reqId')
46+
const responsePayload = { errorTraceId }
4747
if (err instanceof ErrorFeatureDisabled) {
4848
responsePayload.message = err.message
49-
logger.error(`ErrorFeatureDisabled. Error: ${JSON.stringify(responsePayload)}`)
50-
res.status(409).send({ error: responsePayload })
49+
logger.error(`ErrorFeatureDisabled error, errorTraceId=${errorTraceId} error=${err.stack}`)
50+
res.status(409).send(responsePayload)
5151
} else {
52-
logger.error(`Unexpected error: '${traceId}'. Unhandled error from async express handler. Error details:`)
53-
logger.error(err.stack)
54-
res.status(500).send({ message: `Something went wrong unexpectedly. traceId=${traceId}`, errorId: traceId })
52+
logger.error(`Unhandled error from async express handler, errorTraceId=${errorTraceId} error=${err.stack}`)
53+
res.status(500).send(responsePayload)
5554
}
5655
})
5756
return result
5857
}
5958
}
6059

61-
module.exports.logRequestsWithoutBody = function logRequestsWithoutBody (req, res, next) {
62-
logger.info(`${req.method} ${req.originalUrl}`)
63-
next()
64-
}
65-
6660
module.exports.logRequestsWithBody = function logRequestsWithBody (req, res, next) {
6761
logger.info(`${req.method} ${req.originalUrl} Request body: ${JSON.stringify(req.body)}`)
6862
next()

‎vcxagency-node/src/configuration/app-config-loader.js‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ function buildAppConfigFromEnvVariables () {
3333
LOG_LEVEL: process.env.LOG_LEVEL || 'info',
3434
LOG_ENABLE_INDYSDK: process.env.LOG_ENABLE_INDYSDK || 'false',
3535
LOG_JSON_TO_CONSOLE: process.env.LOG_JSON_TO_CONSOLE,
36+
LOG_HEALTH_REQUESTS: process.env.LOG_HEALTH_REQUESTS,
3637

3738
SERVER_PORT: process.env.SERVER_PORT,
3839
SERVER_HOSTNAME: process.env.SERVER_HOSTNAME,

‎vcxagency-node/src/configuration/app-config.js‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,8 @@ const configValidation = Joi.object().keys({
4242
LOG_LEVEL: Joi.string().valid('silly', 'debug', 'info', 'warn', 'error'),
4343
LOG_ENABLE_INDYSDK: Joi.string().valid('true', 'false'),
4444
LOG_JSON_TO_CONSOLE: Joi.string().valid('true', 'false'),
45+
LOG_HEALTH_REQUESTS: Joi.string().valid('true', 'false').default('false'),
46+
4547
SERVER_PORT: Joi.number().integer().min(1025).max(65535).required(),
4648
SERVER_HOSTNAME: Joi.string().default('0.0.0.0'),
4749
SERVER_MAX_REQUEST_SIZE_KB: Joi.number().integer().min(1).max(MB_AS_KB * 10).default(512),

‎vcxagency-node/src/logging/logger-builder.js‎

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@
1818

1919
const winston = require('winston')
2020
const path = require('path')
21-
const { characterTruncater, jsonFormatter, tryAddRequestId } = require('./logger-common')
21+
const { jsonFormatter, tryAddRequestId } = require('./logger-common')
2222

2323
const prettyFormatter = winston.format.combine(
2424
winston.format.colorize({ all: true }),
@@ -36,7 +36,6 @@ function createConsoleLogger (mainLoggerName, formatter, logLevel, makeItSilent
3636
silent: makeItSilent,
3737
level: logLevel,
3838
format: winston.format.combine(
39-
characterTruncater(5000),
4039
winston.format.timestamp({
4140
format: 'YYYY-MM-DD HH:mm:ss.SSS'
4241
}),
@@ -58,7 +57,7 @@ const mainLoggerName = 'main'
5857

5958
const formatter = process.env.LOG_JSON_TO_CONSOLE === 'true' ? jsonFormatter : prettyFormatter
6059
const logLevel = process.env.LOG_LEVEL ? process.env.LOG_LEVEL : 'info'
61-
createConsoleLogger(mainLoggerName, formatter, logLevel, process.env.SILENT_WINSTON)
60+
createConsoleLogger(mainLoggerName, formatter, logLevel, process.env.SILENT_WINSTON === 'true')
6261

6362
module.exports = function (fullPath) {
6463
return addChildLogger(mainLoggerName, fullPath)

‎vcxagency-node/src/logging/logger-common.js‎

Lines changed: 1 addition & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -26,26 +26,11 @@ const tryAddRequestId = winston.format.combine(
2626
})
2727
)
2828

29-
const characterTruncater = lengthLimit => {
30-
return winston.format.combine(
31-
winston.format.printf(info => {
32-
const m = info.message
33-
if (typeof m === 'string') {
34-
const tailLength = Math.floor(lengthLimit / 2)
35-
const filler = `[${Math.floor(m.length - lengthLimit)} chars]`
36-
info.message = (m.length < lengthLimit) ? m : (m.substring(0, tailLength) + filler + m.substring(m.length - tailLength, m.length))
37-
}
38-
return info
39-
})
40-
)
41-
}
42-
4329
const jsonFormatter = winston.format.combine(
4430
winston.format.printf(
45-
info => JSON.stringify(info).replace(/\\n/g, '\\n').replace(/\\t/g, '\\t')
31+
info => JSON.stringify(info)
4632
)
4733
)
4834

49-
module.exports.characterTruncater = characterTruncater
5035
module.exports.jsonFormatter = jsonFormatter
5136
module.exports.tryAddRequestId = tryAddRequestId

‎vcxagency-node/src/service/entities/agent-connection/agent-connection.js‎

Lines changed: 30 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
const {
2020
MSGTYPE_ARIES_FWD,
2121
MSGTYPE_GET_MSGS,
22+
MSGTYPE_MSGS,
2223
tryParseAuthcrypted,
2324
buildMsgVcxV2Msgs
2425
} = require('vcxagency-client')
@@ -136,11 +137,21 @@ async function buildAgentConnectionAO (entityRecord, serviceWallets, serviceStor
136137
}
137138
logger.info(`${whoami} Handling message ${JSON.stringify(msgObject)}`)
138139
const resObject = await _handleAuthorizedAgentConnectionMsg(msgObject)
139-
logger.debug(`${whoami} Sending response: ${JSON.stringify(resObject)}`)
140+
_logResponseObject(resObject)
140141
return { response: resObject, shouldEncrypt: true }
141142
}
142143
}
143144

145+
function _logResponseObject (responseObject) {
146+
const msgType = responseObject['@type']
147+
if (msgType === MSGTYPE_MSGS) {
148+
const msgCount = responseObject.msgs.length
149+
logger.info(`${whoami} Sending response of type ${msgType}, retrieved ${msgCount} messages.`)
150+
} else {
151+
logger.info(`${whoami} Sending response: ${JSON.stringify(responseObject)}`)
152+
}
153+
}
154+
144155
async function _handleAuthorizedAgentConnectionMsg (msgObject) {
145156
const msgType = msgObject['@type']
146157
if (msgType === MSGTYPE_GET_MSGS) {
@@ -150,29 +161,35 @@ async function buildAgentConnectionAO (entityRecord, serviceWallets, serviceStor
150161
}
151162
}
152163

153-
async function trySendNotification (msgUid, statusCode) {
164+
async function trySendNotification (msgUid) {
154165
const webhookUrl = await serviceStorage.getAgentWebhook(agentDid)
155-
logger.info(`Agent ${agentDid} received aries message and resolved webhook ${webhookUrl}`)
156166
if (webhookUrl) {
157-
const notificationId = uuid.v4()
158-
sendNotification(webhookUrl, msgUid, statusCode, notificationId, userPairwiseDid)
159-
.then(() => {
160-
logger.info(`Notification ${notificationId} from agentConnectionDid ${agentConnectionDid} sent to ${webhookUrl} successfully.`)
161-
}, reason => {
162-
const respData = reason.response && reason.response.data
163-
? ` Response data ${JSON.stringify(reason.response.data)}`
164-
: ''
165-
logger.warn(`Notification ${notificationId} from agentConnectionDid ${agentConnectionDid} sent to ${webhookUrl} encountered problem. Reason: ${reason}. ${respData}`)
167+
sendNotification(webhookUrl, msgUid, userPairwiseDid)
168+
.catch(err => {
169+
if (err.message.includes('timeout')) {
170+
logger.debug(`${whoami} Webhook url didn't respond quickly enough, err=${err.stack}`)
171+
// we don't log timeout errors, webhook integrators are expected to respond quickly
172+
} else {
173+
logger.warn(`${whoami} Error sending webhook notification, err=${err.stack}`)
174+
}
166175
})
167176
}
168177
}
169178

170179
async function _handleAriesFwd (msgObject) {
171180
const msgUid = uuid.v4()
172181
const statusCode = 'MS-103'
182+
logger.info(`${whoami} Received new Aries message msgUid=${msgUid}.`)
173183
await serviceStorage.storeMessage(agentDid, agentConnectionDid, msgUid, statusCode, msgObject.msg)
184+
logger.info(`${whoami} Stored message msgUid=${msgUid}.`)
174185
serviceNewMessages.flagNewMessage(agentDid)
175-
trySendNotification(msgUid, statusCode)
186+
.catch(err => {
187+
logger.error(`${whoami} Failed to set new-message flag, agentDid=${agentDid}, msgUid=${msgUid} Error: ${err.stack}`)
188+
})
189+
trySendNotification(msgUid)
190+
.catch(err => {
191+
logger.error(`${whoami} Failed trying to send webhook notification, agentDid=${agentDid}, msgUid=${msgUid} Error: ${err.stack}`)
192+
})
176193
}
177194

178195
async function _handleGetMsgs (msgObject) {

‎vcxagency-node/src/service/entities/agent/agent.js‎

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -128,11 +128,21 @@ async function buildAgentAO (entityRecord, serviceWallets, serviceStorage, route
128128
} else {
129129
logger.info(`${whoami} Handling message ${JSON.stringify(msgObject)}`)
130130
const responseObject = await _handleAuthorizedAgentMessage(msgObject, senderVerkey)
131-
logger.debug(`${whoami} Sending response: ${JSON.stringify(responseObject)}`)
131+
_logResponseObject(responseObject)
132132
return { response: responseObject, wasEncrypted: false }
133133
}
134134
}
135135

136+
function _logResponseObject (responseObject) {
137+
const msgType = responseObject['@type']
138+
if (msgType === MSGTYPE_GET_MSGS_BY_CONNS) {
139+
const msgCount = responseObject.msgs.length
140+
logger.info(`${whoami} Sending response of type ${msgType}, retrieved ${msgCount} messages.`)
141+
} else {
142+
logger.info(`${whoami} Sending response: ${JSON.stringify(responseObject)}`)
143+
}
144+
}
145+
136146
async function _handleAuthorizedAgentMessage (msgObject) {
137147
const msgType = msgObject['@type']
138148
if (msgType === MSGTYPE_SIGNUP) {

0 commit comments

Comments
 (0)