Skip to content

Commit dc56afc

Browse files
NickOvtNickOvt
authored
fix(logging): ZMS-216 add logs for debugging timeout issue (#823)
1 parent 70aed51 commit dc56afc

2 files changed

Lines changed: 117 additions & 0 deletions

File tree

‎lib/filter-handler.js‎

Lines changed: 89 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -155,6 +155,14 @@ class FilterHandler {
155155
});
156156
}
157157

158+
this.loggelf({
159+
short_message: '[FILTER-HANDLER] Prepared Message',
160+
_user: userData._id.toString(),
161+
_sender: sender,
162+
_recipient: recipient,
163+
_message_id: prepared.mimeTree.parsedHeader['message-id']
164+
});
165+
158166
prepared.mimeTree.header.unshift('Return-Path: <' + Buffer.from(sender).toString('binary') + '>');
159167
prepared.mimeTree.header.unshift('Delivered-To: ' + Buffer.from(recipient).toString('binary'));
160168

@@ -227,6 +235,14 @@ class FilterHandler {
227235
// ignore as filters are not so importand
228236
}
229237

238+
this.loggelf({
239+
short_message: '[FILTER-HANDLER] Got User Filters',
240+
_user: userData._id.toString(),
241+
_sender: sender,
242+
_recipient: recipient,
243+
_message_id: prepared.mimeTree.parsedHeader['message-id']
244+
});
245+
230246
let isEncrypted = false;
231247
let forwardTargets = new Map();
232248

@@ -267,6 +283,14 @@ class FilterHandler {
267283
}
268284
}
269285

286+
this.loggelf({
287+
short_message: '[FILTER-HANDLER] Checked Global Whitelist/Blacklist',
288+
_user: userData._id.toString(),
289+
_sender: sender,
290+
_recipient: recipient,
291+
_message_id: prepared.mimeTree.parsedHeader['message-id']
292+
});
293+
270294
for (let filterData of filters) {
271295
if (!(await checkFilter(filterData, prepared, maildata))) {
272296
continue;
@@ -290,6 +314,14 @@ class FilterHandler {
290314
});
291315
}
292316

317+
this.loggelf({
318+
short_message: '[FILTER-HANDLER] Checked Filters',
319+
_user: userData._id.toString(),
320+
_sender: sender,
321+
_recipient: recipient,
322+
_message_id: prepared.mimeTree.parsedHeader['message-id']
323+
});
324+
293325
if (typeof userData.spamLevel === 'number' && userData.spamLevel >= 0) {
294326
let isSpam;
295327

@@ -520,7 +552,21 @@ class FilterHandler {
520552
let outbound = [];
521553

522554
try {
555+
this.loggelf({
556+
short_message: '[FILTER-HANDLER] Before Forward',
557+
_user: userData._id.toString(),
558+
_sender: sender,
559+
_recipient: recipient,
560+
_message_id: prepared.mimeTree.parsedHeader['message-id']
561+
});
523562
let forwardId = await forwardMessage();
563+
this.loggelf({
564+
short_message: '[FILTER-HANDLER] After Forward',
565+
_user: userData._id.toString(),
566+
_sender: sender,
567+
_recipient: recipient,
568+
_message_id: prepared.mimeTree.parsedHeader['message-id']
569+
});
524570
if (forwardId) {
525571
filterResults.push({
526572
forward: Array.from(forwardTargets)
@@ -556,7 +602,21 @@ class FilterHandler {
556602
}
557603

558604
try {
605+
this.loggelf({
606+
short_message: '[FILTER-HANDLER] Before Autoreply',
607+
_user: userData._id.toString(),
608+
_sender: sender,
609+
_recipient: recipient,
610+
_message_id: prepared.mimeTree.parsedHeader['message-id']
611+
});
559612
let autoreplyId = await sendAutoreply();
613+
this.loggelf({
614+
short_message: '[FILTER-HANDLER] After Autoreply',
615+
_user: userData._id.toString(),
616+
_sender: sender,
617+
_recipient: recipient,
618+
_message_id: prepared.mimeTree.parsedHeader['message-id']
619+
});
560620
if (autoreplyId) {
561621
filterResults.push({ autoreply: sender, 'autoreply-queue-id': autoreplyId });
562622
outbound.push(autoreplyId);
@@ -596,6 +656,14 @@ class FilterHandler {
596656
} catch (err) {
597657
log.error('Filter', '%s AUDITFAIL from=%s to=%s error=%s', prepared.id.toString(), '<>', sender, err.message);
598658
}
659+
660+
this.loggelf({
661+
short_message: '[FILTER-HANDLER] After Audits',
662+
_user: userData._id.toString(),
663+
_sender: sender,
664+
_recipient: recipient,
665+
_message_id: prepared.mimeTree.parsedHeader['message-id']
666+
});
599667
return {
600668
response: {
601669
userData,
@@ -676,6 +744,13 @@ class FilterHandler {
676744
}
677745

678746
if (userData.encryptMessages && userData.pubKey) {
747+
this.loggelf({
748+
short_message: '[FILTER-HANDLER] Before Encryption',
749+
_user: userData._id.toString(),
750+
_sender: sender,
751+
_recipient: recipient,
752+
_message_id: prepared.mimeTree.parsedHeader['message-id']
753+
});
679754
await encryptMessage();
680755
if (isEncrypted) {
681756
// make sure we have the updated message structure values
@@ -692,7 +767,21 @@ class FilterHandler {
692767
}
693768

694769
try {
770+
this.loggelf({
771+
short_message: '[FILTER-HANDLER] Before Adding Message',
772+
_user: userData._id.toString(),
773+
_sender: sender,
774+
_recipient: recipient,
775+
_message_id: prepared.mimeTree.parsedHeader['message-id']
776+
});
695777
const { data } = await this.messageHandler.addAsync(messageOpts); // returns {status, data}
778+
this.loggelf({
779+
short_message: '[FILTER-HANDLER] After Adding Message',
780+
_user: userData._id.toString(),
781+
_sender: sender,
782+
_recipient: recipient,
783+
_message_id: prepared.mimeTree.parsedHeader['message-id']
784+
});
696785
if (data) {
697786
filterResults.push({
698787
mailbox: data.mailbox && data.mailbox.toString(),

‎lib/message-handler.js‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -200,6 +200,13 @@ class MessageHandler {
200200
// if throws will be handled by caller or wrapper
201201
let [mailboxData, userData] = await Promise.all([this.getMailboxAsync(options), this.users.collection('users').findOne({ _id: options.user })]);
202202

203+
this.loggelf({
204+
short_message: '[MESSAGE-HANDLER] Got Mailbox and User Data',
205+
_user: mailboxData.user,
206+
_sess: options.session && options.session.id,
207+
_mailbox: mailboxData._id
208+
});
209+
203210
if (!userData) {
204211
throw new Error('No such user!');
205212
}
@@ -240,6 +247,13 @@ class MessageHandler {
240247
}
241248
}
242249

250+
this.loggelf({
251+
short_message: '[MESSAGE-HANDLER] Checked if Encrypted',
252+
_user: mailboxData.user,
253+
_sess: options.session && options.session.id,
254+
_mailbox: mailboxData._id
255+
});
256+
243257
let flags = Array.isArray(options.flags) ? options.flags : [].concat(options.flags || []);
244258

245259
if (!alreadyEncrypted) {
@@ -283,6 +297,13 @@ class MessageHandler {
283297
prepared = newPrepared;
284298
}
285299

300+
this.loggelf({
301+
short_message: '[MESSAGE-HANDLER] Got New Prepared',
302+
_user: mailboxData.user,
303+
_sess: options.session && options.session.id,
304+
_mailbox: mailboxData._id
305+
});
306+
286307
let id = prepared.id;
287308
let mimeTree = prepared.mimeTree;
288309
let size = prepared.size;
@@ -327,6 +348,13 @@ class MessageHandler {
327348
return resolve();
328349
});
329350
});
351+
352+
this.loggelf({
353+
short_message: '[MESSAGE-HANDLER] Stored Initial Node Bodies',
354+
_user: mailboxData.user,
355+
_sess: options.session && options.session.id,
356+
_mailbox: mailboxData._id
357+
});
330358
} catch (err) {
331359
return cleanup(err);
332360
}

0 commit comments

Comments
 (0)