n8n-io / n8n

Free and source-available fair-code licensed workflow automation tool. Easily automate tasks across different services.
https://n8n.io
Other
47.86k stars 7.31k forks source link

GMail Trigger : Fetching duplicate emails again #10470

Closed Alexandero89 closed 1 month ago

Alexandero89 commented 2 months ago

Bug Description

Hello all,

My Gmail trigger is firing multiple times for the same email.

It seems it was a problem before https://github.com/n8n-io/n8n/issues/5510 https://github.com/n8n-io/n8n/pull/9424 and is one again.

Every time the Gmailtrigger fired it processed the last available emails. Sometimes it processed the same email up to 5 times. And i could finally find the reason for that.

In the GmailTrigger especially the function nextPollPossibleDuplicates https://github.com/n8n-io/n8n/blob/ab9faf109ca66e08e9346296bd989e8c687d6187/packages/nodes-base/nodes/Google/Gmail/GmailTrigger.node.ts#L360-L368 It checks if the email has the same timestamp as lastEmailDate. If so it adds it to the list of possible duplicates for the next run.

But if the poll from gmail gives back an array of emails every email that has not the identical timestamp as lastEmailDate slips through the logic of this filter although it is a duplicate. Lets say we get an array of 2 emails from google and responseData is [{id:"email1"}, {id: "email2"}]. email1 has timestamp 1724052900 and email2 has timestamp 1724052800. The function lastEmailDate https://github.com/n8n-io/n8n/blob/ab9faf109ca66e08e9346296bd989e8c687d6187/packages/nodes-base/nodes/Google/Gmail/GmailTrigger.node.ts#L355-L358 sets the lastEmailDate to 1724052900. Then email1 gets added to the nextPollPossibleDuplicates list because it has the same timestamp as lastEmailDate, but not email2.

So if next time we pull data from gmail again and we get the same two emails (because no new email arrived), email1 is recognised as duplicate, but not email2. Email2 will then be processed by the workflow everytime the trigger runs. It only stops until a new mail arrives and we get new data from the gmail poll.

My thoughts:

I dont really understand why there is even a need for a duplicateemail list? Why is there not just a reduce function to delete all emails from responsedata which have a smaller timestamp than nodeStaticData.lastTimeChecked ? I mean nodeStaticData.lastTimeChecked gives us the exact timestamp every mail up to this time was polled and processed. So we can be kind of sure that every mail that arrives with a timestamp before nodeStaticData.lastTimeChecked is a duplicate.

I added some logger to find the error. Here are the logs if they help you.

Click to see the log > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ comment: 'Starting poll function', file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ Lasttimechecked: 1724052792, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ comment: \"Time now '1724053016'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ comment: \"Startdate '1724052792'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ comment: \"Enddate '1724053016'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.007Z | error | "{ comment: 'Options ', options: {}, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.008Z | error | "{ comment: 'Filters ', filters: { labelIds: [ 'Label_2641557787588889810' ], receivedAfter: 1724052792 }, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:56.192Z | error | "{ comment: 'Responsedata ', responseData: [ { id: '1916990b5e5b8bb2', threadId: '1916990b5e5b8bb2' }, { id: '1916990a6644fbd3', threadId: '1916990a6644fbd3' }, { id: '191698dffa7d2f00', threadId: '191698dffa7d2f00' } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.051Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.051Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.051Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.051Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ emailid: '191698dffa7d2f00', comment: \"Email date '1724052791'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ emailid: '191698dffa7d2f00', comment: \"Email date '1724052791'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.052Z | error | "{ comment: 'Possible duplicates not empty ', possibleDuplicates: [ '191698dffa7d2f00' ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.054Z | error | "{ comment: 'Filtered response data ', responseData: [ { json: [Object], binary: undefined }, { json: [Object], binary: undefined } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.054Z | error | "{ comment: \"Nextpollpossibleduplicates '1916990b5e5b8bb2'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:36:57.055Z | error | "{ comment: \"Setting lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > > ######################################################################################################################################### > > n8n-1 | 2024-08-19T07:37:56.007Z | error | "{ comment: 'Starting poll function', file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.007Z | error | "{ Lasttimechecked: 1724052963, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.007Z | error | "{ comment: \"Time now '1724053076'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.007Z | error | "{ comment: \"Startdate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.007Z | error | "{ comment: \"Enddate '1724053076'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.008Z | error | "{ comment: 'Options ', options: {}, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.008Z | error | "{ comment: 'Filters ', filters: { labelIds: [ 'Label_2641557787588889810' ], receivedAfter: 1724052963 }, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.202Z | error | "{ comment: 'Responsedata ', responseData: [ { id: '1916990b5e5b8bb2', threadId: '1916990b5e5b8bb2' }, { id: '1916990a6644fbd3', threadId: '1916990a6644fbd3' } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:56.958Z | debug | Wait tracker resuming execution 1947 "{ executionId: '1947', file: 'WaitTracker.js', function: 'startExecution'}" > n8n-1 | 2024-08-19T07:37:57.026Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.026Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.026Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.027Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.027Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.027Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.027Z | error | "{ comment: 'Possible duplicates not empty ', possibleDuplicates: [ '1916990b5e5b8bb2' ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.028Z | error | "{ comment: 'Filtered response data ', responseData: [ { json: [Object], binary: undefined } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.028Z | error | "{ comment: \"Nextpollpossibleduplicates '1916990b5e5b8bb2'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:37:57.028Z | error | "{ comment: \"Setting lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > > ######################################################################################################################################### > > n8n-1 | 2024-08-19T07:38:56.006Z | error | "{ comment: 'Starting poll function', file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.006Z | error | "{ Lasttimechecked: 1724052963, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.007Z | error | "{ comment: \"Time now '1724053136'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.007Z | error | "{ comment: \"Startdate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.007Z | error | "{ comment: \"Enddate '1724053136'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.007Z | error | "{ comment: 'Options ', options: {}, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.007Z | error | "{ comment: 'Filters ', filters: { labelIds: [ 'Label_2641557787588889810' ], receivedAfter: 1724052963 }, file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.231Z | error | "{ comment: 'Responsedata ', responseData: [ { id: '1916990b5e5b8bb2', threadId: '1916990b5e5b8bb2' }, { id: '1916990a6644fbd3', threadId: '1916990a6644fbd3' } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.830Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.830Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.831Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.831Z | error | "{ comment: \"Lastemaildate '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.831Z | error | "{ emailid: '1916990b5e5b8bb2', comment: \"Email date '1724052963'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.831Z | error | "{ emailid: '1916990a6644fbd3', comment: \"Email date '1724052961'\", file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.831Z | error | "{ comment: 'Possible duplicates not empty ', possibleDuplicates: [ '1916990b5e5b8bb2' ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.832Z | error | "{ comment: 'Filtered response data ', responseData: [ { json: [Object], binary: undefined } ], file: 'LoggerProxy.js', function: 'exports.error'}" > n8n-1 | 2024-08-19T07:38:56.832Z | error | "{ comment: \"Nextpollpossibleduplicates '1916990b5e5b8bb2'\", file: 'LoggerProxy.js', function: 'exports.error'}"

To Reproduce

1) Set up docker compose with version 1.54.02 2) Add workflow with gmail trigger

Expected behavior

Every email from gmail should be polled/processed once

Operating System

docker compose

n8n Version

1.45.2

Node.js Version

docker compose

Database

SQLite (default)

Execution mode

main (default)

Joffcom commented 2 months ago

Hey @Alexandero89,

We have created an internal ticket to look into this which we will be tracking as "GHC-174"

Alexandero89 commented 2 months ago

Nice.

just FYI @Joffcom: Had a typo with a timestamp in my logs. Just changed that

Joffcom commented 2 months ago

@Alexandero89 no worries, Oddly I noticed this issue a couple of weeks back and forgot to create an internal ticket so this perfect.

Alexandero89 commented 2 months ago

A simple change did the trick for me: Change Line 363 in https://github.com/n8n-io/n8n/blob/ab9faf109ca66e08e9346296bd989e8c687d6187/packages/nodes-base/nodes/Google/Gmail/GmailTrigger.node.ts#L360-L368 to "<=".

Although i think it would still be better to replace this duplicate list thing at all.

Joffcom commented 2 months ago

@Alexandero89 we are currently working on an internal dedupe mechanism which will likely be a better option for this kind of trigger in the future although using message IDs or date in theory should work it is a bit of a strange one.

Joffcom commented 1 month ago

Fix got released with n8n@1.59.0