Forward Statement - Duplicated data (Open Source)

[Nmarinsiruela]

What version were you using?

Open Source.
Open source hosted in AWS with Redis as queue provider.

What steps can we follow to reproduce the behaviour?

Configuring the forward statement option to go into an endpoint, then check the results on said endpoint.

What is the actual behaviour?

When we use the forward statement logic, instead of receiving one POST request in our system, we're receiving two. The first one lacks the person property entirely, with the second event having that property with its right data.

Additionally, we found that when we restarted the Worker (or sometimes), a single event was sent rather than two. It seems there is a race condition within the queues.

What is the expected behavior?

When we use the forward statement logic, we receive a single POST request with all the filled fields.

Is there any additional information that will help us replicate/understand the problem?

We have retrieved the API logs on when an event is sent once, and then when the event is sent twice:

Worker log when it's being sent once:

1|Worker  | 2022-03-25 11:26:49:065 - debug: Message on channel 'LEARNINGLOCKER:statement.notify'
1|Worker  | 2022-03-25 11:26:49:067 - debug: Popped 'LEARNINGLOCKER:statement.new': {"statementId":"aaa","organisationId":"bbb"}
1|Worker  | 2022-03-25 11:26:49:077 - debug: NO STATUS, statementId: ccc
1|Worker  | 2022-03-25 11:26:49:088 - debug: ADDING STATEMENT TO QUEUE STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:26:49:091 - debug: ADDING STATEMENT TO QUEUE STATEMENT_PERSON_QUEUE
1|Worker  | 2022-03-25 11:26:49:092 - debug: START STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:094 - debug: ADDING STATEMENT TO QUEUE STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:26:49:095 - debug: START STATEMENT_PERSON_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:102 - debug: ADDED ccc to STATEMENT_QUERYBUILDERCACHE_QUEUE, STATEMENT_PERSON_QUEUE, STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:26:49:105 - debug: START STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:157 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:162 - debug: SUCCESS adding forwarding statement to forwarding statement request queue
1|Worker  | 2022-03-25 11:26:49:163 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:165 - debug: COMPLETED ccc - STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:26:49:167 - debug: COMPLETED JOB 8364
1|Worker  | 2022-03-25 11:26:49:167 - debug: REMOVING JOB 8364
1|Worker  | 2022-03-25 11:26:49:172 - debug: COMPLETED JOB 11808
1|Worker  | 2022-03-25 11:26:49:172 - debug: REMOVING JOB 11808
1|Worker  | 2022-03-25 11:26:49:179 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_PERSON_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:182 - debug: COMPLETED JOB 7889
1|Worker  | 2022-03-25 11:26:49:182 - debug: REMOVING JOB 7889
1|Worker  | 2022-03-25 11:26:49:186 - debug: ADDING STATEMENT TO QUEUE STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:26:49:188 - debug: ADDED ccc to STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:26:49:188 - debug: START STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:189 - debug: COMPLETED JOB 28058
1|Worker  | 2022-03-25 11:26:49:189 - debug: REMOVING JOB 28058
1|Worker  | 2022-03-25 11:26:49:190 - debug: COMPLETED ccc - STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:26:49:256 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:26:49:259 - debug: COMPLETED JOB 8365
1|Worker  | 2022-03-25 11:26:49:259 - debug: REMOVING JOB 8365
1|Worker  | 2022-03-25 11:26:49:262 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:26:49:263 - debug: COMPLETED JOB 28059
1|Worker  | 2022-03-25 11:26:49:263 - debug: REMOVING JOB 28059
1|Worker  | 2022-03-25 11:26:49:264 - debug: COMPLETED ccc - STATEMENT_PERSON_QUEUE
1|Worker  | 2022-03-25 11:26:49:273 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:26:49:274 - debug: COMPLETED JOB 28060
1|Worker  | 2022-03-25 11:26:49:275 - debug: REMOVING JOB 28060
1|Worker  | 2022-03-25 11:26:49:276 - debug: COMPLETED ccc - STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:26:49:289 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:26:49:290 - debug: COMPLETED JOB 28061
1|Worker  | 2022-03-25 11:26:49:290 - debug: REMOVING JOB 28061
1|Worker  | 2022-03-25 11:26:49:615 - debug: SUCCESS sending statement ccc to externalURL
1|Worker  | 2022-03-25 11:26:49:616 - debug: COMPLETED JOB 96
1|Worker  | 2022-03-25 11:26:49:616 - debug: REMOVING JOB 96

Worker log when it's being sent twice:

1|Worker  | 2022-03-25 11:03:34:684 - debug: Message on channel 'LEARNINGLOCKER:statement.notify'
1|Worker  | 2022-03-25 11:03:34:686 - debug: Popped 'LEARNINGLOCKER:statement.new': {"statementId":"xxx","organisationId":"yyy"}
1|Worker  | 2022-03-25 11:03:34:696 - debug: NO STATUS, statementId: ccc
1|Worker  | 2022-03-25 11:03:34:703 - debug: ADDING STATEMENT TO QUEUE STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:03:34:705 - debug: ADDING STATEMENT TO QUEUE STATEMENT_PERSON_QUEUE
1|Worker  | 2022-03-25 11:03:34:707 - debug: START STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:709 - debug: ADDING STATEMENT TO QUEUE STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:710 - debug: START STATEMENT_PERSON_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:716 - debug: ADDED ccc to STATEMENT_QUERYBUILDERCACHE_QUEUE, STATEMENT_PERSON_QUEUE, STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:720 - debug: START STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:730 - debug: SUCCESS adding forwarding statement to forwarding statement request queue
1|Worker  | 2022-03-25 11:03:34:730 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:733 - debug: COMPLETED ccc - STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:734 - debug: COMPLETED JOB 11794
1|Worker  | 2022-03-25 11:03:34:754 - debug: REMOVING JOB 11794
1|Worker  | 2022-03-25 11:03:34:759 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_QUERYBUILDERCACHE_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:772 - debug: COMPLETED JOB 8354
1|Worker  | 2022-03-25 11:03:34:772 - debug: REMOVING JOB 8354
1|Worker  | 2022-03-25 11:03:34:774 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:03:34:776 - debug: COMPLETED JOB 28026
1|Worker  | 2022-03-25 11:03:34:776 - debug: REMOVING JOB 28026
1|Worker  | 2022-03-25 11:03:34:776 - debug: COMPLETED ccc - STATEMENT_QUERYBUILDERCACHE_QUEUE
1|Worker  | 2022-03-25 11:03:34:780 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_PERSON_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:782 - debug: COMPLETED JOB 7881
1|Worker  | 2022-03-25 11:03:34:784 - debug: REMOVING JOB 7881
1|Worker  | 2022-03-25 11:03:34:862 - debug: ADDING STATEMENT TO QUEUE STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:864 - debug: ADDED ccc to STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:865 - debug: START STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:866 - debug: COMPLETED JOB 28027
1|Worker  | 2022-03-25 11:03:34:866 - debug: REMOVING JOB 28027
1|Worker  | 2022-03-25 11:03:34:867 - debug: COMPLETED ccc - STATEMENT_PERSON_QUEUE
1|Worker  | 2022-03-25 11:03:34:875 - debug: SUCCESS adding forwarding statement to forwarding statement request queue
1|Worker  | 2022-03-25 11:03:34:876 - debug: COMPLETED STATEMENT HANDLER FOR STATEMENT_FORWARDING_QUEUE ccc
1|Worker  | 2022-03-25 11:03:34:877 - debug: COMPLETED JOB 11795
1|Worker  | 2022-03-25 11:03:34:877 - debug: REMOVING JOB 11795
1|Worker  | 2022-03-25 11:03:34:879 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:03:34:880 - debug: COMPLETED JOB 28028
1|Worker  | 2022-03-25 11:03:34:881 - debug: REMOVING JOB 28028
1|Worker  | 2022-03-25 11:03:34:881 - debug: COMPLETED ccc - STATEMENT_FORWARDING_QUEUE
1|Worker  | 2022-03-25 11:03:34:898 - debug: PROCESSED QUEUE FOR STATEMENT ccc
1|Worker  | 2022-03-25 11:03:34:898 - debug: COMPLETED JOB 28029
1|Worker  | 2022-03-25 11:03:34:899 - debug: REMOVING JOB 28029
1|Worker  | 2022-03-25 11:03:35:155 - debug: SUCCESS sending statement ccc to externalURL
1|Worker  | 2022-03-25 11:03:35:157 - debug: COMPLETED JOB 82
1|Worker  | 2022-03-25 11:03:35:157 - debug: REMOVING JOB 82
1|Worker  | 2022-03-25 11:03:35:556 - debug: SUCCESS sending statement ccc to externalURL
1|Worker  | 2022-03-25 11:03:35:557 - debug: COMPLETED JOB 83
1|Worker  | 2022-03-25 11:03:35:558 - debug: REMOVING JOB 83