search

mojaloop / project

Repo to track product development issues for the Mojaloop project.
Other
25 stars 15 forks source link

Idempotency for duplicate quote request #2119

Open tullon opened 3 years ago

tullon commented 3 years ago

Summary: When performing transfers between 2 DFSPs through Mowali, the following behavior is observed in Quote request:

  1. Normally a quote request is completed in approximately 2 seconds.
  2. However, if there is a delay in the second leg quote for a forex transfer, Mowali receives a retry of the first leg quote request from payer DFSP.
  3. As per API documentation, this should be neglected via idempotency, where a duplicate request is not acted upon.
  4. However, as per our observation, Mowali does a duplicate check on every quote ID, and if this returns true, sends back an error message to payer DFSP, which then aborts the transfer. But Mowali keeps the quote request alive and pending response from payee DFSP.
  5. In scenario 4 above, if eventually the right response is received from payee DFSP, Mowali will forward this to payer DFSP but the transfer will already have been aborted.

Severity: Medium

Priority: Critical

Expected Behavior A duplicate quote request is supposed to be ignored, as API specs. This will keep the quote alive for payer, payee and hub pending response to the original request. Any error generated terminates the request at one or more actors.

Steps to Reproduce

  1. Send a quote request by Payer DFSP
  2. Delay it's response from switch
  3. Resend the same quote request from Payer DFSP

Specifications

Notes:

elnyry-sam-k commented 3 years ago

@tullon - to confirm, are these two requests exactly the same? If thats the case, the team's initial impression is that there shouldn't be an error message if they're exactly the same.. However, if there's even a minor change, then the error message should be expected (as there's a modification)...

Please confirm and then someone can try to reproduce this...

tullon commented 3 years ago

@elnyry-sam-k I am going to update with more information that we have got from further testing, which should be more helpful to process the bug.

elnyry-sam-k commented 3 years ago

Thanks @tullon ..

tullon commented 3 years ago

Idempotency on Quotes:

We have revisited testing on quotes with the following further notes: a. We have done testing for both forex and non-forex duplicate quotes. b. Upon re-evaluation, the error we receive is generated by FXP, and not by core switch quoting service. Below is the flow of both forex and non-forex scenarios: i. Forex: Step 1: Payer_DFSP sends 1st quote request Step 2. Switch processed the request, including duplicate check Step 3: Switch forwards the quote request to FXP (vDFSP1) Step 4: FXP (vDFSP2) generates 2nd leg quote to Payee_DFSP via Switch Step 5: Switch forwards 2nd leg quote to Payee_DFSP

                       ---------- DELAY IN RECEIVING RESPONSE FROM PAYEE DFSP --------------

                 Step 6: Payer_DFSP resends quote request to Switch
                 Step 7: Switch processes the quote request (including duplicate check – which returns true)
                 Step 8: Switch forwards the duplicate quote request to FXP (vDFSP1)
                 Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)
                Step 10: Switch sends the error back to Payer_DFSP (who then fails that quote request)

------------- At this point, Payer_DFSP has failed that request, but FXP is still waiting for response ------------------------------

              Step 11:  FXP generates a second leg quote time out and sends error to Switch (errorInformation: {errorCode: '2004', errorDescription: 'Second leg of the Request to quote timed out')
              Step 12: Switch sends the second leg time out error to Payer_DFSP

ii. Non-Forex • After testing with non-Forex, we find that Switch still forwards the same duplicate quote to payee DFSP, which also fails it with the same error status as FXP ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}} • In this case, the remote DFSP is behaving exactly the same as the FXP vDFSP in handling the duplicate request.

How does idempotency relate? i. As per the API spec, the server has only 2 options when it receives a duplicate object: Option 1: If the unique ID exists and some parameters are different: Raise an error to the payer DFSP Option 2: If the unique ID and parameter match a previous request: Ignore new request

Expected Behavior: From the Client / Server idempotency documentation on Mojaloop API Spec, the server should handle idempotency. All this boils down to what product designers meant in this provision:- a. For transfer, the server is switch, no debate. For quotes, is switch a server, or just a mediator? b. If we define switch as server, then switch should drop the duplicate request and not forward to remote DFSP c. If we define the switch as just a middleman, and the payee DFSP as server, then SDK should drop the duplicate request and not raise an error back to switch

@elnyry-sam-k

elnyry-sam-k commented 3 years ago

Thanks again, for the details @tullon ...

As you rightly pointed out, there are some nuances we need to take into account here. Mojaloop quoting-service is designed to work in two modes: 1) A pass-through mode and 2) A persistent mode (I believe Mowali uses this).

In the pass-through mode, as you pointed out, the Switch is primarily a pass-through service (for quotes) and just mediates the messages based on the headers.

In the persistent mode, it still relies on the FSP (payee FSP) side for most of the decisions (quotes only) but the data is persisted and there are capabilities to apply/enforce rules as configured..

In any case, the API definition terminology of client-server applies to an entity and its neighboring entity, so in this case, (I believe) the Switch is the server, though for any data requirements, it relies on the FSP on the other side for queries or errors, etc.

TL;DR - I think duplicate handling has been designed to work on the quoting-service on both modes and should work.. This seems to be a bug to me. (Also, while noting that the concepts of FXP, vDFSPs are a bit new to the ML open source space.)

tullon commented 3 years ago

Hi Sam,

We are totally on the same understanding, thank you.

Pardon the infusion of FXP/vDFSP in this scenario, but these just represent the payee DFSP in a forex scenario, as currently implemented by Mowali. So our scenario should not bring any confusion whether Mowali is "talking" to an independent remote payee DFSP, or a virtual DFSP helping to facilitate forex quotes/transfers for a payee DFSP.

Hope this makes sense?

Rgds

KadidiaN commented 3 years ago

FYI, vDFSP is implemented using the SDK as well as the remote DFSP involved in one of the tests.

elnyry-sam-k commented 3 years ago

Planning to further investigate this during the current Sprint (13.5)

KadidiaN commented 3 years ago

Hello Sam, @elnyry-sam-k Any updates on this issues? Thanks

elnyry-sam-k commented 3 years ago

Hi @KadidiaN , thanks for the reminder, we've prioritized it for this sprint 14.1.. will keep you posted..

mdebarros commented 3 years ago

How Quoting Service handles duplicates

  1. The Quoting Service does NOT handle duplicates in "SIMPLE ROUTING MODE". It will always forward an incoming POST/PUT request/callback as no information is persisted in this mode.

  2. In "PERSISTENT MODE" the following has been observed:

    2.1. When receiving a DUPLICATE POST /quotes request that matches the original request, the Quoting Service will forward the request from the Payer to the Payee without modification. It will do this regardless of the Quote was completed (i.e. received a PUT callback).

    2.2. When receiving a DUPLICATE POST /quotes request that DOES not match the original request, the Quoting Service will respond to the Payer with an Error Callback as follows:

    {
  "method" : "PUT",
  "path" : "/payerfsp/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error",
  "headers" : {
    "Content-Type" : [ "application/vnd.interoperability.quotes+json;version=1.0" ],
    "Date" : [ "Tue, 04 May 2021 16:42:26 GMT" ],
    "FSPIOP-Source" : [ "switch" ],
    "FSPIOP-Destination" : [ "payerfsp" ],
    "FSPIOP-HTTP-Method" : [ "PUT" ],
    "FSPIOP-URI" : [ "/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error" ],
    "traceparent" : [ "00-82c04bb480a60a9ac72575815d49b281-973705d6d0cc69ca-00" ],
    "tracestate" : [ "acmevendor=eyJzcGFuSWQiOiI5NzM3MDVkNmQwY2M2OWNhIn0=" ],
    "User-Agent" : [ "axios/0.21.1" ],
    "Content-Length" : [ "161" ],
    "Host" : [ "localhost:1080" ],
    "Connection" : [ "close" ]
  },
  "keepAlive" : false,
  "secure" : false,
  "body" : {
    "type" : "STRING",
    "string" : "{\"errorInformation\":{\"errorCode\":\"3106\",\"errorDescription\":\"Modified request - Quote ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0 is a duplicate but hashes dont match\"}}",
    "contentType" : "application/vnd.interoperability.quotes+json; version=1.0"
  }
}

    2.3. When receiving a DUPLICATE PUT quotes/{quoteId} callback that matches the original callback, the Quoting Service will forward the callback from the Payee to the Payer without modification.

    2.4. When receiving a DUPLICATE PUT quotes/{quoteId} callback that DOES not match the original callback, the Quoting Service will respond to the Payee with an Error Callback as follows:

    {
  "method" : "PUT",
  "path" : "/payerfsp/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error",
  "headers" : {
    "Content-Type" : [ "application/vnd.interoperability.quotes+json;version=1.0" ],
    "Date" : [ "Tue, 04 May 2021 16:42:26 GMT" ],
    "FSPIOP-Source" : [ "switch" ],
    "FSPIOP-Destination" : [ "payeefsp" ],
    "FSPIOP-HTTP-Method" : [ "PUT" ],
    "FSPIOP-URI" : [ "/quotes/ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0/error" ],
    "traceparent" : [ "00-82c04bb480a60a9ac72575815d49b281-973705d6d0cc69ca-00" ],
    "tracestate" : [ "acmevendor=eyJzcGFuSWQiOiI5NzM3MDVkNmQwY2M2OWNhIn0=" ],
    "User-Agent" : [ "axios/0.21.1" ],
    "Content-Length" : [ "161" ],
    "Host" : [ "localhost:1080" ],
    "Connection" : [ "close" ]
  },
  "keepAlive" : false,
  "secure" : false,
  "body" : {
    "type" : "STRING",
    "string" : "{\"errorInformation\":{\"errorCode\":\"3106\",\"errorDescription\":\"Modified request - Quote ab4d54fe-a775-4d15-93d7-a9dc5c8bcda0 is a duplicate but hashes dont match\"}}",
    "contentType" : "application/vnd.interoperability.quotes+json; version=1.0"
  }
}

  3. Quoting Service does not persist "states" as per Mojaloop FSPIOP Specification, section 6.5.6. of a quote, nor does it manage the quote "lifecycle". It only persists the incoming request, incoming callback, and error callback. Thus we can or cannot defer the following: 3.1. RECEIVED <-- Not possible, as the quoting service does not differentiate from RECEIVED/PENDING states 3.2. PENDING <-- Could be deferred from a quote record existing in the persistent store 3.3. ACCEPTED <-- Could be deferred from a quoteResponse record existing in the persistent store 3.4. REJECTED <-- Could be deferred from a quoteError record existing in the persistent store 3.5. EXPIRED <-- Not possible. No validations are done for expiration on the PUT /quotes{quoteId}

Analysis

Based on Mojaloop FSPIOP Specification, section 3.2.5.1:

  1. If the previously-created object matches the parameter from the new request, the request should be assumed to be a resend from the client. 1.1. If the server has not finished processing the old request and therefore has not yet sent the callback to the client, this new request can be ignored, because a callback is about to be sent to the client. <-- Not functioning as per spec on the POST request, the request will be forwarded regardless of the "state" of the Quote. 1.2. If the server has finished processing the old request and a callback has already been sent, a new callback should be sent to the client, similar to if an HTTP GET request had been sent. <-- Not functioning as per spec on the POST request, and the request is forwarded.

  2. If the previously-created object does not match the parameters from the new request, an error callback should be sent to the client explaining that an object with the provided ID already exists with conflicting parameters. <-- This functionality is as per spec.

Note: It is also unclear if the above-described functionality was originally intended for the /transfers operations only, as such we need to clarify if this should be applied to all other operations (e.g. /quotes, etc).

Additionally, the use of the term server is also unclear. If the server is considered the "Hub" or "Switch", then the Quoting Service is not functioning as per spec. However, the Quoting Service would function mostly correct if the server is considered the "PayeeFSP" as the "Hub" or "Switch" is merely a Message Router, however, we would expect 2. to be handled by the "PayeeFSP".

I believe the term server should be taken as the "Hub" or "Switch", and that Mojaloop FSPIOP Specification, section 3.2.5.1 should be applied to most FSPIOP operations (e.g. /transfers and /quotes) where the "Hub" or "Switch" needs to validate duplicate requests/callbacks with a backend persistence store.

Recommendation

My recommendation is to change the Quoting Service behaviours to follow Mojaloop FSPIOP Specification, section 3.2.5.1:

a. Ignore DUPLICATE POST /quotes that is in a pending state (i.e. quoting-service has not received a PUT /quotes/{quoteId}). b. Respond with as a GET /quotes/{quoteId} when receiving DUPLICATE POST /quotes to "PayerFSP" when the quote state is completed (i.e. quoting-service has been processed the associated PUT /quotes/{quoteId}). The GET /quotes/{quoteId} currently only forwards requests, as such it would need to be modified to retrieve the quote response from the persistent store (if it exists - we can assume that the deferred state is "PENDING", and this would only be applicable when "SIMPLE ROUTING MODE" is disabled). c. Ignore DUPLICATE PUT /quotes/{quoteId} when the quote state is accepted, but log an INTERNAL server error/audit d. Respond with a PUT /quotes/{quoteId}/error to the "PayerFSP" when the DUPLICATE POST /quotes does not match the original request.

elnyry-sam-k commented 3 years ago

Thanks Miguel.

The behavior in "simple routing mode" seems fair, since there's no storage of anything.. But we need to look at the persistent mode behavior of forwarding duplicate (resend) requests..

mdebarros commented 3 years ago 
             Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)

@tullon it's worth mentioning that on Step 9, I believe that the FXP service is not functioning as per Spec. It should also be implementing the same kind of logic as per Mojaloop FSPIOP Specification, section 3.2.5.1. I.e. it should not be responding if the Quote is still in a "PENDING" state as per Mojaloop FSPIOP Specification, section 6.5.6..

I believe that your issue would be fixed if this change was done for the FXP service. This would similarly be applicable for any "FSP" Service receiving a POST /quotes request...i.e. no FSP Service should respond with an error callback if the quote is still "PENDING".

KadidiaN commented 3 years ago

Hello Miguel,

In "PERSISTENT MODE" the following has been observed: 2.1. When receiving a DUPLICATE POST request that matches the original request, the Quoting Service will forward the request from the Payer to the Payee without modification. It will do this regardless if the Quote was completed (i.e. received a PUT callback).

Is that the expected behavior ? I think that what is documented is that it will either send back the same response or hold onto it if the object doesn't has an updated status.

If it forwards to the payee, do you know how is the payee handling?

Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)

@tullonhttps://github.com/tullon it's worth mentioning that on Step 9, I believe that the FXP service is not functioning as per Spec. It should also be implementing the same kind of logic as per Mojaloop FSPIOP Specification, section 3.2.5.1https://docs.mojaloop.io/mojaloop-specification/fspiop-api/documents/API%20Definition%20v1.1.html#3251-duplicate-analysis-in-server-on-receiving-a-http-post-request. I.e. it should not be responding if the Quote is still in a "PENDING" state as per Mojaloop FSPIOP Specification, section 6.5.6.https://docs.mojaloop.io/mojaloop-specification/fspiop-api/documents/API%20Definition%20v1.1.html#656-states.

I believe that your issue would be fixed if this change was done for the FXP service.

I agree , but I think the FXP is implemented using the SDK the same that the simulators are using that 's why we wanted to check if the current DFSP participant SDK supports idempotency let's say as a payee for instance.

Kadidia

From: Miguel de Barros @.> Sent: Wednesday, May 5, 2021 5:52 AM To: mojaloop/project @.> Cc: Kadidia NIANGADO @.>; Mention @.> Subject: Re: [mojaloop/project] Idempotency not working for duplicate quote request (#2119)

         Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)

@tullonhttps://github.com/tullon it's worth mentioning that on Step 9, I believe that the FXP service is not functioning as per Spec. It should also be implementing the same kind of logic as per Mojaloop FSPIOP Specification, section 3.2.5.1https://docs.mojaloop.io/mojaloop-specification/fspiop-api/documents/API%20Definition%20v1.1.html#3251-duplicate-analysis-in-server-on-receiving-a-http-post-request. I.e. it should not be responding if the Quote is still in a "PENDING" state as per Mojaloop FSPIOP Specification, section 6.5.6.https://docs.mojaloop.io/mojaloop-specification/fspiop-api/documents/API%20Definition%20v1.1.html#656-states.

I believe that your issue would be fixed if this change was done for the FXP service.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://github.com/mojaloop/project/issues/2119#issuecomment-832561180, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ATF7CAD2QM2RJ6QFY7RLPNDTMEINXANCNFSM4ZGEXLEQ.

mdebarros commented 3 years ago

In "PERSISTENT MODE" the following has been observed: 2.1. When receiving a DUPLICATE POST request that matches the original request, the Quoting Service will forward the request from the Payer to the Payee without modification. It will do this regardless if the Quote was completed (i.e. received a PUT callback).

This is correct, this how is what I observed when testing the "DUPLICATE" functionality. This will occur for either POST /quotes or PUT /quotes/{quoteId}.

If it forwards to the payee, do you know how is the payee handling?

Step 9: FXP (vDFSP1) generates an error on this duplicate request and sends back to switch ({\"errorInformation\":{\"errorCode\":\"2001\",\"errorDescription\":\"Internal server error\"}}",)

Yes, refer to Mojaloop FSPIOP Specification, section 3.2.5.1. This describes how a "server" should handle the incoming POST or PUT callbacks, regardless of how the "Quoting Service" itself operators. In my opinion, the "hub" and "PayeeFSP" are "servers" depending on the context....and both should adhere to the functionality described in this section.

I agree , but I think the FXP is implemented using the SDK the same that the simulators are using that's why we wanted to check if the current DFSP participant SDK supports idempotency let's say as a payee for instance.

That is a good question. I only validated the DUPLICATE functionality against the Quoting Service and did not include any FSPs (i.e. simulators) using the SDK.

I will investigate this and provide some feedback.

mdebarros commented 3 years ago

Confirmed how a DUPLICATE POST /quotes is handled by the SDK Scheme Adapter:

Logs from the Quoting Service receiving a DUPLICATE POST /quotes:

2021-05-07T12:20:09.208Z - info: 2021-05-07T12:20:09.208Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Check duplicate for quoteId 67b91cab-203a-4a81-b5a8-536016d2dd03 returned: { isResend: true, isDuplicateId: true }
2021-05-07T12:20:09.209Z - info: 2021-05-07T12:20:09.209Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Handling resend of quoteRequest: {
  quoteId: '67b91cab-203a-4a81-b5a8-536016d2dd03',
  transactionId: '2cf54810-a720-499e-95a4-26caa7731233',
  payer: {
    partyIdInfo: {
      partyIdType: 'MSISDN',
      partyIdentifier: '44123456789',
      fspId: 'testingtoolkitdfsp'
    },
    personalInfo: { complexName: [Object], dateOfBirth: '1984-01-01' }
  },
  payee: {
    partyIdInfo: {
      partyIdType: 'MSISDN',
      partyIdentifier: '27713803912',
      fspId: 'payeefsp'
    }
  },
  amountType: 'RECEIVE',
  amount: { amount: '100', currency: 'USD' },
  transactionType: {
    scenario: 'TRANSFER',
    initiator: 'PAYER',
    initiatorType: 'CONSUMER'
  },
  note: 'test'
} from testingtoolkitdfsp to payeefsp

Logs showing Quoting Service forwarding the DUPLICATE POST /quotes to the PayeeFSP (SDK-Scheme-Adapter):

2021-05-07T12:20:09.217Z - info: 2021-05-07T12:20:09.217Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Forwarding quote request to endpoint: http://dev2-sim-payeefsp-scheme-adapter:4000/quotes
2021-05-07T12:20:09.218Z - info: 2021-05-07T12:20:09.218Z, (1620390009182:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10004) [quotesmodel]: Forwarding request : {
  method: 'POST',
  url: 'http://dev2-sim-payeefsp-scheme-adapter:4000/quotes',
  data: '{"quoteId":"67b91cab-203a-4a81-b5a8-536016d2dd03","transactionId":"2cf54810-a720-499e-95a4-26caa7731233","payer":{"partyIdInfo":{"partyIdType":"MSISDN","partyIdentifier":"44123456789","fspId":"testingtoolkitdfsp"},"personalInfo":{"complexName":{"firstName":"Firstname-Test","lastName":"Lastname-Test"},"dateOfBirth":"1984-01-01"}},"payee":{"partyIdInfo":{"partyIdType":"MSISDN","partyIdentifier":"27713803912","fspId":"payeefsp"}},"amountType":"RECEIVE","amount":{"amount":"100","currency":"USD"},"transactionType":{"scenario":"TRANSFER","initiator":"PAYER","initiatorType":"CONSUMER"},"note":"test"}',
  headers: {
    'Content-Type': 'application/vnd.interoperability.quotes+json;version=1.0',
    Date: 'Fri, 07 May 2021 12:15:14 GMT',
    'FSPIOP-Source': 'testingtoolkitdfsp',
    'FSPIOP-Destination': 'payeefsp',
    Accept: 'application/vnd.interoperability.quotes+json;version=1.0',
    traceparent: '00-aabb3909fcab3cd8080d37b6b2b65980-48e4ade9b3b222d7-30',
    tracestate: 'mojaloop=eyJzcGFuSWQiOiI0OGU0YWRlOWIzYjIyMmQ3In0='
  }
}

Logs from Quoting services, showing PayeeFSP (SDK-Scheme-Adapter) responding to Quoting Service with aPUT /quotes/{quoteId}/error`:

2021-05-07T12:20:09Z, [log,info] data: got a `PUT /quotes/{id}/error` callback: {
  errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }
}

Logs from Quoting Service forwarding PUT /quotes/{id}/errorcallback to PayerFSP (Testing Toolkit):

2021-05-07T12:20:09.335Z - info: 2021-05-07T12:20:09.335Z, (1620390009303:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10005) [quotesmodel]: Making error callback to participant 'testingtoolkitdfsp' for quoteId '67b91cab-203a-4a81-b5a8-536016d2dd03' to http://dev2-ml-testing-toolkit-backend:5000/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error for error: {
  message: 'Generic server error',
  replyTo: undefined,
  apiErrorCode: {
    code: '2000',
    message: 'Generic server error',
    httpStatusCode: 500
  },
  extensions: undefined,
  cause: undefined
}
2021-05-07T12:20:09.356Z - info: 2021-05-07T12:20:09.356Z, (1620390009303:dev2-quoting-service-c68fcf99c-8nfbk:18:koa6xzln:10005) [quotesmodel]: Error callback got response 200 OK

Here is the log from the SDK-Scheme-Adapter:

{"ts":"2021-05-07T12:20:09.224Z","msg":"Executing HTTP POST","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"reqOpts":{"method":"POST","uri":"http://dev2-sim-payeefsp-backend:3000/quoterequests","headers":{"Content-Type":"application/json","Accept":"application/json","Date":"Fri, 07 May 2021 12:20:09 GMT"},"body":"{\"quoteId\":\"67b91cab-203a-4a81-b5a8-536016d2dd03\",\"transactionId\":\"2cf54810-a720-499e-95a4-26caa7731233\",\"to\":{\"idType\":\"MSISDN\",\"idValue\":\"27713803912\"},\"from\":{\"idType\":\"MSISDN\",\"idValue\":\"44123456789\",\"dateOfBirth\":\"1984-01-01\",\"firstName\":\"Firstname-Test\",\"lastName\":\"Lastname-Test\"},\"amountType\":\"RECEIVE\",\"amount\":\"100\",\"currency\":\"USD\",\"transactionType\":\"TRANSFER\",\"initiator\":\"PAYER\",\"initiatorType\":\"CONSUMER\",\"note\":\"test\"}"}}}
{"ts":"2021-05-07T12:20:09.224Z","msg":"Request processed","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.225Z","msg":"Cache message received on channel __keyevent@0__:set. Making callback with id 0","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","component":"cache"}}
{"ts":"2021-05-07T12:20:09.225Z","msg":"Received Redis keyevent notification","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-test-api","component":"websocket-server","key":"request_67b91cab-203a-4a81-b5a8-536016d2dd03","channel":"__keyevent@0__:set","id":"0"}}
{"ts":"2021-05-07T12:20:09.271Z","msg":"Error in quoteRequest","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"err":"{\"msg\":\"Request returned non-success status code 500\",\"res\":{\"statusCode\":500,\"headers\":{\"content-type\":\"application/json; charset=utf-8\",\"content-length\":\"46\",\"date\":\"Fri, 07 May 2021 12:20:09 GMT\",\"connection\":\"keep-alive\"},\"data\":{\"statusCode\":\"2000\",\"message\":\"Server error\"},\"originalRequest\":{\"method\":\"POST\",\"host\":\"dev2-sim-payeefsp-backend\",\"port\":\"3000\",\"path\":\"/quoterequests\",\"headers\":{\"Content-Type\":\"application/json\",\"Accept\":\"application/json\",\"Date\":\"Fri, 07 May 2021 12:20:09 GMT\",\"content-length\":433},\"agent\":\"[REDACTED]\",\"body\":\"{\\\"quoteId\\\":\\\"67b91cab-203a-4a81-b5a8-536016d2dd03\\\",\\\"transactionId\\\":\\\"2cf54810-a720-499e-95a4-26caa7731233\\\",\\\"to\\\":{\\\"idType\\\":\\\"MSISDN\\\",\\\"idValue\\\":\\\"27713803912\\\"},\\\"from\\\":{\\\"idType\\\":\\\"MSISDN\\\",\\\"idValue\\\":\\\"44123456789\\\",\\\"dateOfBirth\\\":\\\"1984-01-01\\\",\\\"firstName\\\":\\\"Firstname-Test\\\",\\\"lastName\\\":\\\"Lastname-Test\\\"},\\\"amountType\\\":\\\"RECEIVE\\\",\\\"amount\\\":\\\"100\\\",\\\"currency\\\":\\\"USD\\\",\\\"transactionType\\\":\\\"TRANSFER\\\",\\\"initiator\\\":\\\"PAYER\\\",\\\"initiatorType\\\":\\\"CONSUMER\\\",\\\"note\\\":\\\"test\\\"}\"}}}"}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"Sending error response to testingtoolkitdfsp","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"mojaloopError":{"errorInformation":{"errorCode":"2000","errorDescription":"Generic server error"}}}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"JWS Signing request: {\n  method: 'PUT',\n  uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n  headers: {\n    'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n    date: 'Fri, 07 May 2021 12:20:09 GMT',\n    'fspiop-source': 'payeefsp',\n    'fspiop-destination': 'testingtoolkitdfsp'\n  },\n  body: {\n    errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }\n  },\n  qs: {},\n  agent: Agent {\n    _events: [Object: null prototype] {\n      free: [Function (anonymous)],\n      newListener: [Function: maybeEnableKeylog]\n    },\n    _eventsCount: 2,\n    _maxListeners: undefined,\n    defaultPort: 80,\n    protocol: 'http:',\n    options: { path: null },\n    requests: {},\n    sockets: {},\n    freeSockets: {},\n    keepAliveMsecs: 1000,\n    keepAlive: false,\n    maxSockets: Infinity,\n    maxFreeSockets: 256,\n    scheduling: 'fifo',\n    maxTotalSockets: Infinity,\n    totalSocketCount: 0,\n    [Symbol(kCapture)]: false\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.272Z","msg":"Get JWS Signature: {\n  method: 'PUT',\n  uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n  headers: {\n    'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n    date: 'Fri, 07 May 2021 12:20:09 GMT',\n    'fspiop-source': 'payeefsp',\n    'fspiop-destination': 'testingtoolkitdfsp',\n    'fspiop-http-method': 'PUT',\n    'fspiop-uri': '/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error'\n  },\n  body: {\n    errorInformation: { errorCode: '2000', errorDescription: 'Generic server error' }\n  },\n  qs: {},\n  agent: Agent {\n    _events: [Object: null prototype] {\n      free: [Function (anonymous)],\n      newListener: [Function: maybeEnableKeylog]\n    },\n    _eventsCount: 2,\n    _maxListeners: undefined,\n    defaultPort: 80,\n    protocol: 'http:',\n    options: { path: null },\n    requests: {},\n    sockets: {},\n    freeSockets: {},\n    keepAliveMsecs: 1000,\n    keepAlive: false,\n    maxSockets: Infinity,\n    maxFreeSockets: 256,\n    scheduling: 'fifo',\n    maxTotalSockets: Infinity,\n    totalSocketCount: 0,\n    [Symbol(kCapture)]: false\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.274Z","msg":"Executing HTTP PUT: {\n  reqOpts: {\n    method: 'PUT',\n    uri: 'http://dev2-quoting-service.mojaloop.live/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n    headers: {\n      'content-type': 'application/vnd.interoperability.quotes+json;version=1.0',\n      date: 'Fri, 07 May 2021 12:20:09 GMT',\n      'fspiop-source': 'payeefsp',\n      'fspiop-destination': 'testingtoolkitdfsp',\n      'fspiop-http-method': 'PUT',\n      'fspiop-uri': '/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error',\n      'fspiop-signature': '{\"signature\":\"t0JM_GlAw2WseedgyB_PwgdiFWnrJ3FSzAfiSFe97o1yw4H0Nj1c4MDcBz8YS9OnhL_h1Y5wBU0k7GvXSjI57yj2hEUBDuJf3NTOgQTcSFAfo9GVxAtMyv9tqd-yeh73CxMgrkTqCUUwsaH7nX3-6M24Q5cmTd_gXmZdGujknvlFBWxz-mYFHyyi0Z6xcZFjlMv_Xyq7Rrb5gMIQjnY5pN2jzEExvhAGff7LqN5-L4EvPT-4KHV0gzoCK-ipcmjOPqnzXnnKf9s3vCS4dKn2dL4bp1AcRpWUqXqZ15KnJYMa6MqFV4jubuegip3jYIjVQHc8d9qCUVssJ4hSFrn1hw\",\"protectedHeader\":\"eyJhbGciOiJSUzI1NiIsIkZTUElPUC1VUkkiOiIvcXVvdGVzLzY3YjkxY2FiLTIwM2EtNGE4MS1iNWE4LTUzNjAxNmQyZGQwMy9lcnJvciIsIkZTUElPUC1IVFRQLU1ldGhvZCI6IlBVVCIsIkZTUElPUC1Tb3VyY2UiOiJwYXllZWZzcCIsIkZTUElPUC1EZXN0aW5hdGlvbiI6InRlc3Rpbmd0b29sa2l0ZGZzcCIsIkRhdGUiOiJGcmksIDA3IE1heSAyMDIxIDEyOjIwOjA5IEdNVCJ9\"}'\n    },\n    body: '{\"errorInformation\":{\"errorCode\":\"2000\",\"errorDescription\":\"Generic server error\"}}',\n    qs: {},\n    agent: '[REDACTED]'\n  }\n}","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"}}}
{"ts":"2021-05-07T12:20:09.315Z","msg":"Inbound transfers model handled POST /quotes request","ctx":{"simulator":"payeefsp","hostname":"dev2-sim-payeefsp-scheme-adapter-644d98b9fc-k8cvh","app":"mojaloop-sdk-inbound-api","component":"api","request":{"id":"deafening-sneeze-cooing-hall","path":"/quotes","method":"POST"},"response":{"originalRequest":{"method":"PUT","host":"dev2-quoting-service.mojaloop.live","port":"","path":"/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error","headers":{"content-type":"application/vnd.interoperability.quotes+json;version=1.0","date":"Fri, 07 May 2021 12:20:09 GMT","fspiop-source":"payeefsp","fspiop-destination":"testingtoolkitdfsp","fspiop-http-method":"PUT","fspiop-uri":"/quotes/67b91cab-203a-4a81-b5a8-536016d2dd03/error","fspiop-signature":"{\"signature\":\"t0JM_GlAw2WseedgyB_PwgdiFWnrJ3FSzAfiSFe97o1yw4H0Nj1c4MDcBz8YS9OnhL_h1Y5wBU0k7GvXSjI57yj2hEUBDuJf3NTOgQTcSFAfo9GVxAtMyv9tqd-yeh73CxMgrkTqCUUwsaH7nX3-6M24Q5cmTd_gXmZdGujknvlFBWxz-mYFHyyi0Z6xcZFjlMv_Xyq7Rrb5gMIQjnY5pN2jzEExvhAGff7LqN5-L4EvPT-4KHV0gzoCK-ipcmjOPqnzXnnKf9s3vCS4dKn2dL4bp1AcRpWUqXqZ15KnJYMa6MqFV4jubuegip3jYIjVQHc8d9qCUVssJ4hSFrn1hw\",\"protectedHeader\":\"eyJhbGciOiJSUzI1NiIsIkZTUElPUC1VUkkiOiIvcXVvdGVzLzY3YjkxY2FiLTIwM2EtNGE4MS1iNWE4LTUzNjAxNmQyZGQwMy9lcnJvciIsIkZTUElPUC1IVFRQLU1ldGhvZCI6IlBVVCIsIkZTUElPUC1Tb3VyY2UiOiJwYXllZWZzcCIsIkZTUElPUC1EZXN0aW5hdGlvbiI6InRlc3Rpbmd0b29sa2l0ZGZzcCIsIkRhdGUiOiJGcmksIDA3IE1heSAyMDIxIDEyOjIwOjA5IEdNVCJ9\"}","content-length":83},"agent":"[REDACTED]","body":"{\"errorInformation\":{\"errorCode\":\"2000\",\"errorDescription\":\"Generic server error\"}}"}}}}

Log from Mojaloop-Simulator processing DUPLICATE POST /quoterequests:

{
  app: 'simulator',
  msg: 'Rule engine evaluating facts: {\n' +
    "  path: '/quoterequests',\n" +
    '  body: {\n' +
    "    quoteId: '67b91cab-203a-4a81-b5a8-536016d2dd03',\n" +
    "    transactionId: '2cf54810-a720-499e-95a4-26caa7731233',\n" +
    "    to: { idType: 'MSISDN', idValue: '27713803912' },\n" +
    '    from: {\n' +
    "      idType: 'MSISDN',\n" +
    "      idValue: '44123456789',\n" +
    "      dateOfBirth: '1984-01-01',\n" +
    "      firstName: 'Firstname-Test',\n" +
    "      lastName: 'Lastname-Test'\n" +
    '    },\n' +
    "    amountType: 'RECEIVE',\n" +
    "    amount: '100',\n" +
    "    currency: 'USD',\n" +
    "    transactionType: 'TRANSFER',\n" +
    "    initiator: 'PAYER',\n" +
    "    initiatorType: 'CONSUMER',\n" +
    "    note: 'test'\n" +
    '  },\n' +
    "  method: 'POST'\n" +
    '}',
  timestamp: '2021-05-07T12:20:09.229Z'
}

Logs from Mojaloop-Simulator showing the POST /quoterequests processing result error: INSERT failure caused by UNIQUE constraint on the quoteId:

{
  app: 'simulator',
  request: {
    id: 'cool-church-thinkable-word',
    path: '/quoterequests',
    method: 'POST'
  },
  msg: 'Error in postQuotes: Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: quote.id',
  timestamp: '2021-05-07T12:20:09.270Z'
}

Additionally looking at the Mojaloop-Simulator code, we can see that there is no "additional" logic to handle duplicate quotes:

From this, we can see that the DUPLICATE POST /quote is being sent by the SDK-Scheme-Adapter to the Mojaloop-Simulator which is then failing to process the request and responding to the SDK-Scheme-Adapter with an error resulting in the POST /quotes/{quoteId}/error callback.

Thus I believe that the issue originating from your FXP Service is NOT generated from the SDK-Scheme-Adapter, but rather the "Backend" implementation.

Please validate this on your side.

Finally, there is a question here to be answered:

Which "FSP" component should be responsible for handling the "DUPLICATE" resend validation...should this be done by the SDK-Scheme-Adapter or the "Backend"?

elnyry-sam-k commented 3 years ago

Investigation completed, findings documented above and discussed with Mowali team who raised this.