fetch.on("message") event is firing twice, though imap.search result is only one result

[SharmaBiswadev]

I am trying to fetch all unseen messages, but some times mail event is triggering twice

var self = this, search = self.options.search || [[ 'UNSEEN', ['SINCE', 'May 20, 2010'] ]];
    self.dbg('scanning %s with filter `%s`.', self.options.box,  search);
    self.imap.search(search, function (err, seachResults) {
        if (err) {
            self.emit('error', err);
            callback();
            return;
        }
        if (!seachResults || seachResults.length === 0) {
            self.dbg('no new mail in %s', self.options.box);
            callback();
            return;
        }
        self.dbg('found %d new messages', seachResults.length);
        var fetch = self.imap.fetch(seachResults, {
            markSeen: self.options.markSeen !== false,
            bodies: ''
        });
//this below event emitting twice
        fetch.on('message' function (msg,seqno) {
            var uid, flags;
            msg.on('attributes', function(attrs) {                                                           
                uid = attrs.uid;
                flags = attrs.flags;
                **self.dbg("Message uid", attrs.uid);                                                               
            }); 
            var mp = new MailParser();
            mp.once('end', function (mail) {
                mail.uid = uid;
                mail.flags = flags;
                if(uid>last_seq)
                self.emit('mail', mail);
                self.dbg('found mail '+mail.headers["message-id"]);
            });
            msg.once('body', function (stream, info) {
                stream.pipe(mp);
            });
        });
        fetch.once('end', function () {
            self.dbg('Done fetching all messages!');
            callback();
        });
```   The logs are showing mail id/uid printed twice but scanned only once and scan result was 1 item
This is not always happening, any solution so that fetch.on message only triggered once for once search result

[mscdex]

What is in seachResults and is it the same seqno both times inside your 'message' event handler?

[SharmaBiswadev]

yes, both time seq number are same, searchResults we have not printed, as this issue we are facing in deployed server. Seq number we have printed and both are logging the same uid @mscdex

[mscdex]

If you insert a log statement right inside your 'message' event handler, does it show up the correct number of times for your search? That will allow us to verify the issue is/is not with MailParser.

[SharmaBiswadev]

Also from the logs, I notice,

self.imap.on('mail', function (id) {
                self.dbg('mail event : %s', id);
                q.push({name: 'scan', id : id}, function(err) {
                    self.dbg('finished processing scan '+id);
                });
            });

Here the mail event is firing more than once for a single mail. @mscdex

[SharmaBiswadev]

If you insert a log statement right inside your 'message' event handler, does it show up the correct number of times for your search? That will allow us to verify the issue is/is not with MailParser.

Ok, I will add logs to check

[mscdex]

Ok, but are you getting the double scan because you're emitting 'mail' from your fetch callback?

[SharmaBiswadev]

This mail event is not bound to imap, its in global scope which I have used to listen in my server in another file Imap is bound to self.imap = new Imap(self.options); self.imap.on mail will not listen to self.emit mail self is bound to this as

function listener(opts, dbg) {
    EventEmitter.call(this);
    var self = this;
    self.options = opts;
    if (self.options.username) { //backward compat
        self.options.user = self.options.username;
    }
    self.options.box = self.options.box || 'INBOX';
    self.options.debug = self.options.debug || debug('imap');

    if(dbg) {
        self.dbg = dbg;
    }
}
util.inherits(listener, EventEmitter);

module.exports = function (opts, customDbg) {
    return new listener(opts, customDbg);
};

Please find the logs for the same. Message uid 477. Mail event log is twice @mscdex

debug: imap  mail event : %s 1
debug: imap  process queue scan
debug: imap  scanning %s with filter `%s`. INBOX 0=UNSEEN
debug: imap  mail event : %s 1
debug: imap  process queue scan
debug: imap  scanning %s with filter `%s`. INBOX 0=UNSEEN
debug: imap  found %d new messages 1
debug: imap  found %d new messages 1
debug: imap  Message uid 477
debug: New email recieved function=processEmail()
debug: imap  found mail <CA+P6n_HkyzwF5cC-jr9MAWOtvda=Ahdg84A6v--AkjEgSLQTNg@mail.gmail.com>
debug: imap  Message uid 477
debug: New email recieved function=processEmail()
debug: imap notifier found mail <CA+P6n_HkyzwF5cC-jr9MAWOtvda=Ahdg84A6v--AkjEgSLQTNg@mail.gmail.com>
debug: imap  Done fetching all messages!
debug: imap  finished processing scan 1
debug: imap  all items have been processed
debug: imap  Done fetching all messages!
debug: imap  finished processing scan 1
debug: imap  all items have been processed

[SharmaBiswadev]

Also I got this error twice.

2019-11-25T05:42:18.599Z - debug: imap  Message uid 440
Error: Encoding not recognized: 'ISO-2022-JP' (searched as: 'iso2022jp')
    at Object.getCodec (/code/server/node_modules/iconv-lite/lib/index.js:106:23)
    at Object.getDecoder (/code/server/node_modules/iconv-lite/lib/index.js:127:23)
    at Object.decode (/code/server/node_modules/iconv-lite/lib/index.js:40:25)
    at convertIconvLite (/code/server/node_modules/encoding/lib/encoding.js:91:26)
    at convert (/code/server/node_modules/encoding/lib/encoding.js:51:22)
    at Object.mimeDecode (/code/server/node_modules/mimelib/lib/mimelib.js:247:16)
    at Object.decodeQuotedPrintable (/code/server/node_modules/mimelib/lib/mimelib.js:263:21)
    at Object.module.exports.decodeQuotedPrintable (/code/server/node_modules/mimelib/lib/mimelib.js:108:54)
    at MailParser._finalizeContents (/code/server/node_modules/mailparser/lib/mailparser.js:964:53)
    at MailParser._processStateBody (/code/server/node_modules/mailparser/lib/mailparser.js:396:26)
    at MailParser._process (/code/server/node_modules/mailparser/lib/mailparser.js:233:22)
    at runCallback (timers.js:705:18)
    at tryOnImmediate (timers.js:676:5)
    at processImmediate (timers.js:658:5)
    at process.topLevelDomainCallback (domain.js:126:23)

[mscdex]

As far as the error goes, that's coming from mailparser, not imap, so you'd want to submit an issue with that project instead.

[SharmaBiswadev]

Ok, for MailParser I raise issue requests.For mail event, could you suggest any solution? I was thinking to store seq number/message id in the database, and not to process duplicate mails @mscdex

[mscdex]

Can you post the resulting output when you set debug: console.log in your connection config object along with the debug output you already have? Perhaps the two together will shed some light as to what is happening.

If you do post the built-in debug output, please be sure to mask the login credentials first before posting.

[SharmaBiswadev]

While searching using SINCE criteria it still reads mail from older date, as you can see below I have used Nov 27, but when I marked one mail dated Nov 24 as unread and restarted IMAP server, it detected the mail dated 24 I have marked unread. As we want to search and retrieve only unseen mails since 26 Nov @mscdex

IMAP config setting:

formattedDate = new Date().toLocaleString('en-us',{month:'long', year:'numeric', day:'numeric'})
            query_string = 'user=' + adapterConfig.emailserver.user + '\1auth=Bearer ' + access_token + '\1\1';
            buffer = new Buffer(query_string);
            encoded_string = buffer.toString('base64');
        imap = {
                xoauth2: encoded_string,
                host: adapterConfig.emailserver.host,
                port: adapterConfig.emailserver.port,
                tls: true,
                debug: console.log,
                search : [[ 'UNSEEN', ['SINCE', formattedDate] ]]
// tlsOptions: { rejectUnauthorized: false }
}

Logs:~~~~~~~

=> 'A4 SELECT "INBOX" (CONDSTORE)'
<= '* FLAGS (\\Answered \\Flagged \\Draft \\Deleted \\Seen $NotPhishing $Phishing)'
<= '* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Draft \\Deleted \\Seen $NotPhishing $Phishing \\*)] Flags permitted.'
<= '* OK [UIDVALIDITY 1] UIDs valid.'
<= '* 280 EXISTS'
<= '* 0 RECENT'
<= '* OK [UIDNEXT 369] Predicted next UID.'
<= '* OK [HIGHESTMODSEQ 52285]'
<= 'A4 OK [READ-WRITE] INBOX selected. (Success)'
=> 'IDLE IDLE'
2019-11-27T11:23:07.777Z - debug: imap  process queue scan initial
2019-11-27T11:23:07.785Z - debug: imap  scanning %s with filter `%s`. **INBOX 0=[UNSEEN, 0=SINCE, 1=November 27, 2019]**
<= '+ idling'
=> DONE
<= 'IDLE OK IDLE terminated (Success)'
=> 'A5 UID SEARCH UNSEEN'
<= '* SEARCH 286'
<= 'A5 OK SEARCH completed (Success)'
debug: imap  found %d new messages 1
=> 'A6 UID FETCH 286 (X-GM-THRID X-GM-MSGID X-GM-LABELS MODSEQ UID FLAGS INTERNALDATE BODY[])'
<= '* **255 FETCH (X-GM-THRID 1651085588330440135 X-GM-MSGID 1651085588330440135 X-GM-LABELS ("\\\\Important") UID 286 MODSEQ (52260) INTERNALDATE "24-Nov-2019 12:18:39 +0000" FLAGS (\\Seen) BODY[] {4757}'**
<= '* 255 FETCH (X-GM-THRID 1651085588330440135 X-GM-MSGID 1651085588330440135 X-GM-LABELS ("\\\\Important") UID 286 MODSEQ (52260) INTERNALDATE "24-Nov-2019 12:18:39 +0000" FLAGS (\\Seen) )'
2019-11-27T11:23:09.570Z - debug: imap  Message uid 286
2019-11-27T11:23:09.685Z - debug: imap  found mail <CAMgP8BApeoHKotZ=Mkad7A+tXN4n2Jzhzuaw=qdcJoDzQoA_5w@mail.gmail.com>
<= '* 255 FETCH (UID 286 MODSEQ (52288) FLAGS (\\Seen))'
<= 'A6 OK Success'
=> 'IDLE IDLE'
debug: imap  Done fetching all messages!
debug: imap  finished processing scan initial
debug: imap  all items have been processed
<= '+ idling'
 => DONE
<= 'IDLE OK IDLE terminated (Success)'
=> 'IDLE IDLE'
<= '+ idling'

[SharmaBiswadev]

Can you post the resulting output when you set debug: console.log in your connection config object along with the debug output you already have? Perhaps the two together will shed some light as to what is happening.

If you do post the built-in debug output, please be sure to mask the login credentials first before posting.

I have added and deployed in the server. Till now it is working, once I ll get duplication, I will share the logs as duplicate events are not always happening.

[mscdex]

As far as the search criteria goes, I think there is an extra set of brackets that need to be removed, it should be just [ 'UNSEEN', ['SINCE', formattedDate] ] that is passed to search().